Skip to content

Commit 6c5baa7

Browse files
committed
added @timestamp decorator
1 parent fce4476 commit 6c5baa7

27 files changed

+1498
-2
lines changed
Lines changed: 99 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,99 @@
1+
"""
2+
Timestamp Collector - Core Recording
3+
=====================================
4+
5+
Collects timestamps from @timestamp decorated methods.
6+
Found via stack-walking - no need to pass through call chain.
7+
8+
Usage:
9+
_timestamp_collector_ = Timestamp_Collector(name="my_workflow")
10+
with _timestamp_collector_:
11+
result = do_work()
12+
"""
13+
14+
import time
15+
import threading
16+
from typing import List, Dict, Any
17+
from osbot_utils.helpers.timestamp_capture.schemas.Schema__Timestamp_Entry import Schema__Timestamp_Entry
18+
from osbot_utils.type_safe.Type_Safe import Type_Safe
19+
20+
21+
class Timestamp_Collector(Type_Safe):
22+
23+
name : str = 'default'
24+
entries : List[Schema__Timestamp_Entry] = None
25+
start_time_ns : int = 0
26+
end_time_ns : int = 0
27+
thread_id : int = 0
28+
_depth : int = 0
29+
_active : bool = False
30+
_call_stack : List[Schema__Timestamp_Entry] = None # For self-time calculation
31+
32+
def __init__(self, **kwargs):
33+
super().__init__(**kwargs)
34+
self.entries = []
35+
self._call_stack = []
36+
self.thread_id = threading.get_ident()
37+
38+
# ═══════════════════════════════════════════════════════════════════════════
39+
# Context Manager
40+
# ═══════════════════════════════════════════════════════════════════════════
41+
42+
def __enter__(self):
43+
self.start_time_ns = time.perf_counter_ns()
44+
self._active = True
45+
return self
46+
47+
def __exit__(self, exc_type, exc_val, exc_tb):
48+
self.end_time_ns = time.perf_counter_ns()
49+
self._active = False
50+
return False # Don't suppress exceptions
51+
52+
# ═══════════════════════════════════════════════════════════════════════════
53+
# Recording API
54+
# ═══════════════════════════════════════════════════════════════════════════
55+
56+
def record(self, name: str, event: str, extra: Dict[str, Any] = None) -> Schema__Timestamp_Entry:
57+
if not self._active: # Record a timestamp entry (low-level API)
58+
return None
59+
60+
entry = Schema__Timestamp_Entry(name = name ,
61+
event = event ,
62+
timestamp_ns = time.perf_counter_ns() ,
63+
clock_ns = time.time_ns() ,
64+
thread_id = threading.get_ident() ,
65+
depth = self._depth ,
66+
extra = extra )
67+
self.entries.append(entry)
68+
return entry
69+
70+
def enter(self, name: str, extra: Dict[str, Any] = None): # Record method entry
71+
entry = self.record(name, 'enter', extra)
72+
if entry:
73+
self._call_stack.append(entry)
74+
self._depth += 1
75+
76+
def exit(self, name: str, extra: Dict[str, Any] = None): # Record method exit
77+
self._depth = max(0, self._depth - 1)
78+
self.record(name, 'exit', extra)
79+
if self._call_stack:
80+
self._call_stack.pop()
81+
82+
# ═══════════════════════════════════════════════════════════════════════════
83+
# Basic Accessors
84+
# ═══════════════════════════════════════════════════════════════════════════
85+
86+
def total_duration_ns(self) -> int:
87+
return self.end_time_ns - self.start_time_ns
88+
89+
def total_duration_ms(self) -> float:
90+
return self.total_duration_ns() / 1_000_000
91+
92+
def entry_count(self) -> int:
93+
return len(self.entries)
94+
95+
def method_count(self) -> int:
96+
return len(set(e.name for e in self.entries))
97+
98+
def is_active(self) -> bool:
99+
return self._active
Lines changed: 67 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,67 @@
1+
"""
2+
Timestamp Collector Analysis
3+
=============================
4+
5+
Analyzes collected timestamps to compute method timings and hotspots.
6+
"""
7+
8+
from typing import List, Dict
9+
from osbot_utils.helpers.timestamp_capture.schemas.Schema__Method_Timing import Schema__Method_Timing
10+
from osbot_utils.type_safe.Type_Safe import Type_Safe
11+
from osbot_utils.helpers.timestamp_capture.Timestamp_Collector import Timestamp_Collector
12+
13+
14+
class Timestamp_Collector__Analysis(Type_Safe):
15+
16+
collector: Timestamp_Collector = None
17+
18+
def get_method_timings(self) -> Dict[str, Schema__Method_Timing]: # Calculate per-method timing with self-time
19+
timings : Dict[str, Schema__Method_Timing] = {}
20+
stack : List[tuple] = [] # (entry_index, entry)
21+
children : Dict[int, int] = {} # entry_index -> child_time_ns
22+
23+
for i, entry in enumerate(self.collector.entries):
24+
if entry.event == 'enter':
25+
stack.append((i, entry))
26+
children[i] = 0
27+
28+
elif entry.event == 'exit' and stack:
29+
for j in range(len(stack) - 1, -1, -1): # Find matching enter (reverse search)
30+
enter_idx, enter_entry = stack[j]
31+
if enter_entry.name == entry.name:
32+
stack.pop(j)
33+
34+
duration_ns = entry.timestamp_ns - enter_entry.timestamp_ns
35+
child_time = children.pop(enter_idx, 0)
36+
self_time = duration_ns - child_time
37+
38+
if stack: # Add child time to parent
39+
parent_idx = stack[-1][0]
40+
children[parent_idx] = children.get(parent_idx, 0) + duration_ns
41+
42+
if entry.name not in timings: # Update timing stats
43+
timings[entry.name] = Schema__Method_Timing(name = entry.name ,
44+
min_ns = duration_ns ,
45+
max_ns = duration_ns )
46+
47+
mt = timings[entry.name]
48+
mt.call_count += 1
49+
mt.total_ns += duration_ns
50+
mt.self_ns += self_time
51+
mt.min_ns = min(mt.min_ns, duration_ns)
52+
mt.max_ns = max(mt.max_ns, duration_ns)
53+
break
54+
55+
return timings
56+
57+
def get_hotspots(self, top_n: int = 10) -> List[Schema__Method_Timing]: # Get top N methods by self-time
58+
timings = self.get_method_timings()
59+
return sorted(timings.values(), key=lambda t: t.self_ns, reverse=True)[:top_n]
60+
61+
def get_timings_by_total(self) -> List[Schema__Method_Timing]: # Get all timings sorted by total time
62+
timings = self.get_method_timings()
63+
return sorted(timings.values(), key=lambda t: t.total_ns, reverse=True)
64+
65+
def get_timings_by_call_count(self) -> List[Schema__Method_Timing]: # Get all timings sorted by call count
66+
timings = self.get_method_timings()
67+
return sorted(timings.values(), key=lambda t: t.call_count, reverse=True)
Lines changed: 119 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,119 @@
1+
"""
2+
Timestamp Collector Report
3+
===========================
4+
5+
Formats and prints timing reports from collected timestamps.
6+
"""
7+
from osbot_utils.helpers.timestamp_capture.Timestamp_Collector import Timestamp_Collector
8+
from osbot_utils.helpers.timestamp_capture.Timestamp_Collector__Analysis import Timestamp_Collector__Analysis
9+
from osbot_utils.helpers.timestamp_capture.static_methods.timestamp_utils import method_timing__total_ms, method_timing__self_ms, method_timing__avg_ms
10+
from osbot_utils.type_safe.Type_Safe import Type_Safe
11+
12+
13+
class Timestamp_Collector__Report(Type_Safe):
14+
15+
collector: Timestamp_Collector = None
16+
17+
def format_report(self, show_self_time: bool = True) -> str: # Format comprehensive timing report
18+
lines = []
19+
lines.append("=" * 100)
20+
lines.append(f"Timestamp Report: {self.collector.name}")
21+
lines.append("=" * 100)
22+
lines.append("")
23+
24+
total_ms = self.collector.total_duration_ms()
25+
lines.append(f" Total Duration : {total_ms:,.2f} ms")
26+
lines.append(f" Entry Count : {self.collector.entry_count():,}")
27+
lines.append(f" Methods Traced : {self.collector.method_count()}")
28+
lines.append("")
29+
30+
analysis = Timestamp_Collector__Analysis(collector=self.collector)
31+
timings = analysis.get_method_timings()
32+
33+
if timings:
34+
lines.append("Method Timings (sorted by total time):")
35+
lines.append("-" * 100)
36+
37+
if show_self_time:
38+
header = f"{'Method':<50} {'Calls':>6} {'Total':>10} {'Self':>10} {'Avg':>8} {'%Total':>7}"
39+
else:
40+
header = f"{'Method':<50} {'Calls':>6} {'Total(ms)':>10} {'Avg(ms)':>10} {'%Total':>7}"
41+
42+
lines.append(header)
43+
lines.append("-" * 100)
44+
45+
sorted_timings = analysis.get_timings_by_total()
46+
total_ns = self.collector.total_duration_ns()
47+
48+
for mt in sorted_timings:
49+
pct = (mt.total_ns / total_ns * 100) if total_ns > 0 else 0
50+
51+
if show_self_time:
52+
lines.append(
53+
f"{mt.name:<50} {mt.call_count:>6} "
54+
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}%"
56+
)
57+
else:
58+
lines.append(
59+
f"{mt.name:<50} {mt.call_count:>6} "
60+
f"{method_timing__total_ms(mt):>10.2f} {method_timing__avg_ms(mt):>10.3f} {pct:>6.1f}%"
61+
)
62+
63+
lines.append("")
64+
lines.append("=" * 100)
65+
return "\n".join(lines)
66+
67+
def format_timeline(self, max_entries: int = 100) -> str: # Format timeline view
68+
lines = []
69+
lines.append("=" * 80)
70+
lines.append("Execution Timeline")
71+
lines.append("=" * 80)
72+
73+
entries = self.collector.entries[:max_entries]
74+
if len(self.collector.entries) > max_entries:
75+
lines.append(f"(showing first {max_entries} of {len(self.collector.entries)} entries)")
76+
77+
for entry in entries:
78+
offset_ms = (entry.timestamp_ns - self.collector.start_time_ns) / 1_000_000
79+
indent = " " * entry.depth
80+
marker = "▶" if entry.event == 'enter' else "◀"
81+
lines.append(f"{offset_ms:>10.3f}ms {indent}{marker} {entry.name}")
82+
83+
lines.append("=" * 80)
84+
return "\n".join(lines)
85+
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+
92+
analysis = Timestamp_Collector__Analysis(collector=self.collector)
93+
hotspots = analysis.get_hotspots(top_n)
94+
total_ns = self.collector.total_duration_ns()
95+
96+
for i, mt in enumerate(hotspots, 1):
97+
pct = (mt.self_ns / total_ns * 100) if total_ns > 0 else 0
98+
lines.append(
99+
f" {i:>2}. {mt.name:<45} "
100+
f"{method_timing__self_ms(mt):>8.2f}ms ({pct:>5.1f}%) "
101+
f"[{mt.call_count} calls]"
102+
)
103+
104+
lines.append("=" * 80)
105+
return "\n".join(lines)
106+
107+
def print_all(self):
108+
self.print_report ()
109+
self.print_timeline()
110+
self.print_hotspots()
111+
112+
def print_report(self, show_self_time: bool = True):
113+
print(self.format_report(show_self_time))
114+
115+
def print_timeline(self, max_entries: int = 100):
116+
print(self.format_timeline(max_entries))
117+
118+
def print_hotspots(self, top_n: int = 10):
119+
print(self.format_hotspots(top_n))
Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,29 @@
1+
"""
2+
Timestamp Capture - Type_Safe Integration
3+
==========================================
4+
5+
Type_Safe compatible version of the timestamp capture system,
6+
designed for integration with the Html_MGraph pipeline.
7+
8+
Key Features:
9+
- Inherits from Type_Safe for consistency with codebase
10+
- Stack-walking to find collector (no signature changes needed)
11+
- Minimal overhead when collector not present
12+
- Rich timing data with aggregation
13+
14+
Integration Example:
15+
# In Html__To__Html_MGraph__Document
16+
@timestamp
17+
def convert(self, html: str) -> Html_MGraph__Document:
18+
...
19+
20+
@timestamp
21+
def _process_body(self, ...):
22+
...
23+
24+
# In test or profiling code
25+
_timestamp_collector_ = Timestamp_Collector()
26+
with _timestamp_collector_:
27+
doc = converter.convert(html)
28+
_timestamp_collector_.print_report()
29+
"""

osbot_utils/helpers/timestamp_capture/context_managers/__init__.py

Whitespace-only changes.
Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
"""
2+
Context manager to timestamp a code block.
3+
4+
Usage:
5+
with timestamp_block("my_phase"):
6+
# code to measure
7+
...
8+
"""
9+
from contextlib import contextmanager
10+
from osbot_utils.helpers.timestamp_capture.static_methods.find_timestamp_collector import find_timestamp_collector
11+
12+
13+
@contextmanager
14+
def timestamp_block(name: str):
15+
16+
collector = find_timestamp_collector()
17+
if collector:
18+
collector.enter(name)
19+
try:
20+
yield
21+
finally:
22+
if collector:
23+
collector.exit(name)

osbot_utils/helpers/timestamp_capture/decorators/__init__.py

Whitespace-only changes.
Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
"""
2+
Timestamp Capture - @timestamp decorator
3+
==========================================
4+
5+
Usage:
6+
@timestamp
7+
def my_method(self):
8+
...
9+
10+
@timestamp(name="custom.name")
11+
def another(self):
12+
...
13+
"""
14+
15+
from functools import wraps
16+
from typing import Callable, Optional
17+
from osbot_utils.helpers.timestamp_capture.static_methods.find_timestamp_collector import find_timestamp_collector
18+
19+
20+
def timestamp(func: Callable = None, *, name: str = None): # Decorator to capture method timestamps.
21+
22+
def decorator(fn: Callable) -> Callable:
23+
method_name = name or fn.__qualname__
24+
25+
@wraps(fn)
26+
def wrapper(*args, **kwargs):
27+
collector = find_timestamp_collector()
28+
29+
if collector is None:
30+
return fn(*args, **kwargs)
31+
32+
collector.enter(method_name)
33+
try:
34+
return fn(*args, **kwargs)
35+
finally:
36+
collector.exit(method_name)
37+
38+
return wrapper
39+
40+
if func is not None:
41+
return decorator(func)
42+
return decorator
43+
44+

0 commit comments

Comments
 (0)