diff --git a/docs/Profiler.md b/docs/Profiler.md index 67934e5..3aae38a 100644 --- a/docs/Profiler.md +++ b/docs/Profiler.md @@ -7,6 +7,23 @@ per command call). The HTMX debug traces (via `htmx_debug.js`) confirmed the bot server-side. A persistent, in-application profiling system is needed for continuous analysis across sessions and future investigations. +--- + +## Implementation Status + +| Phase | Item | Status | +|-------|------|--------| +| **Phase 1 — Core** | `profiler.py` — data model + probe mechanisms | ✅ Done | +| **Phase 1 — Core** | `tests/core/test_profiler.py` — full test suite (7 classes) | ✅ Done | +| **Phase 1 — Core** | Hook `utils.py` — Level A `command_span` | ✅ Done | +| **Phase 1 — Core** | Hook `commands.py` — Level B phases | ⏳ Deferred | +| **Phase 2 — Controls** | `Profiler.py` — global layout (toolbar + list) | 🔄 In progress | +| **Phase 2 — Controls** | `Profiler.py` — detail panel (span tree + pie) | ⏳ Pending | +| **Phase 2 — Controls** | CSS `profiler.css` | 🔄 In progress | +| **Phase 2 — Controls** | `ProfilerPieChart.py` | ⏳ Future | + +--- + ## Design Decisions ### Data Collection Strategy @@ -150,7 +167,7 @@ of the first command's active span. The `ProfilingManager` self-profiles its own `span.__enter__` and `span.__exit__` calls. Exposes: -- `overhead_per_span_ns` — average cost of one span boundary in nanoseconds +- `overhead_per_span_us` — average cost of one span boundary in microseconds - `total_overhead_ms` — estimated total overhead across all active spans Visible in the UI to verify the profiler does not bias measurements significantly. @@ -186,19 +203,20 @@ CumulativeSpan --- -## Existing Code Hooks +## Code Hooks -### `src/myfasthtml/core/utils.py` — route handler (Level A) +### `src/myfasthtml/core/utils.py` — route handler (Level A) ✅ ```python -@utils_rt(Routes.Commands) -async def post(session, c_id: str, client_response: dict = None): - with profiler.span("command", args={"c_id": c_id}): - command = CommandsManager.get_command(c_id) - return await command.execute(client_response) +command = CommandsManager.get_command(c_id) +if command: + with profiler.command_span(command.name, c_id, client_response or {}): + return command.execute(client_response) ``` -### `src/myfasthtml/core/commands.py` — execution phases (Level B) +### `src/myfasthtml/core/commands.py` — execution phases (Level B) ⏳ Deferred + +Planned breakdown inside `Command.execute()`: ```python def execute(self, client_response=None): @@ -212,54 +230,120 @@ def execute(self, client_response=None): ... ``` +Deferred: will be added once the UI control is functional to immediately observe the breakdown. + +--- + +## UI Control Design + +### Control name: `Profiler` (SingleInstance) + +Single entry point. Replaces the earlier `ProfilerList` name. + +**Files:** +- `src/myfasthtml/controls/Profiler.py` +- `src/myfasthtml/assets/core/profiler.css` + +### Layout + +Split view using `Panel`: + +``` +┌─────────────────────────────────────────────────────┐ +│ [●] [🗑] Overhead/span: 1.2µs Traces: 8/500│ ← toolbar (icon-only) +├──────────────────────┬──────────────────────────────┤ +│ Command Duration Time│ NavigateCell — 173.4ms [≡][◕]│ +│ ──────────────────────│ ─────────────────────────────│ +│ NavigateCell 173ms … │ [Metadata card] │ +│ NavigateCell 168ms … │ [kwargs card] │ +│ SelectRow 42ms … │ [Span breakdown / Pie chart] │ +│ … │ │ +└──────────────────────┴──────────────────────────────┘ +``` + +### Toolbar + +Icon-only buttons, no `Menu` control (Menu does not support toggle state). +Direct `mk.icon()` calls: + +- **Enable/disable**: icon changes between "recording" and "stopped" states based on `profiler.enabled` +- **Clear**: delete icon, always red +- **Refresh**: manual refresh of the trace list (no auto-refresh yet — added in Step 2.1) + +Overhead metrics displayed as plain text on the right side of the toolbar. + +### Trace list (left panel) + +Three columns: command name / duration (color-coded) / timestamp. +Click on a row → update right panel via HTMX. + +**Duration color thresholds:** +- Green (`mf-profiler-fast`): < 20 ms +- Orange (`mf-profiler-medium`): 20–100 ms +- Red (`mf-profiler-slow`): > 100 ms + +### Detail panel (right) + +Two view modes, toggled by icons in the detail panel header: + +1. **Tree view** (default): Properties-style cards (Metadata, kwargs) + span breakdown with + proportional bars and indentation. Cumulative spans show `×N · min/avg/max` badge. +2. **Pie view**: `ProfilerPieChart` control (future) — distribution of time across spans + at the current zoom level. + +The `Properties` control is used as-is for Metadata and kwargs cards. +The span breakdown is custom rendering (not a `Properties` instance). + +### Font conventions + +- Labels, headings, command names: `--font-sans` (DaisyUI default) +- Values (durations, timestamps, kwargs values): `--font-mono` +- Consistent with `properties.css` (`mf-properties-value` uses `--default-mono-font-family`) + +### Visual reference + +Mockups available in `examples/`: +- `profiler_mockup.html` — first iteration (monospace font everywhere) +- `profiler_mockup_2.html` — **reference** (correct fonts, icon toolbar, tree/pie toggle) + --- ## Implementation Plan -### Phase 1 — Core +### Phase 1 — Core ✅ Complete -**File**: `src/myfasthtml/core/profiler.py` +1. `ProfilingSpan`, `CumulativeSpan`, `ProfilingTrace` dataclasses +2. `ProfilingManager` with all probe mechanisms +3. `profiler` singleton +4. Hook into `utils.py` (Level A) ✅ +5. Hook into `commands.py` (Level B) — deferred -1. `ProfilingSpan` dataclass -2. `CumulativeSpan` dataclass -3. `ProfilingTrace` dataclass -4. `ProfilingManager` class with all probe mechanisms -5. `profiler` singleton -6. Hook into `utils.py` (Level A) -7. Hook into `commands.py` (Level B) - -**Tests**: `tests/core/test_profiler.py` - -| Test | Description | -|------|-------------| -| `test_i_can_create_a_span` | Basic span creation and timing | -| `test_i_can_nest_spans` | Child spans are correctly parented | -| `test_i_can_use_span_as_decorator` | Decorator captures args automatically | -| `test_i_can_use_cumulative_span` | Aggregates count/total/min/max/avg | -| `test_i_can_attach_data_to_span` | `span.set()` and `current_span().set()` | -| `test_i_can_clear_traces` | Buffer is emptied after `clear()` | -| `test_i_can_enable_disable_profiler` | Probes are no-ops when disabled | -| `test_i_can_measure_overhead` | Overhead metrics are exposed | -| `test_i_can_use_trace_all_on_class` | All methods of a class are wrapped | -| `test_i_can_use_trace_calls_on_function` | Sub-calls are traced via setprofile | +**Tests**: `tests/core/test_profiler.py` — 7 classes, full coverage ✅ ### Phase 2 — Controls -**`src/myfasthtml/controls/ProfilerList.py`** (SingleInstance) -- Table of all traces: command name / total duration / timestamp -- Right panel: trace detail (kwargs, span breakdown) -- Buttons: enable/disable, clear -- Click on a trace → opens ProfilerDetail +#### Step 2.1 — Global layout (current) 🔄 -**`src/myfasthtml/controls/ProfilerDetail.py`** (MultipleInstance) -- Hierarchical span tree for a single trace -- Two display modes: list and pie chart -- Click on a span → zooms into its children (if any) -- Displays cumulative spans with count/min/max/avg -- Shows overhead metrics +`src/myfasthtml/controls/Profiler.py`: +- `SingleInstance` inheriting +- Toolbar: `mk.icon()` for enable/disable and clear, overhead text +- `Panel` for split layout +- Left: trace list table (command / duration / timestamp), click → select_trace command +- Right: placeholder (empty until Step 2.2) -**`src/myfasthtml/controls/ProfilerPieChart.py`** (future) -- Pie chart visualization of span distribution at a given zoom level +`src/myfasthtml/assets/core/profiler.css`: +- All `mf-profiler-*` classes + +#### Step 2.2 — Detail panel ⏳ + +Right panel content: +- Metadata and kwargs via `Properties` +- Span tree: custom `_mk_span_tree()` with bars and cumulative badges +- View toggle (tree / pie) in detail header + +#### Step 2.3 — Pie chart ⏳ Future + +`src/myfasthtml/controls/ProfilerPieChart.py` --- diff --git a/examples/profiler_mockup.html b/examples/profiler_mockup.html new file mode 100644 index 0000000..2e878f0 --- /dev/null +++ b/examples/profiler_mockup.html @@ -0,0 +1,640 @@ + + + + + Profiler — UI Mockup + + + + + + + +
+ Profiler + + + + +
+ Overhead/span: 1.2 µs + Total overhead: 0.04 ms + Traces: 8 / 500 +
+
+ + + + +
+ + + + +
+
+ Command + Duration + Time +
+
+ +
+ NavigateCell + 173.4 ms + 14:32:07.881 +
+ +
+ NavigateCell + 168.1 ms + 14:32:07.712 +
+ +
+ SelectRow + 42.7 ms + 14:32:06.501 +
+ +
+ FilterChanged + 38.2 ms + 14:32:05.334 +
+ +
+ NavigateCell + 12.0 ms + 14:32:04.102 +
+ +
+ SortColumn + 8.4 ms + 14:32:03.770 +
+ +
+ SelectRow + 5.1 ms + 14:32:02.441 +
+ +
+ NavigateCell + 4.8 ms + 14:32:01.003 +
+ +
+
+ + + + +
+
+ Trace detail — NavigateCell +
+ +
+ + +
+
Metadata
+
+
command
+
NavigateCell
+
+
+
total_duration_ms
+
173.4
+
+
+
timestamp
+
2026-03-21 14:32:07.881
+
+
+ + +
+
kwargs
+
+
row
+
12
+
+
+
col
+
3
+
+
+
direction
+
down
+
+
+ + +
+
Span breakdown
+ + +
+
+
+ NavigateCell +
+
+
+ 173.4 ms +
+
+ + +
+
+
+ before_commands +
+
+
+ 0.8 ms +
+
+ + +
+
+
+ callback +
+
+
+ 152.6 ms +
+
+ + +
+
+
+ navigate_cell +
+
+
+ 149.0 ms +
+
+ + +
+
+
+ process_row +
+
+
+ 138.5 ms +
+ ×1000 · min 0.1 · avg 0.14 · max 0.4 ms +
+ + +
+
+
+ after_commands +
+
+
+ 10.3 ms +
+
+ + +
+
+
+ oob_swap +
+
+
+ 9.7 ms +
+
+ +
+ +
+
+ +
+ + + + diff --git a/examples/profiler_mockup_2.html b/examples/profiler_mockup_2.html new file mode 100644 index 0000000..33f46eb --- /dev/null +++ b/examples/profiler_mockup_2.html @@ -0,0 +1,920 @@ + + + + + Profiler — UI Mockup 2 + + + + + + + +
+ + + + + + + +
+ + +
+ Overhead/span: 1.2 µs + Total overhead: 0.04 ms + Traces: 8 / 500 +
+ +
+ + + + +
+ + + + +
+
+ Command + Duration + Time +
+
+ +
+ NavigateCell + 173.4 ms + 14:32:07.881 +
+
+ NavigateCell + 168.1 ms + 14:32:07.712 +
+
+ SelectRow + 42.7 ms + 14:32:06.501 +
+
+ FilterChanged + 38.2 ms + 14:32:05.334 +
+
+ NavigateCell + 12.0 ms + 14:32:04.102 +
+
+ SortColumn + 8.4 ms + 14:32:03.770 +
+
+ SelectRow + 5.1 ms + 14:32:02.441 +
+
+ NavigateCell + 4.8 ms + 14:32:01.003 +
+ +
+
+ + + + +
+ + +
+ + NavigateCell — 173.4 ms + +
+ + + + +
+
+ +
+ + +
+
Metadata
+
+
command
+
NavigateCell
+
+
+
total_duration_ms
+
173.4
+
+
+
timestamp
+
2026-03-21 14:32:07.881
+
+
+ + +
+
kwargs
+
+
row
+
12
+
+
+
col
+
3
+
+
+
direction
+
down
+
+
+ + + + +
+
Span breakdown
+ + +
+
+ NavigateCell +
+
+
+ 173.4 ms +
+
+ + +
+
+
+ before_commands +
+
+
+ 0.8 ms +
+
+ + +
+
+
+ callback +
+
+
+ 152.6 ms +
+
+ + +
+
+
+
+ navigate_cell +
+
+
+ 149.0 ms +
+
+ + +
+
+
+
+
+ process_row +
+
+
+ 138.5 ms +
+ ×1000 · min 0.10 · avg 0.14 · max 0.40 ms +
+ + +
+
+
+ after_commands +
+
+
+ 10.3 ms +
+
+ + +
+
+
+ oob_swap +
+
+
+ 9.7 ms +
+
+ +
+ + + + +
+
Distribution
+
+ + + + + + + + + + + + + + + +
+
+
+ process_row + 80.0% +
+
+
+ callback + 8.0% +
+
+
+ after_commands + 6.0% +
+
+
+ oob_swap + 5.6% +
+
+
+ before_commands + 0.4% +
+
+
+
+ +
+
+ +
+ + + + diff --git a/src/app.py b/src/app.py index 870fd64..72aba72 100644 --- a/src/app.py +++ b/src/app.py @@ -13,13 +13,14 @@ from myfasthtml.controls.FileUpload import FileUpload from myfasthtml.controls.InstancesDebugger import InstancesDebugger from myfasthtml.controls.Keyboard import Keyboard from myfasthtml.controls.Layout import Layout +from myfasthtml.controls.Profiler import Profiler from myfasthtml.controls.TabsManager import TabsManager from myfasthtml.controls.helpers import Ids, mk from myfasthtml.core.dbengine_utils import DataFrameHandler from myfasthtml.core.instances import UniqueInstance from myfasthtml.icons.carbon import volume_object_storage from myfasthtml.icons.fluent_p2 import key_command16_regular -from myfasthtml.icons.fluent_p3 import folder_open20_regular, text_edit_style20_regular +from myfasthtml.icons.fluent_p3 import folder_open20_regular, text_edit_style20_regular, timer20_regular from myfasthtml.myfastapp import create_app with open('logging.yaml', 'r') as f: @@ -55,13 +56,19 @@ def index(session): btn_show_instances_debugger = mk.label("Instances", icon=volume_object_storage, command=add_tab("Instances", instances_debugger), - id=instances_debugger.get_id()) + id=f"l_{instances_debugger.get_id()}") commands_debugger = CommandsDebugger(layout) btn_show_commands_debugger = mk.label("Commands", icon=key_command16_regular, command=add_tab("Commands", commands_debugger), - id=commands_debugger.get_id()) + id=f"l_{commands_debugger.get_id()}") + + profiler = Profiler(layout) + btn_show_profiler = mk.label("Profiler", + icon=timer20_regular, + command=add_tab("Profiler", profiler), + id=f"l_{profiler.get_id()}") btn_file_upload = mk.label("Upload", icon=folder_open20_regular, @@ -75,12 +82,14 @@ def index(session): layout.header_right.add(btn_show_right_drawer) layout.left_drawer.add(btn_show_instances_debugger, "Debugger") layout.left_drawer.add(btn_show_commands_debugger, "Debugger") + layout.left_drawer.add(btn_show_profiler, "Debugger") # Parameters formatting_manager = DataGridFormattingManager(layout) btn_show_formatting_manager = mk.label("Formatting", icon=text_edit_style20_regular, - command=add_tab("Formatting", formatting_manager)) + command=add_tab("Formatting", formatting_manager), + id=f"l_{formatting_manager.get_id()}") layout.left_drawer.add(btn_show_formatting_manager, "Parameters") layout.left_drawer.add(btn_file_upload, "Test") diff --git a/src/myfasthtml/assets/core/profiler.css b/src/myfasthtml/assets/core/profiler.css new file mode 100644 index 0000000..7c120f6 --- /dev/null +++ b/src/myfasthtml/assets/core/profiler.css @@ -0,0 +1,177 @@ +/* ================================================================== */ +/* Profiler Control */ +/* ================================================================== */ + +/* ------------------------------------------------------------------ + Root wrapper — fills parent, stacks toolbar above panel + ------------------------------------------------------------------ */ +.mf-profiler { + display: flex; + flex-direction: column; + width: 100%; + height: 100%; + overflow: hidden; + font-family: var(--font-sans); + font-size: var(--text-sm); +} + +/* ------------------------------------------------------------------ + Toolbar + ------------------------------------------------------------------ */ +.mf-profiler-toolbar { + display: flex; + align-items: center; + gap: 2px; + padding: 4px 8px; + background: var(--color-base-200); + border-bottom: 1px solid var(--color-border); + flex-shrink: 0; +} + +/* Danger variant for clear button */ +.mf-profiler-btn-danger { + color: var(--color-error) !important; +} + +.mf-profiler-btn-danger:hover { + background: color-mix(in oklab, var(--color-error) 15%, transparent) !important; +} + +/* Overhead metrics — right-aligned text */ +.mf-profiler-overhead { + margin-left: auto; + font-family: var(--font-sans); + font-size: var(--text-xs); + color: color-mix(in oklab, var(--color-base-content) 50%, transparent); + white-space: nowrap; +} + +/* ------------------------------------------------------------------ + Trace list — left panel content + ------------------------------------------------------------------ */ +.mf-profiler-list { + display: flex; + flex-direction: column; + width: 100%; + height: 100%; + overflow: hidden; +} + +.mf-profiler-list-header { + display: grid; + grid-template-columns: 1fr 80px 96px; + padding: 4px 10px; + background: var(--color-base-200); + border-bottom: 1px solid var(--color-border); + font-size: var(--text-xs); + color: color-mix(in oklab, var(--color-base-content) 50%, transparent); + text-transform: uppercase; + letter-spacing: 0.06em; + flex-shrink: 0; +} + +.mf-profiler-col-header { + font-family: var(--font-sans); +} + +.mf-profiler-col-right { + text-align: right; +} + +.mf-profiler-list-body { + overflow-y: auto; + flex: 1; +} + +/* ------------------------------------------------------------------ + Trace row + ------------------------------------------------------------------ */ +.mf-profiler-row { + display: grid; + grid-template-columns: 1fr 80px 96px; + align-items: center; + padding: 5px 10px; + border-bottom: 1px solid color-mix(in oklab, var(--color-border) 60%, transparent); + cursor: pointer; + transition: background 0.1s; +} + +.mf-profiler-row:hover { + background: var(--color-base-200); +} + +.mf-profiler-row-selected { + background: color-mix(in oklab, var(--color-primary) 12%, transparent); + border-left: 2px solid var(--color-primary); + padding-left: 8px; +} + +.mf-profiler-row-selected:hover { + background: color-mix(in oklab, var(--color-primary) 18%, transparent); +} + +/* Command name + description cell */ +.mf-profiler-cmd-cell { + display: flex; + align-items: baseline; + gap: 6px; + overflow: hidden; +} + +.mf-profiler-cmd { + font-family: var(--font-sans); + font-size: var(--text-sm); + white-space: nowrap; + flex-shrink: 0; +} + +.mf-profiler-cmd-description { + font-family: var(--font-sans); + font-size: var(--text-xs); + font-style: italic; + color: color-mix(in oklab, var(--color-base-content) 45%, transparent); + white-space: nowrap; + overflow: hidden; + text-overflow: ellipsis; +} + +/* Duration cell — monospace, color-coded */ +.mf-profiler-duration { + font-family: var(--font-mono); + font-size: var(--text-xs); + text-align: right; +} + +.mf-profiler-fast { + color: var(--color-success); +} + +.mf-profiler-medium { + color: var(--color-warning); +} + +.mf-profiler-slow { + color: var(--color-error); +} + +/* Timestamp cell */ +.mf-profiler-ts { + font-family: var(--font-mono); + font-size: var(--text-xs); + text-align: right; + color: color-mix(in oklab, var(--color-base-content) 45%, transparent); +} + +/* ------------------------------------------------------------------ + Empty state + ------------------------------------------------------------------ */ +.mf-profiler-empty { + display: flex; + align-items: center; + justify-content: center; + height: 100%; + padding: 24px; + font-family: var(--font-sans); + font-size: var(--text-sm); + color: color-mix(in oklab, var(--color-base-content) 40%, transparent); +} diff --git a/src/myfasthtml/controls/DataGrid.py b/src/myfasthtml/controls/DataGrid.py index b924280..2093cd8 100644 --- a/src/myfasthtml/controls/DataGrid.py +++ b/src/myfasthtml/controls/DataGrid.py @@ -272,7 +272,7 @@ class DataGrid(MultipleInstance): self._datagrid_filter.bind_command("ChangeFilterType", self.commands.filter()) self._state.filtered[FILTER_INPUT_CID] = self._datagrid_filter.get_query() - # add Selection Selector + # add Selection Selector (cell, row, column) selection_types = { "cell": mk.icon(grid, tooltip="Cell selection"), # default "row": mk.icon(row, tooltip="Row selection"), diff --git a/src/myfasthtml/controls/IconsHelper.py b/src/myfasthtml/controls/IconsHelper.py index df48a23..0c6342f 100644 --- a/src/myfasthtml/controls/IconsHelper.py +++ b/src/myfasthtml/controls/IconsHelper.py @@ -1,13 +1,14 @@ from fastcore.basics import NotStr -from myfasthtml.core.constants import ColumnType +from myfasthtml.core.constants import ColumnType, MediaActions from myfasthtml.core.utils import pascal_to_snake from myfasthtml.icons.fluent import question20_regular, brain_circuit20_regular, number_symbol20_regular, \ number_row20_regular from myfasthtml.icons.fluent_p1 import checkbox_checked20_regular, checkbox_unchecked20_regular, \ - checkbox_checked20_filled, math_formula16_regular, folder20_regular, document20_regular -from myfasthtml.icons.fluent_p2 import text_field20_regular, text_bullet_list_square20_regular -from myfasthtml.icons.fluent_p3 import calendar_ltr20_regular + checkbox_checked20_filled, math_formula16_regular, folder20_regular, document20_regular, pause_circle20_regular +from myfasthtml.icons.fluent_p2 import text_field20_regular, text_bullet_list_square20_regular, play_circle20_regular, \ + dismiss_circle20_regular +from myfasthtml.icons.fluent_p3 import calendar_ltr20_regular, record_stop20_regular default_icons = { # default type icons @@ -22,6 +23,12 @@ default_icons = { "TreeViewFolder": folder20_regular, "TreeViewFile": document20_regular, + # Media + MediaActions.Play: play_circle20_regular, + MediaActions.Pause: pause_circle20_regular, + MediaActions.Stop: record_stop20_regular, + MediaActions.Cancel: dismiss_circle20_regular, + # Datagrid column icons ColumnType.RowIndex: number_symbol20_regular, ColumnType.Text: text_field20_regular, diff --git a/src/myfasthtml/controls/Panel.py b/src/myfasthtml/controls/Panel.py index 7b64045..7b5d414 100644 --- a/src/myfasthtml/controls/Panel.py +++ b/src/myfasthtml/controls/Panel.py @@ -104,7 +104,7 @@ class Panel(MultipleInstance): the panel with appropriate HTML elements and JavaScript for interactivity. """ - def __init__(self, parent, conf: Optional[PanelConf] = None, _id=None): + def __init__(self, parent, conf: Optional[PanelConf] = None, _id="-panel"): super().__init__(parent, _id=_id) self.conf = conf or PanelConf() self.commands = Commands(self) diff --git a/src/myfasthtml/controls/Profiler.py b/src/myfasthtml/controls/Profiler.py new file mode 100644 index 0000000..cab237e --- /dev/null +++ b/src/myfasthtml/controls/Profiler.py @@ -0,0 +1,202 @@ +import logging + +from fasthtml.components import Div, Span + +from myfasthtml.controls.BaseCommands import BaseCommands +from myfasthtml.controls.IconsHelper import IconsHelper +from myfasthtml.controls.Panel import Panel, PanelConf +from myfasthtml.controls.helpers import mk +from myfasthtml.core.commands import Command +from myfasthtml.core.constants import PROFILER_MAX_TRACES, MediaActions +from myfasthtml.core.instances import SingleInstance +from myfasthtml.core.profiler import profiler +from myfasthtml.icons.fluent import arrow_clockwise20_regular + +logger = logging.getLogger("Profiler") + + +class Commands(BaseCommands): + + def toggle_enable(self): + return Command( + "ProfilerToggleEnable", + "Enable / Disable profiler", + self._owner, + self._owner.handle_toggle_enable, + ).htmx(target=f"#{self._id}") + + def clear_traces(self): + return Command( + "ProfilerClearTraces", + "Clear all recorded traces", + self._owner, + self._owner.handle_clear_traces, + icon=IconsHelper.get(MediaActions.Cancel), + ).htmx(target=f"#{self._id}") + + def refresh(self): + return Command( + "ProfilerRefresh", + "Refresh traces", + self._owner, + self._owner.handle_refresh, + icon=arrow_clockwise20_regular, + ).htmx(target=f"#{self._id}") + + def select_trace(self, trace_id: str): + return Command( + "ProfilerSelectTrace", + "Display trace details", + self._owner, + self._owner.handle_select_trace, + kwargs={"trace_id": trace_id}, + ).htmx(target=f"#{self._id}") + + +class Profiler(SingleInstance): + """In-application profiler UI. + + Displays all recorded traces in a scrollable list (left) and trace + details in a resizable panel (right). The toolbar provides enable / + disable toggle and clear actions via icon-only buttons. + + Attributes: + commands: Commands exposed by this control. + """ + + def __init__(self, parent, _id=None): + super().__init__(parent, _id=_id) + self._panel = Panel(self, conf=PanelConf(show_right_title=False, show_display_right=False)) + self._selected_id: str | None = None + self.commands = Commands(self) + logger.debug(f"Profiler created with id={self._id}") + + # ------------------------------------------------------------------ + # Command handlers + # ------------------------------------------------------------------ + + def handle_toggle_enable(self): + """Toggle profiler.enabled and re-render.""" + profiler.enabled = not profiler.enabled + logger.debug(f"Profiler enabled set to {profiler.enabled}") + return self + + def handle_clear_traces(self): + """Clear the trace buffer and re-render.""" + profiler.clear() + logger.debug("Profiler traces cleared from UI") + return self + + def handle_select_trace(self, trace_id: str): + """Select a trace row and re-render to show it highlighted.""" + self._selected_id = trace_id + return self + + def handle_refresh(self): + """Select a trace row and re-render to show it highlighted.""" + return self + + # ------------------------------------------------------------------ + # Private rendering helpers + # ------------------------------------------------------------------ + + def _duration_cls(self, duration_ms: float) -> str: + """Return the CSS modifier class for a given duration.""" + if duration_ms < 20: + return "mf-profiler-fast" + if duration_ms < 100: + return "mf-profiler-medium" + return "mf-profiler-slow" + + def _mk_toolbar(self): + """Build the icon toolbar with enable/disable, clear and overhead metrics.""" + enable_icon = ( + IconsHelper.get(MediaActions.Pause) + if profiler.enabled + else IconsHelper.get(MediaActions.Play) + ) + enable_tooltip = "Disable profiler" if profiler.enabled else "Enable profiler" + + overhead = ( + f"Overhead/span: {profiler.overhead_per_span_us:.1f} µs " + f"Total: {profiler.total_overhead_ms:.3f} ms " + f"Traces: {len(profiler.traces)} / {PROFILER_MAX_TRACES}" + ) + + return Div( + mk.icon( + enable_icon, + command=self.commands.toggle_enable(), + tooltip=enable_tooltip, + ), + mk.icon( + command=self.commands.clear_traces(), + tooltip="Clear traces", + cls="mf-profiler-btn-danger", + ), + mk.icon( + command=self.commands.refresh(), + ), + Span(overhead, cls="mf-profiler-overhead"), + cls="mf-profiler-toolbar", + id=f"tb_{self._id}", + ) + + def _mk_trace_list(self): + """Build the trace list with one clickable row per recorded trace.""" + traces = profiler.traces + if not traces: + return Div("No traces recorded.", cls="mf-profiler-empty") + + rows = [] + for trace in traces: + ts = trace.timestamp.strftime("%H:%M:%S.") + f"{trace.timestamp.microsecond // 1000:03d}" + duration_cls = self._duration_cls(trace.total_duration_ms) + row_cls = "mf-profiler-row mf-profiler-row-selected" if trace.trace_id == self._selected_id else "mf-profiler-row" + + row = mk.mk( + Div( + Div( + Span(trace.command_name, cls="mf-profiler-cmd"), + Span(trace.command_description, cls="mf-profiler-cmd-description"), + cls="mf-profiler-cmd-cell", + ), + Span(f"{trace.total_duration_ms:.1f} ms", cls=f"mf-profiler-duration {duration_cls}"), + Span(ts, cls="mf-profiler-ts"), + cls=row_cls, + ), + command=self.commands.select_trace(trace.trace_id), + ) + rows.append(row) + + return Div( + Div( + Span("Command", cls="mf-profiler-col-header"), + Span("Duration", cls="mf-profiler-col-header mf-profiler-col-right"), + Span("Time", cls="mf-profiler-col-header mf-profiler-col-right"), + cls="mf-profiler-list-header", + ), + Div(*rows, cls="mf-profiler-list-body"), + cls="mf-profiler-list", + ) + + def _mk_detail_placeholder(self): + """Placeholder shown in the right panel before a trace is selected.""" + return Div("Select a trace to view details.", cls="mf-profiler-empty") + + # ------------------------------------------------------------------ + # Render + # ------------------------------------------------------------------ + + def render(self): + self._panel.set_main(self._mk_trace_list()) + self._panel.set_right(self._mk_detail_placeholder()) + return Div( + self._mk_toolbar(), + self._panel, + id=self._id, + cls="mf-profiler", + ) + + def __ft__(self): + return self.render() diff --git a/src/myfasthtml/core/constants.py b/src/myfasthtml/core/constants.py index a1b29c0..64fe12e 100644 --- a/src/myfasthtml/core/constants.py +++ b/src/myfasthtml/core/constants.py @@ -33,6 +33,13 @@ class ColumnType(Enum): Formula = "Formula" +class MediaActions(Enum): + Play = "Play" + Pause = "Pause" + Stop = "Stop" + Cancel = "Cancel" + + def get_columns_types() -> list[ColumnType]: return [c for c in ColumnType if not c.value.endswith("_")] diff --git a/src/myfasthtml/core/profiler.py b/src/myfasthtml/core/profiler.py index 049961e..b45f115 100644 --- a/src/myfasthtml/core/profiler.py +++ b/src/myfasthtml/core/profiler.py @@ -8,6 +8,7 @@ from contextvars import ContextVar from dataclasses import dataclass, field from datetime import datetime from typing import Optional +from uuid import uuid4 logger = logging.getLogger("Profiler") @@ -17,19 +18,19 @@ logger = logging.getLogger("Profiler") # --------------------------------------------------------------------------- class _NullSpan: - """No-op span returned when profiler is disabled.""" - - def set(self, key: str, value) -> '_NullSpan': - return self - - def __enter__(self) -> '_NullSpan': - return self - - def __exit__(self, *args): - pass - - def __call__(self, fn): - return fn + """No-op span returned when profiler is disabled.""" + + def set(self, key: str, value) -> '_NullSpan': + return self + + def __enter__(self) -> '_NullSpan': + return self + + def __exit__(self, *args): + pass + + def __call__(self, fn): + return fn # --------------------------------------------------------------------------- @@ -38,95 +39,98 @@ class _NullSpan: @dataclass class CumulativeSpan: - """Aggregated span for loops — one entry regardless of iteration count. + """Aggregated span for loops — one entry regardless of iteration count. - Attributes: - name: Span name. - count: Number of iterations recorded. - total_ms: Cumulative duration in milliseconds. - min_ms: Shortest recorded iteration in milliseconds. - max_ms: Longest recorded iteration in milliseconds. + Attributes: + name: Span name. + count: Number of iterations recorded. + total_ms: Cumulative duration in milliseconds. + min_ms: Shortest recorded iteration in milliseconds. + max_ms: Longest recorded iteration in milliseconds. + """ + + name: str + count: int = 0 + total_ms: float = 0.0 + min_ms: float = float('inf') + max_ms: float = 0.0 + + @property + def avg_ms(self) -> float: + """Average duration per iteration in milliseconds.""" + return self.total_ms / self.count if self.count > 0 else 0.0 + + def record(self, duration_ms: float): + """Record one iteration. + + Args: + duration_ms: Duration of this iteration in milliseconds. """ - - name: str - count: int = 0 - total_ms: float = 0.0 - min_ms: float = float('inf') - max_ms: float = 0.0 - - @property - def avg_ms(self) -> float: - """Average duration per iteration in milliseconds.""" - return self.total_ms / self.count if self.count > 0 else 0.0 - - def record(self, duration_ms: float): - """Record one iteration. - - Args: - duration_ms: Duration of this iteration in milliseconds. - """ - self.count += 1 - self.total_ms += duration_ms - if duration_ms < self.min_ms: - self.min_ms = duration_ms - if duration_ms > self.max_ms: - self.max_ms = duration_ms + self.count += 1 + self.total_ms += duration_ms + if duration_ms < self.min_ms: + self.min_ms = duration_ms + if duration_ms > self.max_ms: + self.max_ms = duration_ms @dataclass class ProfilingSpan: - """A named timing segment. + """A named timing segment. - Attributes: - name: Span name. - data: Arbitrary metadata attached via span.set(). - children: Nested spans and cumulative spans. - duration_ms: Duration of this span in milliseconds (set on finish). + Attributes: + name: Span name. + data: Arbitrary metadata attached via span.set(). + children: Nested spans and cumulative spans. + duration_ms: Duration of this span in milliseconds (set on finish). + """ + + name: str + data: dict = field(default_factory=dict) + children: list = field(default_factory=list) + _start: float = field(default_factory=time.perf_counter, repr=False) + duration_ms: float = field(default=0.0) + + def set(self, key: str, value) -> 'ProfilingSpan': + """Attach metadata to this span. + + Args: + key: Metadata key. + value: Metadata value. + + Returns: + Self, for chaining. """ - - name: str - data: dict = field(default_factory=dict) - children: list = field(default_factory=list) - _start: float = field(default_factory=time.perf_counter, repr=False) - duration_ms: float = field(default=0.0) - - def set(self, key: str, value) -> 'ProfilingSpan': - """Attach metadata to this span. - - Args: - key: Metadata key. - value: Metadata value. - - Returns: - Self, for chaining. - """ - self.data[key] = value - return self - - def finish(self): - """Stop timing and record the duration.""" - self.duration_ms = (time.perf_counter() - self._start) * 1000 + self.data[key] = value + return self + + def finish(self): + """Stop timing and record the duration.""" + self.duration_ms = (time.perf_counter() - self._start) * 1000 @dataclass class ProfilingTrace: - """One complete command execution, from route handler to response. + """One complete command execution, from route handler to response. - Attributes: - command_name: Name of the executed command. - command_id: UUID of the command. - kwargs: Arguments received from the client. - timestamp: When the command was received. - root_span: Top-level span wrapping the full execution. - total_duration_ms: Total server-side duration in milliseconds. - """ - - command_name: str - command_id: str - kwargs: dict - timestamp: datetime - root_span: Optional[ProfilingSpan] = None - total_duration_ms: float = 0.0 + Attributes: + command_name: Name of the executed command. + command_description: Human-readable description of the command. + command_id: UUID of the command. + kwargs: Arguments received from the client. + timestamp: When the command was received. + root_span: Top-level span wrapping the full execution. + total_duration_ms: Total server-side duration in milliseconds. + """ + + command_name: str + command_description: str + command_id: str + kwargs: dict + timestamp: datetime + root_span: Optional[ProfilingSpan] = None + total_duration_ms: float = 0.0 + trace_id: str = field(default_factory=lambda: str(uuid4())) # --------------------------------------------------------------------------- @@ -134,134 +138,140 @@ class ProfilingTrace: # --------------------------------------------------------------------------- class _ActiveSpan: - """Context manager and decorator for a single named span. + """Context manager and decorator for a single named span. - When used as a context manager, returns the ProfilingSpan so callers can - attach metadata via ``span.set()``. When used as a decorator, captures - function arguments automatically. - """ - - def __init__(self, manager: 'ProfilingManager', name: str, args: dict = None): - self._manager = manager - self._name = name - self._args = args - self._span: Optional[ProfilingSpan] = None - self._token = None - - def __enter__(self) -> ProfilingSpan: - if not self._manager.enabled: - return _NullSpan() - - overhead_start = time.perf_counter() - self._span = ProfilingSpan(name=self._name) - if self._args: - self._span.data.update(self._args) - self._token = self._manager.push_span(self._span) - self._manager.record_overhead(time.perf_counter() - overhead_start) - return self._span - - def __exit__(self, *args): - if self._span is not None: - overhead_start = time.perf_counter() - self._manager.pop_span(self._span, self._token) - self._manager.record_overhead(time.perf_counter() - overhead_start) - - def __call__(self, fn): - """Use as decorator — enabled check deferred to call time.""" - manager = self._manager - name = self._name - - @functools.wraps(fn) - def wrapper(*args, **kwargs): - if not manager.enabled: - return fn(*args, **kwargs) - captured = manager.capture_args(fn, args, kwargs) - with _ActiveSpan(manager, name, captured): - return fn(*args, **kwargs) - - return wrapper + When used as a context manager, returns the ProfilingSpan so callers can + attach metadata via ``span.set()``. When used as a decorator, captures + function arguments automatically. + """ + + def __init__(self, manager: 'ProfilingManager', name: str, args: dict = None): + self._manager = manager + self._name = name + self._args = args + self._span: Optional[ProfilingSpan] = None + self._token = None + + def __enter__(self) -> ProfilingSpan: + if not self._manager.enabled: + return _NullSpan() + + overhead_start = time.perf_counter() + self._span = ProfilingSpan(name=self._name) + if self._args: + self._span.data.update(self._args) + self._token = self._manager.push_span(self._span) + self._manager.record_overhead(time.perf_counter() - overhead_start) + return self._span + + def __exit__(self, *args): + if self._span is not None: + overhead_start = time.perf_counter() + self._manager.pop_span(self._span, self._token) + self._manager.record_overhead(time.perf_counter() - overhead_start) + + def __call__(self, fn): + """Use as decorator — enabled check deferred to call time.""" + manager = self._manager + name = self._name + + @functools.wraps(fn) + def wrapper(*args, **kwargs): + if not manager.enabled: + return fn(*args, **kwargs) + captured = manager.capture_args(fn, args, kwargs) + with _ActiveSpan(manager, name, captured): + return fn(*args, **kwargs) + + return wrapper class _CumulativeActiveSpan: - """Context manager and decorator for cumulative spans. + """Context manager and decorator for cumulative spans. - Finds or creates a CumulativeSpan in the current parent and records - each iteration without adding a new child entry. - """ - - def __init__(self, manager: 'ProfilingManager', name: str): - self._manager = manager - self._name = name - self._cumulative_span: Optional[CumulativeSpan] = None - self._iter_start: float = 0.0 - - def _get_or_create(self) -> CumulativeSpan: - parent = self._manager.current_span() - if isinstance(parent, ProfilingSpan): - for child in parent.children: - if isinstance(child, CumulativeSpan) and child.name == self._name: - return child - cumulative_span = CumulativeSpan(name=self._name) - parent.children.append(cumulative_span) - return cumulative_span - return CumulativeSpan(name=self._name) - - def __enter__(self) -> CumulativeSpan: - if not self._manager.enabled: - return _NullSpan() - self._cumulative_span = self._get_or_create() - self._iter_start = time.perf_counter() - return self._cumulative_span - - def __exit__(self, *args): - if self._cumulative_span is not None: - duration_ms = (time.perf_counter() - self._iter_start) * 1000 - self._cumulative_span.record(duration_ms) - - def __call__(self, fn): - manager = self._manager - name = self._name - - @functools.wraps(fn) - def wrapper(*args, **kwargs): - with _CumulativeActiveSpan(manager, name): - return fn(*args, **kwargs) - - return wrapper + Finds or creates a CumulativeSpan in the current parent and records + each iteration without adding a new child entry. + """ + + def __init__(self, manager: 'ProfilingManager', name: str): + self._manager = manager + self._name = name + self._cumulative_span: Optional[CumulativeSpan] = None + self._iter_start: float = 0.0 + + def _get_or_create(self) -> CumulativeSpan: + parent = self._manager.current_span() + if isinstance(parent, ProfilingSpan): + for child in parent.children: + if isinstance(child, CumulativeSpan) and child.name == self._name: + return child + cumulative_span = CumulativeSpan(name=self._name) + parent.children.append(cumulative_span) + return cumulative_span + return CumulativeSpan(name=self._name) + + def __enter__(self) -> CumulativeSpan: + if not self._manager.enabled: + return _NullSpan() + self._cumulative_span = self._get_or_create() + self._iter_start = time.perf_counter() + return self._cumulative_span + + def __exit__(self, *args): + if self._cumulative_span is not None: + duration_ms = (time.perf_counter() - self._iter_start) * 1000 + self._cumulative_span.record(duration_ms) + + def __call__(self, fn): + manager = self._manager + name = self._name + + @functools.wraps(fn) + def wrapper(*args, **kwargs): + with _CumulativeActiveSpan(manager, name): + return fn(*args, **kwargs) + + return wrapper class _CommandSpan: - """Context manager that creates both a ProfilingTrace and its root span. + """Context manager that creates both a ProfilingTrace and its root span. - Used exclusively by the route handler to wrap the full command execution. - """ - - def __init__(self, manager: 'ProfilingManager', command_name: str, - command_id: str, kwargs: dict): - self._manager = manager - self._command_name = command_name - self._command_id = command_id - self._kwargs = kwargs - self._trace: Optional[ProfilingTrace] = None - self._span: Optional[ProfilingSpan] = None - self._token = None - - def __enter__(self) -> ProfilingSpan: - self._trace = ProfilingTrace( - command_name=self._command_name, - command_id=self._command_id, - kwargs=dict(self._kwargs) if self._kwargs else {}, - timestamp=datetime.now(), - ) - self._span = ProfilingSpan(name=self._command_name) - self._token = self._manager.push_span(self._span) - return self._span - - def __exit__(self, *args): - self._manager.pop_span(self._span, self._token) - self._trace.root_span = self._span - self._trace.total_duration_ms = self._span.duration_ms - self._manager.add_trace(self._trace) + Used exclusively by the route handler to wrap the full command execution. + """ + + def __init__(self, + manager: 'ProfilingManager', + command_name: str, + command_description: str, + command_id: str, + kwargs: dict): + self._manager = manager + self._command_name = command_name + self._command_description = command_description + self._command_id = command_id + self._kwargs = kwargs + self._trace: Optional[ProfilingTrace] = None + self._span: Optional[ProfilingSpan] = None + self._token = None + + def __enter__(self) -> ProfilingSpan: + self._trace = ProfilingTrace( + command_name=self._command_name, + command_description=self._command_description, + command_id=self._command_id, + kwargs=dict(self._kwargs) if self._kwargs else {}, + timestamp=datetime.now(), + ) + self._span = ProfilingSpan(name=self._command_name) + self._token = self._manager.push_span(self._span) + return self._span + + def __exit__(self, *args): + self._manager.pop_span(self._span, self._token) + self._trace.root_span = self._span + self._trace.total_duration_ms = self._span.duration_ms + self._manager.add_trace(self._trace) # --------------------------------------------------------------------------- @@ -269,274 +279,278 @@ class _CommandSpan: # --------------------------------------------------------------------------- class ProfilingManager: - """Global in-memory profiling manager. + """Global in-memory profiling manager. - All probe mechanisms check ``enabled`` at call time, so the profiler can - be toggled without restarting the server. Use the module-level ``profiler`` - singleton rather than instantiating this class directly. + All probe mechanisms check ``enabled`` at call time, so the profiler can + be toggled without restarting the server. Use the module-level ``profiler`` + singleton rather than instantiating this class directly. + """ + + def __init__(self, max_traces: int = None): + from myfasthtml.core.constants import PROFILER_MAX_TRACES + self.enabled: bool = False + self._traces: deque = deque(maxlen=max_traces or PROFILER_MAX_TRACES) + self._current_span: ContextVar[Optional[ProfilingSpan]] = ContextVar( + 'profiler_current_span', default=None + ) + self._overhead_samples: list = [] + + # --- Span lifecycle --- + + def push_span(self, span: ProfilingSpan) -> object: + """Register a span as the current context and attach it to the parent. + + Args: + span: The span to activate. + + Returns: + A reset token to pass to pop_span(). """ + parent = self._current_span.get() + if isinstance(parent, ProfilingSpan): + parent.children.append(span) + return self._current_span.set(span) + + def pop_span(self, span: ProfilingSpan, token: object) -> None: + """Finish a span and restore the previous context. - def __init__(self, max_traces: int = None): - from myfasthtml.core.constants import PROFILER_MAX_TRACES - self.enabled: bool = False - self._traces: deque = deque(maxlen=max_traces or PROFILER_MAX_TRACES) - self._current_span: ContextVar[Optional[ProfilingSpan]] = ContextVar( - 'profiler_current_span', default=None - ) - self._overhead_samples: list = [] + Args: + span: The span to finish. + token: The reset token returned by push_span(). + """ + span.finish() + self._current_span.reset(token) + + def add_trace(self, trace: ProfilingTrace) -> None: + """Add a completed trace to the buffer. - # --- Span lifecycle --- + Args: + trace: The trace to store. + """ + self._traces.appendleft(trace) + + def record_overhead(self, duration_s: float) -> None: + """Record a span boundary overhead sample. - def push_span(self, span: ProfilingSpan) -> object: - """Register a span as the current context and attach it to the parent. + Args: + duration_s: Duration in seconds of the profiler's own housekeeping. + """ + self._overhead_samples.append(duration_s * 1e6) + if len(self._overhead_samples) > 1000: + self._overhead_samples = self._overhead_samples[-1000:] + + @staticmethod + def capture_args(fn, args, kwargs) -> dict: + """Capture function arguments as a truncated string dict. - Args: - span: The span to activate. + Args: + fn: The function whose signature is inspected. + args: Positional arguments passed to the function. + kwargs: Keyword arguments passed to the function. - Returns: - A reset token to pass to pop_span(). - """ - parent = self._current_span.get() - if isinstance(parent, ProfilingSpan): - parent.children.append(span) - return self._current_span.set(span) + Returns: + Dict of parameter names to string-truncated values. + """ + try: + sig = inspect.signature(fn) + bound = sig.bind(*args, **kwargs) + bound.apply_defaults() + params = dict(bound.arguments) + params.pop('self', None) + params.pop('cls', None) + return {k: str(v)[:200] for k, v in params.items()} + except Exception: + return {} + + # --- Public interface --- + + @property + def traces(self) -> list[ProfilingTrace]: + """All recorded traces, most recent first.""" + return list(self._traces) + + def current_span(self) -> Optional[ProfilingSpan]: + """Return the active span in the current async context. - def pop_span(self, span: ProfilingSpan, token: object) -> None: - """Finish a span and restore the previous context. + Can be called from anywhere within a span to attach metadata:: - Args: - span: The span to finish. - token: The reset token returned by push_span(). - """ - span.finish() - self._current_span.reset(token) + profiler.current_span().set("row_count", len(rows)) + """ + return self._current_span.get() + + def clear(self): + """Empty the trace buffer.""" + self._traces.clear() + logger.debug("Profiler traces cleared.") + + # --- Probe mechanisms --- + + def span(self, name: str, args: dict = None) -> _ActiveSpan: + """Context manager and decorator for a named span. - def add_trace(self, trace: ProfilingTrace) -> None: - """Add a completed trace to the buffer. + The enabled check is deferred to call/enter time, so this can be used + as a static decorator without concern for startup order. - Args: - trace: The trace to store. - """ - self._traces.appendleft(trace) + Args: + name: Span name. + args: Optional metadata to attach immediately. - def record_overhead(self, duration_s: float) -> None: - """Record a span boundary overhead sample. + Returns: + An object usable as a context manager or decorator. + """ + return _ActiveSpan(self, name, args) + + def cumulative_span(self, name: str) -> _CumulativeActiveSpan: + """Context manager and decorator for loop spans. - Args: - duration_s: Duration in seconds of the profiler's own housekeeping. - """ - self._overhead_samples.append(duration_s * 1e6) - if len(self._overhead_samples) > 1000: - self._overhead_samples = self._overhead_samples[-1000:] + Aggregates all iterations into a single entry (count, total, min, max, avg). - @staticmethod - def capture_args(fn, args, kwargs) -> dict: - """Capture function arguments as a truncated string dict. + Args: + name: Span name. - Args: - fn: The function whose signature is inspected. - args: Positional arguments passed to the function. - kwargs: Keyword arguments passed to the function. + Returns: + An object usable as a context manager or decorator. + """ + return _CumulativeActiveSpan(self, name) + + def command_span(self, + command_name: str, + command_description: str, + command_id: str, + kwargs: dict) -> '_CommandSpan | _NullSpan': + """Context manager for the route handler. - Returns: - Dict of parameter names to string-truncated values. - """ - try: - sig = inspect.signature(fn) - bound = sig.bind(*args, **kwargs) - bound.apply_defaults() - params = dict(bound.arguments) - params.pop('self', None) - params.pop('cls', None) - return {k: str(v)[:200] for k, v in params.items()} - except Exception: - return {} + Creates a ProfilingTrace and its root span together. When the context + exits, the trace is added to the buffer. - # --- Public interface --- + Args: + command_name: Human-readable command name. + command_description: Human-readable description of the command. + command_id: UUID string of the command. + kwargs: Client arguments received by the route handler. - @property - def traces(self) -> list[ProfilingTrace]: - """All recorded traces, most recent first.""" - return list(self._traces) + Returns: + An object usable as a context manager. + """ + if not self.enabled: + return _NullSpan() + return _CommandSpan(self, command_name, command_description, command_id, kwargs) + + def trace_all(self, cls=None, *, exclude: list = None): + """Class decorator — statically wraps all non-dunder methods with spans. - def current_span(self) -> Optional[ProfilingSpan]: - """Return the active span in the current async context. + Wrapping happens at class definition time; the enabled check is deferred + to call time via _ActiveSpan.__call__. - Can be called from anywhere within a span to attach metadata:: + Args: + cls: The class to instrument (when used without parentheses). + exclude: List of method names to skip. - profiler.current_span().set("row_count", len(rows)) - """ - return self._current_span.get() + Usage:: - def clear(self): - """Empty the trace buffer.""" - self._traces.clear() - logger.debug("Profiler traces cleared.") + @profiler.trace_all + class MyClass: ... - # --- Probe mechanisms --- + @profiler.trace_all(exclude=["render"]) + class MyClass: ... + """ + _exclude = set(exclude or []) + + def decorator(klass): + for attr_name, method in inspect.getmembers(klass, predicate=inspect.isfunction): + if attr_name in _exclude: + continue + if attr_name.startswith('__') and attr_name.endswith('__'): + continue + setattr(klass, attr_name, _ActiveSpan(self, attr_name)(method)) + return klass + + if cls is not None: + return decorator(cls) + return decorator + + def trace_calls(self, fn): + """Function decorator — traces all sub-calls via sys.setprofile(). - def span(self, name: str, args: dict = None) -> _ActiveSpan: - """Context manager and decorator for a named span. + Use for exploration when the bottleneck location is unknown. + sys.setprofile() is scoped to this function's execution only; + the global profiler is restored on exit. - The enabled check is deferred to call/enter time, so this can be used - as a static decorator without concern for startup order. + The root span for ``fn`` itself is created before setprofile is + activated so that profiler internals are not captured as children. - Args: - name: Span name. - args: Optional metadata to attach immediately. - - Returns: - An object usable as a context manager or decorator. - """ - return _ActiveSpan(self, name, args) - - def cumulative_span(self, name: str) -> _CumulativeActiveSpan: - """Context manager and decorator for loop spans. - - Aggregates all iterations into a single entry (count, total, min, max, avg). - - Args: - name: Span name. - - Returns: - An object usable as a context manager or decorator. - """ - return _CumulativeActiveSpan(self, name) - - def command_span(self, command_name: str, command_id: str, - kwargs: dict) -> '_CommandSpan | _NullSpan': - """Context manager for the route handler. - - Creates a ProfilingTrace and its root span together. When the context - exits, the trace is added to the buffer. - - Args: - command_name: Human-readable command name. - command_id: UUID string of the command. - kwargs: Client arguments received by the route handler. - - Returns: - An object usable as a context manager. - """ - if not self.enabled: - return _NullSpan() - return _CommandSpan(self, command_name, command_id, kwargs) - - def trace_all(self, cls=None, *, exclude: list = None): - """Class decorator — statically wraps all non-dunder methods with spans. - - Wrapping happens at class definition time; the enabled check is deferred - to call time via _ActiveSpan.__call__. - - Args: - cls: The class to instrument (when used without parentheses). - exclude: List of method names to skip. - - Usage:: - - @profiler.trace_all - class MyClass: ... - - @profiler.trace_all(exclude=["render"]) - class MyClass: ... - """ - _exclude = set(exclude or []) - - def decorator(klass): - for attr_name, method in inspect.getmembers(klass, predicate=inspect.isfunction): - if attr_name in _exclude: - continue - if attr_name.startswith('__') and attr_name.endswith('__'): - continue - setattr(klass, attr_name, _ActiveSpan(self, attr_name)(method)) - return klass - - if cls is not None: - return decorator(cls) - return decorator - - def trace_calls(self, fn): - """Function decorator — traces all sub-calls via sys.setprofile(). - - Use for exploration when the bottleneck location is unknown. - sys.setprofile() is scoped to this function's execution only; - the global profiler is restored on exit. - - The root span for ``fn`` itself is created before setprofile is - activated so that profiler internals are not captured as children. - - Args: - fn: The function to instrument. - """ - manager = self - - @functools.wraps(fn) - def wrapper(*args, **kwargs): - if not manager.enabled: - return fn(*args, **kwargs) - - call_stack: list[tuple[ProfilingSpan, object]] = [] - # Skip the first call event (fn itself — already represented by root_span) - skip_first = [True] - - def _profile(frame, event, arg): - if event == 'call': - if skip_first[0]: - skip_first[0] = False - return - span = ProfilingSpan(name=frame.f_code.co_name) - token = manager.push_span(span) - call_stack.append((span, token)) - elif event in ('return', 'exception'): - if call_stack: - span, token = call_stack.pop() - manager.pop_span(span, token) - - # Build root span BEFORE activating setprofile so that profiler - # internals (capture_args, ProfilingSpan.__init__, etc.) are not - # captured as children. - captured = manager.capture_args(fn, args, kwargs) - root_span = ProfilingSpan(name=fn.__name__) - root_span.data.update(captured) - root_token = manager.push_span(root_span) - - old_profile = sys.getprofile() - sys.setprofile(_profile) - try: - result = fn(*args, **kwargs) - finally: - sys.setprofile(old_profile) - manager.pop_span(root_span, root_token) - - return result - - return wrapper - - # --- Overhead measurement --- - - @property - def overhead_per_span_us(self) -> float: - """Average overhead per span boundary in microseconds.""" - if not self._overhead_samples: - return 0.0 - return sum(self._overhead_samples) / len(self._overhead_samples) - - @property - def total_overhead_ms(self) -> float: - """Estimated total overhead across all recorded traces.""" - total_spans = sum( - self._count_spans(t.root_span) for t in self._traces if t.root_span - ) - return (total_spans * self.overhead_per_span_us * 2) / 1000 - - def _count_spans(self, span: ProfilingSpan) -> int: - if span is None: - return 0 - count = 1 - for child in span.children: - if isinstance(child, ProfilingSpan): - count += self._count_spans(child) - return count + Args: + fn: The function to instrument. + """ + manager = self + + @functools.wraps(fn) + def wrapper(*args, **kwargs): + if not manager.enabled: + return fn(*args, **kwargs) + + call_stack: list[tuple[ProfilingSpan, object]] = [] + # Skip the first call event (fn itself — already represented by root_span) + skip_first = [True] + + def _profile(frame, event, arg): + if event == 'call': + if skip_first[0]: + skip_first[0] = False + return + span = ProfilingSpan(name=frame.f_code.co_name) + token = manager.push_span(span) + call_stack.append((span, token)) + elif event in ('return', 'exception'): + if call_stack: + span, token = call_stack.pop() + manager.pop_span(span, token) + + # Build root span BEFORE activating setprofile so that profiler + # internals (capture_args, ProfilingSpan.__init__, etc.) are not + # captured as children. + captured = manager.capture_args(fn, args, kwargs) + root_span = ProfilingSpan(name=fn.__name__) + root_span.data.update(captured) + root_token = manager.push_span(root_span) + + old_profile = sys.getprofile() + sys.setprofile(_profile) + try: + result = fn(*args, **kwargs) + finally: + sys.setprofile(old_profile) + manager.pop_span(root_span, root_token) + + return result + + return wrapper + + # --- Overhead measurement --- + + @property + def overhead_per_span_us(self) -> float: + """Average overhead per span boundary in microseconds.""" + if not self._overhead_samples: + return 0.0 + return sum(self._overhead_samples) / len(self._overhead_samples) + + @property + def total_overhead_ms(self) -> float: + """Estimated total overhead across all recorded traces.""" + total_spans = sum( + self._count_spans(t.root_span) for t in self._traces if t.root_span + ) + return (total_spans * self.overhead_per_span_us * 2) / 1000 + + def _count_spans(self, span: ProfilingSpan) -> int: + if span is None: + return 0 + count = 1 + for child in span.children: + if isinstance(child, ProfilingSpan): + count += self._count_spans(child) + return count # --------------------------------------------------------------------------- diff --git a/src/myfasthtml/core/utils.py b/src/myfasthtml/core/utils.py index 65cd21a..6c31437 100644 --- a/src/myfasthtml/core/utils.py +++ b/src/myfasthtml/core/utils.py @@ -11,6 +11,7 @@ from rich.table import Table from starlette.routing import Mount from myfasthtml.core.constants import Routes, ROUTE_ROOT +from myfasthtml.core.profiler import profiler from myfasthtml.core.dsl.exceptions import DSLSyntaxError from myfasthtml.core.dsl.types import Position from myfasthtml.core.dsls import DslsManager @@ -379,8 +380,9 @@ def post(session, c_id: str, client_response: dict = None): command = CommandsManager.get_command(c_id) if command: logger.debug(f"Executing command {command.name}.") - return command.execute(client_response) - + with profiler.command_span(command.name, command.description, c_id, client_response or {}): + return command.execute(client_response) + raise ValueError(f"Command with ID '{c_id}' not found.") diff --git a/tests/controls/test_profiler.py b/tests/controls/test_profiler.py new file mode 100644 index 0000000..d54659f --- /dev/null +++ b/tests/controls/test_profiler.py @@ -0,0 +1,255 @@ +import shutil +from datetime import datetime +from uuid import uuid4 + +import pytest +from fasthtml.common import Div, Span + +from myfasthtml.controls.Panel import Panel +from myfasthtml.controls.Profiler import Profiler +from myfasthtml.core.instances import InstancesManager +from myfasthtml.core.profiler import profiler, ProfilingTrace +from myfasthtml.test.matcher import matches, find, Contains, TestIcon, DoesNotContain, And, TestObject + + +def make_trace( + command_name: str = "TestCommand", + duration_ms: float = 50.0, + trace_id: str = None, +) -> ProfilingTrace: + """Create a fake ProfilingTrace for testing purposes.""" + return ProfilingTrace( + command_name=command_name, + command_description=f"{command_name} description", + command_id=str(uuid4()), + kwargs={}, + timestamp=datetime.now(), + total_duration_ms=duration_ms, + trace_id=trace_id or str(uuid4()), + ) + + +@pytest.fixture(autouse=True) +def reset_profiler(): + """Reset profiler singleton state before and after each test.""" + profiler.clear() + profiler.enabled = False + yield + profiler.clear() + profiler.enabled = False + + +class TestProfilerBehaviour: + """Tests for Profiler control behavior and logic.""" + + @pytest.fixture + def profiler_control(self, root_instance): + shutil.rmtree(".myFastHtmlDb", ignore_errors=True) + ctrl = Profiler(root_instance) + yield ctrl + InstancesManager.reset() + shutil.rmtree(".myFastHtmlDb", ignore_errors=True) + + def test_i_can_create_profiler(self, profiler_control): + """Test that Profiler initializes with no trace selected.""" + assert profiler_control._selected_id is None + + @pytest.mark.parametrize("initial", [ + False, + True, + ]) + def test_i_can_toggle_enable(self, profiler_control, initial): + """Test that handle_toggle_enable inverts profiler.enabled.""" + profiler.enabled = initial + profiler_control.handle_toggle_enable() + assert profiler.enabled == (not initial) + + def test_i_can_add_traces(self, profiler_control): + trace_a = make_trace("CommandA", 30.0) + trace_b = make_trace("CommandB", 60.0) + profiler._traces.appendleft(trace_a) + profiler._traces.appendleft(trace_b) + + assert len(profiler.traces) == 2 + assert profiler.traces == [trace_b, trace_a] + + def test_i_can_clear_traces_via_handler(self, profiler_control): + """Test that handle_clear_traces empties the profiler trace buffer.""" + profiler._traces.appendleft(make_trace()) + profiler_control.handle_clear_traces() + assert len(profiler.traces) == 0 + + def test_i_can_select_trace_by_id(self, profiler_control): + """Test that handle_select_trace stores the given trace_id.""" + trace_id = str(uuid4()) + profiler_control.handle_select_trace(trace_id) + assert profiler_control._selected_id == trace_id + + def test_i_can_select_trace_stable_when_new_trace_added(self, profiler_control): + """Test that selection by trace_id remains correct when a new trace is prepended. + + This validates the fix for the index-shift bug: adding a new trace (appendleft) + must not affect which row appears selected. + """ + trace_a = make_trace("CommandA", 30.0) + trace_b = make_trace("CommandB", 60.0) + profiler._traces.appendleft(trace_a) + profiler._traces.appendleft(trace_b) + profiler_control.handle_select_trace(trace_a.trace_id) + + # Add a new trace (simulates a new command executing after selection) + profiler._traces.appendleft(make_trace("NewCommand", 10.0)) + + # Selection still points to trace_a, unaffected by the new prepended trace + assert profiler_control._selected_id == trace_a.trace_id + + @pytest.mark.parametrize("duration_ms, expected_cls", [ + (10.0, "mf-profiler-fast"), + (50.0, "mf-profiler-medium"), + (150.0, "mf-profiler-slow"), + ]) + def test_i_can_get_duration_class(self, profiler_control, duration_ms, expected_cls): + """Test that _duration_cls returns the correct CSS class for each threshold.""" + assert profiler_control._duration_cls(duration_ms) == expected_cls + + +class TestProfilerRender: + """Tests for Profiler control HTML rendering.""" + + @pytest.fixture + def profiler_control(self, root_instance): + shutil.rmtree(".myFastHtmlDb", ignore_errors=True) + ctrl = Profiler(root_instance) + yield ctrl + InstancesManager.reset() + shutil.rmtree(".myFastHtmlDb", ignore_errors=True) + + def test_profiler_renders_global_structure(self, profiler_control): + """Test that Profiler renders with correct global structure. + + Why these elements matter: + - id: Required for HTMX targeting (all commands target this id) + - cls Contains "mf-profiler": Root CSS class for layout and styling + - toolbar Div: Always present, contains control actions + - Panel: Always present, hosts trace list and detail panels + """ + html = profiler_control.render() + expected = Div( + Div(cls=Contains("mf-profiler-toolbar")), # toolbar + TestObject(Panel), # panel + id=profiler_control.get_id(), + cls=Contains("mf-profiler"), + ) + assert matches(html, expected) + + def test_i_can_render_toolbar_when_enabled(self, profiler_control): + """Test that toolbar shows pause icon when profiler is enabled. + + Why these elements matter: + - pause icon: visual indicator that profiler is actively recording + """ + profiler.enabled = True + toolbar = profiler_control._mk_toolbar() + assert matches(toolbar, Div(TestIcon("pause_circle20_regular"))) + + def test_i_can_render_toolbar_when_disabled(self, profiler_control): + """Test that toolbar shows play icon when profiler is disabled. + + Why these elements matter: + - play icon: visual indicator that profiler is stopped and ready to record + """ + profiler.enabled = False + toolbar = profiler_control._mk_toolbar() + assert matches(toolbar, Div(TestIcon("play_circle20_regular"))) + + def test_i_can_render_toolbar_clear_button(self, profiler_control): + """Test that toolbar contains exactly one danger-styled clear button. + + Why these elements matter: + - cls Contains "mf-profiler-btn-danger": Ensures the clear button is visually + distinct (red) to warn the user before clearing all traces + """ + toolbar = profiler_control._mk_toolbar() + danger_buttons = find(toolbar, Div(cls=Contains("mf-profiler-btn-danger"))) + assert len(danger_buttons) == 1, "Toolbar should contain exactly one danger-styled button" + + def test_i_can_render_empty_trace_list(self, profiler_control): + """Test that an empty-state message is shown when no traces are recorded. + + Why these elements matter: + - "No traces recorded.": User-facing feedback when profiler has no data + - cls Contains "mf-profiler-empty": Applies centered empty-state styling + """ + trace_list = profiler_control._mk_trace_list() + assert matches(trace_list, Div("No traces recorded.", cls=Contains("mf-profiler-empty"))) + + def test_i_can_render_trace_with_name_and_timestamp(self, profiler_control): + """Test that a trace row shows command name and formatted timestamp. + + Why these elements matter: + - Span.mf-profiler-cmd with command_name: primary identifier for the user + - Span.mf-profiler-ts with formatted timestamp: helps correlate traces with events + """ + trace = make_trace("NavigateCell", 50.0) + ts_expected = trace.timestamp.strftime("%H:%M:%S.") + f"{trace.timestamp.microsecond // 1000:03d}" + profiler._traces.appendleft(trace) + + trace_list = profiler_control._mk_trace_list() + + cmd_spans = find(trace_list, Span("NavigateCell", cls=Contains("mf-profiler-cmd"))) + assert len(cmd_spans) == 1, "Command name should appear exactly once in the trace list" + + ts_spans = find(trace_list, Span(ts_expected, cls=Contains("mf-profiler-ts"))) + assert len(ts_spans) == 1, "Formatted timestamp should appear exactly once in the trace list" + + def test_i_can_render_selected_row_has_selected_class(self, profiler_control): + """Test that the selected row carries the selected CSS class. + + Why these elements matter: + - cls Contains "mf-profiler-row-selected": Visual highlight of the active trace, + matched by trace_id (stable identifier) rather than list index + """ + trace = make_trace("NavigateCell", 50.0) + profiler._traces.appendleft(trace) + profiler_control._selected_id = trace.trace_id + + trace_list = profiler_control._mk_trace_list() + selected_rows = find(trace_list, Div(cls=Contains("mf-profiler-row-selected"))) + assert len(selected_rows) == 1, "Exactly one row should carry the selected class" + + def test_i_can_render_unselected_row_has_no_selected_class(self, profiler_control): + """Test that non-selected rows do not carry the selected CSS class. + + Why these elements matter: + - cls And(Contains("mf-profiler-row"), DoesNotContain("mf-profiler-row-selected")): + Confirms that only the selected trace is highlighted, not its siblings + """ + trace_a = make_trace("CommandA", 30.0) + trace_b = make_trace("CommandB", 80.0) + profiler._traces.appendleft(trace_a) + profiler._traces.appendleft(trace_b) + profiler_control._selected_id = trace_b.trace_id + + trace_list = profiler_control._mk_trace_list() + unselected_rows = find(trace_list, + Div(cls=And(Contains("mf-profiler-row"), DoesNotContain("mf-profiler-row-selected")))) + assert len(unselected_rows) == 1, "Exactly one row should remain unselected" + + @pytest.mark.parametrize("duration_ms, expected_cls", [ + (10.0, "mf-profiler-fast"), + (50.0, "mf-profiler-medium"), + (150.0, "mf-profiler-slow"), + ]) + def test_i_can_render_duration_color_class(self, profiler_control, duration_ms, expected_cls): + """Test that the duration span carries the correct color class per threshold. + + Why these elements matter: + - mf-profiler-fast/medium/slow on the duration Span: color-codes performance + at a glance, consistent with the thresholds defined in _duration_cls() + """ + trace = make_trace("TestCommand", duration_ms) + profiler._traces.appendleft(trace) + + trace_list = profiler_control._mk_trace_list() + duration_spans = find(trace_list, Span(cls=Contains(expected_cls))) + assert len(duration_spans) == 1, f"Expected exactly one span with class '{expected_cls}'" diff --git a/tests/core/test_profiler.py b/tests/core/test_profiler.py index 513da28..a6811bc 100644 --- a/tests/core/test_profiler.py +++ b/tests/core/test_profiler.py @@ -4,20 +4,20 @@ from datetime import datetime import pytest from myfasthtml.core.profiler import ( - ProfilingManager, - ProfilingSpan, - CumulativeSpan, - ProfilingTrace, - _NullSpan, + ProfilingManager, + ProfilingSpan, + CumulativeSpan, + ProfilingTrace, + _NullSpan, ) @pytest.fixture(autouse=True) def fresh_profiler(): - """Provide a fresh ProfilingManager for each test.""" - p = ProfilingManager(max_traces=10) - p.enabled = True - return p + """Provide a fresh ProfilingManager for each test.""" + p = ProfilingManager(max_traces=10) + p.enabled = True + return p # --------------------------------------------------------------------------- @@ -25,53 +25,53 @@ def fresh_profiler(): # --------------------------------------------------------------------------- class TestProfilingModels: - - def test_i_can_compute_avg_ms_when_no_iterations(self): - """Test that avg_ms returns 0.0 on a fresh CumulativeSpan to avoid division by zero.""" - cum = CumulativeSpan(name="empty") - assert cum.avg_ms == 0.0 - assert cum.total_ms == 0.0 - assert cum.count == 0 - assert cum.min_ms == float('inf') - assert cum.max_ms == 0 - - @pytest.mark.parametrize("durations, expected_min, expected_max, expected_total, expected_avg", [ - ([10.0, 5.0, 8.0], 5.0, 10.0, 23.0, 23.0 / 3), - ([1.0], 1.0, 1.0, 1.0, 1.0), - ([3.0, 3.0, 3.0], 3.0, 3.0, 9.0, 3.0), - ]) - def test_i_can_aggregate_iterations_in_cumulative_span( - self, durations, expected_min, expected_max, expected_total, expected_avg - ): - """Test that CumulativeSpan correctly aggregates all metrics across iterations.""" - cum = CumulativeSpan(name="probe") - for d in durations: - cum.record(d) - - assert cum.count == len(durations) - assert cum.min_ms == expected_min - assert cum.max_ms == expected_max - assert cum.total_ms == expected_total - assert cum.avg_ms == pytest.approx(expected_avg) - - def test_i_can_chain_set_calls_on_span(self, fresh_profiler): - """Test that set() returns self to allow fluent chaining.""" - p = fresh_profiler - with p.span("query") as s: - result = s.set("table", "orders").set("rows", 42) - - assert result is s - assert s.data["table"] == "orders" - assert s.data["rows"] == 42 - - def test_i_can_access_span_data_after_context_exits(self, fresh_profiler): - """Test that span data and duration persist after the with block has exited.""" - p = fresh_profiler - with p.span("query") as s: - s.set("key", "value") - - assert s.data["key"] == "value" - assert s.duration_ms > 0 + + def test_i_can_compute_avg_ms_when_no_iterations(self): + """Test that avg_ms returns 0.0 on a fresh CumulativeSpan to avoid division by zero.""" + cum = CumulativeSpan(name="empty") + assert cum.avg_ms == 0.0 + assert cum.total_ms == 0.0 + assert cum.count == 0 + assert cum.min_ms == float('inf') + assert cum.max_ms == 0 + + @pytest.mark.parametrize("durations, expected_min, expected_max, expected_total, expected_avg", [ + ([10.0, 5.0, 8.0], 5.0, 10.0, 23.0, 23.0 / 3), + ([1.0], 1.0, 1.0, 1.0, 1.0), + ([3.0, 3.0, 3.0], 3.0, 3.0, 9.0, 3.0), + ]) + def test_i_can_aggregate_iterations_in_cumulative_span( + self, durations, expected_min, expected_max, expected_total, expected_avg + ): + """Test that CumulativeSpan correctly aggregates all metrics across iterations.""" + cum = CumulativeSpan(name="probe") + for d in durations: + cum.record(d) + + assert cum.count == len(durations) + assert cum.min_ms == expected_min + assert cum.max_ms == expected_max + assert cum.total_ms == expected_total + assert cum.avg_ms == pytest.approx(expected_avg) + + def test_i_can_chain_set_calls_on_span(self, fresh_profiler): + """Test that set() returns self to allow fluent chaining.""" + p = fresh_profiler + with p.span("query") as s: + result = s.set("table", "orders").set("rows", 42) + + assert result is s + assert s.data["table"] == "orders" + assert s.data["rows"] == 42 + + def test_i_can_access_span_data_after_context_exits(self, fresh_profiler): + """Test that span data and duration persist after the with block has exited.""" + p = fresh_profiler + with p.span("query") as s: + s.set("key", "value") + + assert s.data["key"] == "value" + assert s.duration_ms > 0 # --------------------------------------------------------------------------- @@ -79,175 +79,175 @@ class TestProfilingModels: # --------------------------------------------------------------------------- class TestSpan: + + def test_i_can_create_a_span(self, fresh_profiler): + """Test that a span is created with correct name and measured duration.""" + p = fresh_profiler + with p.span("my_span") as s: + time.sleep(0.01) + + assert isinstance(s, ProfilingSpan) + assert s.name == "my_span" + assert s.duration_ms >= 10 + + def test_i_can_nest_spans(self, fresh_profiler): + """Test that a span created inside another becomes its child.""" + p = fresh_profiler + with p.span("parent") as parent: + with p.span("child") as child: + pass + + assert len(parent.children) == 1 + assert parent.children[0] is child + assert child.name == "child" + + def test_i_can_have_sibling_spans(self, fresh_profiler): + """Test that consecutive spans under the same parent are recorded as siblings.""" + p = fresh_profiler + with p.span("parent") as parent: + with p.span("child_a"): + pass + with p.span("child_b"): + pass + + assert len(parent.children) == 2 + assert parent.children[0].name == "child_a" + assert parent.children[1].name == "child_b" + + def test_i_can_create_two_spans_with_same_name_under_same_parent(self, fresh_profiler): + """Test that two normal spans with the same name under the same parent are two distinct entries. - def test_i_can_create_a_span(self, fresh_profiler): - """Test that a span is created with correct name and measured duration.""" - p = fresh_profiler - with p.span("my_span") as s: - time.sleep(0.01) - - assert isinstance(s, ProfilingSpan) - assert s.name == "my_span" - assert s.duration_ms >= 10 - - def test_i_can_nest_spans(self, fresh_profiler): - """Test that a span created inside another becomes its child.""" - p = fresh_profiler - with p.span("parent") as parent: - with p.span("child") as child: - pass - - assert len(parent.children) == 1 - assert parent.children[0] is child - assert child.name == "child" - - def test_i_can_have_sibling_spans(self, fresh_profiler): - """Test that consecutive spans under the same parent are recorded as siblings.""" - p = fresh_profiler - with p.span("parent") as parent: - with p.span("child_a"): - pass - with p.span("child_b"): - pass - - assert len(parent.children) == 2 - assert parent.children[0].name == "child_a" - assert parent.children[1].name == "child_b" - - def test_i_can_create_two_spans_with_same_name_under_same_parent(self, fresh_profiler): - """Test that two normal spans with the same name under the same parent are two distinct entries. - - This contrasts with cumulative spans, which merge same-name entries into one aggregated entry. - """ - p = fresh_profiler - with p.span("parent") as parent: - with p.span("work"): - pass - with p.span("work"): - pass - - assert len(parent.children) == 2, "Normal spans with the same name must remain separate entries" - assert parent.children[0] is not parent.children[1] - - def test_i_can_use_same_span_name_under_different_parents(self, fresh_profiler): - """Test that spans with the same name under different parents are independent objects.""" - p = fresh_profiler - with p.span("root"): - with p.span("parent_a") as parent_a: - with p.span("work"): - pass - with p.span("parent_b") as parent_b: - with p.span("work"): - pass - - span_a = parent_a.children[0] - span_b = parent_b.children[0] - assert span_a is not span_b, "Same name under different parents must be separate objects" - - def test_i_can_use_span_as_decorator(self, fresh_profiler): - """Test that @span wraps a function and captures all positional arguments.""" - p = fresh_profiler - - @p.span("decorated") - def my_func(x, y): - return x + y - - with p.span("root") as root: - result = my_func(1, 2) - - assert result == 3 - assert len(root.children) == 1 - child = root.children[0] - assert child.name == "decorated" - assert child.data.get("x") == "1" - assert child.data.get("y") == "2" - - def test_i_can_capture_all_args_with_span_decorator(self, fresh_profiler): - """Test that all positional and keyword arguments are captured by the @span decorator.""" - p = fresh_profiler - - @p.span("compute") - def my_func(x, y, z=10): - return x + y + z - - with p.span("root") as root: - my_func(1, 2, z=3) - - child = root.children[0] - assert child.data.get("x") == "1" - assert child.data.get("y") == "2" - assert child.data.get("z") == "3" - - def test_i_can_exclude_self_from_captured_args_with_span_decorator(self, fresh_profiler): - """Test that 'self' is not included in the captured args of a decorated method.""" - p = fresh_profiler - - class MyClass: - @p.span("method") - def my_method(self, value): - return value - - with p.span("root") as root: - MyClass().my_method(42) - - child = root.children[0] - assert "self" not in child.data - assert child.data.get("value") == "42" - - def test_i_can_use_span_decorator_without_parent(self, fresh_profiler): - """Test that a decorated function runs correctly with no active parent span.""" - p = fresh_profiler - - @p.span("solo") - def my_func(): - return 42 - - result = my_func() - assert result == 42 - - def test_i_can_attach_data_to_span_via_context_manager(self, fresh_profiler): - """Test that metadata can be attached to a span inside the with block.""" - p = fresh_profiler - with p.span("query") as s: - s.set("row_count", 42) - s.set("table", "users") - - assert s.data["row_count"] == 42 - assert s.data["table"] == "users" - - def test_i_can_attach_data_via_current_span(self, fresh_profiler): - """Test that current_span().set() attaches metadata to the active span from anywhere.""" - p = fresh_profiler - - @p.span("process") - def process(): - p.current_span().set("result", "ok") - - with p.span("root") as root: - process() - - child = root.children[0] - assert child.data["result"] == "ok" - - def test_i_can_pass_args_to_span_context_manager(self, fresh_profiler): - """Test that metadata can be pre-attached to a span via the args parameter.""" - p = fresh_profiler - with p.span("query", args={"table": "orders"}) as s: - pass - - assert s.data["table"] == "orders" - - def test_i_can_get_none_from_current_span_when_no_span_active(self, fresh_profiler): - """Test that current_span() returns None when called outside any span context.""" - p = fresh_profiler - assert p.current_span() is None - - def test_i_can_get_innermost_span_via_current_span(self, fresh_profiler): - """Test that current_span() returns the innermost active span in nested contexts.""" - p = fresh_profiler - with p.span("outer"): - with p.span("inner") as inner: - assert p.current_span() is inner + This contrasts with cumulative spans, which merge same-name entries into one aggregated entry. + """ + p = fresh_profiler + with p.span("parent") as parent: + with p.span("work"): + pass + with p.span("work"): + pass + + assert len(parent.children) == 2, "Normal spans with the same name must remain separate entries" + assert parent.children[0] is not parent.children[1] + + def test_i_can_use_same_span_name_under_different_parents(self, fresh_profiler): + """Test that spans with the same name under different parents are independent objects.""" + p = fresh_profiler + with p.span("root"): + with p.span("parent_a") as parent_a: + with p.span("work"): + pass + with p.span("parent_b") as parent_b: + with p.span("work"): + pass + + span_a = parent_a.children[0] + span_b = parent_b.children[0] + assert span_a is not span_b, "Same name under different parents must be separate objects" + + def test_i_can_use_span_as_decorator(self, fresh_profiler): + """Test that @span wraps a function and captures all positional arguments.""" + p = fresh_profiler + + @p.span("decorated") + def my_func(x, y): + return x + y + + with p.span("root") as root: + result = my_func(1, 2) + + assert result == 3 + assert len(root.children) == 1 + child = root.children[0] + assert child.name == "decorated" + assert child.data.get("x") == "1" + assert child.data.get("y") == "2" + + def test_i_can_capture_all_args_with_span_decorator(self, fresh_profiler): + """Test that all positional and keyword arguments are captured by the @span decorator.""" + p = fresh_profiler + + @p.span("compute") + def my_func(x, y, z=10): + return x + y + z + + with p.span("root") as root: + my_func(1, 2, z=3) + + child = root.children[0] + assert child.data.get("x") == "1" + assert child.data.get("y") == "2" + assert child.data.get("z") == "3" + + def test_i_can_exclude_self_from_captured_args_with_span_decorator(self, fresh_profiler): + """Test that 'self' is not included in the captured args of a decorated method.""" + p = fresh_profiler + + class MyClass: + @p.span("method") + def my_method(self, value): + return value + + with p.span("root") as root: + MyClass().my_method(42) + + child = root.children[0] + assert "self" not in child.data + assert child.data.get("value") == "42" + + def test_i_can_use_span_decorator_without_parent(self, fresh_profiler): + """Test that a decorated function runs correctly with no active parent span.""" + p = fresh_profiler + + @p.span("solo") + def my_func(): + return 42 + + result = my_func() + assert result == 42 + + def test_i_can_attach_data_to_span_via_context_manager(self, fresh_profiler): + """Test that metadata can be attached to a span inside the with block.""" + p = fresh_profiler + with p.span("query") as s: + s.set("row_count", 42) + s.set("table", "users") + + assert s.data["row_count"] == 42 + assert s.data["table"] == "users" + + def test_i_can_attach_data_via_current_span(self, fresh_profiler): + """Test that current_span().set() attaches metadata to the active span from anywhere.""" + p = fresh_profiler + + @p.span("process") + def process(): + p.current_span().set("result", "ok") + + with p.span("root") as root: + process() + + child = root.children[0] + assert child.data["result"] == "ok" + + def test_i_can_pass_args_to_span_context_manager(self, fresh_profiler): + """Test that metadata can be pre-attached to a span via the args parameter.""" + p = fresh_profiler + with p.span("query", args={"table": "orders"}) as s: + pass + + assert s.data["table"] == "orders" + + def test_i_can_get_none_from_current_span_when_no_span_active(self, fresh_profiler): + """Test that current_span() returns None when called outside any span context.""" + p = fresh_profiler + assert p.current_span() is None + + def test_i_can_get_innermost_span_via_current_span(self, fresh_profiler): + """Test that current_span() returns the innermost active span in nested contexts.""" + p = fresh_profiler + with p.span("outer"): + with p.span("inner") as inner: + assert p.current_span() is inner # --------------------------------------------------------------------------- @@ -255,88 +255,88 @@ class TestSpan: # --------------------------------------------------------------------------- class TestCumulativeSpan: - - def test_i_can_use_cumulative_span(self, fresh_profiler): - """Test that repeated iterations are aggregated into a single child entry.""" - p = fresh_profiler - with p.span("loop") as loop_span: - for _ in range(5): - with p.cumulative_span("item"): - time.sleep(0.001) - - assert len(loop_span.children) == 1 - cum = loop_span.children[0] - assert isinstance(cum, CumulativeSpan) - assert cum.count == 5 - assert cum.total_ms >= 5 - assert cum.min_ms <= cum.avg_ms <= cum.max_ms - - def test_i_can_use_cumulative_span_as_decorator(self, fresh_profiler): - """Test that @cumulative_span aggregates all decorated function calls.""" - p = fresh_profiler - - @p.cumulative_span("item") - def process_item(x): - return x * 2 - - with p.span("loop") as loop_span: - for i in range(3): - process_item(i) - - assert len(loop_span.children) == 1 - cum = loop_span.children[0] - assert cum.count == 3 - - def test_i_can_continue_using_the_cumulative_span(self, fresh_profiler): - """Test that the same cumulative span accumulates across separate loop blocks.""" - p = fresh_profiler - with p.span("parent") as parent: - for _ in range(3): - with p.cumulative_span("reads"): - pass - for _ in range(2): - with p.cumulative_span("reads"): - pass - - assert len(parent.children) == 1 - reads = parent.children[0] - assert reads.count == 5 - - def test_i_can_have_two_cumulative_spans_with_different_names(self, fresh_profiler): - """Test that two cumulative spans with different names create separate entries in the parent.""" - p = fresh_profiler - with p.span("parent") as parent: - for _ in range(3): - with p.cumulative_span("reads"): - pass - for _ in range(2): - with p.cumulative_span("writes"): - pass - - assert len(parent.children) == 2 - reads = next(c for c in parent.children if c.name == "reads") - writes = next(c for c in parent.children if c.name == "writes") - assert reads.count == 3 - assert writes.count == 2 - - def test_i_can_use_same_cumulative_span_name_under_different_parents(self, fresh_profiler): - """Test that cumulative spans with the same name under different parents are independent.""" - p = fresh_profiler - with p.span("root"): - with p.span("parent_a") as parent_a: - for _ in range(3): - with p.cumulative_span("items"): - pass - with p.span("parent_b") as parent_b: - for _ in range(2): - with p.cumulative_span("items"): - pass - - items_a = parent_a.children[0] - items_b = parent_b.children[0] - assert items_a is not items_b, "Same name under different parents must be separate objects" - assert items_a.count == 3 - assert items_b.count == 2 + + def test_i_can_use_cumulative_span(self, fresh_profiler): + """Test that repeated iterations are aggregated into a single child entry.""" + p = fresh_profiler + with p.span("loop") as loop_span: + for _ in range(5): + with p.cumulative_span("item"): + time.sleep(0.001) + + assert len(loop_span.children) == 1 + cum = loop_span.children[0] + assert isinstance(cum, CumulativeSpan) + assert cum.count == 5 + assert cum.total_ms >= 5 + assert cum.min_ms <= cum.avg_ms <= cum.max_ms + + def test_i_can_use_cumulative_span_as_decorator(self, fresh_profiler): + """Test that @cumulative_span aggregates all decorated function calls.""" + p = fresh_profiler + + @p.cumulative_span("item") + def process_item(x): + return x * 2 + + with p.span("loop") as loop_span: + for i in range(3): + process_item(i) + + assert len(loop_span.children) == 1 + cum = loop_span.children[0] + assert cum.count == 3 + + def test_i_can_continue_using_the_cumulative_span(self, fresh_profiler): + """Test that the same cumulative span accumulates across separate loop blocks.""" + p = fresh_profiler + with p.span("parent") as parent: + for _ in range(3): + with p.cumulative_span("reads"): + pass + for _ in range(2): + with p.cumulative_span("reads"): + pass + + assert len(parent.children) == 1 + reads = parent.children[0] + assert reads.count == 5 + + def test_i_can_have_two_cumulative_spans_with_different_names(self, fresh_profiler): + """Test that two cumulative spans with different names create separate entries in the parent.""" + p = fresh_profiler + with p.span("parent") as parent: + for _ in range(3): + with p.cumulative_span("reads"): + pass + for _ in range(2): + with p.cumulative_span("writes"): + pass + + assert len(parent.children) == 2 + reads = next(c for c in parent.children if c.name == "reads") + writes = next(c for c in parent.children if c.name == "writes") + assert reads.count == 3 + assert writes.count == 2 + + def test_i_can_use_same_cumulative_span_name_under_different_parents(self, fresh_profiler): + """Test that cumulative spans with the same name under different parents are independent.""" + p = fresh_profiler + with p.span("root"): + with p.span("parent_a") as parent_a: + for _ in range(3): + with p.cumulative_span("items"): + pass + with p.span("parent_b") as parent_b: + for _ in range(2): + with p.cumulative_span("items"): + pass + + items_a = parent_a.children[0] + items_b = parent_b.children[0] + assert items_a is not items_b, "Same name under different parents must be separate objects" + assert items_a.count == 3 + assert items_b.count == 2 # --------------------------------------------------------------------------- @@ -344,63 +344,81 @@ class TestCumulativeSpan: # --------------------------------------------------------------------------- class TestCommandSpan: - - def test_i_can_record_a_trace_via_command_span(self, fresh_profiler): - """Test that command_span creates a complete trace with root span and children.""" - p = fresh_profiler - with p.command_span("NavigateCell", "abc-123", {"row": "5"}): - with p.span("callback"): - time.sleep(0.01) - - assert len(p.traces) == 1 - trace = p.traces[0] - assert isinstance(trace, ProfilingTrace) - assert trace.command_name == "NavigateCell" - assert trace.command_id == "abc-123" - assert trace.kwargs == {"row": "5"} - assert trace.total_duration_ms >= 10 - assert len(trace.root_span.children) == 1 - assert trace.root_span.children[0].name == "callback" - - def test_i_cannot_record_trace_when_profiler_disabled(self, fresh_profiler): - """Test that command_span is a no-op when the profiler is disabled.""" - p = fresh_profiler - p.enabled = False - with p.command_span("cmd", "id", {}): - pass - - assert len(p.traces) == 0 - - def test_i_can_record_up_to_max_traces(self, fresh_profiler): - """Test that the trace buffer respects the max_traces limit (FIFO eviction).""" - p = fresh_profiler - for i in range(15): - with p.command_span(f"cmd_{i}", str(i), {}): - pass - - assert len(p.traces) == 10, "Buffer should cap at max_traces=10" - - def test_i_can_access_trace_timestamp(self, fresh_profiler): - """Test that a recorded trace contains a valid datetime timestamp.""" - p = fresh_profiler - before = datetime.now() - with p.command_span("MyCmd", "id-001", {}): - pass - after = datetime.now() - - trace = p.traces[0] - assert before <= trace.timestamp <= after - - def test_i_can_verify_kwargs_are_copied_in_command_span(self, fresh_profiler): - """Test that mutating the original kwargs dict does not affect the recorded trace.""" - p = fresh_profiler - kwargs = {"row": "5", "col": "2"} - with p.command_span("MyCmd", "id-001", kwargs): - pass - - kwargs["row"] = "99" - trace = p.traces[0] - assert trace.kwargs["row"] == "5" + + def test_i_can_record_a_trace_via_command_span(self, fresh_profiler): + """Test that command_span creates a complete trace with root span and children.""" + p = fresh_profiler + with p.command_span("NavigateCell", "", "abc-123", {"row": "5"}): + with p.span("callback"): + time.sleep(0.01) + + assert len(p.traces) == 1 + trace = p.traces[0] + assert isinstance(trace, ProfilingTrace) + assert trace.command_name == "NavigateCell" + assert trace.command_id == "abc-123" + assert trace.kwargs == {"row": "5"} + assert trace.total_duration_ms >= 10 + assert len(trace.root_span.children) == 1 + assert trace.root_span.children[0].name == "callback" + + def test_i_cannot_record_trace_when_profiler_disabled(self, fresh_profiler): + """Test that command_span is a no-op when the profiler is disabled.""" + p = fresh_profiler + p.enabled = False + with p.command_span("cmd", "", "id", {}): + pass + + assert len(p.traces) == 0 + + def test_i_can_record_up_to_max_traces(self, fresh_profiler): + """Test that the trace buffer respects the max_traces limit (FIFO eviction).""" + p = fresh_profiler + for i in range(15): + with p.command_span(f"cmd_{i}", "", str(i), {}): + pass + + assert len(p.traces) == 10, "Buffer should cap at max_traces=10" + + def test_i_can_access_trace_timestamp(self, fresh_profiler): + """Test that a recorded trace contains a valid datetime timestamp.""" + p = fresh_profiler + before = datetime.now() + with p.command_span("MyCmd", "", "id-001", {}): + pass + after = datetime.now() + + trace = p.traces[0] + assert before <= trace.timestamp <= after + + def test_i_can_verify_kwargs_are_copied_in_command_span(self, fresh_profiler): + """Test that mutating the original kwargs dict does not affect the recorded trace.""" + p = fresh_profiler + kwargs = {"row": "5", "col": "2"} + with p.command_span("MyCmd", "", "id-001", kwargs): + pass + + kwargs["row"] = "99" + trace = p.traces[0] + assert trace.kwargs["row"] == "5" + + def test_i_can_record_command_description_in_trace(self, fresh_profiler): + """Test that the command description passed to command_span is stored in the trace.""" + p = fresh_profiler + with p.command_span("NavigateCell", "Navigate to adjacent cell", "abc-123", {}): + pass + + trace = p.traces[0] + assert trace.command_description == "Navigate to adjacent cell" + + def test_i_can_record_empty_description_in_trace(self, fresh_profiler): + """Test that an empty description is stored as-is in the trace.""" + p = fresh_profiler + with p.command_span("MyCmd", "", "id-001", {}): + pass + + trace = p.traces[0] + assert trace.command_description == "" # --------------------------------------------------------------------------- @@ -408,90 +426,90 @@ class TestCommandSpan: # --------------------------------------------------------------------------- class TestTraceAll: - - def test_i_can_use_trace_all_on_class(self, fresh_profiler): - """Test that trace_all wraps all non-dunder methods of a class.""" - p = fresh_profiler - - @p.trace_all - class MyClass: - def method_a(self): - return "a" - - def method_b(self): - return "b" - - def __repr__(self): - return "MyClass()" - - obj = MyClass() - with p.span("root") as root: - obj.method_a() - obj.method_b() - - assert len(root.children) == 2 - assert root.children[0].name == "method_a" - assert root.children[1].name == "method_b" - - def test_i_can_use_trace_all_with_exclude(self, fresh_profiler): - """Test that excluded methods are not wrapped by trace_all.""" - p = fresh_profiler - - @p.trace_all(exclude=["method_b"]) - class MyClass: - def method_a(self): - return "a" - - def method_b(self): - return "b" - - obj = MyClass() - with p.span("root") as root: - obj.method_a() - obj.method_b() - - assert len(root.children) == 1 - assert root.children[0].name == "method_a" - - def test_i_can_confirm_trace_all_skips_dunder_methods(self, fresh_profiler): - """Test that trace_all does not wrap dunder methods like __repr__.""" - p = fresh_profiler - call_log = [] - - @p.trace_all - class MyClass: - def __repr__(self): - call_log.append("repr") - return "MyClass()" - - def method_a(self): - return "a" - - obj = MyClass() - with p.span("root") as root: - repr(obj) - obj.method_a() - - child_names = [c.name for c in root.children] - assert "method_a" in child_names - assert "__repr__" not in child_names - assert "repr" in call_log - - def test_i_can_use_trace_all_with_parentheses_and_no_exclude(self, fresh_profiler): - """Test that @profiler.trace_all() with parentheses and no args behaves like @profiler.trace_all.""" - p = fresh_profiler - - @p.trace_all() - class MyClass: - def method_a(self): - return "a" - - obj = MyClass() - with p.span("root") as root: - obj.method_a() - - assert len(root.children) == 1 - assert root.children[0].name == "method_a" + + def test_i_can_use_trace_all_on_class(self, fresh_profiler): + """Test that trace_all wraps all non-dunder methods of a class.""" + p = fresh_profiler + + @p.trace_all + class MyClass: + def method_a(self): + return "a" + + def method_b(self): + return "b" + + def __repr__(self): + return "MyClass()" + + obj = MyClass() + with p.span("root") as root: + obj.method_a() + obj.method_b() + + assert len(root.children) == 2 + assert root.children[0].name == "method_a" + assert root.children[1].name == "method_b" + + def test_i_can_use_trace_all_with_exclude(self, fresh_profiler): + """Test that excluded methods are not wrapped by trace_all.""" + p = fresh_profiler + + @p.trace_all(exclude=["method_b"]) + class MyClass: + def method_a(self): + return "a" + + def method_b(self): + return "b" + + obj = MyClass() + with p.span("root") as root: + obj.method_a() + obj.method_b() + + assert len(root.children) == 1 + assert root.children[0].name == "method_a" + + def test_i_can_confirm_trace_all_skips_dunder_methods(self, fresh_profiler): + """Test that trace_all does not wrap dunder methods like __repr__.""" + p = fresh_profiler + call_log = [] + + @p.trace_all + class MyClass: + def __repr__(self): + call_log.append("repr") + return "MyClass()" + + def method_a(self): + return "a" + + obj = MyClass() + with p.span("root") as root: + repr(obj) + obj.method_a() + + child_names = [c.name for c in root.children] + assert "method_a" in child_names + assert "__repr__" not in child_names + assert "repr" in call_log + + def test_i_can_use_trace_all_with_parentheses_and_no_exclude(self, fresh_profiler): + """Test that @profiler.trace_all() with parentheses and no args behaves like @profiler.trace_all.""" + p = fresh_profiler + + @p.trace_all() + class MyClass: + def method_a(self): + return "a" + + obj = MyClass() + with p.span("root") as root: + obj.method_a() + + assert len(root.children) == 1 + assert root.children[0].name == "method_a" # --------------------------------------------------------------------------- @@ -499,76 +517,76 @@ class TestTraceAll: # --------------------------------------------------------------------------- class TestTraceCalls: + + def test_i_can_use_trace_calls_on_function(self, fresh_profiler): + """Test that trace_calls traces all sub-calls as children of the decorated function span. - def test_i_can_use_trace_calls_on_function(self, fresh_profiler): - """Test that trace_calls traces all sub-calls as children of the decorated function span. - - Verifies both direct children (helper_a, helper_b under main_func) and nested hierarchy - (grandchild under helper_a, not under main_func). - """ - p = fresh_profiler - - def grandchild(): - return 0 - - def helper_a(): - grandchild() - return 1 - - def helper_b(): - return 2 - - @p.trace_calls - def main_func(): - helper_a() - helper_b() - return 42 - - with p.span("root") as root: - main_func() - - assert len(root.children) == 1 - main_span = root.children[0] - assert main_span.name == "main_func" - assert len(main_span.children) == 2, "main_func should have exactly 2 direct children" - child_names = [c.name for c in main_span.children] - assert "helper_a" in child_names - assert "helper_b" in child_names - - helper_a_span = next(c for c in main_span.children if c.name == "helper_a") - assert len(helper_a_span.children) == 1, "grandchild must be nested under helper_a, not main_func" - assert helper_a_span.children[0].name == "grandchild" - - def test_i_cannot_use_trace_calls_when_disabled(self, fresh_profiler): - """Test that trace_calls creates no spans when the profiler is disabled at call time.""" - p = fresh_profiler - - @p.trace_calls - def main_func(): - return 99 - - with p.span("root") as root: - p.enabled = False - main_func() - p.enabled = True - - assert len(root.children) == 0, "trace_calls should not create spans when profiler is disabled" - - def test_i_can_verify_trace_calls_captures_function_args(self, fresh_profiler): - """Test that trace_calls captures the decorated function's arguments in the root span data.""" - p = fresh_profiler - - @p.trace_calls - def compute(x, y): - return x + y - - with p.span("root") as root: - compute(3, 7) - - main_span = root.children[0] - assert main_span.name == "compute" - assert main_span.data.get("x") == "3" - assert main_span.data.get("y") == "7" + Verifies both direct children (helper_a, helper_b under main_func) and nested hierarchy + (grandchild under helper_a, not under main_func). + """ + p = fresh_profiler + + def grandchild(): + return 0 + + def helper_a(): + grandchild() + return 1 + + def helper_b(): + return 2 + + @p.trace_calls + def main_func(): + helper_a() + helper_b() + return 42 + + with p.span("root") as root: + main_func() + + assert len(root.children) == 1 + main_span = root.children[0] + assert main_span.name == "main_func" + assert len(main_span.children) == 2, "main_func should have exactly 2 direct children" + child_names = [c.name for c in main_span.children] + assert "helper_a" in child_names + assert "helper_b" in child_names + + helper_a_span = next(c for c in main_span.children if c.name == "helper_a") + assert len(helper_a_span.children) == 1, "grandchild must be nested under helper_a, not main_func" + assert helper_a_span.children[0].name == "grandchild" + + def test_i_cannot_use_trace_calls_when_disabled(self, fresh_profiler): + """Test that trace_calls creates no spans when the profiler is disabled at call time.""" + p = fresh_profiler + + @p.trace_calls + def main_func(): + return 99 + + with p.span("root") as root: + p.enabled = False + main_func() + p.enabled = True + + assert len(root.children) == 0, "trace_calls should not create spans when profiler is disabled" + + def test_i_can_verify_trace_calls_captures_function_args(self, fresh_profiler): + """Test that trace_calls captures the decorated function's arguments in the root span data.""" + p = fresh_profiler + + @p.trace_calls + def compute(x, y): + return x + y + + with p.span("root") as root: + compute(3, 7) + + main_span = root.children[0] + assert main_span.name == "compute" + assert main_span.data.get("x") == "3" + assert main_span.data.get("y") == "7" # --------------------------------------------------------------------------- @@ -576,85 +594,85 @@ class TestTraceCalls: # --------------------------------------------------------------------------- class TestProfilingManager: + + def test_i_can_enable_disable_profiler(self, fresh_profiler): + """Test that disabling the profiler makes span() return a no-op NullSpan.""" + p = fresh_profiler + p.enabled = False + + with p.span("ignored") as s: + pass + + assert isinstance(s, _NullSpan) + + def test_i_can_use_decorator_when_profiler_is_disabled(self, fresh_profiler): + """Test that a @span decorated function still executes correctly when profiler is disabled.""" + p = fresh_profiler + + @p.span("my_span") + def my_func(): + return "result" + + p.enabled = False + result = my_func() + assert result == "result" + + def test_i_can_toggle_profiler_at_runtime(self, fresh_profiler): + """Test that spans are captured only while the profiler is enabled. - def test_i_can_enable_disable_profiler(self, fresh_profiler): - """Test that disabling the profiler makes span() return a no-op NullSpan.""" - p = fresh_profiler - p.enabled = False - - with p.span("ignored") as s: - pass - - assert isinstance(s, _NullSpan) - - def test_i_can_use_decorator_when_profiler_is_disabled(self, fresh_profiler): - """Test that a @span decorated function still executes correctly when profiler is disabled.""" - p = fresh_profiler - - @p.span("my_span") - def my_func(): - return "result" - - p.enabled = False - result = my_func() - assert result == "result" - - def test_i_can_toggle_profiler_at_runtime(self, fresh_profiler): - """Test that spans are captured only while the profiler is enabled. - - Three phases: enabled -> disabled -> re-enabled, verifying capture behavior at each step. - """ - p = fresh_profiler - - @p.span("traced") - def my_func(): - return 1 - - # Phase 1: enabled — span must be captured - with p.span("root") as root: - my_func() - assert len(root.children) == 1, "Span should be captured when profiler is enabled" - - # Phase 2: disabled — p.span() returns NullSpan, nothing captured - p.enabled = False - with p.span("root_disabled") as root_disabled: - my_func() - assert isinstance(root_disabled, _NullSpan), "p.span() should return NullSpan when disabled" - - # Phase 3: re-enabled — span must be captured again - p.enabled = True - with p.span("root_reenabled") as root_reenabled: - my_func() - assert len(root_reenabled.children) == 1, "Span should be captured again after re-enabling" - - def test_i_can_clear_traces(self, fresh_profiler): - """Test that clear() empties the trace buffer completely.""" - p = fresh_profiler - with p.command_span("cmd", "uuid-1", {}): - pass - with p.command_span("cmd", "uuid-2", {}): - pass - - assert len(p.traces) == 2 - p.clear() - assert len(p.traces) == 0 - - def test_i_can_measure_overhead(self, fresh_profiler): - """Test that overhead metrics are populated after spans are recorded.""" - p = fresh_profiler - for _ in range(20): - with p.span("probe"): - pass - - assert p.overhead_per_span_us >= 0 - assert p.total_overhead_ms >= 0 - - def test_i_can_get_zero_overhead_when_no_samples(self, fresh_profiler): - """Test that overhead_per_span_us returns 0.0 when no spans have been recorded.""" - p = fresh_profiler - assert p.overhead_per_span_us == 0.0 - - def test_i_can_get_zero_total_overhead_when_buffer_empty(self, fresh_profiler): - """Test that total_overhead_ms returns 0.0 when the trace buffer is empty.""" - p = fresh_profiler - assert p.total_overhead_ms == 0.0 + Three phases: enabled -> disabled -> re-enabled, verifying capture behavior at each step. + """ + p = fresh_profiler + + @p.span("traced") + def my_func(): + return 1 + + # Phase 1: enabled — span must be captured + with p.span("root") as root: + my_func() + assert len(root.children) == 1, "Span should be captured when profiler is enabled" + + # Phase 2: disabled — p.span() returns NullSpan, nothing captured + p.enabled = False + with p.span("root_disabled") as root_disabled: + my_func() + assert isinstance(root_disabled, _NullSpan), "p.span() should return NullSpan when disabled" + + # Phase 3: re-enabled — span must be captured again + p.enabled = True + with p.span("root_reenabled") as root_reenabled: + my_func() + assert len(root_reenabled.children) == 1, "Span should be captured again after re-enabling" + + def test_i_can_clear_traces(self, fresh_profiler): + """Test that clear() empties the trace buffer completely.""" + p = fresh_profiler + with p.command_span("cmd", "", "uuid-1", {}): + pass + with p.command_span("cmd", "", "uuid-2", {}): + pass + + assert len(p.traces) == 2 + p.clear() + assert len(p.traces) == 0 + + def test_i_can_measure_overhead(self, fresh_profiler): + """Test that overhead metrics are populated after spans are recorded.""" + p = fresh_profiler + for _ in range(20): + with p.span("probe"): + pass + + assert p.overhead_per_span_us >= 0 + assert p.total_overhead_ms >= 0 + + def test_i_can_get_zero_overhead_when_no_samples(self, fresh_profiler): + """Test that overhead_per_span_us returns 0.0 when no spans have been recorded.""" + p = fresh_profiler + assert p.overhead_per_span_us == 0.0 + + def test_i_can_get_zero_total_overhead_when_buffer_empty(self, fresh_profiler): + """Test that total_overhead_ms returns 0.0 when the trace buffer is empty.""" + p = fresh_profiler + assert p.total_overhead_ms == 0.0