diff --git a/README.md b/README.md index ec68c3a6..6121d5b0 100644 --- a/README.md +++ b/README.md @@ -271,8 +271,8 @@ path. | --- | --- | | `summary` | comparison selection and headline summary | | `files` | per-file wall time and peak RSS estimates | -| `phases` | per-file phase confidence intervals, wall shares, and change contributions | -| `rulesets` | the top 10 changed rulesets per file, including phase deltas | +| `phases` | additive suite and per-file slowdown decomposition | +| `rulesets` | Program/Equality driver groups and changed rulesets per file | The default is `summary`. For example: @@ -325,46 +325,17 @@ Every successful benchmark observation records timing from the same measured process. Timing collection is always enabled; requesting a detailed report does not rerun a diagnostic process or change the cache key. -The engine records these components per ruleset and the JSONL stores their raw -nanosecond totals: - -- Search: matching and join execution. -- Apply: executing rule-head instructions and staging updates. -- Unattributed: measured pre-merge work that cannot be accurately classified - as Search or Apply. -- Merge: resolving and installing staged updates. -- Rebuild: rebuilding indexes and e-graph state. - -The engine measures one contiguous pre-merge interval and records the remainder -after Search and Apply as Unattributed. - -The phase report aggregates all rulesets and keeps two kinds of otherwise -hidden time distinct: - -- Execution overhead is the stored Unattributed component: measured work - inside ruleset execution that cannot be split accurately into Search or - Apply. -- Outside recorded rulesets is derived as process wall time minus Search, - Apply, Execution overhead, Merge, and Rebuild. It includes process setup, - reporting, teardown, and other work outside timed ruleset execution. - -Each file gets its own phase table. For both endpoints, it displays the phase -mean's 95% confidence interval and the phase's share of that endpoint's wall -time. It also displays the signed mean change and that phase's contribution to -the file's total wall-time change. Contributions may be negative or exceed -100% when phases offset each other. A negative Outside recorded rulesets value -is prefixed with `!`; it means recorded phase totals exceed wall time and should -be treated as an attribution warning. - -The ruleset report totals all five stored components for each ruleset, aligns -the union of names across the two endpoints, and ranks by the absolute -candidate-minus-baseline total difference. It omits exact-zero changes and -displays at most 10 rulesets per file. Each row includes the baseline and -candidate total confidence intervals, total change, and descriptive Search, -Apply, Execution overhead, Merge, and Rebuild changes. Timings are aggregated -across the selected observations; iterations are not separate report rows. A -ruleset absent from one endpoint is displayed as `—`, while a measured zero -remains `0 ns`. +The versioned timing summary stores seven fixed process counters, one typed row +per named ruleset with its Program or Equality role and five exclusive own-work +phases, and one global native-Rebuild counter. Parent mechanisms, shares, and +Residual are derived rather than stored; the same canonical per-file breakdown +feeds both the decomposition and ruleset-driver views, so their parent totals +match by construction. + +Checks are charged to the command counters in both modes. One known boundary is +that a rebuild triggered by a top-level action such as `(union ...)` remains in +Commands/Actions. The captions printed next to `--detail phases` and +`--detail rulesets` are the source of truth for grouping and display rules. Benchmarks run single-threaded. This keeps Search and Apply attribution additive for egglog's interleaved executor. @@ -500,9 +471,14 @@ Each observation contains target and workload provenance, exact cache coordinates, status, wall time, peak RSS, and failure details. A top-level report schema version covers both the persisted shape and measurement semantics, so methodology changes cannot silently reuse stale -measurements. Successful observations also contain the version-2 per-ruleset -timing summary: name plus Search, Apply, Unattributed, Merge, and Rebuild -nanoseconds. +measurements. Successful observations also contain the version-4 timing +summary: fixed process counters, a typed list of named ruleset timings, and one +global native-Rebuild counter. Changes to timing coverage or meaning require a +schema-version change so stale measurements cannot be reused silently. +The experimental custom-scheduler API times its backend query and action +invocations as ruleset work; lazy rule compilation and its intermediate update +flush remain surrounding work and are charged to an enclosing command when one +exists. Timed-out rows have null wall time, peak RSS, and timing summary. Failed rows have no timing summary and retain whatever process measurements the operating @@ -513,16 +489,17 @@ This tool is the only supported reader and writer. The codec rejects old report and timing-summary schema versions and requires successful rows to contain timing data. It trusts the tool's typed writer rather than repeating the `TypedDict` as runtime field-by-field validation. A schema change intentionally -invalidates existing caches: move or remove an incompatible report and recompute -it. +invalidates existing caches: move or remove an incompatible report and +recompute it. ### Report-analysis ownership `ComparisonSpec` owns the exact endpoints, files, rounds, and timeout; `store.py` owns physical row order and cache selection. `analysis.py` computes -immutable summary, file, phase, and ruleset rows, while `presentation.py` maps -them to the renderer-neutral catalog. Rich, Markdown, and the interactive page -serialize that catalog without recomputing report facts. +immutable summary and file comparisons plus one canonical timing breakdown per +file. `presentation.py` projects that breakdown into mechanism and ruleset +tables; Rich, Markdown, and the interactive page serialize the catalog without +recomputing report facts. ## Statistics @@ -557,9 +534,9 @@ shown. No median or geometric mean is mixed into this minimal headline. A timed-out, failed, or otherwise incomplete selected result invalidates the suite result that depends on it. Valid per-file tail comparisons remain useful -when an unrelated file is incomplete. Phase endpoint means and ruleset totals -receive confidence intervals; phase contributions and individual ruleset -component deltas are descriptive diagnostics. +when an unrelated file is incomplete. Mechanism contributions and ruleset +totals or component deltas are descriptive diagnostics; only endpoint +estimates and ratios receive confidence intervals. The `<2x` proof goal is established only when the upper bound of the suite wall ratio's 95% confidence interval is below `2x` for a proofs-versus-off diff --git a/benchmarking/reports/analysis.py b/benchmarking/reports/analysis.py index e237d62a..2ca545ee 100644 --- a/benchmarking/reports/analysis.py +++ b/benchmarking/reports/analysis.py @@ -1,8 +1,8 @@ """Compute renderer-neutral statistics for one benchmark endpoint pair. This module selects observations, estimates means and confidence intervals, -computes Fieller ratios, exhaustively attributes wall time, and ranks changed -rulesets. Persistence lives in :mod:`benchmarking.reports.store`; all labels, +computes Fieller ratios, exhaustively attributes wall time, and partitions +ruleset work. Persistence lives in :mod:`benchmarking.reports.store`; all labels, units, and presentation policy live in :mod:`benchmarking.reports.presentation`. """ @@ -11,8 +11,7 @@ import math import statistics from collections.abc import Iterable -from dataclasses import dataclass -from typing import Literal, NamedTuple +from typing import Literal, NamedTuple, cast from scipy import stats @@ -22,15 +21,20 @@ MetricName = Literal["wall_sec", "max_rss_bytes"] ResultClass = Literal["higher", "invalid", "lower", "point_only", "unclear"] SummaryKind = Literal["suite", "lowest_file", "highest_file"] -PhaseName = Literal["search", "apply", "unattributed", "merge", "rebuild", "outside"] -RulesetPhaseName = Literal["search", "apply", "unattributed", "merge", "rebuild"] - +RulesetPhaseName = Literal["assembly", "search", "apply", "execution", "merge", "rebuild"] +RulesetMechanism = Literal["program", "equality"] type _MetricKey = tuple[int, int, MetricName] type _ObservationKey = tuple[int, int] _METRICS: tuple[MetricName, ...] = ("wall_sec", "max_rss_bytes") -_RULESET_PHASES: tuple[RulesetPhaseName, ...] = ("search", "apply", "unattributed", "merge", "rebuild") -_PHASES: tuple[PhaseName, ...] = (*_RULESET_PHASES, "outside") +RULESET_PHASES: tuple[RulesetPhaseName, ...] = ( + "assembly", + "search", + "apply", + "execution", + "merge", + "rebuild", +) class Estimate(NamedTuple): @@ -49,43 +53,19 @@ class RatioEstimate(NamedTuple): issue: str | None -class PhaseEstimate(NamedTuple): - """One phase estimate and its share of endpoint wall time.""" - - timing: Estimate - wall_share: float | None - - class PhaseValues(NamedTuple): - """Five recorded timing components aggregated for one observation/ruleset.""" + """Six recorded timing components aggregated for one observation/ruleset.""" + assembly: float search: float apply: float - unattributed: float + execution: float merge: float rebuild: float @property def total(self) -> float: - return sum(self) - - def phase(self, name: RulesetPhaseName) -> float: - if name == "search": - return self.search - if name == "apply": - return self.apply - if name == "unattributed": - return self.unattributed - if name == "merge": - return self.merge - return self.rebuild - - -class RulesetDelta(NamedTuple): - """One exact total delta and its five timing-component deltas.""" - - total: float - phases: PhaseValues + return math.fsum(self) class SummaryView(NamedTuple): @@ -107,26 +87,52 @@ class FileComparisonView(NamedTuple): ratio: RatioEstimate -class PhaseComparisonView(NamedTuple): - """One exhaustive per-file wall-time phase comparison.""" +class RulesetChange(NamedTuple): + """One named ruleset's own-work phase changes.""" - file_order: int - phase: PhaseName - baseline: PhaseEstimate - candidate: PhaseEstimate - delta_ns: float | None - wall_delta_contribution: float | None + name: str + phases: PhaseValues -class RulesetComparisonView(NamedTuple): - """One top absolute-total-delta ruleset with component deltas.""" +class RulesetGroup(NamedTuple): + """One mechanism's named rulesets and optional global rebuild change.""" - file_order: int - ruleset_count: int - name: str - baseline: Estimate | None - candidate: Estimate | None - delta: RulesetDelta + rulesets: tuple[RulesetChange, ...] + native_rebuild_delta_ns: float = 0.0 + + @property + def phases(self) -> PhaseValues: + values = [math.fsum(ruleset.phases[index] for ruleset in self.rulesets) for index in range(len(RULESET_PHASES))] + values[-1] += self.native_rebuild_delta_ns + return PhaseValues(*values) + + +class FileTimingBreakdown(NamedTuple): + """One canonical additive timing partition consumed by both timing views.""" + + file_order: int | None + wall_delta_ns: float | None + typecheck_delta_ns: float + frontend_delta_ns: float + program: RulesetGroup + equality: RulesetGroup + commands_delta_ns: float + residual_delta_ns: float + residual_warning: bool + issue: str | None + + @property + def mechanism_deltas(self) -> tuple[float | None, ...]: + if self.issue is not None: + return (None,) * 6 + return ( + self.typecheck_delta_ns, + self.frontend_delta_ns, + self.program.phases.total, + self.equality.phases.total, + self.commands_delta_ns, + self.residual_delta_ns, + ) class PairReportViewData(NamedTuple): @@ -134,8 +140,7 @@ class PairReportViewData(NamedTuple): summary: tuple[SummaryView, ...] files: tuple[FileComparisonView, ...] - phases: tuple[PhaseComparisonView, ...] - rulesets: tuple[RulesetComparisonView, ...] + timing: tuple[FileTimingBreakdown, ...] class _MetricEstimate(NamedTuple): @@ -145,30 +150,15 @@ class _MetricEstimate(NamedTuple): issue: str | None -@dataclass -class _RulesetSamples: - """Sparse per-observation samples; omitted observations contribute zero.""" - - total: list[float] - phases: dict[RulesetPhaseName, list[float]] +class _TimingMean(NamedTuple): + """One endpoint/file's direct means from the typed timing record.""" - -@dataclass -class _TimingAggregate: - """One-pass phase and ruleset samples for an endpoint/file selection.""" - - observation_count: int - phases: dict[PhaseName, list[float]] - rulesets: dict[str, _RulesetSamples] - - -class _RankedRuleset(NamedTuple): - """One changed ruleset before the per-file top-ten cutoff.""" - - name: str - baseline: _MetricEstimate | None - candidate: _MetricEstimate | None - delta: RulesetDelta + typecheck_ns: float + frontend_ns: float + commands_ns: float + rulesets: dict[tuple[RulesetMechanism, str], PhaseValues] + native_rebuild_ns: float + residual_ns: float | None def analyze_pair( @@ -186,16 +176,12 @@ def analyze_pair( summary = _summary_rows(comparison, estimates, file_rows, t_critical) if detail == "summary": - return PairReportViewData(summary, (), (), ()) + return PairReportViewData(summary, (), ()) if detail == "files": - return PairReportViewData(summary, file_rows, (), ()) + return PairReportViewData(summary, file_rows, ()) - timing = _timing_aggregates(observations) - phases = _phase_comparisons(comparison, timing, issues, estimates, t_critical) - if detail == "phases": - return PairReportViewData(summary, file_rows, phases, ()) - rulesets = _ruleset_comparisons(comparison, timing, issues, t_critical) - return PairReportViewData(summary, file_rows, phases, rulesets) + timing = _timing_breakdowns(comparison, observations, issues, estimates) + return PairReportViewData(summary, file_rows, timing) def _selected_observations( @@ -267,20 +253,18 @@ def _ratio_estimate( baseline_mean = baseline.estimate.point candidate_mean = candidate.estimate.point issue = baseline.issue or candidate.issue - if issue is None and (baseline_mean is None or candidate_mean is None): - issue = "estimate unavailable" - if issue is None and baseline_mean is not None and baseline_mean <= 0: - issue = "baseline mean is not positive" if issue is not None: return RatioEstimate(Estimate(None, None, None), "invalid", issue) + if baseline_mean is None or candidate_mean is None: + return RatioEstimate(Estimate(None, None, None), "invalid", "estimate unavailable") + if baseline_mean <= 0: + return RatioEstimate(Estimate(None, None, None), "invalid", "baseline mean is not positive") - assert baseline_mean is not None and candidate_mean is not None point = candidate_mean / baseline_mean if min(baseline.sample_count, candidate.sample_count) < 2: return RatioEstimate(Estimate(point, None, None), "point_only", "CI undefined for n < 2") - assert baseline.var_mean is not None - assert candidate.var_mean is not None - assert t_critical is not None + if baseline.var_mean is None or candidate.var_mean is None or t_critical is None: + raise ValueError("multi-sample ratio is missing variance or its t critical value") critical_squared = t_critical * t_critical fieller_a = baseline_mean * baseline_mean - critical_squared * baseline.var_mean fieller_d = candidate_mean * candidate_mean - critical_squared * candidate.var_mean @@ -370,189 +354,154 @@ def _summary_rows( return tuple(rows) -def _phase_comparisons( +def _timing_breakdowns( comparison: ComparisonSpec, - timing: dict[_ObservationKey, _TimingAggregate], + observations: dict[_ObservationKey, tuple[IndexedRecord, ...]], issues: dict[_ObservationKey, str | None], metric_estimates: dict[_MetricKey, _MetricEstimate], - t_critical: float | None, -) -> tuple[PhaseComparisonView, ...]: - estimates: dict[tuple[int, int, PhaseName], _MetricEstimate] = {} - for (endpoint_order, file_order), aggregate in timing.items(): - for phase in _PHASES: - issue = issues[(endpoint_order, file_order)] - if phase == "outside" and issue is None: - issue = metric_estimates[(endpoint_order, file_order, "wall_sec")].issue - estimates[(endpoint_order, file_order, phase)] = _sample_estimate( - aggregate.phases[phase], - issue, - t_critical, - ) - - result: list[PhaseComparisonView] = [] +) -> tuple[FileTimingBreakdown, ...]: + means = _timing_means(observations, metric_estimates) + files: list[FileTimingBreakdown] = [] for file_order in range(len(comparison.files)): - baseline_wall = metric_estimates[(0, file_order, "wall_sec")].estimate.point - candidate_wall = metric_estimates[(1, file_order, "wall_sec")].estimate.point + baseline = means[(0, file_order)] + candidate = means[(1, file_order)] + baseline_wall = metric_estimates[(0, file_order, "wall_sec")] + candidate_wall = metric_estimates[(1, file_order, "wall_sec")] + issue = issues[(0, file_order)] or issues[(1, file_order)] or baseline_wall.issue or candidate_wall.issue wall_delta_ns = ( None - if baseline_wall is None or candidate_wall is None - else (candidate_wall - baseline_wall) * 1_000_000_000.0 + if issue is not None or baseline_wall.estimate.point is None or candidate_wall.estimate.point is None + else (candidate_wall.estimate.point - baseline_wall.estimate.point) * 1_000_000_000.0 ) - for phase in _PHASES: - baseline = estimates[(0, file_order, phase)] - candidate = estimates[(1, file_order, phase)] - baseline_point = baseline.estimate.point - candidate_point = candidate.estimate.point - delta = None if baseline_point is None or candidate_point is None else candidate_point - baseline_point - result.append( - PhaseComparisonView( - file_order, - phase, - PhaseEstimate( - baseline.estimate, - _share(baseline_point, baseline_wall, scale=1_000_000_000.0), - ), - PhaseEstimate( - candidate.estimate, - _share(candidate_point, candidate_wall, scale=1_000_000_000.0), - ), - delta, - _share(delta, wall_delta_ns), - ) + residual_delta_ns = ( + 0.0 + if baseline.residual_ns is None or candidate.residual_ns is None + else candidate.residual_ns - baseline.residual_ns + ) + files.append( + FileTimingBreakdown( + file_order, + wall_delta_ns, + candidate.typecheck_ns - baseline.typecheck_ns, + candidate.frontend_ns - baseline.frontend_ns, + _ruleset_group_delta(baseline, candidate, "program"), + _ruleset_group_delta(baseline, candidate, "equality"), + candidate.commands_ns - baseline.commands_ns, + residual_delta_ns, + (baseline.residual_ns is not None and baseline.residual_ns < 0) + or (candidate.residual_ns is not None and candidate.residual_ns < 0), + issue, ) - return tuple(result) + ) + + suite_issue = next((row.issue for row in files if row.issue is not None), None) + suite = FileTimingBreakdown( + None, + None if suite_issue is not None else math.fsum(cast(float, row.wall_delta_ns) for row in files), + math.fsum(row.typecheck_delta_ns for row in files), + math.fsum(row.frontend_delta_ns for row in files), + _sum_ruleset_groups(row.program for row in files), + _sum_ruleset_groups(row.equality for row in files), + math.fsum(row.commands_delta_ns for row in files), + math.fsum(row.residual_delta_ns for row in files), + any(row.residual_warning for row in files), + suite_issue, + ) + return (suite, *files) -def _timing_aggregates( +def _timing_means( observations: dict[_ObservationKey, tuple[IndexedRecord, ...]], -) -> dict[_ObservationKey, _TimingAggregate]: - result: dict[_ObservationKey, _TimingAggregate] = {} + metric_estimates: dict[_MetricKey, _MetricEstimate], +) -> dict[_ObservationKey, _TimingMean]: + result: dict[_ObservationKey, _TimingMean] = {} for key, rows in observations.items(): - aggregate = _TimingAggregate( - len(rows), - {phase: [] for phase in _PHASES}, - {}, - ) + typecheck = 0.0 + frontend = 0.0 + commands = 0.0 + native_rebuild = 0.0 + rulesets: dict[tuple[RulesetMechanism, str], list[float]] = {} for row in rows: record = row.record if record["status"] != "success": continue summary = record["timing_summary"] - assert summary is not None - per_ruleset: dict[str, PhaseValues] = {} - for ruleset in summary["rulesets"]: - totals = PhaseValues( - float(ruleset["search_ns"]), - float(ruleset["apply_ns"]), - float(ruleset["unattributed_ns"]), - float(ruleset["merge_ns"]), - float(ruleset["rebuild_ns"]), - ) - per_ruleset[ruleset["name"]] = _add_totals(per_ruleset.get(ruleset["name"], _ZERO_PHASE_TOTALS), totals) - recorded = _sum_totals(per_ruleset.values()) - for phase in _RULESET_PHASES: - aggregate.phases[phase].append(recorded.phase(phase)) - wall_sec = record["wall_sec"] - if wall_sec is not None: - aggregate.phases["outside"].append(wall_sec * 1_000_000_000.0 - recorded.total) - for name, totals in per_ruleset.items(): - samples = aggregate.rulesets.setdefault( - name, - _RulesetSamples([], {phase: [] for phase in _RULESET_PHASES}), - ) - samples.total.append(totals.total) - for phase in _RULESET_PHASES: - samples.phases[phase].append(totals.phase(phase)) - result[key] = aggregate + if summary is None: + raise ValueError("successful benchmark record is missing its timing summary") + typecheck += summary["typecheck_ns"] + frontend += summary["frontend_parse_ns"] + summary["frontend_other_ns"] + summary["frontend_install_ns"] + commands += summary["commands_actions_ns"] + summary["commands_check_ns"] + summary["commands_other_ns"] + native_rebuild += summary["native_rebuild_ns"] + for timing in summary["rulesets"]: + phase_sums = rulesets.setdefault((timing["role"], timing["name"]), [0.0] * 6) + phase_sums[0] += timing["assembly_ns"] + phase_sums[1] += timing["search_ns"] + phase_sums[2] += timing["apply_ns"] + phase_sums[3] += timing["execution_ns"] + phase_sums[4] += timing["merge_ns"] + + denominator = len(rows) or 1 + ruleset_means = { + key: PhaseValues(*(value / denominator for value in values)) for key, values in rulesets.items() + } + typecheck /= denominator + frontend /= denominator + commands /= denominator + native_rebuild /= denominator + recorded = ( + typecheck + + frontend + + commands + + native_rebuild + + math.fsum(phases.total for phases in ruleset_means.values()) + ) + wall = metric_estimates[(key[0], key[1], "wall_sec")].estimate.point + result[key] = _TimingMean( + typecheck, + frontend, + commands, + ruleset_means, + native_rebuild, + None if wall is None else wall * 1_000_000_000.0 - recorded, + ) return result -_ZERO_PHASE_TOTALS = PhaseValues(0.0, 0.0, 0.0, 0.0, 0.0) - - -def _add_totals(left: PhaseValues, right: PhaseValues) -> PhaseValues: - return PhaseValues( - left.search + right.search, - left.apply + right.apply, - left.unattributed + right.unattributed, - left.merge + right.merge, - left.rebuild + right.rebuild, +def _ruleset_group_delta( + baseline: _TimingMean, + candidate: _TimingMean, + mechanism: RulesetMechanism, +) -> RulesetGroup: + names = sorted({name for role, name in baseline.rulesets.keys() | candidate.rulesets.keys() if role == mechanism}) + zero = PhaseValues(0.0, 0.0, 0.0, 0.0, 0.0, 0.0) + rulesets = [] + for name in names: + baseline_phases = baseline.rulesets.get((mechanism, name), zero) + candidate_phases = candidate.rulesets.get((mechanism, name), zero) + phases = PhaseValues( + *(candidate_phases[index] - baseline_phases[index] for index in range(len(RULESET_PHASES))) + ) + if any(phases): + rulesets.append(RulesetChange(name, phases)) + rebuild = candidate.native_rebuild_ns - baseline.native_rebuild_ns if mechanism == "equality" else 0.0 + return RulesetGroup(tuple(rulesets), rebuild) + + +def _sum_ruleset_groups(groups: Iterable[RulesetGroup]) -> RulesetGroup: + """Combine file-level ruleset groups while preserving named phase totals.""" + + phase_sums: dict[str, list[float]] = {} + native_rebuild = 0.0 + for group in groups: + native_rebuild += group.native_rebuild_delta_ns + for ruleset in group.rulesets: + values = phase_sums.setdefault(ruleset.name, [0.0] * len(RULESET_PHASES)) + for index, value in enumerate(ruleset.phases): + values[index] += value + rulesets = tuple( + RulesetChange(name, PhaseValues(*values)) for name, values in sorted(phase_sums.items()) if any(values) ) - - -def _sum_totals(values: Iterable[PhaseValues]) -> PhaseValues: - result = _ZERO_PHASE_TOTALS - for value in values: - result = _add_totals(result, value) - return result - - -def _ruleset_comparisons( - comparison: ComparisonSpec, - timing: dict[_ObservationKey, _TimingAggregate], - issues: dict[_ObservationKey, str | None], - t_critical: float | None, -) -> tuple[RulesetComparisonView, ...]: - result: list[RulesetComparisonView] = [] - for file_order in range(len(comparison.files)): - if issues[(0, file_order)] is not None or issues[(1, file_order)] is not None: - continue - names = sorted({name for endpoint_order in (0, 1) for name in timing[(endpoint_order, file_order)].rulesets}) - comparisons: list[_RankedRuleset] = [] - for name in names: - baseline = _ruleset_estimate(timing[(0, file_order)], name, None, t_critical) - candidate = _ruleset_estimate(timing[(1, file_order)], name, None, t_critical) - total_delta = _estimate_point(candidate) - _estimate_point(baseline) - if total_delta == 0.0: - continue - delta = RulesetDelta(total_delta, _ruleset_phase_deltas(timing, file_order, name, t_critical)) - comparisons.append(_RankedRuleset(name, baseline, candidate, delta)) - comparisons.sort(key=lambda row: (-abs(row.delta.total), row.name)) - count = len(comparisons) - for row in comparisons[:10]: - result.append( - RulesetComparisonView( - file_order, - count, - row.name, - None if row.baseline is None else row.baseline.estimate, - None if row.candidate is None else row.candidate.estimate, - row.delta, - ) - ) - return tuple(result) - - -def _ruleset_estimate( - aggregate: _TimingAggregate, - name: str, - phase: RulesetPhaseName | None, - t_critical: float | None, -) -> _MetricEstimate | None: - samples = aggregate.rulesets.get(name) - if samples is None: - return None - observed = samples.total if phase is None else samples.phases[phase] - values = [*observed, *(0.0 for _ in range(aggregate.observation_count - len(observed)))] - return _sample_estimate(values, None, t_critical) - - -def _estimate_point(estimate: _MetricEstimate | None) -> float: - return 0.0 if estimate is None or estimate.estimate.point is None else estimate.estimate.point - - -def _ruleset_phase_deltas( - timing: dict[_ObservationKey, _TimingAggregate], - file_order: int, - name: str, - t_critical: float | None, -) -> PhaseValues: - def delta(phase: RulesetPhaseName) -> float: - candidate = _ruleset_estimate(timing[(1, file_order)], name, phase, t_critical) - baseline = _ruleset_estimate(timing[(0, file_order)], name, phase, t_critical) - return _estimate_point(candidate) - _estimate_point(baseline) - - return PhaseValues(delta("search"), delta("apply"), delta("unattributed"), delta("merge"), delta("rebuild")) + return RulesetGroup(rulesets, native_rebuild) def _sample_estimate( @@ -566,14 +515,9 @@ def _sample_estimate( ci_high: float | None = None if mean is not None and len(values) >= 2: var_mean = statistics.variance(values) / len(values) - assert t_critical is not None + if t_critical is None: + raise ValueError("multi-sample estimate is missing its t critical value") half_width = t_critical * math.sqrt(var_mean) ci_low = mean - half_width ci_high = mean + half_width return _MetricEstimate(len(values), Estimate(mean, ci_low, ci_high), var_mean, issue) - - -def _share(numerator: float | None, denominator: float | None, *, scale: float = 1.0) -> float | None: - if numerator is None or denominator is None or denominator == 0: - return None - return numerator / (denominator * scale) diff --git a/benchmarking/reports/catalog.py b/benchmarking/reports/catalog.py index 1b095759..3a824008 100644 --- a/benchmarking/reports/catalog.py +++ b/benchmarking/reports/catalog.py @@ -14,7 +14,7 @@ type ReportScalar = str | int | float | bool | None TableAlignment = Literal["left", "right"] -CellTone = Literal["default", "positive", "negative", "warning", "error", "muted"] +CellTone = Literal["default", "positive", "emphasis", "warning", "error", "muted"] @dataclass(frozen=True) diff --git a/benchmarking/reports/interactive_runtime.py b/benchmarking/reports/interactive_runtime.py index 66fd2547..d5db90d3 100644 --- a/benchmarking/reports/interactive_runtime.py +++ b/benchmarking/reports/interactive_runtime.py @@ -429,8 +429,8 @@ def _primitive_display(value: JsonScalar) -> str: def _tone_style(tone: CellTone) -> dict[str, JsonValue]: if tone == "positive": return {"color": "green"} - if tone == "negative": - return {"color": "red"} + if tone == "emphasis": + return {"bold": True} if tone == "warning": return {"color": "yellow"} if tone == "error": diff --git a/benchmarking/reports/presentation.py b/benchmarking/reports/presentation.py index d4882f55..e36a7fd1 100644 --- a/benchmarking/reports/presentation.py +++ b/benchmarking/reports/presentation.py @@ -1,7 +1,7 @@ """Build the canonical benchmark presentation and format its values. This module maps typed statistics from :mod:`benchmarking.reports.analysis` -into Comparison, Summary, Files, Phases, and Rulesets sections. It owns shared +into Comparison, Summary, Files, Mechanisms, and Rulesets sections. It owns shared labels, units, interval formatting, and result wording; Rich and Markdown only serialize the resulting catalog. """ @@ -15,16 +15,15 @@ from ..engines import TREATMENT_SPECS from ..models import BenchmarkEndpoint, ComparisonSpec, DetailLevel, FileSpec from .analysis import ( + RULESET_PHASES, Estimate, FileComparisonView, + FileTimingBreakdown, MetricName, - PairReportViewData, - PhaseComparisonView, - PhaseEstimate, - PhaseName, + PhaseValues, RatioEstimate, ResultClass, - RulesetComparisonView, + RulesetGroup, SummaryView, analyze_pair, ) @@ -46,34 +45,42 @@ NULL = "—" DEFAULT_RULESET = "" +RULESET_CONTRIBUTOR_LIMIT = 5 DETAIL_ORDER: dict[DetailLevel, int] = { "summary": 0, "files": 1, "phases": 2, "rulesets": 3, } +RESULT_TONES: dict[ResultClass, CellTone] = { + "higher": "default", + "invalid": "error", + "lower": "positive", + "point_only": "muted", + "unclear": "muted", +} RATIO_DIRECTION = "Ratios are candidate / baseline; below 1 is lower and above 1 is higher." -PHASE_CAPTION = ( - "Endpoint cells show a 95% CI (or one-round point) and that phase's share of endpoint wall time. " - "Delta is the signed candidate − baseline mean; Δ contribution is the phase's share of the wall-time " - "change and may be negative or exceed 100% when phases offset. Execution overhead is stored per-ruleset " - "unattributed time. Outside recorded rulesets is wall time minus all five recorded phases; ! marks a negative " - "residual." +DECOMPOSITION_CAPTION = ( + "The Suite total row sums each selected file's candidate − baseline mean; file rows are per-file mean deltas. " + "Each mechanism cell is its share of that row's wall-time change followed by its signed mean time change. " + "Frontend includes parsing, other lowering, and declaration/install commands. Program rules includes every " + "phase of source-origin rulesets except rebuild. Equality/rebuild combines encoded maintenance rulesets with " + "native rebuild tails. Commands includes actions/input, checks, and other schedules. Shares may be negative or " + "exceed 100% when mechanisms offset. ◆ and bold type mark each row's largest absolute share; contributions below " + "5% are dimmed and improvements are green in Rich and interactive reports. Signed values carry the same " + "information without styling. Residual is wall time minus every recorded leaf; ! means an endpoint's mean " + "residual is negative." ) RULESET_CAPTION = ( - "Totals show a 95% CI or one-round point. S/A/Exec/M/R are signed candidate − baseline mean deltas for " - "Search, Apply, Execution overhead (stored unattributed time), Merge, and Rebuild." + "Each panel unfolds the Program and Equality cells from the decomposition. Parent rows exactly match those " + "cells and alone show wall share. Program children contain only source-rule Assembly, Search, Apply, Execution, " + "and Merge; Equality children contain every encoded maintenance ruleset plus one global Native rebuild replaced " + "row. ↳ marks children in every format. Zero children are hidden. Source children are ranked by absolute own-work " + f"Δ (top {RULESET_CONTRIBUTOR_LIMIT} plus an exact per-group Other); every nonzero maintenance child is shown. " + "Important phases include every |phase Δ| ≥ max(1 ms, 10% of |row Δ|), always include the dominant phase (◆), " + "and appear in Assembly, Search, Apply, Execution, Merge, Rebuild order; … marks omitted nonzero phases." ) -PHASE_LABELS: dict[PhaseName, str] = { - "search": "Search", - "apply": "Apply", - "unattributed": "Execution overhead", - "merge": "Merge", - "rebuild": "Rebuild", - "outside": "Outside recorded rulesets", -} - def build_report_catalog( store: ReportStore, @@ -92,9 +99,9 @@ def build_report_catalog( if _includes(detail, "files"): sections.append(_files_section(views.files, comparison, file_labels)) if _includes(detail, "phases"): - sections.append(_phases_section(views.phases, comparison, file_labels)) + sections.append(_phases_section(views.timing, comparison, file_labels)) if _includes(detail, "rulesets"): - sections.append(_rulesets_section(views, comparison, file_labels)) + sections.append(_rulesets_section(views.timing, comparison, file_labels)) return ReportCatalog(tuple(sections)) @@ -318,63 +325,127 @@ def _files_section( def _phases_section( - rows: Sequence[PhaseComparisonView], + rows: Sequence[FileTimingBreakdown], comparison: ComparisonSpec, file_labels: dict[FileSpec, str], ) -> ReportSection: - by_file: dict[int, list[PhaseComparisonView]] = {} + report_rows = [] for row in rows: - by_file.setdefault(row.file_order, []).append(row) - blocks: list[ReportBlock] = [ - ReportMessage(report_id("message", "phases", "guide"), None, PHASE_CAPTION, tone="muted") - ] - for file_order, file in enumerate(comparison.files): - blocks.append( - _table( - report_id("table", "phases", file.sha256, file.fact_directory_sha256), - f"Phase comparison — {file_labels[file]}", - ("phase", "baseline", "candidate", "delta", "wall_delta"), - ("Phase", "Baseline (95% CI · wall)", "Candidate (95% CI · wall)", "Delta", "Δ contribution"), - tuple(_phase_row(row, file) for row in by_file[file_order]), - alignments=("left", "right", "right", "right", "right"), + if row.file_order is None: + row_id = report_id("row", "phases", "suite") + file_count = len(comparison.files) + label = f"Suite total ({file_count} {'file' if file_count == 1 else 'files'})" + else: + file = comparison.files[row.file_order] + row_id = report_id("row", "phases", file.sha256, file.fact_directory_sha256) + label = file_labels[file] + deltas = row.mechanism_deltas + wall_delta = row.wall_delta_ns + shares = tuple( + None if delta is None or wall_delta is None or wall_delta == 0 else delta / wall_delta for delta in deltas + ) + comparable = [index for index, share in enumerate(shares) if share is not None] + leader = max(comparable, key=lambda index: abs(shares[index] or 0.0), default=None) + if leader is not None and shares[leader] == 0.0: + leader = None + mechanism_cells = tuple( + _slowdown_cell( + delta, + shares[index], + leader=index == leader, + warning=row.residual_warning and index == len(deltas) - 1, ) + for index, delta in enumerate(deltas) ) - return ReportSection("phases", "Phase comparison", tuple(blocks)) + report_rows.append( + _row( + row_id, + text_cell(row.file_order, label), + text_cell( + row.wall_delta_ns, + _format_delta_ms(row.wall_delta_ns), + tone=_delta_tone(row.wall_delta_ns), + ), + *mechanism_cells, + ) + ) + table = _table( + report_id("table", "phases", "decomposition"), + "Slowdown decomposition", + ("file", "wall_delta", "typecheck", "frontend", "program", "equality", "commands", "residual"), + ( + "File", + "Wall Δ", + "Typecheck", + "Frontend", + "Program", + "Equality", + "Commands", + "Residual", + ), + tuple(report_rows), + caption=DECOMPOSITION_CAPTION, + alignments=("left", "right", "right", "right", "right", "right", "right", "right"), + ) + return ReportSection("phases", "Slowdown decomposition", (table,)) -def _phase_row(row: PhaseComparisonView, file: FileSpec) -> ReportRow: - return _row( - report_id("row", "phases", file.sha256, file.fact_directory_sha256, row.phase), - text_cell(row.phase, PHASE_LABELS[row.phase]), - _phase_estimate_cell(row.baseline, attribution=row.phase == "outside"), - _phase_estimate_cell(row.candidate, attribution=row.phase == "outside"), - text_cell(row.delta_ns, format_duration(row.delta_ns, signed=True)), - text_cell(row.wall_delta_contribution, _format_percent(row.wall_delta_contribution, signed=True)), +def _slowdown_cell( + delta_ns: float | None, + slowdown_share: float | None, + *, + leader: bool, + warning: bool, +) -> ReportCell: + duration = _format_delta_ms(delta_ns) + share = _format_percent(slowdown_share, signed=True) + marker = "◆ " if leader else "" + display = NULL if delta_ns is None else f"{marker}{share} {duration}" + if warning: + display = f"!{display}" + return text_cell( + slowdown_share, + display, + tone=_delta_tone(delta_ns, share=slowdown_share, emphasis=leader, warning=warning), ) +def _delta_tone( + delta_ns: float | None, + *, + share: float | None = None, + emphasis: bool = False, + warning: bool = False, +) -> CellTone: + """Apply the report's anomaly-first styling policy to one signed delta.""" + + if warning: + return "warning" + if emphasis: + return "emphasis" + if share is not None and abs(share) < 0.05: + return "muted" + if delta_ns is not None and delta_ns < 0: + return "positive" + if delta_ns == 0: + return "muted" + return "default" + + def _rulesets_section( - views: PairReportViewData, + timing: Sequence[FileTimingBreakdown], comparison: ComparisonSpec, file_labels: dict[FileSpec, str], ) -> ReportSection: - by_file: dict[int, list[RulesetComparisonView]] = {} - for row in views.rulesets: - by_file.setdefault(row.file_order, []).append(row) - file_issues = { - row.file_order: row.ratio.issue - for row in views.files - if row.metric == "wall_sec" and row.ratio.issue is not None - } - blocks: list[ReportBlock] = [] - if views.rulesets: - blocks.append(ReportMessage(report_id("message", "rulesets", "guide"), None, RULESET_CAPTION, tone="muted")) + by_file = {row.file_order: row for row in timing if row.file_order is not None} + blocks: list[ReportBlock] = [ + ReportMessage(report_id("message", "rulesets", "guide"), None, RULESET_CAPTION, tone="muted") + ] for file_order, file in enumerate(comparison.files): - title = f"Ruleset comparison — {file_labels[file]}" - rulesets = by_file.get(file_order, []) - if not rulesets: - issue = file_issues.get(file_order) - status = f"Status: {issue}" if issue is not None else "No nonzero ruleset timing differences." + title = f"Ruleset drivers — {file_labels[file]}" + breakdown = by_file.get(file_order) + if breakdown is None or breakdown.issue is not None: + status = f"Status: {breakdown.issue}" if breakdown is not None else "Timing unavailable." blocks.append( ReportMessage( report_id("message", "rulesets", file.sha256, file.fact_directory_sha256), @@ -383,47 +454,172 @@ def _rulesets_section( ) ) continue - count = rulesets[0].ruleset_count - caption = None if count <= 10 else f"Showing 10 of {count} changed rulesets by absolute total delta." + program = sorted(breakdown.program.rulesets, key=lambda row: (-abs(row.phases.total), row.name)) + maintenance = sorted(breakdown.equality.rulesets, key=lambda row: (-abs(row.phases.total), row.name)) + wall_delta = breakdown.wall_delta_ns + coverage = ( + None + if wall_delta is None or wall_delta == 0 + else (breakdown.program.phases.total + breakdown.equality.phases.total) / wall_delta + ) + coverage_text = ( + "Program + Equality coverage is unavailable because wall time did not change." + if coverage is None + else ( + f"Program + Equality account for {_format_percent(coverage, signed=True)} " + "of this file's wall-time change." + ) + ) + source_count = len(program) + source_shown = min(source_count, RULESET_CONTRIBUTOR_LIMIT) + source_text = f"Source rules shown: {source_shown}/{source_count}" + source_text += " plus exact Other." if source_count > source_shown else "." + maintenance_count = len(maintenance) + maintenance_text = ( + "Maintenance rules shown: none." + if maintenance_count == 0 + else f"Maintenance rules shown: {maintenance_count}/{maintenance_count}." + ) + caption = f"{coverage_text} {source_text} {maintenance_text}" + report_rows = [ + _ruleset_report_row( + file, + "aggregate", + "program", + "", + source_count, + breakdown.program.phases, + breakdown.wall_delta_ns, + ) + ] + report_rows.extend( + _ruleset_report_row( + file, + "ruleset", + "program", + ruleset.name, + 1, + ruleset.phases, + breakdown.wall_delta_ns, + ) + for ruleset in program[:RULESET_CONTRIBUTOR_LIMIT] + ) + if len(program) > RULESET_CONTRIBUTOR_LIMIT: + omitted = tuple(program[RULESET_CONTRIBUTOR_LIMIT:]) + report_rows.append( + _ruleset_report_row( + file, + "other", + "program", + "", + len(omitted), + RulesetGroup(omitted).phases, + breakdown.wall_delta_ns, + ) + ) + report_rows.append( + _ruleset_report_row( + file, + "aggregate", + "equality", + "", + maintenance_count, + breakdown.equality.phases, + breakdown.wall_delta_ns, + ) + ) + report_rows.extend( + _ruleset_report_row( + file, + "ruleset", + "equality", + ruleset.name, + 1, + ruleset.phases, + breakdown.wall_delta_ns, + ) + for ruleset in maintenance + ) + if breakdown.equality.native_rebuild_delta_ns != 0: + report_rows.append( + _ruleset_report_row( + file, + "native_rebuild", + "equality", + "", + 0, + PhaseValues(0, 0, 0, 0, 0, breakdown.equality.native_rebuild_delta_ns), + breakdown.wall_delta_ns, + ) + ) blocks.append( _table( report_id("table", "rulesets", file.sha256, file.fact_directory_sha256), title, - ( - "ruleset", - "baseline", - "candidate", - "delta", - "search_delta", - "apply_delta", - "execution_delta", - "merge_delta", - "rebuild_delta", - ), - ("Ruleset", "Baseline total", "Candidate total", "Total Δ", "S Δ", "A Δ", "Exec Δ", "M Δ", "R Δ"), - tuple( - _row( - report_id("row", "rulesets", file.sha256, file.fact_directory_sha256, row.name), - text_cell(row.name, DEFAULT_RULESET if row.name == "" else row.name), - _duration_estimate_cell(row.baseline), - _duration_estimate_cell(row.candidate), - text_cell(row.delta.total, format_duration(row.delta.total, signed=True)), - text_cell(row.delta.phases.search, format_duration(row.delta.phases.search, signed=True)), - text_cell(row.delta.phases.apply, format_duration(row.delta.phases.apply, signed=True)), - text_cell( - row.delta.phases.unattributed, - format_duration(row.delta.phases.unattributed, signed=True), - ), - text_cell(row.delta.phases.merge, format_duration(row.delta.phases.merge, signed=True)), - text_cell(row.delta.phases.rebuild, format_duration(row.delta.phases.rebuild, signed=True)), - ) - for row in rulesets - ), + ("driver", "delta", "share", "important_phases"), + ("Driver", "Δ", "Wall share", "Important phase changes"), + tuple(report_rows), caption=caption, - alignments=("left", "right", "right", "right", "right", "right", "right", "right", "right"), + alignments=("left", "right", "right", "left"), ) ) - return ReportSection("rulesets", "Ruleset comparison", tuple(blocks)) + return ReportSection("rulesets", "Ruleset drivers", tuple(blocks)) + + +def _ruleset_report_row( + file: FileSpec, + kind: str, + mechanism: str, + name: str, + ruleset_count: int, + phases: PhaseValues, + wall_delta: float | None, +) -> ReportRow: + parent = kind == "aggregate" + share = None if not parent or wall_delta is None or wall_delta == 0 else phases.total / wall_delta + tone = _delta_tone(phases.total, share=share) + if kind == "aggregate": + label = "Program rules — own work" if mechanism == "program" else "Equality/rebuild — net" + elif kind == "native_rebuild": + label = "↳ Native rebuild replaced" + elif kind == "other": + label = f"↳ Other ({ruleset_count} more source rulesets)" + else: + label = f"↳ {DEFAULT_RULESET if name == '' else name}" + return _row( + report_id( + "row", + "rulesets", + file.sha256, + file.fact_directory_sha256, + kind, + mechanism, + name, + ), + text_cell(name, label, tone="emphasis" if parent else "default"), + text_cell(phases.total, format_duration(phases.total, signed=True), tone=tone), + text_cell(share, _format_percent(share, signed=True) if parent else "", tone=tone), + text_cell(_important_phase_changes(phases), tone=tone), + ) + + +def _important_phase_changes(phases: PhaseValues) -> str: + changed = [index for index, value in enumerate(phases) if value != 0] + if not changed: + return "0 ns" + dominant = max(changed, key=lambda index: abs(phases[index])) + threshold = max(1_000_000.0, abs(phases.total) * 0.1) + included = {index for index in changed if abs(phases[index]) >= threshold} + included.add(dominant) + parts = [ + f"{'◆ ' if index == dominant else ''}{RULESET_PHASES[index].title()} " + f"{format_duration(phases[index], signed=True)}" + for index in range(len(RULESET_PHASES)) + if index in included + ] + if any(index not in included for index in changed): + parts.append("…") + return "; ".join(parts) def report_file_labels(files: Sequence[FileSpec]) -> dict[FileSpec, str]: @@ -469,32 +665,33 @@ def report_file_labels(files: Sequence[FileSpec]) -> dict[FileSpec, str]: def format_duration( value_ns: float | None, *, - attribution: bool = False, signed: bool = False, ) -> str: """Format nanoseconds with three significant digits and a local unit.""" if value_ns is None: return NULL - prefix = "!" if attribution and value_ns < 0 else "" divisor, unit = _duration_unit(abs(value_ns)) - return f"{prefix}{_format_scaled(value_ns / divisor, signed=signed)} {unit}" + return f"{_format_scaled(value_ns / divisor, signed=signed)} {unit}" + + +def _format_delta_ms(value_ns: float | None) -> str: + if value_ns is None: + return NULL + return f"{_format_scaled(value_ns / 1_000_000.0, signed=True)} ms" def _format_duration_interval( point_ns: float | None, low_ns: float | None, high_ns: float | None, - *, - attribution: bool = False, ) -> str: if point_ns is None: return NULL if low_ns is None or high_ns is None: - return format_duration(point_ns, attribution=attribution) + return format_duration(point_ns) divisor, unit = _duration_unit(max(abs(point_ns), abs(low_ns), abs(high_ns))) - prefix = "!" if attribution and point_ns < 0 else "" - return f"{prefix}{_format_scaled(low_ns / divisor)}–{_format_scaled(high_ns / divisor)} {unit}" + return f"{_format_scaled(low_ns / divisor)}–{_format_scaled(high_ns / divisor)} {unit}" def _duration_unit(magnitude_ns: float) -> tuple[float, str]: @@ -543,27 +740,9 @@ def _estimate_cell( return text_cell(point, display) -def _duration_estimate_cell(estimate: Estimate | None) -> ReportCell: - if estimate is None: - return text_cell(None, NULL) - return text_cell(estimate.point, _format_duration_interval(*estimate)) - - -def _phase_estimate_cell( - phase: PhaseEstimate, - *, - attribution: bool, -) -> ReportCell: - duration = _format_duration_interval(*phase.timing, attribution=attribution) - display = duration if phase.wall_share is None else f"{duration} · {_format_percent(phase.wall_share)}" - point = phase.timing.point - tone: CellTone = "warning" if attribution and point is not None and point < 0 else "default" - return text_cell(point, display, tone=tone) - - def _ratio_cell(ratio: RatioEstimate) -> ReportCell: # Retain the point for sorting/filtering while keeping the visible CI cell compact. - return text_cell(ratio.estimate.point, format_ratio_summary(ratio)) + return text_cell(ratio.estimate.point, format_ratio_summary(ratio), tone=RESULT_TONES[ratio.result_class]) def format_ratio_summary(ratio: RatioEstimate) -> str: @@ -628,14 +807,7 @@ def _result_cell(result_class: ResultClass, issue: str | None, *, rss: bool) -> text = "CI includes 1" else: raise AssertionError(f"unknown result class: {result_class}") - tones: dict[ResultClass, CellTone] = { - "higher": "negative", - "invalid": "error", - "lower": "positive", - "point_only": "muted", - "unclear": "warning", - } - return text_cell(result_class, text, tone=tones[result_class]) + return text_cell(result_class, text, tone=RESULT_TONES[result_class]) def _table( diff --git a/benchmarking/reports/render.py b/benchmarking/reports/render.py index 635b174a..ec30fce0 100644 --- a/benchmarking/reports/render.py +++ b/benchmarking/reports/render.py @@ -9,6 +9,7 @@ from __future__ import annotations from rich import box +from rich.cells import cell_len from rich.console import Group, RenderableType from rich.rule import Rule from rich.table import Table @@ -17,6 +18,7 @@ from .catalog import CellTone, ReportCatalog, ReportMessage, ReportSection, ReportTable RICH_DETAIL_MIN_WIDTH = 120 +RICH_TEXT_COLUMN_MIN_WIDTH = 12 RICH_DETAIL_NARROW_WARNING = ( "Warning: detailed Rich report output is designed for terminals at least 120 columns wide " "(detected {width}); output may wrap. Widen the terminal or use --format markdown." @@ -28,19 +30,24 @@ TONE_STYLES: dict[CellTone, str] = { "default": "", "positive": "green", - "negative": "red", + "emphasis": "bold", "warning": "yellow", "error": "bold red", "muted": "dim", } -def report_table(title: str | None, *, caption: str | None = None) -> Table: - """Create one consistently styled Rich report table.""" +def render_rich_table( + table_data: ReportTable, + *, + show_title: bool = True, + preferred_widths: tuple[int, ...] | None = None, +) -> Table: + """Render one catalog table without interpreting its display strings.""" - return Table( - title=None if title is None else Text(title, style="bold"), - caption=None if caption is None else Text(caption, style="dim"), + table = Table( + title=Text(table_data.title, style="bold") if show_title else None, + caption=None if table_data.caption is None else Text(table_data.caption, style="dim"), caption_justify="left", header_style="bold", box=box.SIMPLE_HEAVY, @@ -48,17 +55,31 @@ def report_table(title: str | None, *, caption: str | None = None) -> Table: collapse_padding=True, padding=(0, 1), ) - - -def render_rich_table(table_data: ReportTable, *, show_title: bool = True) -> Table: - """Render one catalog table without interpreting its display strings.""" - - table = report_table(table_data.title if show_title else None, caption=table_data.caption) - for column in table_data.columns: + widths: tuple[int | None, ...] = preferred_widths or tuple(None for _ in table_data.columns) + for column, preferred_width in zip(table_data.columns, widths, strict=True): + if preferred_width is None: + ratio = width = min_width = None + no_wrap = False + elif column.alignment == "right": + ratio = min_width = None + width = preferred_width + no_wrap = True + else: + ratio = preferred_width + width = None + min_width = min( + preferred_width, + max(_max_line_width(column.label), RICH_TEXT_COLUMN_MIN_WIDTH), + ) + no_wrap = False table.add_column( Text(column.label), justify="right" if column.alignment == "right" else "left", overflow="fold", + ratio=ratio, + width=width, + min_width=min_width, + no_wrap=no_wrap, ) for row in table_data.rows: table.add_row(*(Text(cell.display, style=TONE_STYLES[cell.tone]) for cell in row.cells)) @@ -92,6 +113,7 @@ def render_markdown_table(table_data: ReportTable, *, heading_level: int | None def render_rich_report_document(catalog: ReportCatalog, width: int) -> Group: """Render rulesets, phases, files, comparison, then the final summary.""" + shared_column_widths = _shared_column_widths(catalog) sections = {section.id: section for section in catalog.sections} ordered = tuple(sections[section_id] for section_id in RICH_SECTION_ORDER if section_id in sections) ordered_ids = {section.id for section in ordered} @@ -103,7 +125,7 @@ def render_rich_report_document(catalog: ReportCatalog, width: int) -> Group: if warning_pending and section.id in DETAIL_SECTION_IDS: renderables.append(Text(RICH_DETAIL_NARROW_WARNING.format(width=width), style="yellow")) warning_pending = False - renderables.extend(_rich_section_renderables(section)) + renderables.extend(_rich_section_renderables(section, shared_column_widths)) return Group(*renderables) @@ -116,7 +138,10 @@ def render_markdown_report_document(catalog: ReportCatalog) -> str: return "\n\n".join(part.strip() for part in parts if part.strip()) -def _rich_section_renderables(section: ReportSection) -> tuple[RenderableType, ...]: +def _rich_section_renderables( + section: ReportSection, + shared_column_widths: dict[str, tuple[int, ...]], +) -> tuple[RenderableType, ...]: renderables: list[RenderableType] = [] if section.title is not None: renderables.append(Rule(Text(section.title, style="bold"), style="green")) @@ -126,6 +151,7 @@ def _rich_section_renderables(section: ReportSection) -> tuple[RenderableType, . _render_rich_block( block, show_table_title=not (index == 0 and hide_first_table_title), + preferred_widths=shared_column_widths.get(block.id) if isinstance(block, ReportTable) else None, ) ) return tuple(renderables) @@ -136,8 +162,7 @@ def _markdown_section_parts(section: ReportSection) -> tuple[str, ...]: if section.title is not None: parts.append(f"## {_markdown_heading(section.title)}") for index, block in enumerate(section.blocks): - if index == 0 and _first_table_repeats_section_title(section): - assert isinstance(block, ReportTable) + if isinstance(block, ReportTable) and index == 0 and block.title == section.title: parts.append(render_markdown_table(block, heading_level=None)) else: parts.append(_render_markdown_block(block)) @@ -157,9 +182,10 @@ def _render_rich_block( block: ReportTable | ReportMessage, *, show_table_title: bool = True, + preferred_widths: tuple[int, ...] | None = None, ) -> RenderableType: if isinstance(block, ReportTable): - return render_rich_table(block, show_title=show_table_title) + return render_rich_table(block, show_title=show_table_title, preferred_widths=preferred_widths) if block.title is None: return Text(block.text, style=TONE_STYLES[block.tone] or "dim") return Group(Text(block.title, style="bold"), Text(block.text, style=TONE_STYLES[block.tone] or "dim")) @@ -175,3 +201,36 @@ def _render_markdown_block(block: ReportTable | ReportMessage) -> str: def _markdown_heading(value: str) -> str: return value.replace("\n", " ").replace("#", "\\#") + + +def _shared_column_widths(catalog: ReportCatalog) -> dict[str, tuple[int, ...]]: + """Give repeated table schemas one content-derived Rich column layout.""" + + families: dict[tuple[tuple[str, str, str], ...], list[ReportTable]] = {} + for section in catalog.sections: + for block in section.blocks: + if isinstance(block, ReportTable): + signature = tuple((column.id, column.label, column.alignment) for column in block.columns) + families.setdefault(signature, []).append(block) + + result: dict[str, tuple[int, ...]] = {} + for tables in families.values(): + if len(tables) < 2: + continue + widths = tuple( + max( + 1, + _max_line_width(tables[0].columns[column_index].label), + *(_max_line_width(row.cells[column_index].display) for table in tables for row in table.rows), + ) + for column_index in range(len(tables[0].columns)) + ) + for table in tables: + result[table.id] = widths + return result + + +def _max_line_width(value: str) -> int: + """Measure the widest terminal line without counting Unicode code points as cells.""" + + return max((cell_len(line) for line in value.splitlines()), default=0) diff --git a/benchmarking/reports/store.py b/benchmarking/reports/store.py index 61d13d07..c639f5dc 100644 --- a/benchmarking/reports/store.py +++ b/benchmarking/reports/store.py @@ -23,28 +23,40 @@ Treatment, ) -type ReportSchemaVersion = Literal[2] -REPORT_SCHEMA_VERSION: Final[ReportSchemaVersion] = 2 +type ReportSchemaVersion = Literal[4] +REPORT_SCHEMA_VERSION: Final[ReportSchemaVersion] = 4 -type TimingSummarySchemaVersion = Literal[2] -TIMING_SUMMARY_SCHEMA_VERSION: Final[TimingSummarySchemaVersion] = 2 +type TimingSummarySchemaVersion = Literal[4] +TIMING_SUMMARY_SCHEMA_VERSION: Final[TimingSummarySchemaVersion] = 4 + + +type RulesetTimingRole = Literal["program", "equality"] class RulesetTimingRecord(TypedDict): - """Persisted engine time for one ruleset.""" + """Exclusive own-work timing for one named ruleset.""" name: str + role: RulesetTimingRole + assembly_ns: int search_ns: int apply_ns: int - unattributed_ns: int + execution_ns: int merge_ns: int - rebuild_ns: int class TimingSummaryRecord(TypedDict): """Versioned engine timing summary embedded in one successful row.""" schema_version: TimingSummarySchemaVersion + typecheck_ns: int + frontend_parse_ns: int + frontend_other_ns: int + frontend_install_ns: int + commands_actions_ns: int + commands_check_ns: int + commands_other_ns: int + native_rebuild_ns: int rulesets: list[RulesetTimingRecord] diff --git a/egg-math-benchmark/src/main.rs b/egg-math-benchmark/src/main.rs index 31b5e69f..82995e8b 100644 --- a/egg-math-benchmark/src/main.rs +++ b/egg-math-benchmark/src/main.rs @@ -1,7 +1,7 @@ use anyhow::{Context, Result, ensure}; use clap::{Parser, ValueEnum}; use egg::{RecExpr, Runner, SimpleScheduler, StopReason}; -use egglog_reports::{RulesetTimingV2, TimingSummaryV2}; +use egglog_reports::{RulesetTimingRecord, RulesetTimingRole, TimingSummary}; use std::{ fs::File, io::BufWriter, @@ -44,7 +44,7 @@ fn main() -> Result<()> { Ok(()) } -fn run_math(proof_mode: ProofMode) -> Result<(TimingSummaryV2, usize)> { +fn run_math(proof_mode: ProofMode) -> Result<(TimingSummary, usize)> { let left: RecExpr = CHECK_LEFT.parse().expect("fixed left check must parse"); let right: RecExpr = CHECK_RIGHT.parse().expect("fixed right check must parse"); let rules = math::rules(); @@ -89,36 +89,44 @@ fn run_math(proof_mode: ProofMode) -> Result<(TimingSummaryV2, usize)> { ); let proof_postprocessing_started = Instant::now(); - let proof_postprocessing_ns = if matches!(proof_mode, ProofMode::Extract | ProofMode::Check) { + let proof_postprocessing = if matches!(proof_mode, ProofMode::Extract | ProofMode::Check) { let mut explanation = runner.explain_equivalence(&left, &right); explanation.make_flat_explanation(); if proof_mode == ProofMode::Check { explanation.check_proof(&rules); } - duration_to_ns(proof_postprocessing_started.elapsed()) + proof_postprocessing_started.elapsed() } else { - 0 + Duration::ZERO }; - let timing = TimingSummaryV2 { - schema_version: 2, - rulesets: vec![RulesetTimingV2 { + let timing = TimingSummary { + schema_version: TimingSummary::SCHEMA_VERSION, + typecheck_ns: 0, + frontend_parse_ns: 0, + frontend_other_ns: 0, + frontend_install_ns: 0, + commands_actions_ns: 0, + commands_check_ns: 0, + commands_other_ns: proof_postprocessing.as_nanos().min(u64::MAX as u128) as u64, + native_rebuild_ns: seconds_to_ns(report.rebuild_time), + rulesets: vec![RulesetTimingRecord { name: String::new(), + role: RulesetTimingRole::Program, + assembly_ns: 0, search_ns: seconds_to_ns(report.search_time), apply_ns: seconds_to_ns(report.apply_time), - unattributed_ns: seconds_to_ns( + execution_ns: seconds_to_ns( (report.total_time - report.search_time - report.apply_time - report.rebuild_time) .max(0.0), - ) - .saturating_add(proof_postprocessing_ns), + ), merge_ns: 0, - rebuild_ns: seconds_to_ns(report.rebuild_time), }], }; Ok((timing, report.egraph_nodes)) } -fn write_timing_summary(path: &Path, timing: &TimingSummaryV2) -> Result<()> { +fn write_timing_summary(path: &Path, timing: &TimingSummary) -> Result<()> { let file = File::create(path) .with_context(|| format!("failed to create timing summary {}", path.display()))?; serde_json::to_writer(BufWriter::new(file), timing) @@ -132,10 +140,6 @@ fn seconds_to_ns(seconds: f64) -> u64 { (seconds * 1_000_000_000.0).min(u64::MAX as f64) as u64 } -fn duration_to_ns(duration: Duration) -> u64 { - duration.as_nanos().min(u128::from(u64::MAX)) as u64 -} - #[cfg(test)] mod tests { use super::*; diff --git a/egglog-experimental/tests/scheduler_reporting.rs b/egglog-experimental/tests/scheduler_reporting.rs index 36fac13f..838c0436 100644 --- a/egglog-experimental/tests/scheduler_reporting.rs +++ b/egglog-experimental/tests/scheduler_reporting.rs @@ -3,6 +3,7 @@ use egglog::CommandOutput; use egglog_reports::RunReport; +use std::collections::BTreeSet; const PROGRAM: &str = r#" (ruleset grow) @@ -15,14 +16,14 @@ const PROGRAM: &str = r#" (seed 1) "#; -fn ruleset_names(report: &RunReport) -> Vec<&str> { - let mut names = report - .ruleset_timings - .keys() - .map(|name| name.as_ref()) - .collect::>(); - names.sort_unstable(); - names +fn ruleset_names(report: &RunReport) -> Vec { + report + .iterations + .iter() + .map(|iteration| iteration.name.to_string()) + .collect::>() + .into_iter() + .collect() } #[test] diff --git a/egglog/CHANGELOG.md b/egglog/CHANGELOG.md index 0a1f9728..58ae002a 100644 --- a/egglog/CHANGELOG.md +++ b/egglog/CHANGELOG.md @@ -2,6 +2,7 @@ ## [Unreleased] - ReleaseDate +- **Breaking reporting formats.** `--save-report` now stores each iteration with its ruleset name and timing responsibility, and no longer serializes the redundant `ruleset_timings` or `search_and_apply_time_per_rule` aggregates. `--timing-summary` now emits the typed version-4 timing partition used by the benchmark runner; the runner's JSONL schema is also version 4, so older disposable benchmark caches must be recomputed. - **Proof mode is substantially faster and uses less memory.** The term/proof encoding no longer writes each proof's `Congr`/`Trans`/`Sym` steps as rows while rules run; it records what justified a fact and rebuilds the steps when a proof is asked for. A flat `(rewrite (Add a b) (Add b a))` firing writes 2 proof rows where it wrote 13. Across the benchmark suite that is 0.73–0.75x wall time, and peak memory on `math-microbenchmark` goes from 2.3 GiB to 1.1 GiB. Proof semantics are unchanged by this work; the proof snapshots that do move in this release move for the separate fixes and the now-deterministic extraction order below. - Fix `set-if-empty` in the term/proof encoding looking its key up in the committed table while staging its insert, so two calls with the same key in one action batch both missed and both inserted, minting two e-classes for one term — leaving the encoding one iteration behind ordinary execution on programs that do not saturate. It now reads through the batch's predicted rows, as `lookup_or_insert` already did. - **Declared indexes.** `(index (any *))` declares a read-only relation over the rows of ``: each value appearing in *any* of the listed columns, followed by the whole row. It answers "which rows mention this value", which no ordinary atom expresses — repeating a variable across those columns instead constrains them to be equal. Purely physical: it changes no results, only the cost of finding those rows. The database maintains it and creates it on demand, so the declaration binds a name and nothing more. An atom is probed rather than scanned, so a *variable* indexed value must be bound elsewhere in the query by a function's rows — a body primitive runs after the join, so it cannot bind one — while a literal is already known and needs no binder. Over a single indexed column the occurrence is an ordinary equality and the atom is lowered to a plain one, which is also what lets the indexed value sit at another of the row's columns; over several columns that combination is a per-row disjunction and is rejected. A *user-written* declaration is not yet supported under the term/proof encoding, which rewrites a function into a view whose columns differ, so the declaration would name the wrong ones; the encoder's own declarations, written against its views, are unaffected. `(any …)` is an extractor over the row, leaving room for others (e.g. the elements of a container column). diff --git a/egglog/core-relations/src/free_join/execute.rs b/egglog/core-relations/src/free_join/execute.rs index 83ca6727..f9f352d2 100644 --- a/egglog/core-relations/src/free_join/execute.rs +++ b/egglog/core-relations/src/free_join/execute.rs @@ -454,6 +454,10 @@ impl Database { ..RuleSetReport::default() }; } + // This outer interval includes all per-run execution setup. Search and + // apply are measured inside it, and the serial remainder is reported as + // execution overhead. + let pre_merge_timer = Instant::now(); let match_counter = Arc::new(MatchCounter::new(rule_set.actions.n_ids())); // Trie roots are shared across all plans in this run. Tables are frozen // for the duration, so a given root key always denotes the same subset; @@ -478,7 +482,6 @@ impl Database { (!shared.is_empty()).then(|| Arc::new(TrieCache::with_shared(shared))) }; - let pre_merge_timer = Instant::now(); // let mut rule_reports: HashMap>; let mut rule_reports: HashMap, Vec>; let run_in_parallel = parallelize_db_level_op(self.total_size_estimate); diff --git a/egglog/egglog-bridge/src/lib.rs b/egglog/egglog-bridge/src/lib.rs index 4f3f7eda..7609dd42 100644 --- a/egglog/egglog-bridge/src/lib.rs +++ b/egglog/egglog-bridge/src/lib.rs @@ -853,13 +853,14 @@ impl EGraph { let ts = self.next_ts(); let uf_size_before = self.db.get_table(self.uf_table).len(); - let rule_set_report = + let (assembly_time, rule_set_report) = run_rules_impl(&mut self.db, &mut self.rules, rules, ts, self.report_level)?; if let Some(message) = self.panic_message.lock().unwrap().take() { return Err(PanicError(message).into()); } let mut iteration_report = IterationReport { + assembly_time, rule_set_report, rebuild_time: Duration::ZERO, }; @@ -978,6 +979,7 @@ impl EGraph { ts, ReportLevel::TimeOnly, )? + .1 .changed; } // Reset the rule we did not run. These two should be equivalent. @@ -993,6 +995,7 @@ impl EGraph { ts, ReportLevel::TimeOnly, )? + .1 .changed; for rule in &info.incremental_rebuild_rules { self.rules[*rule].last_run_at = ts; @@ -1066,6 +1069,7 @@ impl EGraph { ts, ReportLevel::TimeOnly, )? + .1 .changed; scratch.clear(); let ts = self.next_ts(); @@ -1082,6 +1086,7 @@ impl EGraph { ts, ReportLevel::TimeOnly, )? + .1 .changed; scratch.clear(); } @@ -2191,7 +2196,8 @@ fn run_rules_impl( rules: &[RuleId], next_ts: Timestamp, report_level: ReportLevel, -) -> Result { +) -> Result<(Duration, RuleSetReport)> { + let assembly_timer = Instant::now(); for rule in rules { let info = &mut rule_info[*rule]; if info.cached_plan.is_none() { @@ -2207,7 +2213,8 @@ fn run_rules_impl( info.last_run_at = next_ts; } let ruleset = rsb.build(); - Ok(db.run_rule_set(&ruleset, report_level)) + let assembly_time = assembly_timer.elapsed(); + Ok((assembly_time, db.run_rule_set(&ruleset, report_level))) } // These markers are just used to make it easy to distinguish time spent in diff --git a/egglog/egglog-reports/src/lib.rs b/egglog/egglog-reports/src/lib.rs index 73b2a7a0..67aa6e35 100644 --- a/egglog/egglog-reports/src/lib.rs +++ b/egglog/egglog-reports/src/lib.rs @@ -2,6 +2,7 @@ use clap::clap_derive::ValueEnum; use rustc_hash::FxHasher; use serde::Serialize; use std::{ + collections::BTreeMap, fmt::{Display, Formatter}, hash::BuildHasherDefault, sync::Arc, @@ -139,28 +140,16 @@ impl PreMergeTiming { } } -/// Aggregated timing for all iterations of one ruleset. -#[derive(Debug, Serialize, Clone, Copy, PartialEq, Eq, Default)] -pub struct RulesetTiming { - /// Execution before staged updates are merged. - pub pre_merge: PreMergeTiming, - /// Resolving and installing staged updates. - pub merge: Duration, - /// Rebuilding indexes and e-graph state after merge. - pub rebuild: Duration, +/// The semantic responsibility served by a ruleset invocation. +#[derive(Debug, Serialize, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] +#[serde(rename_all = "snake_case")] +pub enum RulesetTimingRole { + Program, + Equality, } -impl RulesetTiming { - pub fn total(self) -> Duration { - self.pre_merge.total() + self.merge + self.rebuild - } - - fn union(&mut self, other: Self) { - self.pre_merge.union(other.pre_merge); - self.merge += other.merge; - self.rebuild += other.rebuild; - } -} +type AggregatedRulesetTimings = + BTreeMap<(RulesetTimingRole, Arc), (Duration, PreMergeTiming, Duration)>; impl RuleSetReport { pub fn num_matches(&self, rule: &str) -> usize { @@ -180,6 +169,8 @@ impl RuleSetReport { #[derive(Debug, Serialize, Clone, Default)] pub struct IterationReport { + /// Preparing this invocation's executable ruleset before execution starts. + pub assembly_time: Duration, pub rule_set_report: RuleSetReport, pub rebuild_time: Duration, } @@ -196,6 +187,22 @@ impl IterationReport { pub fn rules(&self) -> impl Iterator> { self.rule_set_report.rule_reports.keys() } + + /// Total exclusive wall-clock work recorded for this invocation. + pub fn total_time(&self) -> Duration { + self.assembly_time + + self.rule_set_report.pre_merge.total() + + self.rule_set_report.merge_time + + self.rebuild_time + } +} + +/// One ruleset invocation and the responsibility it served when it ran. +#[derive(Debug, Serialize, Clone)] +pub struct RulesetIteration { + pub name: Arc, + pub role: RulesetTimingRole, + pub report: Arc, } /// Running a schedule produces a report of the results. @@ -205,17 +212,15 @@ impl IterationReport { /// information together. #[derive(Debug, Serialize, Clone)] pub struct RunReport { - // Since `IterationReport`s are immutable, we can reference count them to avoid - // expensive cloning when e-graphs are cloned. - pub iterations: Vec>, + // Each entry carries ruleset metadata; its immutable report payload remains + // reference-counted so cloning e-graphs stays cheap. + pub iterations: Vec, /// If any changes were made to the database. pub updated: bool, /// True if this run observed no database changes and there is no deferred /// scheduler work requiring another iteration. pub can_stop: bool, - pub search_and_apply_time_per_rule: HashMap, Duration>, pub num_matches_per_rule: HashMap, usize>, - pub ruleset_timings: HashMap, RulesetTiming>, } impl Default for RunReport { @@ -224,16 +229,15 @@ impl Default for RunReport { iterations: Vec::new(), updated: false, can_stop: true, - search_and_apply_time_per_rule: HashMap::default(), num_matches_per_rule: HashMap::default(), - ruleset_timings: HashMap::default(), } } } impl Display for RunReport { fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { - let mut rule_times_vec: Vec<_> = self.search_and_apply_time_per_rule.iter().collect(); + let rule_times = self.search_and_apply_time_per_rule(); + let mut rule_times_vec: Vec<_> = rule_times.iter().collect(); rule_times_vec.sort_by_key(|(_, time)| **time); for (rule, time) in rule_times_vec { @@ -246,10 +250,11 @@ impl Display for RunReport { )?; } - for (ruleset, timing) in &self.ruleset_timings { - let merge_time = timing.merge.as_secs_f64(); - let rebuild_time = timing.rebuild.as_secs_f64(); - match timing.pre_merge { + let (rulesets, native_rebuild) = self.aggregate_timings(); + for ((_, name), (assembly, pre_merge, merge)) in rulesets { + let assembly_time = assembly.as_secs_f64(); + let merge_time = merge.as_secs_f64(); + match pre_merge { PreMergeTiming::Split { search, apply, @@ -257,7 +262,8 @@ impl Display for RunReport { } => { writeln!( f, - "Ruleset {ruleset}: search {:.3}s, apply {:.3}s, unattributed {:.3}s, merge {merge_time:.3}s, rebuild {rebuild_time:.3}s", + "Ruleset {}: assembly {assembly_time:.3}s, search {:.3}s, apply {:.3}s, unattributed {:.3}s, merge {merge_time:.3}s", + name, search.as_secs_f64(), apply.as_secs_f64(), unattributed.as_secs_f64(), @@ -266,12 +272,14 @@ impl Display for RunReport { PreMergeTiming::Combined { elapsed } => { writeln!( f, - "Ruleset {ruleset}: pre-merge {:.3}s, merge {merge_time:.3}s, rebuild {rebuild_time:.3}s", + "Ruleset {}: assembly {assembly_time:.3}s, pre-merge {:.3}s, merge {merge_time:.3}s", + name, elapsed.as_secs_f64(), )?; } } } + writeln!(f, "Native rebuild: {:.3}s", native_rebuild.as_secs_f64())?; Ok(()) } @@ -290,51 +298,78 @@ impl RunReport { s } - fn union_times( - times: &mut HashMap, Duration>, - other_times: HashMap, Duration>, - ) { - for (k, v) in other_times { - *times.entry(k).or_default() += v; - } - } - fn union_counts(counts: &mut HashMap, usize>, other_counts: HashMap, usize>) { for (k, v) in other_counts { *counts.entry(k).or_default() += v; } } - pub fn singleton(ruleset: &str, iteration: IterationReport) -> Self { + pub fn singleton(ruleset: &str, role: RulesetTimingRole, iteration: IterationReport) -> Self { let mut report = RunReport::default(); for rule in iteration.rules() { - *report - .search_and_apply_time_per_rule - .entry(rule.clone()) - .or_default() += iteration.rule_set_report.rule_search_and_apply_time(rule); *report.num_matches_per_rule.entry(rule.clone()).or_default() += iteration.rule_set_report.num_matches(rule); } - let ruleset: Arc = ruleset.into(); - report.ruleset_timings.insert( - ruleset, - RulesetTiming { - pre_merge: iteration.rule_set_report.pre_merge, - merge: iteration.rule_set_report.merge_time, - rebuild: iteration.rebuild_time, - }, - ); report.updated = iteration.changed(); report.can_stop = !report.updated; - report.iterations.push(Arc::new(iteration)); + report.iterations.push(RulesetIteration { + name: ruleset.into(), + role, + report: Arc::new(iteration), + }); report } - pub fn add_iteration(&mut self, ruleset: &str, iteration: IterationReport) { - self.union(RunReport::singleton(ruleset, iteration)); + pub fn add_iteration( + &mut self, + ruleset: &str, + role: RulesetTimingRole, + iteration: IterationReport, + ) { + self.union(RunReport::singleton(ruleset, role, iteration)); + } + + /// Derive per-rule search-and-apply totals from the recorded iterations. + pub fn search_and_apply_time_per_rule(&self) -> HashMap, Duration> { + let mut result = HashMap::default(); + for iteration in &self.iterations { + for rule in iteration.report.rules() { + *result.entry(rule.clone()).or_default() += iteration + .report + .rule_set_report + .rule_search_and_apply_time(rule); + } + } + result + } + + /// Derive the ruleset-own-work and global rebuild partition of this run. + fn aggregate_timings(&self) -> (AggregatedRulesetTimings, Duration) { + let mut rulesets = AggregatedRulesetTimings::new(); + let mut native_rebuild = Duration::ZERO; + for iteration in &self.iterations { + native_rebuild = native_rebuild.saturating_add(iteration.report.rebuild_time); + let key = (iteration.role, iteration.name.clone()); + match rulesets.entry(key) { + std::collections::btree_map::Entry::Occupied(mut entry) => { + let (assembly, pre_merge, merge) = entry.get_mut(); + *assembly += iteration.report.assembly_time; + pre_merge.union(iteration.report.rule_set_report.pre_merge); + *merge += iteration.report.rule_set_report.merge_time; + } + std::collections::btree_map::Entry::Vacant(entry) => { + entry.insert(( + iteration.report.assembly_time, + iteration.report.rule_set_report.pre_merge, + iteration.report.rule_set_report.merge_time, + )); + } + } + } + (rulesets, native_rebuild) } /// Merge two reports. @@ -342,95 +377,144 @@ impl RunReport { self.iterations.extend(other.iterations); self.updated |= other.updated; self.can_stop &= other.can_stop; - RunReport::union_times( - &mut self.search_and_apply_time_per_rule, - other.search_and_apply_time_per_rule, - ); RunReport::union_counts(&mut self.num_matches_per_rule, other.num_matches_per_rule); - for (ruleset, timing) in other.ruleset_timings { - self.ruleset_timings - .entry(ruleset) - .and_modify(|current| current.union(timing)) - .or_insert(timing); - } } } -/// Compact, deterministic timing transport for benchmark runners. +/// All cumulative reporting state owned by an e-graph. +/// +/// Local [`RunReport`] values remain scoped to schedules. Process timing lives +/// here because parsing, typechecking, and command work surrounds those runs +/// and must be counted exactly once. +#[derive(Debug, Clone, Default)] +pub struct OverallReport { + pub run: RunReport, + pub typecheck: Duration, + pub frontend_parse: Duration, + pub frontend_other: Duration, + pub frontend_install: Duration, + pub commands_actions: Duration, + pub commands_check: Duration, + pub commands_other: Duration, +} + +impl OverallReport { + pub fn process_time(&self) -> Duration { + [ + self.typecheck, + self.frontend_parse, + self.frontend_other, + self.frontend_install, + self.commands_actions, + self.commands_check, + self.commands_other, + ] + .into_iter() + .sum() + } +} + +/// Compact timing for one ruleset in the benchmark transport. #[derive(Debug, Serialize, Clone, PartialEq, Eq)] -pub struct RulesetTimingV2 { +pub struct RulesetTimingRecord { pub name: String, + pub role: RulesetTimingRole, + pub assembly_ns: u64, pub search_ns: u64, pub apply_ns: u64, - pub unattributed_ns: u64, + pub execution_ns: u64, pub merge_ns: u64, - pub rebuild_ns: u64, } -/// Versioned ruleset timing summary for successful egglog runs. +/// Versioned, deterministic timing transport for successful egglog runs. /// -/// V2 includes every name in [`RunReport::ruleset_timings`], preserves the -/// empty name used by the default ruleset, and sorts names lexicographically. -/// Split pre-merge timing must be available for every included ruleset; -/// otherwise construction returns [`PhaseTimingUnavailable`]. Durations are -/// converted to nanoseconds with saturation at [`u64::MAX`], and the ruleset -/// list is never truncated. +/// Every value is an exclusive wall-clock leaf. Rulesets are sorted by semantic +/// role and name. Native rebuild is global because the ruleset whose tail +/// happened to flush updates is not its semantic owner. #[derive(Debug, Serialize, Clone, PartialEq, Eq)] -pub struct TimingSummaryV2 { +pub struct TimingSummary { pub schema_version: u32, - pub rulesets: Vec, + pub typecheck_ns: u64, + pub frontend_parse_ns: u64, + pub frontend_other_ns: u64, + pub frontend_install_ns: u64, + pub commands_actions_ns: u64, + pub commands_check_ns: u64, + pub commands_other_ns: u64, + pub native_rebuild_ns: u64, + pub rulesets: Vec, } -/// A requested timing summary contains a ruleset whose split phase timing was -/// not recorded. +/// A requested timing summary cannot satisfy the serial, single-role contract. #[derive(Debug, Clone, PartialEq, Eq)] -pub struct PhaseTimingUnavailable { - pub ruleset: String, +pub enum TimingSummaryError { + PhaseTimingUnavailable { ruleset: String }, + InconsistentRulesetRole { ruleset: String }, } -impl Display for PhaseTimingUnavailable { +impl Display for TimingSummaryError { fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { - write!( - f, - "split pre-merge timing is unavailable for ruleset {ruleset:?}", - ruleset = self.ruleset, - ) + match self { + Self::PhaseTimingUnavailable { ruleset } => write!( + f, + "split pre-merge timing is unavailable for ruleset {ruleset:?}" + ), + Self::InconsistentRulesetRole { ruleset } => { + write!(f, "ruleset {ruleset:?} ran with inconsistent timing roles") + } + } } } -impl std::error::Error for PhaseTimingUnavailable {} - -impl TimingSummaryV2 { - pub fn from_run_report(report: &RunReport) -> Result { - let mut timings = report.ruleset_timings.iter().collect::>(); - timings.sort_unstable_by(|(left, _), (right, _)| left.as_ref().cmp(right.as_ref())); - - let rulesets = timings - .into_iter() - .map(|(name, timing)| { - let PreMergeTiming::Split { - search, - apply, - unattributed, - } = timing.pre_merge - else { - return Err(PhaseTimingUnavailable { - ruleset: name.to_string(), - }); - }; - Ok(RulesetTimingV2 { - search_ns: duration_ns(search), - apply_ns: duration_ns(apply), - unattributed_ns: duration_ns(unattributed), - merge_ns: duration_ns(timing.merge), - rebuild_ns: duration_ns(timing.rebuild), - name: name.to_string(), - }) - }) - .collect::, PhaseTimingUnavailable>>()?; +impl std::error::Error for TimingSummaryError {} + +impl TimingSummary { + pub const SCHEMA_VERSION: u32 = 4; + + pub fn from_report(report: &OverallReport) -> Result { + let (timings, native_rebuild) = report.run.aggregate_timings(); + let mut roles = BTreeMap::new(); + let mut rulesets = Vec::with_capacity(timings.len()); + for ((role, name), (assembly, pre_merge, merge)) in timings { + if roles + .insert(name.clone(), role) + .is_some_and(|previous| previous != role) + { + return Err(TimingSummaryError::InconsistentRulesetRole { + ruleset: name.to_string(), + }); + } + let PreMergeTiming::Split { + search, + apply, + unattributed, + } = pre_merge + else { + return Err(TimingSummaryError::PhaseTimingUnavailable { + ruleset: name.to_string(), + }); + }; + rulesets.push(RulesetTimingRecord { + name: name.to_string(), + role, + assembly_ns: duration_ns(assembly), + search_ns: duration_ns(search), + apply_ns: duration_ns(apply), + execution_ns: duration_ns(unattributed), + merge_ns: duration_ns(merge), + }); + } Ok(Self { - schema_version: 2, + schema_version: Self::SCHEMA_VERSION, + typecheck_ns: duration_ns(report.typecheck), + frontend_parse_ns: duration_ns(report.frontend_parse), + frontend_other_ns: duration_ns(report.frontend_other), + frontend_install_ns: duration_ns(report.frontend_install), + commands_actions_ns: duration_ns(report.commands_actions), + commands_check_ns: duration_ns(report.commands_check), + commands_other_ns: duration_ns(report.commands_other), + native_rebuild_ns: duration_ns(native_rebuild), rulesets, }) } @@ -452,213 +536,192 @@ mod tests { } } - #[test] - fn timing_summary_v2_exact_json_is_sorted() { - let mut report = RunReport::default(); - report.ruleset_timings.insert( - "zeta".into(), - RulesetTiming { - pre_merge: PreMergeTiming::Split { - search: Duration::new(1, 234), - apply: Duration::ZERO, - unattributed: Duration::from_nanos(89), - }, - ..RulesetTiming::default() + fn iteration( + assembly: u64, + pre_merge: PreMergeTiming, + merge: u64, + rebuild: Duration, + ) -> IterationReport { + IterationReport { + assembly_time: Duration::from_nanos(assembly), + rule_set_report: RuleSetReport { + pre_merge, + merge_time: Duration::from_nanos(merge), + ..RuleSetReport::default() }, - ); - report.ruleset_timings.insert( - "beta".into(), - RulesetTiming { - pre_merge: split(0, 23, 0), - ..RulesetTiming::default() - }, - ); - report.ruleset_timings.insert( - "".into(), - RulesetTiming { - pre_merge: split(0, 0, 0), - merge: Duration::from_nanos(45), - ..RulesetTiming::default() - }, - ); - report.ruleset_timings.insert( - "alpha".into(), - RulesetTiming { - pre_merge: split(0, 0, 0), - rebuild: Duration::from_nanos(67), - ..RulesetTiming::default() - }, - ); - - let summary = TimingSummaryV2::from_run_report(&report).unwrap(); - let json = serde_json::to_string(&summary).unwrap(); - - assert_eq!( - json, - r#"{"schema_version":2,"rulesets":[{"name":"","search_ns":0,"apply_ns":0,"unattributed_ns":0,"merge_ns":45,"rebuild_ns":0},{"name":"alpha","search_ns":0,"apply_ns":0,"unattributed_ns":0,"merge_ns":0,"rebuild_ns":67},{"name":"beta","search_ns":0,"apply_ns":23,"unattributed_ns":0,"merge_ns":0,"rebuild_ns":0},{"name":"zeta","search_ns":1000000234,"apply_ns":0,"unattributed_ns":89,"merge_ns":0,"rebuild_ns":0}]}"# - ); + rebuild_time: rebuild, + } } #[test] - fn timing_summary_v2_empty_report_golden() { - let summary = TimingSummaryV2::from_run_report(&RunReport::default()).unwrap(); - let json = serde_json::to_string(&summary).unwrap(); + fn run_report_aggregates_every_iteration_of_a_ruleset() { + let mut report = OverallReport::default(); + report.run.add_iteration( + "timed", + RulesetTimingRole::Program, + iteration(2, split(11, 7, 3), 13, Duration::from_nanos(17)), + ); + report.run.add_iteration( + "timed", + RulesetTimingRole::Program, + iteration(3, split(19, 5, 4), 23, Duration::from_nanos(29)), + ); - assert_eq!(json, r#"{"schema_version":2,"rulesets":[]}"#); + let summary = TimingSummary::from_report(&report).unwrap(); + assert_eq!(summary.rulesets[0].assembly_ns, 5); + assert_eq!(summary.rulesets[0].search_ns, 30); + assert_eq!(summary.rulesets[0].apply_ns, 12); + assert_eq!(summary.rulesets[0].execution_ns, 7); + assert_eq!(summary.rulesets[0].merge_ns, 36); + assert_eq!(summary.native_rebuild_ns, 46); } #[test] - fn timing_summary_v2_aggregates_every_iteration_of_a_ruleset() { + fn run_report_preserves_mixed_pre_merge_totals() { let mut report = RunReport::default(); report.add_iteration( - "timed", - IterationReport { - rule_set_report: RuleSetReport { - pre_merge: split(11, 7, 3), - merge_time: Duration::from_nanos(13), - ..RuleSetReport::default() - }, - rebuild_time: Duration::from_nanos(17), - }, + "mixed", + RulesetTimingRole::Program, + iteration(2, split(3, 5, 7), 11, Duration::from_nanos(13)), ); report.add_iteration( - "timed", - IterationReport { - rule_set_report: RuleSetReport { - pre_merge: split(19, 5, 4), - merge_time: Duration::from_nanos(23), - ..RuleSetReport::default() + "mixed", + RulesetTimingRole::Program, + iteration( + 17, + PreMergeTiming::Combined { + elapsed: Duration::from_nanos(19), }, - rebuild_time: Duration::from_nanos(29), - }, + 23, + Duration::from_nanos(29), + ), ); - let summary = TimingSummaryV2::from_run_report(&report).unwrap(); - + let (rulesets, native_rebuild) = report.aggregate_timings(); + let ((role, name), (assembly, pre_merge, merge)) = rulesets.iter().next().unwrap(); + assert_eq!(rulesets.len(), 1); assert_eq!( - report.ruleset_timings["timed"].pre_merge.total(), - Duration::from_nanos(49) + (*role, name.as_ref()), + (RulesetTimingRole::Program, "mixed") ); + assert_eq!(*assembly, Duration::from_nanos(19)); assert_eq!( - report.ruleset_timings["timed"].total(), - Duration::from_nanos(131) + *pre_merge, + PreMergeTiming::Combined { + elapsed: Duration::from_nanos(34) + } + ); + assert_eq!(*merge, Duration::from_nanos(34)); + assert_eq!(native_rebuild, Duration::from_nanos(42)); + } + + #[test] + fn timing_summary_exact_json_is_dense_and_sorted() { + let mut report = OverallReport { + typecheck: Duration::from_nanos(2), + frontend_parse: Duration::from_nanos(1), + commands_check: Duration::from_nanos(6), + ..OverallReport::default() + }; + report.run.add_iteration( + "@parent", + RulesetTimingRole::Equality, + iteration(8, split(9, 10, 11), 12, Duration::from_nanos(13)), + ); + report.run.add_iteration( + "rules/λ", + RulesetTimingRole::Program, + iteration(0, split(1_000_000_234, 3, 4), 5, Duration::ZERO), + ); + report.run.add_iteration( + "", + RulesetTimingRole::Program, + iteration(0, split(0, 0, 0), 0, Duration::ZERO), ); + let summary = TimingSummary::from_report(&report).unwrap(); assert_eq!( - summary.rulesets, - [RulesetTimingV2 { - name: "timed".to_owned(), - search_ns: 30, - apply_ns: 12, - unattributed_ns: 7, - merge_ns: 36, - rebuild_ns: 46, - }] + serde_json::to_string(&summary).unwrap(), + r#"{"schema_version":4,"typecheck_ns":2,"frontend_parse_ns":1,"frontend_other_ns":0,"frontend_install_ns":0,"commands_actions_ns":0,"commands_check_ns":6,"commands_other_ns":0,"native_rebuild_ns":13,"rulesets":[{"name":"","role":"program","assembly_ns":0,"search_ns":0,"apply_ns":0,"execution_ns":0,"merge_ns":0},{"name":"rules/λ","role":"program","assembly_ns":0,"search_ns":1000000234,"apply_ns":3,"execution_ns":4,"merge_ns":5},{"name":"@parent","role":"equality","assembly_ns":8,"search_ns":9,"apply_ns":10,"execution_ns":11,"merge_ns":12}]}"# ); } #[test] - fn timing_summary_v2_does_not_truncate_rulesets() { - let mut report = RunReport::default(); - for index in (0..40).rev() { - report.ruleset_timings.insert( - format!("ruleset-{index:02}").into(), - RulesetTiming { - pre_merge: split(index + 1, 0, 0), - ..RulesetTiming::default() - }, + fn timing_summary_empty_report_golden() { + let summary = TimingSummary::from_report(&OverallReport::default()).unwrap(); + assert_eq!( + serde_json::to_string(&summary).unwrap(), + r#"{"schema_version":4,"typecheck_ns":0,"frontend_parse_ns":0,"frontend_other_ns":0,"frontend_install_ns":0,"commands_actions_ns":0,"commands_check_ns":0,"commands_other_ns":0,"native_rebuild_ns":0,"rulesets":[]}"# + ); + } + + #[test] + fn timing_summary_does_not_truncate_rulesets_and_saturates_nanoseconds() { + let mut report = OverallReport::default(); + for index in (0_u64..40).rev() { + report.run.add_iteration( + &format!("ruleset-{index:02}"), + RulesetTimingRole::Program, + iteration( + 0, + split(index + 1, 0, 0), + 0, + if index == 0 { + Duration::from_secs(u64::MAX) + } else { + Duration::ZERO + }, + ), ); } - - let summary = TimingSummaryV2::from_run_report(&report).unwrap(); + let summary = TimingSummary::from_report(&report).unwrap(); assert_eq!(summary.rulesets.len(), 40); assert_eq!(summary.rulesets.first().unwrap().name, "ruleset-00"); assert_eq!(summary.rulesets.last().unwrap().name, "ruleset-39"); + assert_eq!(summary.native_rebuild_ns, u64::MAX); } #[test] - fn timing_summary_v2_saturates_nanoseconds_to_u64() { - let mut report = RunReport::default(); - report.ruleset_timings.insert( - "long".into(), - RulesetTiming { - pre_merge: PreMergeTiming::Split { - search: Duration::from_secs(u64::MAX), - apply: Duration::ZERO, - unattributed: Duration::ZERO, - }, - ..RulesetTiming::default() - }, - ); - - let summary = TimingSummaryV2::from_run_report(&report).unwrap(); - - assert_eq!(summary.rulesets[0].search_ns, u64::MAX); - } - - #[test] - fn timing_summary_v2_rejects_unavailable_split_timing() { - let mut report = RunReport::default(); - report.ruleset_timings.insert( - "default".into(), - RulesetTiming { - pre_merge: PreMergeTiming::Combined { - elapsed: Duration::from_nanos(42), + fn timing_summary_rejects_combined_timing_and_inconsistent_roles() { + let mut combined_report = OverallReport::default(); + combined_report.run.add_iteration( + "mixed", + RulesetTimingRole::Program, + iteration( + 0, + PreMergeTiming::Combined { + elapsed: Duration::from_nanos(5), }, - ..RulesetTiming::default() - }, + 0, + Duration::ZERO, + ), ); - + let combined = TimingSummary::from_report(&combined_report); assert_eq!( - TimingSummaryV2::from_run_report(&report), - Err(PhaseTimingUnavailable { - ruleset: "default".to_owned(), + combined, + Err(TimingSummaryError::PhaseTimingUnavailable { + ruleset: "mixed".into() }) ); - } - #[test] - fn combined_iteration_degrades_aggregated_pre_merge_timing() { - let mut report = RunReport::default(); - report.add_iteration( + let mut inconsistent_report = OverallReport::default(); + inconsistent_report.run.add_iteration( "mixed", - IterationReport { - rule_set_report: RuleSetReport { - pre_merge: split(1, 2, 3), - merge_time: Duration::from_nanos(7), - ..RuleSetReport::default() - }, - rebuild_time: Duration::from_nanos(11), - }, + RulesetTimingRole::Program, + iteration(0, split(0, 0, 0), 0, Duration::ZERO), ); - report.add_iteration( + inconsistent_report.run.add_iteration( "mixed", - IterationReport { - rule_set_report: RuleSetReport { - pre_merge: PreMergeTiming::Combined { - elapsed: Duration::from_nanos(5), - }, - merge_time: Duration::from_nanos(13), - ..RuleSetReport::default() - }, - rebuild_time: Duration::from_nanos(17), - }, + RulesetTimingRole::Equality, + iteration(0, split(0, 0, 0), 0, Duration::ZERO), ); - + let inconsistent = TimingSummary::from_report(&inconsistent_report); assert_eq!( - report.ruleset_timings["mixed"], - RulesetTiming { - pre_merge: PreMergeTiming::Combined { - elapsed: Duration::from_nanos(11), - }, - merge: Duration::from_nanos(20), - rebuild: Duration::from_nanos(28), - } - ); - assert_eq!( - report.ruleset_timings["mixed"].total(), - Duration::from_nanos(59) + inconsistent, + Err(TimingSummaryError::InconsistentRulesetRole { + ruleset: "mixed".into() + }) ); } } diff --git a/egglog/src/ast/mod.rs b/egglog/src/ast/mod.rs index 6b526846..5f70e7de 100644 --- a/egglog/src/ast/mod.rs +++ b/egglog/src/ast/mod.rs @@ -61,7 +61,13 @@ pub struct ProofConstructorNames { #[derive(Clone, Debug)] /// The egglog internal representation of already compiled rules -pub(crate) enum Ruleset { +pub(crate) struct Ruleset { + pub kind: RulesetKind, + pub timing_role: egglog_reports::RulesetTimingRole, +} + +#[derive(Clone, Debug)] +pub(crate) enum RulesetKind { /// Represents a ruleset with a set of rules. Rules(IndexMap), /// A combined ruleset may contain other rulesets. diff --git a/egglog/src/cli.rs b/egglog/src/cli.rs index 55edefc4..50388221 100644 --- a/egglog/src/cli.rs +++ b/egglog/src/cli.rs @@ -3,7 +3,6 @@ use std::io::{self, BufRead, BufReader, IsTerminal, Read, Write}; use std::str::FromStr; use clap::Parser; -use egglog_reports::TimingSummaryV2; use env_logger::Env; use std::path::PathBuf; @@ -234,11 +233,10 @@ pub fn cli(mut egraph: EGraph) { } if let Some(summary_path) = args.timing_summary { - let summary = TimingSummaryV2::from_run_report(egraph.get_overall_run_report()) - .unwrap_or_else(|error| { - log::error!("failed to create timing summary: {error}"); - std::process::exit(1); - }); + let summary = egraph.timing_summary().unwrap_or_else(|error| { + log::error!("failed to create timing summary: {error}"); + std::process::exit(1); + }); let mut file = std::fs::File::create(&summary_path) .unwrap_or_else(|_| panic!("Failed to create timing summary file at {summary_path:?}")); serde_json::to_writer(&mut file, &summary).expect("Failed to serialize timing summary"); diff --git a/egglog/src/lib.rs b/egglog/src/lib.rs index 5d36ffad..834bef0f 100644 --- a/egglog/src/lib.rs +++ b/egglog/src/lib.rs @@ -42,7 +42,9 @@ use egglog_ast::util::ListDisplay; use egglog_bridge::{ColumnTy, QueryEntry}; use egglog_core_relations as core_relations; use egglog_numeric_id as numeric_id; -use egglog_reports::{ReportLevel, RunReport}; +use egglog_reports::{ + OverallReport, ReportLevel, RulesetTimingRole, RunReport, TimingSummary, TimingSummaryError, +}; pub use exec_state::{ Context, Core, Enode, FullState, FunctionEntry, PureState, Read, ReadState, Write, WriteState, }; @@ -71,6 +73,7 @@ use std::iter::once; use std::ops::Deref; use std::path::PathBuf; use std::sync::Arc; +use std::time::Instant; pub use termdag::{OrdTerm, Term, TermDag, TermId}; use thiserror::Error; use typechecking::FuncType; @@ -322,8 +325,8 @@ pub struct EGraph { pub seminaive: bool, pub no_decomp: bool, type_info: TypeInfo, - /// The run report unioned over all runs so far. - overall_run_report: RunReport, + /// Cumulative run and process reporting state. + overall_report: OverallReport, schedulers: DenseIdMap, commands: IndexMap>, extension_state: HashMap>, @@ -442,7 +445,7 @@ impl EGraph { fact_directory: None, seminaive: true, no_decomp: false, - overall_run_report: Default::default(), + overall_report: Default::default(), type_info: Default::default(), schedulers: Default::default(), commands: Default::default(), @@ -562,8 +565,13 @@ impl EGraph { None, ); - eg.rulesets - .insert("".into(), Ruleset::Rules(Default::default())); + eg.rulesets.insert( + "".into(), + Ruleset { + kind: RulesetKind::Rules(Default::default()), + timing_role: RulesetTimingRole::Program, + }, + ); // The generic `get-fresh!` mint primitive is registered on every e-graph. // Doing it here — rather than per-eq-sort — means it is present whenever @@ -839,8 +847,8 @@ impl EGraph { pub fn pop(&mut self) -> Result<(), Error> { match self.pushed_egraph.take() { Some(mut e) => { - // Preserve the overall report from the popped egraph - std::mem::swap(&mut self.overall_run_report, &mut e.overall_run_report); + // Work performed in the popped scope still belongs to this run. + std::mem::swap(&mut self.overall_report, &mut e.overall_report); // Preserve the symbol generator so that fresh symbols // generated after pop don't collide with ones generated before pop. std::mem::swap(&mut self.parser.symbol_gen, &mut e.parser.symbol_gen); @@ -1367,13 +1375,13 @@ impl EGraph { rulesets: &IndexMap, ids: &mut Vec, ) { - match &rulesets[ruleset] { - Ruleset::Rules(rules) => { + match &rulesets[ruleset].kind { + RulesetKind::Rules(rules) => { for (_, id) in rules.values() { ids.push(*id); } } - Ruleset::Combined(sub_rulesets) => { + RulesetKind::Combined(sub_rulesets) => { for sub_ruleset in sub_rulesets { collect_rule_ids(sub_ruleset, rulesets, ids); } @@ -1389,8 +1397,12 @@ impl EGraph { .run_rules(&rule_ids) .map_err(|e| Error::BackendError(e.to_string()))?; - let report = RunReport::singleton(ruleset, iteration_report); - self.overall_run_report.union(report.clone()); + let report = RunReport::singleton( + ruleset, + self.rulesets[ruleset].timing_role, + iteration_report, + ); + self.overall_report.run.union(report.clone()); Ok(report) } @@ -1414,9 +1426,13 @@ impl EGraph { // it expects only `union` on constructors (not set). let union_to_set = self.proof_state.original_typechecking.is_none(); - match self.rulesets.get(&rule.ruleset) { - Some(Ruleset::Rules(_)) => {} - Some(Ruleset::Combined(_)) => { + match self + .rulesets + .get(&rule.ruleset) + .map(|ruleset| &ruleset.kind) + { + Some(RulesetKind::Rules(_)) => {} + Some(RulesetKind::Combined(_)) => { return Err(Error::CombinedRulesetError( rule.ruleset.clone(), rule.span.clone(), @@ -1449,7 +1465,11 @@ impl EGraph { translator.build(no_decomp) }; - let Some(Ruleset::Rules(rules)) = self.rulesets.get_mut(&rule.ruleset) else { + let Some(Ruleset { + kind: RulesetKind::Rules(rules), + .. + }) = self.rulesets.get_mut(&rule.ruleset) + else { unreachable!("ruleset was validated before compiling the rule") }; match rules.entry(rule.name.clone()) { @@ -1872,17 +1892,55 @@ impl EGraph { Ok(result) } - fn add_combined_ruleset(&mut self, name: String, rulesets: Vec) { + fn add_combined_ruleset( + &mut self, + span: &Span, + name: String, + rulesets: Vec, + ) -> Result<(), Error> { + let mut timing_role = None; + for ruleset in &rulesets { + let role = self + .rulesets + .get(ruleset) + .map(|ruleset| ruleset.timing_role) + .ok_or_else(|| Error::NoSuchRuleset(ruleset.clone(), span.clone()))?; + if timing_role.is_some_and(|expected| expected != role) { + return Err(Error::MixedRulesetResponsibilities(name, span.clone())); + } + timing_role = Some(role); + } match self.rulesets.entry(name.clone()) { Entry::Occupied(_) => panic!("Ruleset '{name}' was already present"), - Entry::Vacant(e) => e.insert(Ruleset::Combined(rulesets)), + Entry::Vacant(e) => e.insert(Ruleset { + kind: RulesetKind::Combined(rulesets), + timing_role: timing_role.unwrap_or(RulesetTimingRole::Program), + }), }; + Ok(()) } fn add_ruleset(&mut self, name: String) { + let proof_names = &self.proof_state.proof_names; + let timing_role = if [ + &proof_names.path_compress_ruleset_name, + &proof_names.rebuilding_ruleset_name, + &proof_names.rebuilding_cleanup_ruleset_name, + &proof_names.subsume_ruleset_name, + ] + .iter() + .any(|generated| generated.as_str() == name) + { + RulesetTimingRole::Equality + } else { + RulesetTimingRole::Program + }; match self.rulesets.entry(name.clone()) { Entry::Occupied(_) => panic!("Ruleset '{name}' was already present"), - Entry::Vacant(e) => e.insert(Ruleset::Rules(Default::default())), + Entry::Vacant(e) => e.insert(Ruleset { + kind: RulesetKind::Rules(Default::default()), + timing_role, + }), }; } @@ -1933,7 +1991,8 @@ impl EGraph { let run_result = self.backend.run_rules(&[id]); self.backend.free_rule(id); self.backend.free_external_func(ext_id); - run_result.map_err(|e| Error::BackendError(e.to_string()))?; + let iteration_report = run_result.map_err(|e| Error::BackendError(e.to_string()))?; + self.overall_report.commands_check += iteration_report.total_time(); let ext_sc_val = ext_sc.lock().unwrap().take(); let matched = matches!(ext_sc_val, Some(())); @@ -1949,6 +2008,54 @@ impl EGraph { } fn run_command(&mut self, command: ResolvedNCommand) -> Result, Error> { + enum CommandPhase { + Install, + Actions, + Check, + Other, + } + + let phase = match &command { + ResolvedNCommand::Sort { .. } + | ResolvedNCommand::Function(_) + | ResolvedNCommand::Index { .. } + | ResolvedNCommand::AddRuleset(..) + | ResolvedNCommand::UnstableCombinedRuleset(..) + | ResolvedNCommand::NormRule { .. } => CommandPhase::Install, + ResolvedNCommand::CoreAction(_) + | ResolvedNCommand::CoreActions(_) + | ResolvedNCommand::Input { .. } => CommandPhase::Actions, + ResolvedNCommand::Check(..) => CommandPhase::Check, + _ => CommandPhase::Other, + }; + let command_timer = Instant::now(); + let process_before = self.overall_report.process_time(); + let iteration_before = self.overall_report.run.iterations.len(); + let result = self.run_command_inner(command); + let nested_process = self + .overall_report + .process_time() + .saturating_sub(process_before); + let nested_rulesets = self.overall_report.run.iterations[iteration_before..] + .iter() + .map(|iteration| iteration.report.total_time()) + .sum(); + let own_time = command_timer + .elapsed() + .saturating_sub(nested_process + nested_rulesets); + match phase { + CommandPhase::Install => self.overall_report.frontend_install += own_time, + CommandPhase::Actions => self.overall_report.commands_actions += own_time, + CommandPhase::Check => self.overall_report.commands_check += own_time, + CommandPhase::Other => self.overall_report.commands_other += own_time, + } + result + } + + fn run_command_inner( + &mut self, + command: ResolvedNCommand, + ) -> Result, Error> { match command { // Sorts are already declared during typechecking ResolvedNCommand::Sort { @@ -1995,8 +2102,8 @@ impl EGraph { self.add_ruleset(name.clone()); log::info!("Declared ruleset {name}."); } - ResolvedNCommand::UnstableCombinedRuleset(_span, name, others) => { - self.add_combined_ruleset(name.clone(), others); + ResolvedNCommand::UnstableCombinedRuleset(span, name, others) => { + self.add_combined_ruleset(&span, name.clone(), others)?; log::info!("Declared ruleset {name}."); } ResolvedNCommand::NormRule { rule } => { @@ -2015,7 +2122,7 @@ impl EGraph { None => { log::info!("Printed overall statistics"); return Ok(vec![CommandOutput::OverallStatistics( - self.overall_run_report.clone(), + self.overall_report.run.clone(), )]); } Some(path) => { @@ -2023,7 +2130,7 @@ impl EGraph { .map_err(|e| Error::IoError(path.clone().into(), e, span.clone()))?; log::info!("Printed overall statistics to json file {path}"); - serde_json::to_writer(&mut file, &self.overall_run_report).map_err(|e| { + serde_json::to_writer(&mut file, &self.overall_report.run).map_err(|e| { Error::BackendError(format!("failed writing statistics: {e}")) })?; } @@ -2518,7 +2625,9 @@ impl EGraph { if let Some(original_typechecking) = self.proof_state.original_typechecking.as_mut() { // Typecheck using the original egraph // TODO this is ugly- we don't need an entire e-graph just for type information. + let typecheck_timer = Instant::now(); let typechecked = original_typechecking.typecheck_program(&desugared)?; + self.overall_report.typecheck += typecheck_timer.elapsed(); for command in &typechecked { if let Err(reason) = command_supports_proof_encoding( @@ -2535,7 +2644,9 @@ impl EGraph { Ok(proof_form(typechecked, &mut self.parser.symbol_gen)) } else { + let typecheck_timer = Instant::now(); let mut typechecked = self.typecheck_program(&desugared)?; + self.overall_report.typecheck += typecheck_timer.elapsed(); typechecked = remove_globals::remove_globals(typechecked, &mut self.parser.symbol_gen); for command in &typechecked { @@ -2549,6 +2660,18 @@ impl EGraph { /// Leverages previous type information in the [`EGraph`] to do so, adding new type information. /// When will_run is true, adds to `desugared_commands_run_so_far`, which is used for proof checking. fn resolve_command(&mut self, command: Command) -> Result { + let lowering_timer = Instant::now(); + let nested_before = self.overall_report.process_time(); + let resolved = self.resolve_command_inner(command); + let nested = self + .overall_report + .process_time() + .saturating_sub(nested_before); + self.overall_report.frontend_other += lowering_timer.elapsed().saturating_sub(nested); + resolved + } + + fn resolve_command_inner(&mut self, command: Command) -> Result { let resolved_before_proofs = self.resolve_command_before_proofs(command)?; // Add term encoding when it is enabled @@ -2596,7 +2719,9 @@ impl EGraph { } // Now typecheck using self, adding term type information. + let typecheck_timer = Instant::now(); let desugared_typechecked = self.typecheck_program(&desugared)?; + self.overall_report.typecheck += typecheck_timer.elapsed(); // Remove the globals the term encoding itself introduced (its minted // `let`s), the same way source-level globals were removed above. let desugared_typechecked = remove_globals::remove_globals( @@ -2633,20 +2758,24 @@ impl EGraph { .as_ref() .map(|egraph| &egraph.type_info) .unwrap_or(&self.type_info); + let macro_timer = Instant::now(); let macro_expanded = self.command_macros.apply( before_expanded_command, &mut self.parser.symbol_gen, macro_type_info, - )?; + ); + self.overall_report.frontend_other += macro_timer.elapsed(); + let macro_expanded = macro_expanded?; for command in macro_expanded { // handle include specially- we keep them as-is for desugaring if let Command::Include(span, file) = &command { + let include_timer = Instant::now(); let s = std::fs::read_to_string(file) - .map_err(|e| Error::IoError(file.clone().into(), e, span.clone()))?; - let included_program = self - .parser - .get_program_from_string(Some(file.clone()), &s)?; + .map_err(|e| Error::IoError(file.clone().into(), e, span.clone())); + self.overall_report.frontend_other += include_timer.elapsed(); + let s = s?; + let included_program = self.parse_program_timed(Some(file.clone()), &s)?; // run program internal on these include commands let resolved = self.process_program_internal(included_program, run_commands)?; outputs.extend(resolved.outputs); @@ -2700,7 +2829,7 @@ impl EGraph { filename: Option, input: &str, ) -> Result, Error> { - let parsed = self.parser.get_program_from_string(filename, input)?; + let parsed = self.parse_program_timed(filename, input)?; let res = self.process_program_internal(parsed, false)?; Ok(res.resolved.into_iter().map(|c| c.to_command()).collect()) } @@ -2711,8 +2840,7 @@ impl EGraph { filename: Option, input: &str, ) -> Result, Error> { - let parsed = self.parser.get_program_from_string(filename, input)?; - Ok(parsed) + self.parse_program_timed(filename, input) } /// Takes a source program `input`, parses it, runs it, and returns a list of messages. @@ -2725,10 +2853,23 @@ impl EGraph { filename: Option, input: &str, ) -> Result, Error> { - let parsed = self.parser.get_program_from_string(filename, input)?; + let parsed = self.parse_program_timed(filename, input)?; self.run_program(parsed) } + /// Parse through the single accounting boundary shared by source, include, + /// and generated term-encoding text. + pub(crate) fn parse_program_timed( + &mut self, + filename: Option, + input: &str, + ) -> Result, Error> { + let parse_timer = Instant::now(); + let parsed = self.parser.get_program_from_string(filename, input); + self.overall_report.frontend_parse += parse_timer.elapsed(); + Ok(parsed?) + } + /// Get the number of tuples in the database. /// pub fn num_tuples(&self) -> usize { @@ -2780,7 +2921,11 @@ impl EGraph { /// Gets the overall run report and returns it. pub fn get_overall_run_report(&self) -> &RunReport { - &self.overall_run_report + &self.overall_report.run + } + + pub(crate) fn timing_summary(&self) -> Result { + TimingSummary::from_report(&self.overall_report) } /// Convert from an egglog value to a Rust type. @@ -2979,13 +3124,25 @@ impl EGraph { results.push(map); Some(()) })?; - prelude::run_ruleset(self, &ruleset)?; + let rule_ids = match &self.rulesets[&ruleset].kind { + RulesetKind::Rules(rules) => rules.values().map(|(_, id)| *id).collect::>(), + RulesetKind::Combined(_) => unreachable!("the query ruleset was created directly"), + }; + let iteration_report = self + .backend + .run_rules(&rule_ids) + .map_err(|e| Error::BackendError(e.to_string()))?; + self.overall_report.commands_check += iteration_report.total_time(); Ok(()) })(); // Tear the temporary rule + ruleset down whether the body // succeeded or not. - if let Some(Ruleset::Rules(rules)) = self.rulesets.swap_remove(&ruleset) { + if let Some(Ruleset { + kind: RulesetKind::Rules(rules), + .. + }) = self.rulesets.swap_remove(&ruleset) + { for (_, rule) in rules { self.backend.free_rule(rule.1); } @@ -3562,6 +3719,8 @@ pub enum Error { CheckError(Vec, Span), #[error("{1}\nNo such ruleset: {0}")] NoSuchRuleset(String, Span), + #[error("{1}\nCombined ruleset {0} mixes program and equality-maintenance rulesets")] + MixedRulesetResponsibilities(String, Span), #[error( "{1}\nAttempted to add a rule to combined ruleset {0}. Combined rulesets may only depend on other rulesets." )] @@ -3624,6 +3783,56 @@ mod tests { use crate::PureState; + #[test] + fn encoded_source_typecheck_is_charged_to_the_outer_egraph() { + let mut egraph = EGraph::new_with_term_encoding(); + + egraph + .parse_and_run_program(None, "(datatype Math (Num i64)) (let value (Num 1))") + .unwrap(); + + assert!(egraph.overall_report.frontend_parse > std::time::Duration::ZERO); + assert!(egraph.overall_report.typecheck > std::time::Duration::ZERO); + assert!(egraph.overall_report.frontend_other > std::time::Duration::ZERO); + let source_checker = egraph.proof_state.original_typechecking.as_ref().unwrap(); + assert_eq!( + source_checker.overall_report.typecheck, + std::time::Duration::ZERO, + "the child checker must not retain time omitted from the outer summary" + ); + } + + #[test] + fn query_is_recorded_as_command_work_without_persistent_ruleset_rows() { + let mut egraph = EGraph::default(); + egraph + .parse_and_run_program(None, "(relation R (i64)) (R 1) (R 2)") + .unwrap(); + let iterations_before = egraph.overall_report.run.iterations.len(); + let check_time_before = egraph.overall_report.commands_check; + + for _ in 0..2 { + let matches = egraph + .query(crate::vars![x: i64], crate::facts![(R x)]) + .unwrap(); + assert_eq!(matches.len(), 2); + } + + assert_eq!( + egraph.overall_report.run.iterations.len(), + iterations_before + ); + assert!(egraph.overall_report.commands_check > check_time_before); + assert!( + egraph + .timing_summary() + .unwrap() + .rulesets + .iter() + .all(|ruleset| !ruleset.name.contains("query_ruleset")) + ); + } + #[derive(Clone)] struct InnerProduct { vec: ArcSort, @@ -4123,6 +4332,36 @@ mod tests { assert!(matches!(err, Error::NoSuchRuleset(name, _) if name == "test2")); } + #[test] + fn test_combined_ruleset_with_undefined_member_errors() { + let err = EGraph::default() + .parse_and_run_program(None, "(unstable-combined-ruleset combined missing)") + .unwrap_err(); + assert!(matches!(err, Error::NoSuchRuleset(name, _) if name == "missing")); + } + + #[test] + fn test_combined_ruleset_with_mixed_responsibilities_errors() { + let mut egraph = EGraph::default(); + let maintenance = egraph + .proof_state + .proof_names + .rebuilding_ruleset_name + .clone(); + egraph.add_ruleset("program".into()); + egraph.add_ruleset(maintenance.clone()); + + let err = egraph + .add_combined_ruleset( + &span!(), + "mixed".into(), + vec!["program".into(), maintenance], + ) + .unwrap_err(); + + assert!(matches!(err, Error::MixedRulesetResponsibilities(name, _) if name == "mixed")); + } + #[test] fn test_duplicate_rule_name_errors() { let err = EGraph::default() diff --git a/egglog/src/proofs/proof_encoding_helpers.rs b/egglog/src/proofs/proof_encoding_helpers.rs index 35fb7523..aa7a80ab 100644 --- a/egglog/src/proofs/proof_encoding_helpers.rs +++ b/egglog/src/proofs/proof_encoding_helpers.rs @@ -472,7 +472,7 @@ impl ProofInstrumentor<'_> { pub(crate) fn parse_program(&mut self, input: &str) -> Vec { self.egraph.parser.ensure_no_reserved_symbols = false; - let res = self.egraph.parser.get_program_from_string(None, input); + let res = self.egraph.parse_program_timed(None, input); self.egraph.parser.ensure_no_reserved_symbols = true; // This program is generated internally by term encoding, so a parse diff --git a/egglog/src/scheduler.rs b/egglog/src/scheduler.rs index f5d1c608..7ca095c1 100644 --- a/egglog/src/scheduler.rs +++ b/egglog/src/scheduler.rs @@ -188,6 +188,9 @@ impl EGraph { /// /// The iteration is recorded in the overall run report, as in /// [`EGraph::step_rules`]. + /// Lazy rule compilation and the intermediate update flush surround the + /// recorded query/action invocations; an enclosing command therefore + /// attributes that work to command timing rather than ruleset timing. pub fn step_rules_with_scheduler( &mut self, scheduler_id: SchedulerId, @@ -201,13 +204,13 @@ impl EGraph { let Some(r) = rulesets.get(ruleset) else { return Err(Error::BackendError(format!("no such ruleset: {ruleset}"))); }; - match r { - Ruleset::Rules(rules) => { + match &r.kind { + RulesetKind::Rules(rules) => { for (rule_name, (core_rule, _)) in rules.iter() { ids.push((rule_name.clone(), core_rule)); } } - Ruleset::Combined(sub_rulesets) => { + RulesetKind::Combined(sub_rulesets) => { for sub_ruleset in sub_rulesets { collect_rules(sub_ruleset, rulesets, ids)?; } @@ -225,6 +228,7 @@ impl EGraph { self.rulesets = rulesets; return Err(e); } + let timing_role = rulesets[ruleset].timing_role; let mut schedulers = std::mem::take(&mut self.schedulers); let result = (|| -> Result { // Step 1: build all the query/action rules and worklist if have not already @@ -288,8 +292,8 @@ impl EGraph { .map_err(|e| Error::BackendError(e.to_string()))?; // Step 5: combine the reports - let mut query_report = RunReport::singleton(ruleset, query_iter_report); - let mut action_report = RunReport::singleton(ruleset, action_iter_report); + let mut query_report = RunReport::singleton(ruleset, timing_role, query_iter_report); + let mut action_report = RunReport::singleton(ruleset, timing_role, action_iter_report); // query matches don't count query_report.updated = false; @@ -309,7 +313,7 @@ impl EGraph { self.schedulers = schedulers; if let Ok(report) = &result { - self.overall_run_report.union(report.clone()); + self.overall_report.run.union(report.clone()); } result } @@ -509,13 +513,16 @@ mod test { // Because of semi-naive, the exact rules that are run are more than just `test-rule` assert!( report - .search_and_apply_time_per_rule + .search_and_apply_time_per_rule() .keys() .all(|k| k.starts_with("test-rule")) ); - assert_eq!( - report.ruleset_timings.keys().collect::>(), - [&"test".into()] + assert!(!report.iterations.is_empty()); + assert!( + report + .iterations + .iter() + .all(|iteration| iteration.name.as_ref() == "test") ); if report.can_stop { diff --git a/egglog/tests/integration_test.rs b/egglog/tests/integration_test.rs index fa234d7b..878b04b5 100644 --- a/egglog/tests/integration_test.rs +++ b/egglog/tests/integration_test.rs @@ -917,7 +917,7 @@ fn test_print_stats() { let outputs = EGraph::default().parse_and_run_program(None, s).unwrap(); assert_eq!( outputs[1].to_string(), - "Overall statistics:\nRuleset : search 0.000s, apply 0.000s, unattributed 0.000s, merge 0.000s, rebuild 0.000s\n" + "Overall statistics:\nRuleset : assembly 0.000s, search 0.000s, apply 0.000s, unattributed 0.000s, merge 0.000s\nNative rebuild: 0.000s\n" ); } diff --git a/egglog/tests/timing_summary_cli.rs b/egglog/tests/timing_summary_cli.rs index 4133cb20..3de513ea 100644 --- a/egglog/tests/timing_summary_cli.rs +++ b/egglog/tests/timing_summary_cli.rs @@ -30,6 +30,114 @@ fn assert_duration(value: &serde_json::Value) { assert!(duration["nanos"].is_u64()); } +fn ruleset<'a>(summary: &'a serde_json::Value, name: &str) -> &'a serde_json::Value { + summary["rulesets"] + .as_array() + .unwrap() + .iter() + .find(|ruleset| ruleset["name"] == name) + .unwrap_or_else(|| panic!("missing ruleset {name:?}")) +} + +#[test] +fn checks_have_the_same_command_timing_path_with_and_without_term_encoding() { + let program = r#" + (relation item (i64)) + (item 1) + (check (item 1)) + "#; + + for (label, treatment_flags) in [("off", &[][..]), ("term", &["--term-encoding"][..])] { + let directory = temporary_directory(label); + let program_path = directory.join("program.egg"); + let summary_path = directory.join("summary.json"); + std::fs::write(&program_path, program).unwrap(); + let mut arguments = treatment_flags.iter().map(Path::new).collect::>(); + arguments.extend([ + Path::new("--timing-summary"), + summary_path.as_path(), + program_path.as_path(), + ]); + + let output = run_egglog(&arguments); + assert!( + output.status.success(), + "egglog failed in {label} mode: {}", + String::from_utf8_lossy(&output.stderr) + ); + let summary: serde_json::Value = + serde_json::from_slice(&std::fs::read(&summary_path).unwrap()).unwrap(); + + assert!(summary["commands_check_ns"].as_u64().unwrap() > 0); + assert!( + !summary["rulesets"] + .as_array() + .unwrap() + .iter() + .any(|ruleset| { + ruleset["name"] + .as_str() + .is_some_and(|name| name.contains("check_facts_ruleset")) + }) + ); + + std::fs::remove_dir_all(directory).unwrap(); + } +} + +#[test] +fn encoded_equality_rulesets_are_tagged_by_role_not_mixed_with_program_rules() { + let directory = temporary_directory("equality-role"); + let program_path = directory.join("program.egg"); + let summary_path = directory.join("summary.json"); + std::fs::write( + &program_path, + r#" + (datatype Math (Num i64)) + (let one (Num 1)) + (let two (Num 2)) + (union one two) + (run 1) + "#, + ) + .unwrap(); + + let output = run_egglog(&[ + Path::new("--term-encoding"), + Path::new("--timing-summary"), + &summary_path, + &program_path, + ]); + assert!( + output.status.success(), + "term-encoded egglog failed: {}", + String::from_utf8_lossy(&output.stderr) + ); + let summary: serde_json::Value = + serde_json::from_slice(&std::fs::read(&summary_path).unwrap()).unwrap(); + let maintenance_names = summary["rulesets"] + .as_array() + .unwrap() + .iter() + .filter(|ruleset| ruleset["role"] == "equality") + .map(|ruleset| ruleset["name"].as_str().unwrap().to_owned()) + .collect::>(); + + assert!(!maintenance_names.is_empty()); + assert!( + !summary["rulesets"] + .as_array() + .unwrap() + .iter() + .any(|ruleset| { + ruleset["role"] == "program" + && maintenance_names.contains(ruleset["name"].as_str().unwrap()) + }) + ); + + std::fs::remove_dir_all(directory).unwrap(); +} + #[test] fn timing_summary_is_compact_and_works_with_every_report_level() { let program = r#" @@ -71,28 +179,46 @@ fn timing_summary_is_compact_and_works_with_every_report_level() { assert!(!bytes[..bytes.len() - 1].contains(&b'\n')); let summary: serde_json::Value = serde_json::from_slice(&bytes).unwrap(); - assert_eq!(summary.as_object().unwrap().len(), 2); - assert_eq!(summary["schema_version"], 2); + assert_eq!(summary.as_object().unwrap().len(), 10); + assert_eq!(summary["schema_version"], 4); + assert_eq!(summary["commands_check_ns"], 0); + for field in [ + "frontend_parse_ns", + "frontend_other_ns", + "frontend_install_ns", + "typecheck_ns", + "commands_actions_ns", + "commands_other_ns", + ] { + assert!( + summary[field].as_u64().unwrap() > 0, + "expected nonzero {field}" + ); + } let rulesets = summary["rulesets"].as_array().unwrap(); - assert_eq!( - rulesets - .iter() - .map(|ruleset| ruleset["name"].as_str().unwrap()) - .collect::>(), - ["alpha", "zeta"] - ); - for ruleset in rulesets { - assert_eq!(ruleset.as_object().unwrap().len(), 6); - assert!(ruleset["search_ns"].is_u64()); - assert!(ruleset["apply_ns"].is_u64()); - assert!(ruleset["unattributed_ns"].is_u64()); - assert!(ruleset["merge_ns"].is_u64()); - assert!(ruleset["rebuild_ns"].is_u64()); + assert_eq!(rulesets.len(), 2); + assert_eq!(rulesets[0]["name"], "alpha"); + assert_eq!(rulesets[1]["name"], "zeta"); + for ruleset_name in ["alpha", "zeta"] { + let timing = ruleset(&summary, ruleset_name); + assert_eq!(timing["role"], "program"); + for phase in [ + "assembly_ns", + "search_ns", + "apply_ns", + "execution_ns", + "merge_ns", + ] { + assert!(timing[phase].is_u64()); + } } + assert!(summary["native_rebuild_ns"].is_u64()); let report: serde_json::Value = serde_json::from_slice(&std::fs::read(&report_path).unwrap()).unwrap(); for iteration in report["iterations"].as_array().unwrap() { - let split = iteration["rule_set_report"]["pre_merge"]["Split"] + assert!(iteration["name"].is_string()); + assert_eq!(iteration["role"], "program"); + let split = iteration["report"]["rule_set_report"]["pre_merge"]["Split"] .as_object() .unwrap(); assert_eq!(split.len(), 3); @@ -141,7 +267,7 @@ fn parallel_saved_report_uses_combined_pre_merge_shape() { let iterations = report["iterations"].as_array().unwrap(); assert!(!iterations.is_empty()); for iteration in iterations { - let combined = iteration["rule_set_report"]["pre_merge"]["Combined"] + let combined = iteration["report"]["rule_set_report"]["pre_merge"]["Combined"] .as_object() .unwrap(); assert_eq!(combined.len(), 1); @@ -196,7 +322,7 @@ fn stdin_program_writes_timing_summary() { let bytes = std::fs::read(&summary_path).unwrap(); assert_eq!(bytes.last(), Some(&b'\n')); let summary: serde_json::Value = serde_json::from_slice(&bytes).unwrap(); - assert_eq!(summary["schema_version"], 2); + assert_eq!(summary["schema_version"], 4); assert!(summary["rulesets"].is_array()); std::fs::remove_dir_all(directory).unwrap(); } diff --git a/tests/__snapshots__/test_report_rendering.ambr b/tests/__snapshots__/test_report_rendering.ambr index ba3164ba..2b0ef8b9 100644 --- a/tests/__snapshots__/test_report_rendering.ambr +++ b/tests/__snapshots__/test_report_rendering.ambr @@ -42,245 +42,193 @@ | math.egg | 89.8–101.9 MiB | 85.0–97.1 MiB | 0.867–1.04x | CI includes 1 | | rewrite.egg | 118.4–130.5 MiB | 137.5–149.6 MiB | 1.08–1.23x | higher RSS | - ## Phase comparison + ## Slowdown decomposition - *Endpoint cells show a 95% CI (or one-round point) and that phase's share of endpoint wall time. Delta is the signed candidate − baseline mean; Δ contribution is the phase's share of the wall-time change and may be negative or exceed 100% when phases offset. Execution overhead is stored per-ruleset unattributed time. Outside recorded rulesets is wall time minus all five recorded phases; ! marks a negative residual.* + | File | Wall Δ | Typecheck | Frontend | Program | Equality | Commands | Residual | + | --- | ---: | ---: | ---: | ---: | ---: | ---: | ---: | + | Suite total (2 files) | +200 ms | 0% 0 ms | 0% 0 ms | ◆ +58.0% +116 ms | 0% 0 ms | 0% 0 ms | +42.0% +84.0 ms | + | math.egg | -200 ms | 0% 0 ms | 0% 0 ms | ◆ +58.0% -116 ms | 0% 0 ms | 0% 0 ms | +42.0% -84.0 ms | + | rewrite.egg | +400 ms | 0% 0 ms | 0% 0 ms | ◆ +58.0% +232 ms | 0% 0 ms | 0% 0 ms | +42.0% +168 ms | - ### Phase comparison — math.egg + *The Suite total row sums each selected file's candidate − baseline mean; file rows are per-file mean deltas. Each mechanism cell is its share of that row's wall-time change followed by its signed mean time change. Frontend includes parsing, other lowering, and declaration/install commands. Program rules includes every phase of source-origin rulesets except rebuild. Equality/rebuild combines encoded maintenance rulesets with native rebuild tails. Commands includes actions/input, checks, and other schedules. Shares may be negative or exceed 100% when mechanisms offset. ◆ and bold type mark each row's largest absolute share; contributions below 5% are dimmed and improvements are green in Rich and interactive reports. Signed values carry the same information without styling. Residual is wall time minus every recorded leaf; ! means an endpoint's mean residual is negative.* - | Phase | Baseline (95% CI · wall) | Candidate (95% CI · wall) | Delta | Δ contribution | - | --- | ---: | ---: | ---: | ---: | - | Search | 353–455 ms · 40.0% | 273–375 ms · 40.0% | -80.0 ms | +40.0% | - | Apply | 159–205 ms · 18.0% | 123–169 ms · 18.0% | -36.0 ms | +18.0% | - | Execution overhead | 0–0 ns · 0% | 0–0 ns · 0% | 0 ns | 0% | - | Merge | 100–100 ms · 9.90% | 100–100 ms · 12.3% | 0 ns | 0% | - | Rebuild | 40.0–40.0 ms · 3.96% | 40.0–40.0 ms · 4.94% | 0 ns | 0% | - | Outside recorded rulesets | 231–338 ms · 28.1% | 147–254 ms · 24.7% | -84.0 ms | +42.0% | + ## Ruleset drivers - ### Phase comparison — rewrite.egg + *Each panel unfolds the Program and Equality cells from the decomposition. Parent rows exactly match those cells and alone show wall share. Program children contain only source-rule Assembly, Search, Apply, Execution, and Merge; Equality children contain every encoded maintenance ruleset plus one global Native rebuild replaced row. ↳ marks children in every format. Zero children are hidden. Source children are ranked by absolute own-work Δ (top 5 plus an exact per-group Other); every nonzero maintenance child is shown. Important phases include every \|phase Δ\| ≥ max(1 ms, 10% of \|row Δ\|), always include the dominant phase (◆), and appear in Assembly, Search, Apply, Execution, Merge, Rebuild order; … marks omitted nonzero phases.* - | Phase | Baseline (95% CI · wall) | Candidate (95% CI · wall) | Delta | Δ contribution | - | --- | ---: | ---: | ---: | ---: | - | Search | 753–855 ms · 40.0% | 0.913–1.01 s · 40.0% | +160 ms | +40.0% | - | Apply | 339–385 ms · 18.0% | 411–457 ms · 18.0% | +72.0 ms | +18.0% | - | Execution overhead | 0–0 ns · 0% | 0–0 ns · 0% | 0 ns | 0% | - | Merge | 100–100 ms · 4.98% | 100–100 ms · 4.15% | 0 ns | 0% | - | Rebuild | 40.0–40.0 ms · 1.99% | 40.0–40.0 ms · 1.66% | 0 ns | 0% | - | Outside recorded rulesets | 651–758 ms · 35.0% | 819–926 ms · 36.2% | +168 ms | +42.0% | + ### Ruleset drivers — math.egg - ## Ruleset comparison + | Driver | Δ | Wall share | Important phase changes | + | --- | ---: | ---: | --- | + | Program rules — own work | -116 ms | +58.0% | ◆ Search -80.0 ms; Apply -36.0 ms | + | ↳ simplify | -84.0 ms | | ◆ Search -60.0 ms; Apply -24.0 ms | + | ↳ finish | -32.0 ms | | ◆ Search -20.0 ms; Apply -12.0 ms | + | Equality/rebuild — net | 0 ns | 0% | 0 ns | - *Totals show a 95% CI or one-round point. S/A/Exec/M/R are signed candidate − baseline mean deltas for Search, Apply, Execution overhead (stored unattributed time), Merge, and Rebuild.* + *Program + Equality account for +58.0% of this file's wall-time change. Source rules shown: 2/2. Maintenance rules shown: none.* - ### Ruleset comparison — math.egg + ### Ruleset drivers — rewrite.egg - | Ruleset | Baseline total | Candidate total | Total Δ | S Δ | A Δ | Exec Δ | M Δ | R Δ | - | --- | ---: | ---: | ---: | ---: | ---: | ---: | ---: | ---: | - | simplify | 481–588 ms | 397–504 ms | -84.0 ms | -60.0 ms | -24.0 ms | 0 ns | 0 ns | 0 ns | - | finish | 171–212 ms | 139–180 ms | -32.0 ms | -20.0 ms | -12.0 ms | 0 ns | 0 ns | 0 ns | + | Driver | Δ | Wall share | Important phase changes | + | --- | ---: | ---: | --- | + | Program rules — own work | +232 ms | +58.0% | ◆ Search +160 ms; Apply +72.0 ms | + | ↳ simplify | +168 ms | | ◆ Search +120 ms; Apply +48.0 ms | + | ↳ finish | +64.0 ms | | ◆ Search +40.0 ms; Apply +24.0 ms | + | Equality/rebuild — net | 0 ns | 0% | 0 ns | - ### Ruleset comparison — rewrite.egg - - | Ruleset | Baseline total | Candidate total | Total Δ | S Δ | A Δ | Exec Δ | M Δ | R Δ | - | --- | ---: | ---: | ---: | ---: | ---: | ---: | ---: | ---: | - | simplify | 0.901–1.01 s | 1.07–1.18 s | +168 ms | +120 ms | +48.0 ms | 0 ns | 0 ns | 0 ns | - | finish | 331–372 ms | 395–436 ms | +64.0 ms | +40.0 ms | +24.0 ms | 0 ns | 0 ns | 0 ns | + *Program + Equality account for +58.0% of this file's wall-time change. Source rules shown: 2/2. Maintenance rules shown: none.* ''' # --- # name: test_realistic_six_file_rich_120_snapshot ''' - ────────────────────────────────────────────────── Ruleset comparison ────────────────────────────────────────────────── - Totals show a 95% CI or one-round point. S/A/Exec/M/R are signed candidate − baseline mean deltas for Search, Apply, - Execution overhead (stored unattributed time), Merge, and Rebuild. - Ruleset comparison — math.egg - - Ruleset Baseline total Candidate total Total Δ S Δ A Δ Exec Δ M Δ R Δ - ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - ruleset-11 41.9–53.9 ms 37.7–48.5 ms -4.79 ms -2.42 ms -1.21 ms -242 us -606 us -303 us - ruleset-10 38.4–49.4 ms 34.5–44.5 ms -4.39 ms -2.22 ms -1.11 ms -222 us -556 us -278 us - ruleset-09 34.9–44.9 ms 31.4–40.4 ms -3.99 ms -2.02 ms -1.01 ms -202 us -505 us -252 us - ruleset-08 31.4–40.4 ms 28.2–36.4 ms -3.59 ms -1.82 ms -909 us -182 us -454 us -227 us - ruleset-07 27.9–35.9 ms 25.1–32.3 ms -3.19 ms -1.62 ms -808 us -162 us -404 us -202 us - ruleset-06 24.4–31.4 ms 22.0–28.3 ms -2.79 ms -1.41 ms -707 us -141 us -354 us -177 us - ruleset-05 20.9–26.9 ms 18.8–24.3 ms -2.39 ms -1.21 ms -606 us -121 us -303 us -152 us - ruleset-04 17.4–22.5 ms 15.7–20.2 ms -1.99 ms -1.01 ms -505 us -101 us -252 us -126 us - ruleset-03 14.0–18.0 ms 12.6–16.2 ms -1.60 ms -808 us -404 us -80.8 us -202 us -101 us - ruleset-02 10.5–13.5 ms 9.42–12.1 ms -1.20 ms -606 us -303 us -60.6 us -152 us -75.8 us - - Showing 10 of 12 changed rulesets by absolute total delta. - Ruleset comparison — eggcc-extract.egg - - Ruleset Baseline total Candidate total Total Δ S Δ A Δ Exec Δ M Δ R Δ - ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - ruleset-11 73.6–94.8 ms 69.2–89.1 ms -5.05 ms -2.91 ms -1.45 ms -145 us -364 us -182 us - ruleset-10 67.5–86.9 ms 63.5–81.7 ms -4.63 ms -2.67 ms -1.33 ms -133 us -333 us -167 us - ruleset-09 61.4–79.0 ms 57.7–74.3 ms -4.21 ms -2.42 ms -1.21 ms -121 us -303 us -152 us - ruleset-08 55.2–71.1 ms 51.9–66.9 ms -3.79 ms -2.18 ms -1.09 ms -109 us -273 us -136 us - ruleset-07 49.1–63.2 ms 46.1–59.4 ms -3.37 ms -1.94 ms -970 us -97.0 us -242 us -121 us - ruleset-06 43.0–55.3 ms 40.4–52.0 ms -2.95 ms -1.70 ms -848 us -84.8 us -212 us -106 us - ruleset-05 36.8–47.4 ms 34.6–44.6 ms -2.53 ms -1.45 ms -727 us -72.7 us -182 us -90.9 us - ruleset-04 30.7–39.5 ms 28.8–37.1 ms -2.11 ms -1.21 ms -606 us -60.6 us -152 us -75.8 us - ruleset-03 24.5–31.6 ms 23.1–29.7 ms -1.68 ms -970 us -485 us -48.5 us -121 us -60.6 us - ruleset-02 18.4–23.7 ms 17.3–22.3 ms -1.26 ms -727 us -364 us -36.4 us -90.9 us -45.5 us - - Showing 10 of 12 changed rulesets by absolute total delta. - Ruleset comparison — pointer-analysis-small.egg - - Ruleset Baseline total Candidate total Total Δ S Δ A Δ Exec Δ M Δ R Δ - ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - ruleset-11 105–136 ms 103–133 ms -2.41 ms -1.45 ms -727 us -48.5 us -121 us -60.6 us - ruleset-10 96.6–124 ms 94.7–122 ms -2.21 ms -1.33 ms -667 us -44.4 us -111 us -55.5 us - ruleset-09 87.9–113 ms 86.1–111 ms -2.01 ms -1.21 ms -606 us -40.4 us -101 us -50.5 us - ruleset-08 79.1–102 ms 77.5–99.8 ms -1.81 ms -1.09 ms -545 us -36.4 us -90.9 us -45.5 us - ruleset-07 70.3–90.5 ms 68.9–88.7 ms -1.61 ms -970 us -485 us -32.3 us -80.8 us -40.4 us - ruleset-06 61.5–79.2 ms 60.3–77.6 ms -1.41 ms -848 us -424 us -28.3 us -70.7 us -35.4 us - ruleset-05 52.7–67.9 ms 51.7–66.5 ms -1.21 ms -727 us -364 us -24.2 us -60.6 us -30.3 us - ruleset-04 43.9–56.6 ms 43.0–55.4 ms -1.00 ms -606 us -303 us -20.2 us -50.5 us -25.2 us - ruleset-03 35.1–45.3 ms 34.4–44.3 ms -804 us -485 us -242 us -16.2 us -40.4 us -20.2 us - ruleset-02 26.4–33.9 ms 25.8–33.3 ms -603 us -364 us -182 us -12.1 us -30.3 us -15.2 us - - Showing 10 of 12 changed rulesets by absolute total delta. - Ruleset comparison — hardboiled.egg - - Ruleset Baseline total Candidate total Total Δ S Δ A Δ Exec Δ M Δ R Δ - ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - ruleset-11 137–177 ms 140–180 ms +3.14 ms +1.94 ms +970 us +48.5 us +121 us +60.6 us - ruleset-10 126–162 ms 128–165 ms +2.88 ms +1.78 ms +889 us +44.4 us +111 us +55.5 us - ruleset-09 114–147 ms 117–150 ms +2.62 ms +1.62 ms +808 us +40.4 us +101 us +50.5 us - ruleset-08 103–133 ms 105–135 ms +2.35 ms +1.45 ms +727 us +36.4 us +90.9 us +45.5 us - ruleset-07 91.5–118 ms 93.3–120 ms +2.09 ms +1.29 ms +646 us +32.3 us +80.8 us +40.4 us - ruleset-06 80.0–103 ms 81.6–105 ms +1.83 ms +1.13 ms +566 us +28.3 us +70.7 us +35.4 us - ruleset-05 68.6–88.3 ms 70.0–90.1 ms +1.57 ms +970 us +485 us +24.2 us +60.6 us +30.3 us - ruleset-04 57.2–73.6 ms 58.3–75.1 ms +1.31 ms +808 us +404 us +20.2 us +50.5 us +25.2 us - ruleset-03 45.7–58.9 ms 46.7–60.1 ms +1.05 ms +646 us +323 us +16.2 us +40.4 us +20.2 us - ruleset-02 34.3–44.2 ms 35.0–45.1 ms +785 us +485 us +242 us +12.1 us +30.3 us +15.2 us - - Showing 10 of 12 changed rulesets by absolute total delta. - Ruleset comparison — luminal.egg - - Ruleset Baseline total Candidate total Total Δ S Δ A Δ Exec Δ M Δ R Δ - ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - ruleset-11 169–218 ms 179–231 ms +11.6 ms +7.27 ms +3.64 ms +145 us +364 us +182 us - ruleset-10 155–199 ms 164–211 ms +10.6 ms +6.67 ms +3.33 ms +133 us +333 us +167 us - ruleset-09 141–181 ms 149–192 ms +9.67 ms +6.06 ms +3.03 ms +121 us +303 us +152 us - ruleset-08 127–163 ms 134–173 ms +8.70 ms +5.45 ms +2.73 ms +109 us +273 us +136 us - ruleset-07 113–145 ms 119–154 ms +7.73 ms +4.85 ms +2.42 ms +97.0 us +242 us +121 us - ruleset-06 98.6–127 ms 104–135 ms +6.77 ms +4.24 ms +2.12 ms +84.8 us +212 us +106 us - ruleset-05 84.5–109 ms 89.6–115 ms +5.80 ms +3.64 ms +1.82 ms +72.7 us +182 us +90.9 us - ruleset-04 70.4–90.7 ms 74.6–96.1 ms +4.83 ms +3.03 ms +1.51 ms +60.6 us +152 us +75.8 us - ruleset-03 56.3–72.5 ms 59.7–76.9 ms +3.87 ms +2.42 ms +1.21 ms +48.5 us +121 us +60.6 us - ruleset-02 42.2–54.4 ms 44.8–57.7 ms +2.90 ms +1.82 ms +909 us +36.4 us +90.9 us +45.5 us - - Showing 10 of 12 changed rulesets by absolute total delta. - Ruleset comparison — herbie.egg - - Ruleset Baseline total Candidate total Total Δ S Δ A Δ Exec Δ M Δ R Δ + ─────────────────────────────────────────────────── Ruleset drivers ──────────────────────────────────────────────────── + Each panel unfolds the Program and Equality cells from the decomposition. Parent rows exactly match those cells and + alone show wall share. Program children contain only source-rule Assembly, Search, Apply, Execution, and Merge; Equality + children contain every encoded maintenance ruleset plus one global Native rebuild replaced row. ↳ marks children in + every format. Zero children are hidden. Source children are ranked by absolute own-work Δ (top 5 plus an exact per-group + Other); every nonzero maintenance child is shown. Important phases include every |phase Δ| ≥ max(1 ms, 10% of |row Δ|), + always include the dominant phase (◆), and appear in Assembly, Search, Apply, Execution, Merge, Rebuild order; … marks + omitted nonzero phases. + Ruleset drivers — math.egg + + Driver Δ Wall share Important phase changes ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - ruleset-11 201–259 ms 221–284 ms +23.0 ms +14.5 ms +7.27 ms +242 us +606 us +303 us - ruleset-10 184–237 ms 202–261 ms +21.1 ms +13.3 ms +6.67 ms +222 us +556 us +278 us - ruleset-09 167–215 ms 184–237 ms +19.1 ms +12.1 ms +6.06 ms +202 us +505 us +252 us - ruleset-08 151–194 ms 166–213 ms +17.2 ms +10.9 ms +5.45 ms +182 us +454 us +227 us - ruleset-07 134–172 ms 147–190 ms +15.3 ms +9.70 ms +4.85 ms +162 us +404 us +202 us - ruleset-06 117–151 ms 129–166 ms +13.4 ms +8.48 ms +4.24 ms +141 us +354 us +177 us - ruleset-05 100–129 ms 110–142 ms +11.5 ms +7.27 ms +3.64 ms +121 us +303 us +152 us - ruleset-04 83.7–108 ms 92.0–119 ms +9.57 ms +6.06 ms +3.03 ms +101 us +252 us +126 us - ruleset-03 66.9–86.2 ms 73.6–94.8 ms +7.66 ms +4.85 ms +2.42 ms +80.8 us +202 us +101 us - ruleset-02 50.2–64.6 ms 55.2–71.1 ms +5.74 ms +3.64 ms +1.82 ms +60.6 us +152 us +75.8 us - - Showing 10 of 12 changed rulesets by absolute total delta. - ─────────────────────────────────────────────────── Phase comparison ─────────────────────────────────────────────────── - Endpoint cells show a 95% CI (or one-round point) and that phase's share of endpoint wall time. Delta is the signed - candidate − baseline mean; Δ contribution is the phase's share of the wall-time change and may be negative or exceed - 100% when phases offset. Execution overhead is stored per-ruleset unattributed time. Outside recorded rulesets is wall - time minus all five recorded phases; ! marks a negative residual. - Phase comparison — math.egg - - Phase Baseline (95% CI · wall) Candidate (95% CI · wall) Delta Δ contribution + Program rules — own work -29.1 ms +14.6% ◆ Search -15.8 ms; Apply -7.88 ms; Merge -3.94 ms; … + ↳ ruleset-11 -4.48 ms ◆ Search -2.42 ms; Apply -1.21 ms; … + ↳ ruleset-10 -4.11 ms ◆ Search -2.22 ms; Apply -1.11 ms; … + ↳ ruleset-09 -3.74 ms ◆ Search -2.02 ms; Apply -1.01 ms; … + ↳ ruleset-08 -3.36 ms ◆ Search -1.82 ms; … + ↳ ruleset-07 -2.99 ms ◆ Search -1.62 ms; … + ↳ Other (7 more source rulesets) -10.5 ms ◆ Search -5.66 ms; Apply -2.83 ms; Merge -1.41 ms; … + Equality/rebuild — net -1.97 ms +0.985% ◆ Rebuild -1.97 ms + ↳ Native rebuild replaced -1.97 ms ◆ Rebuild -1.97 ms + + Program + Equality account for +15.6% of this file's wall-time change. Source rules shown: 5/12 plus exact Other. + Maintenance rules shown: none. + Ruleset drivers — eggcc-extract.egg + + Driver Δ Wall share Important phase changes ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - Search 138–177 ms · 15.7% 124–160 ms · 17.6% -15.8 ms +7.88% - Apply 68.9–88.7 ms · 7.84% 62.0–79.8 ms · 8.81% -7.88 ms +3.94% - Execution overhead 13.8–17.7 ms · 1.57% 12.4–16.0 ms · 1.76% -1.58 ms +0.788% - Merge 34.4–44.3 ms · 3.92% 31.0–39.9 ms · 4.40% -3.94 ms +1.97% - Rebuild 17.2–22.2 ms · 1.96% 15.5–20.0 ms · 2.20% -1.97 ms +0.985% - Outside recorded rulesets 669–718 ms · 69.0% 497–553 ms · 65.2% -169 ms +84.4% - - Phase comparison — eggcc-extract.egg - - Phase Baseline (95% CI · wall) Candidate (95% CI · wall) Delta Δ contribution + Program rules — own work -31.7 ms +21.1% ◆ Search -18.9 ms; Apply -9.45 ms; … + ↳ ruleset-11 -4.87 ms ◆ Search -2.91 ms; Apply -1.45 ms; … + ↳ ruleset-10 -4.47 ms ◆ Search -2.67 ms; Apply -1.33 ms; … + ↳ ruleset-09 -4.06 ms ◆ Search -2.42 ms; Apply -1.21 ms; … + ↳ ruleset-08 -3.65 ms ◆ Search -2.18 ms; Apply -1.09 ms; … + ↳ ruleset-07 -3.25 ms ◆ Search -1.94 ms; … + ↳ Other (7 more source rulesets) -11.4 ms ◆ Search -6.79 ms; Apply -3.39 ms; … + Equality/rebuild — net -1.18 ms +0.788% ◆ Rebuild -1.18 ms + ↳ Native rebuild replaced -1.18 ms ◆ Rebuild -1.18 ms + + Program + Equality account for +21.9% of this file's wall-time change. Source rules shown: 5/12 plus exact Other. + Maintenance rules shown: none. + Ruleset drivers — pointer-analysis-small.egg + + Driver Δ Wall share Important phase changes ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - Search 275–355 ms · 20.9% 259–333 ms · 21.9% -18.9 ms +12.6% - Apply 138–177 ms · 10.5% 129–167 ms · 10.9% -9.45 ms +6.30% - Execution overhead 13.8–17.7 ms · 1.05% 12.9–16.7 ms · 1.09% -945 us +0.630% - Merge 34.4–44.3 ms · 2.62% 32.4–41.7 ms · 2.73% -2.36 ms +1.58% - Rebuild 17.2–22.2 ms · 1.31% 16.2–20.8 ms · 1.37% -1.18 ms +0.788% - Outside recorded rulesets 952–963 ms · 63.6% 839–842 ms · 62.0% -117 ms +78.1% - - Phase comparison — pointer-analysis-small.egg - - Phase Baseline (95% CI · wall) Candidate (95% CI · wall) Delta Δ contribution + Program rules — own work -15.3 ms — ◆ Search -9.45 ms; Apply -4.73 ms; … + ↳ ruleset-11 -2.35 ms ◆ Search -1.45 ms; … + ↳ ruleset-10 -2.16 ms ◆ Search -1.33 ms; … + ↳ ruleset-09 -1.96 ms ◆ Search -1.21 ms; … + ↳ ruleset-08 -1.76 ms ◆ Search -1.09 ms; … + ↳ ruleset-07 -1.57 ms ◆ Search -970 us; … + ↳ Other (7 more source rulesets) -5.49 ms ◆ Search -3.39 ms; Apply -1.70 ms; … + Equality/rebuild — net -394 us — ◆ Rebuild -394 us + ↳ Native rebuild replaced -394 us ◆ Rebuild -394 us + + Program + Equality coverage is unavailable because wall time did not change. Source rules shown: 5/12 plus exact Other. + Maintenance rules shown: none. + Ruleset drivers — hardboiled.egg + + Driver Δ Wall share Important phase changes ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - Search 413–532 ms · 23.6% 405–522 ms · 23.1% -9.45 ms — - Apply 207–266 ms · 11.8% 202–261 ms · 11.6% -4.73 ms — - Execution overhead 13.8–17.7 ms · 0.786% 13.5–17.4 ms · 0.770% -315 us — - Merge 34.4–44.3 ms · 1.96% 33.7–43.5 ms · 1.93% -788 us — - Rebuild 17.2–22.2 ms · 0.982% 16.9–21.7 ms · 0.963% -394 us — - Outside recorded rulesets 1.19–1.26 s · 60.9% 1.20–1.27 s · 61.7% +15.7 ms — - - Phase comparison — hardboiled.egg - - Phase Baseline (95% CI · wall) Candidate (95% CI · wall) Delta Δ contribution + Program rules — own work +20.0 ms +8.00% ◆ Search +12.6 ms; Apply +6.30 ms; … + ↳ ruleset-11 +3.08 ms ◆ Search +1.94 ms; … + ↳ ruleset-10 +2.82 ms ◆ Search +1.78 ms; … + ↳ ruleset-09 +2.57 ms ◆ Search +1.62 ms; … + ↳ ruleset-08 +2.31 ms ◆ Search +1.45 ms; … + ↳ ruleset-07 +2.05 ms ◆ Search +1.29 ms; … + ↳ Other (7 more source rulesets) +7.18 ms ◆ Search +4.52 ms; Apply +2.26 ms; … + Equality/rebuild — net +394 us +0.158% ◆ Rebuild +394 us + ↳ Native rebuild replaced +394 us ◆ Rebuild +394 us + + Program + Equality account for +8.16% of this file's wall-time change. Source rules shown: 5/12 plus exact Other. + Maintenance rules shown: none. + Ruleset drivers — luminal.egg + + Driver Δ Wall share Important phase changes ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - Search 551–710 ms · 25.2% 562–724 ms · 23.3% +12.6 ms +5.04% - Apply 275–355 ms · 12.6% 281–362 ms · 11.7% +6.30 ms +2.52% - Execution overhead 13.8–17.7 ms · 0.629% 14.0–18.1 ms · 0.583% +315 us +0.126% - Merge 34.4–44.3 ms · 1.57% 35.1–45.2 ms · 1.46% +788 us +0.315% - Rebuild 17.2–22.2 ms · 0.786% 17.6–22.6 ms · 0.729% +394 us +0.158% - Outside recorded rulesets 1.42–1.55 s · 59.3% 1.65–1.78 s · 62.2% +230 ms +91.8% - - Phase comparison — luminal.egg - - Phase Baseline (95% CI · wall) Candidate (95% CI · wall) Delta Δ contribution + Program rules — own work +74.2 ms +12.4% ◆ Search +47.3 ms; Apply +23.6 ms; … + ↳ ruleset-11 +11.4 ms ◆ Search +7.27 ms; Apply +3.64 ms; … + ↳ ruleset-10 +10.5 ms ◆ Search +6.67 ms; Apply +3.33 ms; … + ↳ ruleset-09 +9.51 ms ◆ Search +6.06 ms; Apply +3.03 ms; … + ↳ ruleset-08 +8.56 ms ◆ Search +5.45 ms; Apply +2.73 ms; … + ↳ ruleset-07 +7.61 ms ◆ Search +4.85 ms; Apply +2.42 ms; … + ↳ Other (7 more source rulesets) +26.6 ms ◆ Search +17.0 ms; Apply +8.48 ms; … + Equality/rebuild — net +1.18 ms +0.197% ◆ Rebuild +1.18 ms + ↳ Native rebuild replaced +1.18 ms ◆ Rebuild +1.18 ms + + Program + Equality account for +12.6% of this file's wall-time change. Source rules shown: 5/12 plus exact Other. + Maintenance rules shown: none. + Ruleset drivers — herbie.egg + + Driver Δ Wall share Important phase changes ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - Search 689–887 ms · 26.2% 730–940 ms · 23.2% +47.3 ms +7.88% - Apply 344–443 ms · 13.1% 365–470 ms · 11.6% +23.6 ms +3.94% - Execution overhead 13.8–17.7 ms · 0.524% 14.6–18.8 ms · 0.463% +945 us +0.158% - Merge 34.4–44.3 ms · 1.31% 36.5–47.0 ms · 1.16% +2.36 ms +0.394% - Rebuild 17.2–22.2 ms · 0.655% 18.3–23.5 ms · 0.579% +1.18 ms +0.197% - Outside recorded rulesets 1.65–1.84 s · 58.2% 2.17–2.38 s · 63.1% +525 ms +87.4% - - Phase comparison — herbie.egg - - Phase Baseline (95% CI · wall) Candidate (95% CI · wall) Delta Δ contribution + Program rules — own work +147 ms +14.0% ◆ Search +94.5 ms; Apply +47.3 ms; … + ↳ ruleset-11 +22.7 ms ◆ Search +14.5 ms; Apply +7.27 ms; … + ↳ ruleset-10 +20.8 ms ◆ Search +13.3 ms; Apply +6.67 ms; … + ↳ ruleset-09 +18.9 ms ◆ Search +12.1 ms; Apply +6.06 ms; … + ↳ ruleset-08 +17.0 ms ◆ Search +10.9 ms; Apply +5.45 ms; … + ↳ ruleset-07 +15.1 ms ◆ Search +9.70 ms; Apply +4.85 ms; … + ↳ Other (7 more source rulesets) +52.9 ms ◆ Search +33.9 ms; Apply +17.0 ms; … + Equality/rebuild — net +1.97 ms +0.188% ◆ Rebuild +1.97 ms + ↳ Native rebuild replaced +1.97 ms ◆ Rebuild +1.97 ms + + Program + Equality account for +14.2% of this file's wall-time change. Source rules shown: 5/12 plus exact Other. + Maintenance rules shown: none. + ──────────────────────────────────────────────── Slowdown decomposition ──────────────────────────────────────────────── + + File Wall Δ Typecheck Frontend Program Equality Commands Residual ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - Search 0.826–1.06 s · 27.0% 0.909–1.17 s · 22.8% +94.5 ms +9.00% - Apply 413–532 ms · 13.5% 455–585 ms · 11.4% +47.3 ms +4.50% - Execution overhead 13.8–17.7 ms · 0.450% 15.2–19.5 ms · 0.380% +1.58 ms +0.150% - Merge 34.4–44.3 ms · 1.12% 37.9–48.8 ms · 0.951% +3.94 ms +0.375% - Rebuild 17.2–22.2 ms · 0.562% 18.9–24.4 ms · 0.476% +1.97 ms +0.188% - Outside recorded rulesets 1.89–2.14 s · 57.4% 2.77–3.06 s · 63.9% +901 ms +85.8% - + Suite total (6 +1550 ms 0% 0 ms 0% 0 ms +10.7% +165 ms 0% 0 ms 0% 0 ms ◆ +89.3% +1385 ms + files) + math.egg -200 ms 0% 0 ms 0% 0 ms +14.6% -29.1 ms +0.985% -1.97 ms 0% 0 ms ◆ +84.4% -169 ms + eggcc-extract.egg -150 ms 0% 0 ms 0% 0 ms +21.1% -31.7 ms +0.788% -1.18 ms 0% 0 ms ◆ +78.1% -117 ms + pointer-analysis- 0 ms — 0 ms — 0 ms — -15.3 ms — -0.394 ms — 0 ms — +15.7 ms + small.egg + hardboiled.egg +250 ms 0% 0 ms 0% 0 ms +8.00% +20.0 ms +0.158% +0.394 ms 0% 0 ms ◆ +91.8% +230 ms + luminal.egg +600 ms 0% 0 ms 0% 0 ms +12.4% +74.2 ms +0.197% +1.18 ms 0% 0 ms ◆ +87.4% +525 ms + herbie.egg +1050 ms 0% 0 ms 0% 0 ms +14.0% +147 ms +0.188% +1.97 ms 0% 0 ms ◆ +85.8% +901 ms + + The Suite total row sums each selected file's candidate − baseline mean; file rows are per-file mean deltas. Each + mechanism cell is its share of that row's wall-time change followed by its signed mean time change. Frontend includes + parsing, other lowering, and declaration/install commands. Program rules includes every phase of source-origin rulesets + except rebuild. Equality/rebuild combines encoded maintenance rulesets with native rebuild tails. Commands includes + actions/input, checks, and other schedules. Shares may be negative or exceed 100% when mechanisms offset. ◆ and bold + type mark each row's largest absolute share; contributions below 5% are dimmed and improvements are green in Rich and + interactive reports. Signed values carry the same information without styling. Residual is wall time minus every + recorded leaf; ! means an endpoint's mean residual is negative. ─────────────────────────────────────────────────── Per-file results ─────────────────────────────────────────────────── Wall time - File Baseline (95% CI) Candidate (95% CI) Ratio (95% CI) Result + File Baseline (95% CI) Candidate (95% CI) Ratio (95% CI) Result ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - math.egg 0.941–1.07 s 741–869 ms 0.723–0.885x faster - eggcc-extract.egg 1.44–1.57 s 1.29–1.42 s 0.845–0.959x faster - pointer-analysis-small.egg 1.94–2.07 s 1.94–2.07 s 0.956–1.05x CI includes 1 - hardboiled.egg 2.44–2.57 s 2.69–2.82 s 1.06–1.14x slower - luminal.egg 2.94–3.07 s 3.54–3.67 s 1.17–1.23x slower - herbie.egg 3.44–3.57 s 4.49–4.62 s 1.27–1.33x slower + math.egg 0.941–1.07 s 741–869 ms 0.723–0.885x faster + eggcc-extract.egg 1.44–1.57 s 1.29–1.42 s 0.845–0.959x faster + pointer-analysis-small.egg 1.94–2.07 s 1.94–2.07 s 0.956–1.05x CI includes 1 + hardboiled.egg 2.44–2.57 s 2.69–2.82 s 1.06–1.14x slower + luminal.egg 2.94–3.07 s 3.54–3.67 s 1.17–1.23x slower + herbie.egg 3.44–3.57 s 4.49–4.62 s 1.27–1.33x slower Peak RSS - File Baseline (95% CI) Candidate (95% CI) Ratio (95% CI) Result + File Baseline (95% CI) Candidate (95% CI) Ratio (95% CI) Result ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ - math.egg 89.8–101.9 MiB 99.3–111.4 MiB 1.01–1.20x higher RSS - eggcc-extract.egg 108.9–121.0 MiB 118.4–130.5 MiB 1.01–1.16x higher RSS - pointer-analysis-small.egg 127.9–140.1 MiB 137.5–149.6 MiB 1.01–1.14x higher RSS - hardboiled.egg 147.0–159.1 MiB 156.5–168.7 MiB 1.01–1.12x higher RSS - luminal.egg 166.1–178.2 MiB 175.6–187.7 MiB 1.01–1.11x higher RSS - herbie.egg 185.2–197.3 MiB 194.7–206.8 MiB 1.00–1.10x higher RSS + math.egg 89.8–101.9 MiB 99.3–111.4 MiB 1.01–1.20x higher RSS + eggcc-extract.egg 108.9–121.0 MiB 118.4–130.5 MiB 1.01–1.16x higher RSS + pointer-analysis-small.egg 127.9–140.1 MiB 137.5–149.6 MiB 1.01–1.14x higher RSS + hardboiled.egg 147.0–159.1 MiB 156.5–168.7 MiB 1.01–1.12x higher RSS + luminal.egg 166.1–178.2 MiB 175.6–187.7 MiB 1.01–1.11x higher RSS + herbie.egg 185.2–197.3 MiB 194.7–206.8 MiB 1.00–1.10x higher RSS ────────────────────────────────────────────────────── Comparison ────────────────────────────────────────────────────── diff --git a/tests/report_fixtures.py b/tests/report_fixtures.py index ab2cfc9f..38a81794 100644 --- a/tests/report_fixtures.py +++ b/tests/report_fixtures.py @@ -10,6 +10,7 @@ ReportRecord, ReportStore, RulesetTimingRecord, + RulesetTimingRole, TimingSummaryRecord, ) @@ -62,29 +63,49 @@ def make_record( def make_ruleset_timing( name: str = "rules", *, + assembly_ns: int = 0, search_ns: int = 400_000_000, apply_ns: int = 200_000_000, - unattributed_ns: int = 0, + execution_ns: int = 0, merge_ns: int = 200_000_000, - rebuild_ns: int = 100_000_000, + role: RulesetTimingRole = "program", ) -> RulesetTimingRecord: """Construct one valid ruleset timing fixture.""" return { "name": name, + "role": role, + "assembly_ns": assembly_ns, "search_ns": search_ns, "apply_ns": apply_ns, - "unattributed_ns": unattributed_ns, + "execution_ns": execution_ns, "merge_ns": merge_ns, - "rebuild_ns": rebuild_ns, } -def make_timing_summary(*rulesets: RulesetTimingRecord) -> TimingSummaryRecord: - """Construct a valid v2 timing-summary fixture.""" +def make_timing_summary( + *rulesets: RulesetTimingRecord, + typecheck_ns: int = 0, + frontend_parse_ns: int = 0, + frontend_other_ns: int = 0, + frontend_install_ns: int = 0, + commands_actions_ns: int = 0, + commands_check_ns: int = 0, + commands_other_ns: int = 0, + native_rebuild_ns: int = 100_000_000, +) -> TimingSummaryRecord: + """Construct a valid dense timing-summary fixture.""" return { - "schema_version": 2, + "schema_version": 4, + "typecheck_ns": typecheck_ns, + "frontend_parse_ns": frontend_parse_ns, + "frontend_other_ns": frontend_other_ns, + "frontend_install_ns": frontend_install_ns, + "commands_actions_ns": commands_actions_ns, + "commands_check_ns": commands_check_ns, + "commands_other_ns": commands_other_ns, + "native_rebuild_ns": native_rebuild_ns, "rulesets": list(rulesets or (make_ruleset_timing(),)), } diff --git a/tests/test_collection.py b/tests/test_collection.py index 7a79a309..f2c9abd7 100644 --- a/tests/test_collection.py +++ b/tests/test_collection.py @@ -583,15 +583,24 @@ def fake_run_command(command: list[str], checkout_path: Path, timeout_sec: int) summary_path.write_text( json.dumps( { - "schema_version": 2, + "schema_version": 4, + "typecheck_ns": 1, + "frontend_parse_ns": 2, + "frontend_other_ns": 3, + "frontend_install_ns": 4, + "commands_actions_ns": 5, + "commands_check_ns": 6, + "commands_other_ns": 7, + "native_rebuild_ns": 8, "rulesets": [ { "name": "rules", + "role": "program", + "assembly_ns": 3, "search_ns": 4, "apply_ns": 6, - "unattributed_ns": 10, + "execution_ns": 10, "merge_ns": 20, - "rebuild_ns": 30, } ], } @@ -608,10 +617,18 @@ def fake_run_command(command: list[str], checkout_path: Path, timeout_sec: int) assert "--proofs" not in commands[0] assert "--proofs" in commands[1] assert off.timing_summary is not None - assert off.timing_summary["rulesets"][0]["search_ns"] == 4 - assert off.timing_summary["rulesets"][0]["apply_ns"] == 6 - assert off.timing_summary["rulesets"][0]["unattributed_ns"] == 10 - assert off.timing_summary["rulesets"][0]["merge_ns"] == 20 + assert off.timing_summary["rulesets"] == [ + { + "name": "rules", + "role": "program", + "assembly_ns": 3, + "search_ns": 4, + "apply_ns": 6, + "execution_ns": 10, + "merge_ns": 20, + } + ] + assert off.timing_summary["native_rebuild_ns"] == 8 assert proofs.timing_summary is not None diff --git a/tests/test_report_analysis.py b/tests/test_report_analysis.py index fca465fa..672272dd 100644 --- a/tests/test_report_analysis.py +++ b/tests/test_report_analysis.py @@ -68,10 +68,10 @@ def test_analysis_computes_only_the_requested_detail_rows(tmp_path: Path) -> Non rulesets = analyze_pair(store, comparison, "rulesets") assert len(summary.summary) == 5 - assert not summary.files and not summary.phases and not summary.rulesets - assert files.files and not files.phases and not files.rulesets - assert phases.files and phases.phases and not phases.rulesets - assert rulesets.files and rulesets.phases and rulesets.rulesets + assert not summary.files and not summary.timing + assert files.files and not files.timing + assert phases.files and phases.timing + assert rulesets.files and rulesets.timing def test_pair_statistics_and_fieller_intervals(tmp_path: Path) -> None: @@ -255,26 +255,26 @@ def test_valid_tail_does_not_inherit_an_unrelated_invalid_file_issue(tmp_path: P assert all(row.ratio.issue is None for row in tails) -def test_phase_rows_are_exhaustive_and_outside_is_wall_residual(tmp_path: Path) -> None: +def test_mechanism_buckets_are_additive_and_residual_closes_to_wall(tmp_path: Path) -> None: report = tmp_path / "report.jsonl" comparison = _comparison(tmp_path) baseline_timing = make_timing_summary( make_ruleset_timing( search_ns=100, apply_ns=200, - unattributed_ns=17, + execution_ns=17, merge_ns=300, - rebuild_ns=400, - ) + ), + native_rebuild_ns=400, ) candidate_timing = make_timing_summary( make_ruleset_timing( search_ns=200, apply_ns=100, - unattributed_ns=23, + execution_ns=23, merge_ns=600, - rebuild_ns=200, - ) + ), + native_rebuild_ns=200, ) write_report( report, @@ -294,32 +294,77 @@ def test_phase_rows_are_exhaustive_and_outside_is_wall_residual(tmp_path: Path) ), ) - phases = analyze_pair(ReportStore(report), comparison, "phases").phases + suite, file_row = analyze_pair(ReportStore(report), comparison, "phases").timing - assert [row.phase for row in phases] == [ - "search", - "apply", - "unattributed", - "merge", - "rebuild", - "outside", - ] - assert [(row.baseline.timing.point, row.candidate.timing.point) for row in phases] == [ - (100.0, 200.0), - (200.0, 100.0), - (17.0, 23.0), - (300.0, 600.0), - (400.0, 200.0), - (483.0, 877.0), - ] - assert [row.delta_ns for row in phases] == [100.0, -100.0, 6.0, 300.0, -200.0, 394.0] - assert [row.wall_delta_contribution for row in phases] == pytest.approx([0.2, -0.2, 0.012, 0.6, -0.4, 0.788]) - assert sum(row.wall_delta_contribution or 0.0 for row in phases) == pytest.approx(1.0) - assert phases[0].baseline.wall_share == pytest.approx(100.0 / 1_500.0) - assert phases[-1].candidate.wall_share == pytest.approx(877.0 / 2_000.0) + assert suite.file_order is None + assert file_row.file_order == 0 + assert file_row.wall_delta_ns == pytest.approx(500.0) + assert file_row.mechanism_deltas == pytest.approx([0.0, 0.0, 306.0, -200.0, 0.0, 394.0]) + assert sum(delta or 0.0 for delta in file_row.mechanism_deltas) == pytest.approx(file_row.wall_delta_ns) + assert suite.wall_delta_ns == file_row.wall_delta_ns + assert suite.mechanism_deltas == file_row.mechanism_deltas -def test_phase_endpoints_have_student_t_intervals_and_wall_context(tmp_path: Path) -> None: +def test_process_rulesets_and_global_rebuild_are_each_subtracted_from_residual(tmp_path: Path) -> None: + report = tmp_path / "report.jsonl" + comparison = _comparison(tmp_path) + timing = make_timing_summary( + make_ruleset_timing( + assembly_ns=31, + search_ns=37, + apply_ns=41, + execution_ns=43, + merge_ns=47, + ), + frontend_parse_ns=11, + typecheck_ns=13, + frontend_other_ns=17, + frontend_install_ns=19, + commands_actions_ns=23, + commands_check_ns=7, + commands_other_ns=29, + native_rebuild_ns=53, + ) + zero_timing = make_timing_summary( + make_ruleset_timing( + assembly_ns=0, + search_ns=0, + apply_ns=0, + execution_ns=0, + merge_ns=0, + ), + native_rebuild_ns=0, + ) + write_report( + report, + make_record( + 0, + started_at="2026-07-15T12:00:00Z", + binary_sha256="sha256:baseline", + wall_sec=0.000001, + timing_summary=zero_timing, + ), + make_record( + 1, + started_at="2026-07-15T12:00:01Z", + binary_sha256="sha256:candidate", + wall_sec=0.0000015, + timing_summary=timing, + ), + ) + + views = analyze_pair(ReportStore(report), comparison, "rulesets") + file_row = views.timing[1] + + assert file_row.wall_delta_ns == pytest.approx(500.0) + assert file_row.mechanism_deltas == pytest.approx([13.0, 47.0, 199.0, 53.0, 59.0, 129.0]) + assert sum(delta or 0.0 for delta in file_row.mechanism_deltas) == pytest.approx(500.0) + assert file_row.program.phases == pytest.approx((31, 37, 41, 43, 47, 0)) + assert file_row.equality.phases == pytest.approx((0, 0, 0, 0, 0, 53)) + assert file_row.equality.native_rebuild_delta_ns == 53 + + +def test_mechanism_decomposition_uses_endpoint_means_and_wall_context(tmp_path: Path) -> None: report = tmp_path / "report.jsonl" comparison = _comparison(tmp_path, rounds=2) records: list[ReportRecord] = [] @@ -335,35 +380,29 @@ def test_phase_endpoints_have_student_t_intervals_and_wall_context(tmp_path: Pat binary_sha256=binary_sha256, wall_sec=wall_ns / 1_000_000_000.0, timing_summary=make_timing_summary( - make_ruleset_timing(search_ns=search_ns, apply_ns=0, merge_ns=0, rebuild_ns=0) + make_ruleset_timing(search_ns=search_ns, apply_ns=0, merge_ns=0), + native_rebuild_ns=0, ), ) ) write_report(report, *records) - search = analyze_pair(ReportStore(report), comparison, "phases").phases[0] - half_width = 12.706204736432095 * 100.0 + file_row = analyze_pair(ReportStore(report), comparison, "phases").timing[1] - assert search.baseline.timing.point == 200 - assert search.baseline.timing.ci_low == pytest.approx(200 - half_width) - assert search.baseline.timing.ci_high == pytest.approx(200 + half_width) - assert search.baseline.wall_share == pytest.approx(200 / 1_100) - assert search.candidate.timing.point == 300 - assert search.candidate.wall_share == pytest.approx(300 / 1_600) - assert search.delta_ns == 100 - assert search.wall_delta_contribution == pytest.approx(0.2) + assert file_row.wall_delta_ns == pytest.approx(500.0) + assert file_row.program.phases.total == 100 + assert file_row.residual_delta_ns == 400 -def test_ruleset_union_distinguishes_absence_from_zero_and_aggregates_iterations(tmp_path: Path) -> None: +def test_ruleset_union_aligns_absence_with_zero_and_aggregates_iterations(tmp_path: Path) -> None: report = tmp_path / "report.jsonl" comparison = _comparison(tmp_path, rounds=2) zero = make_ruleset_timing( "recorded-zero", search_ns=0, apply_ns=0, - unattributed_ns=0, + execution_ns=0, merge_ns=0, - rebuild_ns=0, ) write_report( report, @@ -372,9 +411,10 @@ def test_ruleset_union_distinguishes_absence_from_zero_and_aggregates_iterations started_at="2026-07-15T12:00:00Z", binary_sha256="sha256:baseline", timing_summary=make_timing_summary( - make_ruleset_timing("baseline-only", search_ns=10, apply_ns=0, merge_ns=0, rebuild_ns=0), - make_ruleset_timing("sporadic", search_ns=8, apply_ns=0, merge_ns=0, rebuild_ns=0), + make_ruleset_timing("baseline-only", search_ns=10, apply_ns=0, merge_ns=0), + make_ruleset_timing("sporadic", search_ns=8, apply_ns=0, merge_ns=0), zero, + native_rebuild_ns=0, ), ), make_record( @@ -382,8 +422,9 @@ def test_ruleset_union_distinguishes_absence_from_zero_and_aggregates_iterations started_at="2026-07-15T12:00:01Z", binary_sha256="sha256:baseline", timing_summary=make_timing_summary( - make_ruleset_timing("baseline-only", search_ns=10, apply_ns=0, merge_ns=0, rebuild_ns=0), + make_ruleset_timing("baseline-only", search_ns=10, apply_ns=0, merge_ns=0), zero, + native_rebuild_ns=0, ), ), make_record( @@ -391,8 +432,16 @@ def test_ruleset_union_distinguishes_absence_from_zero_and_aggregates_iterations started_at="2026-07-15T12:00:02Z", binary_sha256="sha256:candidate", timing_summary=make_timing_summary( - make_ruleset_timing("candidate-only", search_ns=20, apply_ns=0, merge_ns=0, rebuild_ns=0), + make_ruleset_timing("candidate-only", search_ns=20, apply_ns=0, merge_ns=0), + make_ruleset_timing( + "assembly-only", + assembly_ns=5, + search_ns=0, + apply_ns=0, + merge_ns=0, + ), zero, + native_rebuild_ns=0, ), ), make_record( @@ -400,34 +449,44 @@ def test_ruleset_union_distinguishes_absence_from_zero_and_aggregates_iterations started_at="2026-07-15T12:00:03Z", binary_sha256="sha256:candidate", timing_summary=make_timing_summary( - make_ruleset_timing("candidate-only", search_ns=20, apply_ns=0, merge_ns=0, rebuild_ns=0), + make_ruleset_timing("candidate-only", search_ns=20, apply_ns=0, merge_ns=0), + make_ruleset_timing( + "assembly-only", + assembly_ns=5, + search_ns=0, + apply_ns=0, + merge_ns=0, + ), zero, + native_rebuild_ns=0, ), ), ) - rows = {row.name: row for row in analyze_pair(ReportStore(report), comparison, "rulesets").rulesets} + views = analyze_pair(ReportStore(report), comparison, "rulesets") + file_row = views.timing[1] + rows = {row.name: row for row in file_row.program.rulesets} - assert rows["baseline-only"].baseline == (10, 10, 10) - assert rows["baseline-only"].candidate is None - assert rows["candidate-only"].baseline is None - assert rows["candidate-only"].candidate == (20, 20, 20) - assert rows["sporadic"].baseline is not None - assert rows["sporadic"].baseline.point == 4 - assert rows["baseline-only"].delta.phases.search == -10 - assert rows["candidate-only"].delta.phases.search == 20 + assert rows["baseline-only"].phases.search == -10 + assert rows["candidate-only"].phases.search == 20 + assert rows["sporadic"].phases.search == -4 + assert rows["assembly-only"].phases.assembly == 5 + assert rows["assembly-only"].phases.total == 5 assert "recorded-zero" not in rows + assert len(file_row.program.rulesets) == 4 + assert file_row.program.phases.total == 11 -def test_ruleset_presentation_is_fixed_top_ten_by_absolute_delta_then_name(tmp_path: Path) -> None: +def test_role_changes_are_separate_ruleset_changes_and_rebuild_is_global(tmp_path: Path) -> None: report = tmp_path / "report.jsonl" comparison = _comparison(tmp_path) - names = tuple(reversed(tuple(f"rules-{index:02d}" for index in range(12)))) - baseline_rules = tuple( - make_ruleset_timing(name, search_ns=100, apply_ns=0, merge_ns=0, rebuild_ns=0) for name in names + baseline = make_timing_summary( + make_ruleset_timing("rules/λ", search_ns=10, apply_ns=0, merge_ns=0), + native_rebuild_ns=7, ) - candidate_rules = tuple( - make_ruleset_timing(name, search_ns=101, apply_ns=0, merge_ns=0, rebuild_ns=0) for name in names + candidate = make_timing_summary( + make_ruleset_timing("rules/λ", role="equality", search_ns=12, apply_ns=0, merge_ns=0), + native_rebuild_ns=3, ) write_report( report, @@ -435,21 +494,165 @@ def test_ruleset_presentation_is_fixed_top_ten_by_absolute_delta_then_name(tmp_p 0, started_at="2026-07-15T12:00:00Z", binary_sha256="sha256:baseline", - timing_summary=make_timing_summary(*baseline_rules), + timing_summary=baseline, ), make_record( 1, started_at="2026-07-15T12:00:01Z", binary_sha256="sha256:candidate", - timing_summary=make_timing_summary(*candidate_rules), + timing_summary=candidate, ), ) - rulesets = analyze_pair(ReportStore(report), comparison, "rulesets").rulesets + file_row = analyze_pair(ReportStore(report), comparison, "rulesets").timing[1] + assert file_row.program.rulesets[0].phases.search == -10 + assert file_row.equality.rulesets[0].phases.search == 12 + assert file_row.equality.native_rebuild_delta_ns == -4 + assert file_row.program.rulesets[0].phases.rebuild == 0 + assert file_row.equality.rulesets[0].phases.rebuild == 0 + + +def test_ruleset_parent_groups_equal_program_and_equality_mechanisms(tmp_path: Path) -> None: + report = tmp_path / "report.jsonl" + comparison = _comparison(tmp_path) + candidate = make_timing_summary( + make_ruleset_timing( + "source", + assembly_ns=2, + search_ns=3, + apply_ns=5, + execution_ns=7, + merge_ns=11, + ), + make_ruleset_timing( + "maintenance", + assembly_ns=17, + search_ns=19, + apply_ns=23, + execution_ns=29, + merge_ns=31, + role="equality", + ), + native_rebuild_ns=50, + ) + write_report( + report, + make_record( + 0, + started_at="2026-07-15T12:00:00Z", + binary_sha256="sha256:baseline", + timing_summary=make_timing_summary( + make_ruleset_timing(search_ns=0, apply_ns=0, merge_ns=0), + native_rebuild_ns=0, + ), + ), + make_record( + 1, + started_at="2026-07-15T12:00:01Z", + binary_sha256="sha256:candidate", + timing_summary=candidate, + ), + ) + + views = analyze_pair(ReportStore(report), comparison, "rulesets") + file_row = views.timing[1] + maintenance = file_row.equality.rulesets[0] + assert file_row.program.phases.total == file_row.mechanism_deltas[2] == 28 + assert maintenance.phases.total == 119 + assert file_row.equality.native_rebuild_delta_ns == 50 + assert file_row.equality.phases.total == file_row.mechanism_deltas[3] == 169 + assert maintenance.phases.total + file_row.equality.native_rebuild_delta_ns == file_row.equality.phases.total + + +def test_all_maintenance_children_are_shown_and_zero_native_rebuild_is_hidden(tmp_path: Path) -> None: + report = tmp_path / "report.jsonl" + comparison = _comparison(tmp_path) + names = tuple(f"maintenance-{index}" for index in range(7)) + source = make_ruleset_timing( + "source", + assembly_ns=0, + search_ns=0, + apply_ns=0, + execution_ns=0, + merge_ns=0, + ) + baseline_maintenance = tuple( + make_ruleset_timing( + name, + assembly_ns=0, + search_ns=0, + apply_ns=0, + execution_ns=0, + merge_ns=0, + role="equality", + ) + for name in names + ) + candidate_maintenance = tuple( + make_ruleset_timing( + name, + assembly_ns=0, + search_ns=index + 1, + apply_ns=0, + execution_ns=0, + merge_ns=0, + role="equality", + ) + for index, name in enumerate(names) + ) + write_report( + report, + make_record( + 0, + started_at="2026-07-15T12:00:00Z", + binary_sha256="sha256:baseline", + timing_summary=make_timing_summary(source, *baseline_maintenance), + wall_sec=0.000001, + ), + make_record( + 1, + started_at="2026-07-15T12:00:01Z", + binary_sha256="sha256:candidate", + timing_summary=make_timing_summary(source, *candidate_maintenance), + wall_sec=0.000001, + ), + ) + + file_row = analyze_pair(ReportStore(report), comparison, "rulesets").timing[1] + assert len(file_row.equality.rulesets) == 7 + assert [row.name for row in file_row.equality.rulesets] == list(names) + assert file_row.equality.phases.total == sum(range(1, 8)) + assert file_row.equality.native_rebuild_delta_ns == 0 + + +def test_negative_residual_is_preserved_as_an_attribution_warning(tmp_path: Path) -> None: + report = tmp_path / "report.jsonl" + comparison = _comparison(tmp_path) + timing = make_timing_summary( + make_ruleset_timing(search_ns=10, apply_ns=0, merge_ns=0), + native_rebuild_ns=0, + ) + write_report( + report, + make_record( + 0, + started_at="2026-07-15T12:00:00Z", + binary_sha256="sha256:baseline", + wall_sec=5 / 1_000_000_000, + timing_summary=timing, + ), + make_record( + 1, + started_at="2026-07-15T12:00:01Z", + binary_sha256="sha256:candidate", + wall_sec=6 / 1_000_000_000, + timing_summary=timing, + ), + ) - assert len(rulesets) == 10 - assert [row.name for row in rulesets] == [f"rules-{index:02d}" for index in range(10)] - assert {row.ruleset_count for row in rulesets} == {12} + file_row = analyze_pair(ReportStore(report), comparison, "phases").timing[1] + assert file_row.residual_warning + assert file_row.residual_delta_ns == pytest.approx(1) def _fieller_bounds( diff --git a/tests/test_report_rendering.py b/tests/test_report_rendering.py index 1731c635..79956ff7 100644 --- a/tests/test_report_rendering.py +++ b/tests/test_report_rendering.py @@ -6,19 +6,22 @@ from typing import cast from pytest import MonkeyPatch +from rich import box from rich.cells import cell_len from rich.console import Console from rich.rule import Rule from syrupy.assertion import SnapshotAssertion from benchmarking import models +from benchmarking.reports.analysis import PhaseValues from benchmarking.reports.catalog import ReportCatalog, ReportMessage, ReportTable, report_id from benchmarking.reports.presentation import ( + _important_phase_changes, build_report_catalog, format_duration, report_file_labels, ) -from benchmarking.reports.render import render_markdown_report_document, render_rich_report_document +from benchmarking.reports.render import render_markdown_report_document, render_rich_report_document, render_rich_table from benchmarking.reports.store import ReportRecord, ReportStore from .report_fixtures import ( @@ -31,6 +34,10 @@ ) +def _header_positions(lines: list[str], labels: tuple[str, ...]) -> list[tuple[int, ...]]: + return [tuple(line.index(label) for label in labels) for line in lines if all(label in line for label in labels)] + + def test_report_ids_encode_parts_unambiguously() -> None: assert report_id("target", "ab", "c") != report_id("target", "a", "bc") @@ -133,6 +140,7 @@ def test_shared_formatters_keep_compact_units_and_unambiguous_paths() -> None: def test_rich_report_is_readable_at_realistic_widths(tmp_path: Path) -> None: report_path, comparison = _six_file_pair_case(tmp_path) catalog = build_report_catalog(ReportStore(report_path), comparison, "rulesets") + ellipsis_count: int | None = None for width in (80, 119, 120, 160, 200): console = Console(record=True, width=width, color_system=None) @@ -142,16 +150,25 @@ def test_rich_report_is_readable_at_realistic_widths(tmp_path: Path) -> None: assert rendered.count("Warning: detailed Rich report") == (1 if width < 120 else 0) assert max(cell_len(line) for line in rendered.splitlines()) <= width rule_lines = tuple(line for line in rendered.splitlines() if "─" in line) - assert len(rule_lines) == 5 assert all( any(title in line for line in rule_lines) - for title in ("Ruleset comparison", "Phase comparison", "Per-file results", "Comparison", "Summary —") + for title in ( + "Ruleset drivers", + "Slowdown decomposition", + "Per-file results", + "Comparison", + "Summary —", + ) ) - assert rendered.index("Ruleset comparison") < rendered.index("Phase comparison") - assert rendered.index("Phase comparison") < rendered.index("Per-file results") + assert rendered.index("Ruleset drivers") < rendered.index("Slowdown decomposition") + assert rendered.index("Slowdown decomposition") < rendered.index("Per-file results") assert rendered.index("Per-file results") < rendered.index("Comparison") assert rendered.index("Comparison") < rendered.rindex("Summary —") - assert "…" not in rendered + if ellipsis_count is None: + ellipsis_count = rendered.count("…") + assert ellipsis_count > 0 + else: + assert rendered.count("…") == ellipsis_count assert "Per-file wall time" not in rendered assert "Benchmark summary" not in rendered assert "math.egg" in rendered @@ -178,10 +195,30 @@ def test_realistic_six_file_rich_120_snapshot( rendered = console.export_text() assert rendered == snapshot - assert rendered.count("Ruleset comparison —") == 6 - assert rendered.count("Phase comparison —") == 6 + assert rendered.count("Ruleset drivers —") == 6 + assert rendered.count("Slowdown decomposition") >= 1 assert "Warning: detailed Rich report" not in rendered - assert "…" not in rendered + assert "Other (7 more source rulesets)" in rendered + + +def test_repeated_rich_table_schemas_share_column_positions(tmp_path: Path) -> None: + report_path, comparison = _six_file_pair_case(tmp_path) + catalog = build_report_catalog(ReportStore(report_path), comparison, "rulesets") + + for width in (120, 160, 200): + console = Console(record=True, width=width, color_system=None) + console.print(render_rich_report_document(catalog, width)) + lines = console.export_text().splitlines() + + ruleset_positions = _header_positions(lines, ("Driver", "Δ", "Wall share", "Important phase changes")) + assert len(ruleset_positions) == len(comparison.files) + assert len(set(ruleset_positions)) == 1 + + result_positions = _header_positions( + lines, ("File", "Baseline (95% CI)", "Candidate (95% CI)", "Ratio (95% CI)", "Result") + ) + assert len(result_positions) == 2 + assert len(set(result_positions)) == 1 def test_detail_level_is_cumulative(tmp_path: Path) -> None: @@ -202,67 +239,164 @@ def test_detail_level_is_cumulative(tmp_path: Path) -> None: assert tuple(section.id for section in catalog.sections) == section_ids -def test_phase_detail_has_one_six_row_table_per_file_and_one_guide(tmp_path: Path) -> None: +def test_all_rich_tables_use_one_compact_style(tmp_path: Path) -> None: + report_path, comparison = _pair_case(tmp_path) + catalog = build_report_catalog(ReportStore(report_path), comparison, "rulesets") + tables = [ + render_rich_table(block) + for section in catalog.sections + for block in section.blocks + if isinstance(block, ReportTable) + ] + + assert tables + assert all(table.box is box.SIMPLE_HEAVY and not table.show_lines for table in tables) + + +def test_phase_detail_is_one_additive_decomposition_table(tmp_path: Path) -> None: report_path, comparison = _pair_case(tmp_path) catalog = build_report_catalog(ReportStore(report_path), comparison, "phases") section = next(section for section in catalog.sections if section.id == "phases") - assert isinstance(section.blocks[0], ReportMessage) tables = tuple(block for block in section.blocks if isinstance(block, ReportTable)) - assert len(tables) == len(comparison.files) - expected_columns = ("phase", "baseline", "candidate", "delta", "wall_delta") - assert all(tuple(column.id for column in table.columns) == expected_columns for table in tables) - assert all(len(table.rows) == 6 for table in tables) - + assert len(tables) == 1 + (table,) = tables + assert tuple(column.id for column in table.columns) == ( + "file", + "wall_delta", + "typecheck", + "frontend", + "program", + "equality", + "commands", + "residual", + ) + assert len(table.rows) == len(comparison.files) + 1 + assert table.rows[0].cells[0].display == "Suite total (2 files)" + assert [row.cells[0].display for row in table.rows[1:]] == ["math.egg", "rewrite.egg"] + assert table.columns[3].label == "Frontend" + assert table.columns[4].label == "Program" + assert table.columns[5].label == "Equality" + assert table.caption is not None and "candidate − baseline" in table.caption + assert all("%" in cell.display.partition(" ")[0] for cell in table.rows[0].cells[2:]) + assert all(sum("◆" in cell.display for cell in row.cells[2:]) == 1 for row in table.rows) + assert table.rows[0].cells[2].tone == "muted" + assert table.rows[0].cells[4].tone == "emphasis" + assert table.rows[1].cells[1].tone == "positive" + assert table.rows[1].cells[4].tone == "emphasis" + assert table.rows[1].cells[7].tone == "positive" + + +def test_ruleset_detail_unfolds_program_and_equality_with_explicit_children(tmp_path: Path) -> None: + report_path, comparison = _pair_case(tmp_path) + catalog = build_report_catalog(ReportStore(report_path), comparison, "rulesets") -def test_negative_outside_residual_keeps_an_explicit_warning(tmp_path: Path) -> None: - report_path = tmp_path / "negative-residual.jsonl" + section = next(section for section in catalog.sections if section.id == "rulesets") + guide = section.blocks[0] + assert isinstance(guide, ReportMessage) + assert "Parent rows exactly match" in guide.text + assert "one global Native rebuild replaced row" in guide.text + assert "top 5 plus an exact per-group Other" in guide.text + assert "↳ marks children" in guide.text + assert "max(1 ms, 10% of |row Δ|)" in guide.text + + math = next( + block for block in section.blocks if isinstance(block, ReportTable) and block.title.endswith("math.egg") + ) + rewrite = next( + block for block in section.blocks if isinstance(block, ReportTable) and block.title.endswith("rewrite.egg") + ) + assert tuple(column.id for column in math.columns) == ("driver", "delta", "share", "important_phases") + assert math.columns[2].label == "Wall share" + assert [row.cells[0].display for row in math.rows] == [ + "Program rules — own work", + "↳ simplify", + "↳ finish", + "Equality/rebuild — net", + ] + assert math.rows[0].cells[0].tone == "emphasis" + assert math.rows[0].cells[1].tone == "positive" + assert math.rows[0].cells[3].display == "◆ Search -80.0 ms; Apply -36.0 ms" + assert math.rows[0].cells[2].display == "+58.0%" + assert math.rows[1].cells[2].display == "" + assert math.rows[3].cells[0].tone == "emphasis" + assert math.rows[3].cells[3].display == "0 ns" + assert math.caption is not None and "Program + Equality account for +58.0%" in math.caption + assert rewrite.rows[0].cells[1].tone == "default" + + +def test_ruleset_edges_label_empty_names_and_break_equal_deltas_by_name(tmp_path: Path) -> None: + report_path = tmp_path / "ruleset-ties.jsonl" file = models.FileSpec("file.egg", tmp_path / "file.egg", "sha256:file") baseline = make_endpoint(binary_sha256="sha256:baseline", treatment="off") candidate = make_endpoint(binary_sha256="sha256:candidate", treatment="proofs") + unchanged = make_ruleset_timing("unchanged", search_ns=0, apply_ns=0, merge_ns=0) + tied_names = ("zeta", "beta", "eta", "delta", "gamma", "alpha", "epsilon") write_report( report_path, make_record( 0, started_at="2026-07-17T12:00:00Z", binary_sha256=baseline.target.binary_sha256, - treatment=baseline.treatment, - wall_sec=1.0, - timing_summary=make_timing_summary( - make_ruleset_timing( - search_ns=1_200_000_000, - apply_ns=0, - merge_ns=0, - rebuild_ns=0, - ) - ), + timing_summary=make_timing_summary(unchanged, native_rebuild_ns=0), ), make_record( 1, started_at="2026-07-17T12:00:01Z", binary_sha256=candidate.target.binary_sha256, - treatment=candidate.treatment, + treatment="proofs", wall_sec=1.2, timing_summary=make_timing_summary( - make_ruleset_timing( - search_ns=1_100_000_000, - apply_ns=0, - merge_ns=0, - rebuild_ns=0, - ) + *(make_ruleset_timing(name, search_ns=10_000_000, apply_ns=0, merge_ns=0) for name in tied_names), + make_ruleset_timing("", role="equality", search_ns=1_000_000, apply_ns=0, merge_ns=0), + unchanged, + native_rebuild_ns=0, ), ), ) comparison = models.ComparisonSpec(baseline, candidate, (file,), 1, 120) - markdown = render_markdown_report_document(build_report_catalog(ReportStore(report_path), comparison, "phases")) + catalog = build_report_catalog(ReportStore(report_path), comparison, "rulesets") + section = next(section for section in catalog.sections if section.id == "rulesets") + table = next(block for block in section.blocks if isinstance(block, ReportTable)) + default_ruleset = next(row for row in table.rows if row.cells[0].display == "↳ ") + + assert default_ruleset.cells[0].raw == "" + assert [row.cells[0].display for row in table.rows[:8]] == [ + "Program rules — own work", + "↳ alpha", + "↳ beta", + "↳ delta", + "↳ epsilon", + "↳ eta", + "↳ Other (2 more source rulesets)", + "Equality/rebuild — net", + ] + assert table.rows[6].cells[1].display == "+20.0 ms" + + +def test_ratio_tones_use_green_for_improvements_and_dim_unclear_results(tmp_path: Path) -> None: + report_path, comparison = _pair_case(tmp_path) + catalog = build_report_catalog(ReportStore(report_path), comparison) + summary = next(section for section in catalog.sections if section.id == "summary") + table = next(block for block in summary.blocks if isinstance(block, ReportTable)) + expected = { + "higher": "default", + "invalid": "error", + "lower": "positive", + "point_only": "muted", + "unclear": "muted", + } - assert "!-200 ms · -20.0%" in markdown - assert "! marks a negative residual" in markdown + for row in table.rows: + result = row.cells[4].raw + assert isinstance(result, str) + assert row.cells[3].tone == expected[result] + assert row.cells[4].tone == expected[result] -def test_ruleset_display_distinguishes_absent_from_measured_zero(tmp_path: Path) -> None: - report_path = tmp_path / "ruleset-presence.jsonl" +def test_negative_residual_keeps_an_explicit_warning(tmp_path: Path) -> None: + report_path = tmp_path / "negative-residual.jsonl" file = models.FileSpec("file.egg", tmp_path / "file.egg", "sha256:file") baseline = make_endpoint(binary_sha256="sha256:baseline", treatment="off") candidate = make_endpoint(binary_sha256="sha256:candidate", treatment="proofs") @@ -273,9 +407,14 @@ def test_ruleset_display_distinguishes_absent_from_measured_zero(tmp_path: Path) started_at="2026-07-17T12:00:00Z", binary_sha256=baseline.target.binary_sha256, treatment=baseline.treatment, + wall_sec=1.0, timing_summary=make_timing_summary( - make_ruleset_timing("measured-zero", search_ns=0, apply_ns=0, merge_ns=0, rebuild_ns=0), - make_ruleset_timing("removed", search_ns=10, apply_ns=0, merge_ns=0, rebuild_ns=0), + make_ruleset_timing( + search_ns=1_200_000_000, + apply_ns=0, + merge_ns=0, + ), + native_rebuild_ns=0, ), ), make_record( @@ -283,18 +422,31 @@ def test_ruleset_display_distinguishes_absent_from_measured_zero(tmp_path: Path) started_at="2026-07-17T12:00:01Z", binary_sha256=candidate.target.binary_sha256, treatment=candidate.treatment, + wall_sec=1.2, timing_summary=make_timing_summary( - make_ruleset_timing("measured-zero", search_ns=5, apply_ns=0, merge_ns=0, rebuild_ns=0), - make_ruleset_timing("added", search_ns=20, apply_ns=0, merge_ns=0, rebuild_ns=0), + make_ruleset_timing( + search_ns=1_100_000_000, + apply_ns=0, + merge_ns=0, + ), + native_rebuild_ns=0, ), ), ) comparison = models.ComparisonSpec(baseline, candidate, (file,), 1, 120) - markdown = render_markdown_report_document(build_report_catalog(ReportStore(report_path), comparison, "rulesets")) + markdown = render_markdown_report_document(build_report_catalog(ReportStore(report_path), comparison, "phases")) + + assert "!◆ +150% +300 ms" in markdown + assert "! means an endpoint's mean residual is negative" in markdown + - assert "| measured-zero | 0 ns | 5.00 ns | +5.00 ns |" in markdown - assert "| added | — | 20.0 ns | +20.0 ns |" in markdown +def test_important_phase_changes_use_the_documented_deterministic_threshold() -> None: + phases = PhaseValues(500_000, 10_000_000, 3_000_000, 2_000_000, 4_000_000, 500_000) + + assert _important_phase_changes(phases) == ( + "◆ Search +10.0 ms; Apply +3.00 ms; Execution +2.00 ms; Merge +4.00 ms; …" + ) def test_one_file_summary_removes_redundant_wall_and_rss_tails(tmp_path: Path) -> None: @@ -383,11 +535,20 @@ def test_timed_out_file_has_missing_phase_cells_and_ruleset_status(tmp_path: Pat catalog = build_report_catalog(ReportStore(report_path), comparison, "rulesets") phase_section = next(section for section in catalog.sections if section.id == "phases") phase_table = next(block for block in phase_section.blocks if isinstance(block, ReportTable)) - candidate_column = next(index for index, column in enumerate(phase_table.columns) if column.id == "candidate") - assert all(row.cells[candidate_column].display == "—" for row in phase_table.rows) + assert len(phase_table.rows) == 2 + assert all(cell.display == "—" for row in phase_table.rows for cell in row.cells[1:]) ruleset_section = next(section for section in catalog.sections if section.id == "rulesets") - assert isinstance(ruleset_section.blocks[0], ReportMessage) - assert ruleset_section.blocks[0].text == "Status: timeout row selected" + status = next( + block + for block in ruleset_section.blocks + if isinstance(block, ReportMessage) and block.title == "Ruleset drivers — file.egg" + ) + assert status.text == "Status: timeout row selected" + summary_section = next(section for section in catalog.sections if section.id == "summary") + summary_table = next(block for block in summary_section.blocks if isinstance(block, ReportTable)) + invalid = next(row for row in summary_table.rows if row.cells[4].raw == "invalid") + assert invalid.cells[3].tone == "error" + assert invalid.cells[4].tone == "error" def _pair_case(tmp_path: Path) -> tuple[Path, models.ComparisonSpec]: @@ -431,15 +592,14 @@ def _pair_case(tmp_path: Path) -> tuple[Path, models.ComparisonSpec]: search_ns=int(wall * 300_000_000), apply_ns=int(wall * 120_000_000), merge_ns=80_000_000, - rebuild_ns=30_000_000, ), make_ruleset_timing( "finish", search_ns=int(wall * 100_000_000), apply_ns=int(wall * 60_000_000), merge_ns=20_000_000, - rebuild_ns=10_000_000, ), + native_rebuild_ns=40_000_000, ), ) ) @@ -475,9 +635,8 @@ def _six_file_pair_case(tmp_path: Path) -> tuple[Path, models.ComparisonSpec]: f"ruleset-{ruleset_order:02d}", search_ns=int((ruleset_order + 1) * (file_order + 1) * 2_000_000 * timing_factor), apply_ns=int((ruleset_order + 1) * (file_order + 1) * 1_000_000 * timing_factor), - unattributed_ns=int((ruleset_order + 1) * 200_000 * timing_factor), + execution_ns=int((ruleset_order + 1) * 200_000 * timing_factor), merge_ns=int((ruleset_order + 1) * 500_000 * timing_factor), - rebuild_ns=int((ruleset_order + 1) * 250_000 * timing_factor), ) for ruleset_order in range(12) ) @@ -491,7 +650,12 @@ def _six_file_pair_case(tmp_path: Path) -> tuple[Path, models.ComparisonSpec]: target_label=endpoint.target.row.label, wall_sec=baseline_wall * wall_factor + round_index * 0.01, max_rss_bytes=(100 + file_order * 20 + endpoint_order * 10 + round_index) * 1_000_000, - timing_summary=make_timing_summary(*rulesets), + timing_summary=make_timing_summary( + *rulesets, + native_rebuild_ns=sum( + int((ruleset_order + 1) * 250_000 * timing_factor) for ruleset_order in range(12) + ), + ), ) ) write_report(report_path, *records) diff --git a/tests/test_report_store.py b/tests/test_report_store.py index 7a6c4a1b..4cb12d37 100644 --- a/tests/test_report_store.py +++ b/tests/test_report_store.py @@ -114,10 +114,10 @@ def test_typed_dict_schema_and_nested_values_round_trip(tmp_path: Path) -> None: "rules/λ", search_ns=6, apply_ns=5, - unattributed_ns=4, + execution_ns=4, merge_ns=7, - rebuild_ns=3, - ) + ), + native_rebuild_ns=3, ), ) @@ -129,10 +129,22 @@ def test_typed_dict_schema_and_nested_values_round_trip(tmp_path: Path) -> None: summary = cast(TimingSummaryRecord, loaded["timing_summary"]) assert tuple(summary) == tuple(TimingSummaryRecord.__annotations__) rulesets = cast(list[RulesetTimingRecord], summary["rulesets"]) - assert tuple(rulesets[0]) == tuple(RulesetTimingRecord.__annotations__) - - -@pytest.mark.parametrize("schema_version", [None, 1], ids=["missing", "wrong"]) + assert all(tuple(ruleset) == tuple(RulesetTimingRecord.__annotations__) for ruleset in rulesets) + assert rulesets == [ + { + "name": "rules/λ", + "role": "program", + "assembly_ns": 0, + "search_ns": 6, + "apply_ns": 5, + "execution_ns": 4, + "merge_ns": 7, + } + ] + assert summary["native_rebuild_ns"] == 3 + + +@pytest.mark.parametrize("schema_version", [None, 2], ids=["missing", "wrong"]) def test_incompatible_report_schema_fails_during_load(tmp_path: Path, schema_version: int | None) -> None: report = tmp_path / "report.jsonl" current = make_record(0, started_at="2026-07-15T12:00:00Z") @@ -153,7 +165,7 @@ def test_incompatible_report_shapes_fail_during_load(tmp_path: Path, mixed: bool current = make_record(0, started_at="2026-07-15T12:00:00Z") old = cast(dict[str, object], make_record(1, started_at="2026-07-15T12:00:01Z")) timing = cast(dict[str, object], old["timing_summary"]) - timing["schema_version"] = 1 + timing["schema_version"] = 2 records = (current, old) if mixed else (old,) report.write_text("".join(f"{json.dumps(record)}\n" for record in records), encoding="utf-8")