Use integer microseconds instead of float milliseconds

Performance and precision improvements:

- Parse durations as integers (microseconds) instead of floats (milliseconds)
- Accumulate all durations in microseconds for better precision
- Use integer division for average calculations
- Avoid floating point arithmetic throughout data processing

Template updates:
- Add us_to_ms and us_to_s Jinja2 filters for display formatting
- Convert microseconds to milliseconds/seconds only for display
- Update all template fields to use conversion filters
- Maintain precision in calculations, format only for output

Benefits:
- Better precision (no floating point rounding errors)
- Faster processing (integer arithmetic)
- Matches native trace file format (microseconds)
- Cleaner separation of storage vs display formatting

Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
Max Podkorytov
2026-01-14 00:04:08 -06:00
parent cef3e869b0
commit 4b8471b681
2 changed files with 27 additions and 20 deletions

View File

@@ -55,13 +55,13 @@ def process_events(data):
"""Process trace events and extract template instantiation statistics."""
print('Processing events...')
template_stats = defaultdict(lambda: {'count': 0, 'total_dur': 0.0})
phase_stats = defaultdict(float)
template_stats = defaultdict(lambda: {'count': 0, 'total_dur': 0})
phase_stats = defaultdict(int)
top_individual = []
for event in data.get('traceEvents', []):
name = event.get('name', '')
dur = event.get('dur', 0) / 1000.0 # Convert to milliseconds
dur = int(event.get('dur', 0)) # Keep as integer microseconds
if name and dur > 0:
phase_stats[name] += dur
@@ -107,7 +107,7 @@ def prepare_template_data(template_stats, phase_stats, top_individual):
templates_by_time.append((name, {
'count': stats['count'],
'total_dur': stats['total_dur'],
'avg': stats['total_dur'] / stats['count'] if stats['count'] > 0 else 0,
'avg': stats['total_dur'] // stats['count'] if stats['count'] > 0 else 0,
'pct': 100 * stats['total_dur'] / total_template_time if total_template_time > 0 else 0
}))
@@ -117,7 +117,7 @@ def prepare_template_data(template_stats, phase_stats, top_individual):
templates_by_count.append((name, {
'count': stats['count'],
'total_dur': stats['total_dur'],
'avg': stats['total_dur'] / stats['count'] if stats['count'] > 0 else 0
'avg': stats['total_dur'] // stats['count'] if stats['count'] > 0 else 0
}))
# Add friendly type names to individual instantiations
@@ -165,9 +165,19 @@ def setup_jinja_environment(template_dir):
"""Pad string to specified length."""
return f'{value:<{length}}'
def us_to_ms(value):
"""Convert microseconds to milliseconds."""
return value / 1000.0
def us_to_s(value):
"""Convert microseconds to seconds."""
return value / 1000000.0
env.filters['format_number'] = format_number
env.filters['truncate'] = truncate
env.filters['pad'] = pad
env.filters['us_to_ms'] = us_to_ms
env.filters['us_to_s'] = us_to_s
return env
@@ -183,9 +193,6 @@ def generate_report(env, data, args, total_events):
target=args['target'],
granularity=args['granularity'],
build_time=args['build_time'],
trace_time_sec=f'{data["total_trace_time"] / 1000:.1f}',
template_time_sec=f'{data["total_template_time"] / 1000:.1f}',
template_pct=f'{100 * data["total_template_time"] / data["total_trace_time"]:.1f}',
total_events=total_events,
total_instantiations=data['total_inst'],
unique_families=data['unique_families'],
@@ -196,7 +203,7 @@ def generate_report(env, data, args, total_events):
templates_by_time=data['templates_by_time'],
templates_by_count=data['templates_by_count'],
median_count=data['median_count'],
top10_pct=f'{data["top10_pct"]:.1f}'
top10_pct=data['top10_pct']
)
return report_content

View File

@@ -7,8 +7,8 @@
## Executive Summary
- **Wall Clock Time:** {{ build_time }} seconds
- **Trace Time:** {{ trace_time_sec }} seconds
- **Template Instantiation Time:** {{ template_time_sec }} seconds ({{ template_pct }}% of trace)
- **Trace Time:** {{ total_trace_time|us_to_s|round(1) }} seconds
- **Template Instantiation Time:** {{ total_template_time|us_to_s|round(1) }} seconds ({{ (100 * total_template_time / total_trace_time)|round(1) }}% of trace)
- **Total Events Captured:** {{ total_events|format_number }}
- **Total Template Instantiations:** {{ total_instantiations|format_number }}
- **Unique Template Families:** {{ unique_families }}
@@ -18,7 +18,7 @@
| Phase | Time (ms) | Time (s) | % of Total |
|-------|-----------|----------|------------|
{% for phase, dur in phases[:20] -%}
| {{ phase|pad(40) }} | {{ "%9.2f"|format(dur) }} | {{ "%8.2f"|format(dur/1000) }} | {{ "%9.1f"|format(100 * dur / total_trace_time) }}% |
| {{ phase|pad(40) }} | {{ "%9.2f"|format(dur|us_to_ms) }} | {{ "%8.2f"|format(dur|us_to_s) }} | {{ "%9.1f"|format(100 * dur / total_trace_time) }}% |
{% endfor %}
## Top 30 Most Expensive Individual Instantiations
@@ -26,7 +26,7 @@
| Rank | Template | Type | Time (ms) |
|------|----------|------|-----------|
{% for inst in top_individual[:30] -%}
| {{ "%4d"|format(loop.index) }} | {{ inst.detail|truncate(70) }} | {{ inst.inst_type|pad(5) }} | {{ "%9.2f"|format(inst.dur) }} |
| {{ "%4d"|format(loop.index) }} | {{ inst.detail|truncate(70) }} | {{ inst.inst_type|pad(5) }} | {{ "%9.2f"|format(inst.dur|us_to_ms) }} |
{% endfor %}
## Template Families by Total Time (Top 50)
@@ -34,7 +34,7 @@
| Rank | Template Family | Count | Total (ms) | Avg (ms) | % of Total |
|------|-----------------|-------|------------|----------|------------|
{% for name, stats in templates_by_time[:50] -%}
| {{ "%4d"|format(loop.index) }} | {{ name|truncate(43)|pad(43) }} | {{ "%5d"|format(stats.count) }} | {{ "%10.2f"|format(stats.total_dur) }} | {{ "%8.2f"|format(stats.avg) }} | {{ "%9.1f"|format(stats.pct) }}% |
| {{ "%4d"|format(loop.index) }} | {{ name|truncate(43)|pad(43) }} | {{ "%5d"|format(stats.count) }} | {{ "%10.2f"|format(stats.total_dur|us_to_ms) }} | {{ "%8.2f"|format(stats.avg|us_to_ms) }} | {{ "%9.1f"|format(stats.pct) }}% |
{% endfor %}
## Template Families by Instantiation Count (Top 50)
@@ -42,23 +42,23 @@
| Rank | Template Family | Count | Total (ms) | Avg (ms) |
|------|-----------------|-------|------------|----------|
{% for name, stats in templates_by_count[:50] -%}
| {{ "%4d"|format(loop.index) }} | {{ name|truncate(43)|pad(43) }} | {{ "%5d"|format(stats.count) }} | {{ "%10.2f"|format(stats.total_dur) }} | {{ "%8.2f"|format(stats.avg) }} |
| {{ "%4d"|format(loop.index) }} | {{ name|truncate(43)|pad(43) }} | {{ "%5d"|format(stats.count) }} | {{ "%10.2f"|format(stats.total_dur|us_to_ms) }} | {{ "%8.2f"|format(stats.avg|us_to_ms) }} |
{% endfor %}
## Key Insights
### 1. Template Instantiation Impact
- Template instantiation accounts for {{ template_pct }}% of total trace time
- Template instantiation accounts for {{ (100 * total_template_time / total_trace_time)|round(1) }}% of total trace time
{% if unique_families >= 10 -%}
- Top 10 template families account for {{ top10_pct }}% of instantiation time
- Top 10 template families account for {{ top10_pct|round(1) }}% of instantiation time
{% endif %}
### 2. Most Expensive Templates
{% if templates_by_time|length > 0 -%}
- **{{ templates_by_time[0][0] }}**: {{ templates_by_time[0][1].count|format_number }} instantiations, {{ "%.2f"|format(templates_by_time[0][1].total_dur/1000) }}s total
- **{{ templates_by_time[0][0] }}**: {{ templates_by_time[0][1].count|format_number }} instantiations, {{ (templates_by_time[0][1].total_dur|us_to_s)|round(2) }}s total
{% endif -%}
{% if templates_by_time|length > 1 -%}
- **{{ templates_by_time[1][0] }}**: {{ templates_by_time[1][1].count|format_number }} instantiations, {{ "%.2f"|format(templates_by_time[1][1].avg) }}ms average
- **{{ templates_by_time[1][0] }}**: {{ templates_by_time[1][1].count|format_number }} instantiations, {{ (templates_by_time[1][1].avg|us_to_ms)|round(2) }}ms average
{% endif %}
## Optimization Recommendations
@@ -83,7 +83,7 @@
- **Total Unique Templates:** {{ unique_families }}
- **Total Instantiations:** {{ total_instantiations|format_number }}
{% if total_instantiations > 0 -%}
- **Average Instantiation Time:** {{ "%.3f"|format(total_template_time/total_instantiations) }}ms
- **Average Instantiation Time:** {{ ((total_template_time // total_instantiations)|us_to_ms)|round(3) }}ms
{% endif -%}
{% if unique_families > 0 -%}
- **Median Template Family Count:** {{ median_count }}