From 4b8471b68156d5d70d75424bbc0771d0af5df6af Mon Sep 17 00:00:00 2001 From: Max Podkorytov <4273004+tenpercent@users.noreply.github.com> Date: Wed, 14 Jan 2026 00:04:08 -0600 Subject: [PATCH] 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 --- .claude/skills/analyze_build_trace.py | 25 ++++++++++++------- .../templates/build_analysis_report.md.jinja | 22 ++++++++-------- 2 files changed, 27 insertions(+), 20 deletions(-) diff --git a/.claude/skills/analyze_build_trace.py b/.claude/skills/analyze_build_trace.py index f0f7d7fad3..208e038f22 100755 --- a/.claude/skills/analyze_build_trace.py +++ b/.claude/skills/analyze_build_trace.py @@ -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 diff --git a/.claude/skills/templates/build_analysis_report.md.jinja b/.claude/skills/templates/build_analysis_report.md.jinja index b6c4b2bbf5..37933fe607 100644 --- a/.claude/skills/templates/build_analysis_report.md.jinja +++ b/.claude/skills/templates/build_analysis_report.md.jinja @@ -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 }}