Skip to content

Commit d27b2d5

Browse files
committed
added small but powerful feature to the capture_timestamp workflows: timestamp_args (which adjusts the name based on the method call's params)
1 parent 77d2fa3 commit d27b2d5

File tree

6 files changed

+521
-37
lines changed

6 files changed

+521
-37
lines changed

docs/llm-briefs/features/v3.58.0__timestamp-capture__llm-usage-brief.md renamed to docs/llm-briefs/features/v3.59.1__timestamp-capture__llm-usage-brief.md

Lines changed: 125 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
# Timestamp Capture - LLM Usage Brief
22

3-
**Version**: v3.58.0
3+
**Version**: v3.59.1
44
**Purpose**: Guide for LLMs and developers on using the timestamp_capture instrumentation system
55
**Location**: `osbot_utils.helpers.timestamp_capture`
66
**Repo**: https://github.com/owasp-sbot/OSBot-Utils
@@ -103,6 +103,9 @@ from osbot_utils.helpers.timestamp_capture.Timestamp_Collector import T
103103
# Decorator
104104
from osbot_utils.helpers.timestamp_capture.decorators.timestamp import timestamp
105105

106+
# Decorator for dynamic names from function arguments
107+
from osbot_utils.helpers.timestamp_capture.decorators.timestamp_args import timestamp_args
108+
106109
# Context manager for code blocks
107110
from osbot_utils.helpers.timestamp_capture.context_managers.timestamp_block import timestamp_block
108111

@@ -299,7 +302,106 @@ def handle_delete(self):
299302
| `component.stage.action` | `pipeline.stage1.extract` | Pipeline stages |
300303
| `feature.version.method` | `algorithm.v2.sort` | A/B testing |
301304

302-
### Pattern 5: Programmatic Analysis
305+
306+
### Pattern 5: Dynamic Names from Function Arguments
307+
308+
When a method is called multiple times with different arguments and you need to distinguish each call in reports, use `@timestamp_args`. This interpolates function argument values into the metric name at runtime.
309+
```python
310+
from osbot_utils.helpers.timestamp_capture.decorators.timestamp_args import timestamp_args
311+
312+
class DocumentBuilder:
313+
314+
@timestamp_args(name="link_component({name})")
315+
def _link_component(self, name: str, root_id: int):
316+
# Link a component graph to the document
317+
...
318+
319+
# Each call is tracked separately:
320+
builder._link_component("head", 1)
321+
builder._link_component("body", 2)
322+
builder._link_component("attrs", 3)
323+
```
324+
325+
**Timeline shows each call distinctly:**
326+
```
327+
20.879ms ▶ link_component(head)
328+
21.846ms ◀ link_component(head)
329+
21.860ms ▶ link_component(body)
330+
22.659ms ◀ link_component(body)
331+
22.671ms ▶ link_component(attrs)
332+
23.433ms ◀ link_component(attrs)
333+
```
334+
335+
**Hotspots show individual breakdowns:**
336+
```
337+
link_component(head) 0.97ms [1 call]
338+
link_component(body) 0.80ms [1 call]
339+
link_component(attrs) 0.76ms [1 call]
340+
```
341+
342+
#### When to use `@timestamp_args` vs `@timestamp`
343+
344+
| Decorator | Name Resolution | Use When |
345+
|-----------|-----------------|----------|
346+
| `@timestamp` | At decoration time (static) | Same name for all calls |
347+
| `@timestamp_args` | At call time (dynamic) | Need to distinguish calls by argument values |
348+
349+
#### Supported Argument Patterns
350+
```python
351+
# Positional arguments
352+
@timestamp_args(name="process.{item_type}")
353+
def process(item_type: str, data: dict):
354+
...
355+
356+
# Multiple arguments
357+
@timestamp_args(name="handler.{method}.{path}")
358+
def handle_request(method: str, path: str):
359+
...
360+
361+
# Keyword-only arguments (after *)
362+
@timestamp_args(name="config.{env}.{region}")
363+
def configure(*, env: str, region: str = "us-east-1"):
364+
...
365+
366+
# Mixed positional and keyword-only
367+
@timestamp_args(name="request.{method}")
368+
def make_request(method: str, *, timeout: int = 30):
369+
...
370+
371+
# Using default values (defaults are interpolated too)
372+
@timestamp_args(name="cache.{strategy}")
373+
def cache_data(data: dict, *, strategy: str = "lru"):
374+
...
375+
# cache_data({"a": 1}) → "cache.lru"
376+
# cache_data({"a": 1}, strategy="fifo") → "cache.fifo"
377+
```
378+
379+
#### Real-World Example
380+
```python
381+
class Html_MGraph__Document:
382+
383+
@timestamp(name="html_mgraph.document.setup")
384+
def setup(self):
385+
self.head_graph = Html_MGraph__Head().setup()
386+
self.body_graph = Html_MGraph__Body().setup()
387+
self.attrs_graph = Html_MGraph__Attributes().setup()
388+
389+
# Each link is tracked separately
390+
self._link_component_graph('head', self.head_graph.root_id)
391+
self._link_component_graph('body', self.body_graph.root_id)
392+
self._link_component_graph('attrs', self.attrs_graph.root_id)
393+
return self
394+
395+
@timestamp_args(name="html_mgraph.document._link_component_graph({name})")
396+
def _link_component_graph(self, name: str, component_root_id: Node_Id):
397+
# Now each call shows which component in timeline/reports
398+
...
399+
```
400+
401+
**Important:** `@timestamp_args` requires at least one `{placeholder}` in the name. For static names, use `@timestamp` instead (lower overhead).
402+
403+
404+
### Pattern 6: Programmatic Analysis
303405

304406
```python
305407
from osbot_utils.helpers.timestamp_capture.Timestamp_Collector__Analysis import Timestamp_Collector__Analysis
@@ -329,7 +431,7 @@ by_total = analysis.get_timings_by_total()
329431
by_calls = analysis.get_timings_by_call_count()
330432
```
331433

332-
### Pattern 6: Test Performance Assertions
434+
### Pattern 7: Test Performance Assertions
333435

334436
```python
335437
def test_process_performance(self):
@@ -549,6 +651,7 @@ with _timestamp_collector_:
549651
| @timestamp, no collector | ~3 μs | ✅ Yes |
550652
| @timestamp, with collector | ~8 μs | ✅ Yes (for methods >100μs) |
551653
| Nested decorators (N levels) | N × overhead | ✅ Scales linearly |
654+
| @timestamp_args, with collector | ~10 μs | ✅ Yes (slight overhead for arg binding) |
552655

553656
**Rule of thumb**: If your method takes >100μs, the 8μs capture overhead is <8% - acceptable for most scenarios including production profiling.
554657

@@ -712,6 +815,24 @@ with timestamp_block("process_all_items"):
712815
MAX_STACK_DEPTH = 100 # Increase if needed
713816
```
714817

818+
### Problem: Can't Distinguish Multiple Calls to Same Method
819+
820+
**Cause**: Using `@timestamp` on a method called with different arguments
821+
```python
822+
# ❌ All 5 calls show as same name
823+
@timestamp(name="link_component")
824+
def _link_component(self, name: str, root_id: int):
825+
...
826+
```
827+
828+
**Solution**: Use `@timestamp_args` to include argument values in the name
829+
```python
830+
# ✅ Each call shows distinct name
831+
@timestamp_args(name="link_component({name})")
832+
def _link_component(self, name: str, root_id: int):
833+
...
834+
```
835+
715836
---
716837

717838
## Summary Checklist
@@ -721,6 +842,7 @@ When adding timestamp capture to a codebase:
721842
- [ ] Import `@timestamp` decorator and `Timestamp_Collector`
722843
- [ ] Add `@timestamp` to key methods (entry points, major processing steps)
723844
- [ ] Use `@timestamp(name="...")` for hierarchical/grouped naming when helpful
845+
- [ ] Use `@timestamp_args(name="method({arg})")` when you need to distinguish calls by argument values
724846
- [ ] Skip tiny utility functions and hot-loop internals
725847
- [ ] Use `timestamp_block` for code phases not in methods
726848
- [ ] Name collector variable exactly `_timestamp_collector_`

osbot_utils/helpers/timestamp_capture/Timestamp_Collector__Report.py

Lines changed: 64 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -4,21 +4,41 @@
44
55
Formats and prints timing reports from collected timestamps.
66
"""
7-
from osbot_utils.helpers.timestamp_capture.Timestamp_Collector import Timestamp_Collector
7+
88
from osbot_utils.helpers.timestamp_capture.Timestamp_Collector__Analysis import Timestamp_Collector__Analysis
99
from osbot_utils.helpers.timestamp_capture.static_methods.timestamp_utils import method_timing__total_ms, method_timing__self_ms, method_timing__avg_ms
1010
from osbot_utils.type_safe.Type_Safe import Type_Safe
11+
from osbot_utils.helpers.timestamp_capture.Timestamp_Collector import Timestamp_Collector
1112

1213

1314
class Timestamp_Collector__Report(Type_Safe):
1415

1516
collector: Timestamp_Collector = None
1617

17-
def format_report(self, show_self_time: bool = True) -> str: # Format comprehensive timing report
18+
MIN_METHOD_WIDTH = 40 # Minimum width for method column
19+
MAX_METHOD_WIDTH = 80 # Maximum width to prevent excessive stretching
20+
21+
def _calculate_method_width(self, names: list) -> int: # Calculate optimal column width
22+
if not names:
23+
return self.MIN_METHOD_WIDTH
24+
max_name_len = max(len(name) for name in names)
25+
return min(max(max_name_len + 2, self.MIN_METHOD_WIDTH), self.MAX_METHOD_WIDTH)
26+
27+
def _calculate_total_width(self, method_width: int) -> int: # Calculate total line width
28+
return method_width + 50 # method + calls + total + self + avg + %
29+
30+
def format_report(self, show_self_time: bool = True) -> str: # Format comprehensive timing report
31+
analysis = Timestamp_Collector__Analysis(collector=self.collector)
32+
timings = analysis.get_method_timings()
33+
34+
method_names = list(timings.keys()) if timings else []
35+
method_width = self._calculate_method_width(method_names)
36+
total_width = self._calculate_total_width(method_width)
37+
1838
lines = []
19-
lines.append("=" * 100)
39+
lines.append("=" * total_width)
2040
lines.append(f"Timestamp Report: {self.collector.name}")
21-
lines.append("=" * 100)
41+
lines.append("=" * total_width)
2242
lines.append("")
2343

2444
total_ms = self.collector.total_duration_ms()
@@ -27,20 +47,17 @@ def format_report(self, show_self_time: bool = True) -> str: # Fo
2747
lines.append(f" Methods Traced : {self.collector.method_count()}")
2848
lines.append("")
2949

30-
analysis = Timestamp_Collector__Analysis(collector=self.collector)
31-
timings = analysis.get_method_timings()
32-
3350
if timings:
3451
lines.append("Method Timings (sorted by total time):")
35-
lines.append("-" * 100)
52+
lines.append("-" * total_width)
3653

3754
if show_self_time:
38-
header = f"{'Method':<50} {'Calls':>6} {'Total':>10} {'Self':>10} {'Avg':>8} {'%Total':>7}"
55+
header = f"{'Method':<{method_width}} {'Calls':>6} {'Total':>10} {'Self':>10} {'Avg':>9} {'%Total':>7}"
3956
else:
40-
header = f"{'Method':<50} {'Calls':>6} {'Total(ms)':>10} {'Avg(ms)':>10} {'%Total':>7}"
57+
header = f"{'Method':<{method_width}} {'Calls':>6} {'Total(ms)':>10} {'Avg(ms)':>10} {'%Total':>7}"
4158

4259
lines.append(header)
43-
lines.append("-" * 100)
60+
lines.append("-" * total_width)
4461

4562
sorted_timings = analysis.get_timings_by_total()
4663
total_ns = self.collector.total_duration_ns()
@@ -50,27 +67,37 @@ def format_report(self, show_self_time: bool = True) -> str: # Fo
5067

5168
if show_self_time:
5269
lines.append(
53-
f"{mt.name:<50} {mt.call_count:>6} "
70+
f"{mt.name:<{method_width}} {mt.call_count:>6} "
5471
f"{method_timing__total_ms(mt):>9.2f}ms {method_timing__self_ms(mt):>9.2f}ms "
55-
f"{method_timing__avg_ms(mt):>7.3f}ms {pct:>6.1f}%"
72+
f"{method_timing__avg_ms(mt):>8.3f}ms {pct:>6.1f}%"
5673
)
5774
else:
5875
lines.append(
59-
f"{mt.name:<50} {mt.call_count:>6} "
76+
f"{mt.name:<{method_width}} {mt.call_count:>6} "
6077
f"{method_timing__total_ms(mt):>10.2f} {method_timing__avg_ms(mt):>10.3f} {pct:>6.1f}%"
6178
)
6279

6380
lines.append("")
64-
lines.append("=" * 100)
81+
lines.append("=" * total_width)
6582
return "\n".join(lines)
6683

67-
def format_timeline(self, max_entries: int = 100) -> str: # Format timeline view
84+
def format_timeline(self, max_entries: int = 100) -> str: # Format timeline view
85+
entries = self.collector.entries[:max_entries]
86+
87+
# Calculate width based on deepest indent + longest name
88+
if entries:
89+
max_indent = max(entry.depth for entry in entries) * 2
90+
max_name_len = max(len(entry.name) for entry in entries)
91+
content_width = 12 + max_indent + 2 + max_name_len # timestamp + indent + marker + name
92+
total_width = max(80, content_width + 2)
93+
else:
94+
total_width = 80
95+
6896
lines = []
69-
lines.append("=" * 80)
97+
lines.append("=" * total_width)
7098
lines.append("Execution Timeline")
71-
lines.append("=" * 80)
99+
lines.append("=" * total_width)
72100

73-
entries = self.collector.entries[:max_entries]
74101
if len(self.collector.entries) > max_entries:
75102
lines.append(f"(showing first {max_entries} of {len(self.collector.entries)} entries)")
76103

@@ -80,35 +107,39 @@ def format_timeline(self, max_entries: int = 100) -> str: # Fo
80107
marker = "▶" if entry.event == 'enter' else "◀"
81108
lines.append(f"{offset_ms:>10.3f}ms {indent}{marker} {entry.name}")
82109

83-
lines.append("=" * 80)
110+
lines.append("=" * total_width)
84111
return "\n".join(lines)
85112

86-
def format_hotspots(self, top_n: int = 10) -> str: # Format hotspot analysis (by self-time)
87-
lines = []
88-
lines.append("=" * 80)
89-
lines.append(f"Top {top_n} Hotspots (by self-time)")
90-
lines.append("=" * 80)
91-
113+
def format_hotspots(self, top_n: int = 10) -> str: # Format hotspot analysis (by self-time)
92114
analysis = Timestamp_Collector__Analysis(collector=self.collector)
93115
hotspots = analysis.get_hotspots(top_n)
94116
total_ns = self.collector.total_duration_ns()
95117

118+
# Calculate width based on longest method name
119+
if hotspots:
120+
method_names = [mt.name for mt in hotspots]
121+
method_width = self._calculate_method_width(method_names)
122+
else:
123+
method_width = self.MIN_METHOD_WIDTH
124+
125+
total_width = method_width + 40 # method + rank + timing + percentage + calls
126+
127+
lines = []
128+
lines.append("=" * total_width)
129+
lines.append(f"Top {top_n} Hotspots (by self-time)")
130+
lines.append("=" * total_width)
131+
96132
for i, mt in enumerate(hotspots, 1):
97133
pct = (mt.self_ns / total_ns * 100) if total_ns > 0 else 0
98134
lines.append(
99-
f" {i:>2}. {mt.name:<45} "
135+
f" {i:>2}. {mt.name:<{method_width}} "
100136
f"{method_timing__self_ms(mt):>8.2f}ms ({pct:>5.1f}%) "
101137
f"[{mt.call_count} calls]"
102138
)
103139

104-
lines.append("=" * 80)
140+
lines.append("=" * total_width)
105141
return "\n".join(lines)
106142

107-
def print_all(self):
108-
self.print_report ()
109-
self.print_timeline()
110-
self.print_hotspots()
111-
112143
def print_report(self, show_self_time: bool = True):
113144
print(self.format_report(show_self_time))
114145

0 commit comments

Comments
 (0)