From 2a97e1493e864839bbd3da3e3622c796fcf3444e Mon Sep 17 00:00:00 2001 From: yoshifuminakamura Date: Mon, 7 Sep 2026 14:58:29 +0900 Subject: [PATCH] Filter usage timing overview to benchmark records Signed-off-by: yoshifuminakamura --- .github/workflows/result-server-tests.yml | 1 + docs/cx/ESTIMATE_JSON_SPEC.md | 41 +++- ..._report_performance_telemetry_section.html | 38 +++- result_server/templates/usage_report.html | 8 +- .../tests/test_performance_telemetry.py | 87 +++++++- .../tests/test_portal_list_templates.py | 20 ++ result_server/tests/test_usage_report_view.py | 12 +- result_server/utils/performance_telemetry.py | 199 +++++++++++++++++- result_server/utils/usage_report_view.py | 5 +- scripts/estimation/run.sh | 29 +++ scripts/tests/test_estimation_run_timing.sh | 58 +++++ 11 files changed, 468 insertions(+), 30 deletions(-) create mode 100644 scripts/tests/test_estimation_run_timing.sh diff --git a/.github/workflows/result-server-tests.yml b/.github/workflows/result-server-tests.yml index 7e0532a9..efdb94d5 100644 --- a/.github/workflows/result-server-tests.yml +++ b/.github/workflows/result-server-tests.yml @@ -79,6 +79,7 @@ jobs: bash scripts/tests/test_scheduler_extra_args.sh bash scripts/tests/test_send_results_profile_data.sh bash scripts/tests/test_send_estimate_artifacts.sh + bash scripts/tests/test_estimation_run_timing.sh bash scripts/tests/test_estimation_gpu_kernel_ensemble_average.sh bash scripts/tests/test_estimation_gpu_kernel_lightgbm_v10.sh bash scripts/tests/test_estimation_gpu_kernel_mlp_v15.sh diff --git a/docs/cx/ESTIMATE_JSON_SPEC.md b/docs/cx/ESTIMATE_JSON_SPEC.md index a45719b6..3ccc393b 100644 --- a/docs/cx/ESTIMATE_JSON_SPEC.md +++ b/docs/cx/ESTIMATE_JSON_SPEC.md @@ -176,6 +176,7 @@ In addition, `target_nodes` represents the estimated node count on each system s 将来拡張として、Estimate JSON は以下の項目を持ってよい。 - `estimate_metadata` +- `estimation_timing` - `measurement` - `assumptions` - `input_artifacts` @@ -310,7 +311,37 @@ When the source benchmark Result JSON carries `input_info`, that auxiliary input `estimation_package` and `estimation_package_version` identify the package that was actually applied. `requested_estimation_package` and `requested_estimation_package_version` identify the package initially requested before any fallback. -### 6.2 measurement +### 6.2 estimation_timing + +推定処理自体の実行時間を保持する任意項目。 + +想定項目: + +- `schema_version` +- `elapsed_time` +- `unit` +- `recorded_by` + +例: + +```json +{ + "estimation_timing": { + "schema_version": 1, + "elapsed_time": 42, + "unit": "s", + "recorded_by": "scripts/estimation/run.sh" + } +} +``` + +`elapsed_time` は推定ジョブ内で app の `estimate.sh` 実行に要した wall-clock 秒数を表す。 +これは推定された benchmark 実行時間ではなく、推定処理そのものの運用コストを観測するための値である。 + +`elapsed_time` records wall-clock seconds spent running the app's `estimate.sh` inside the estimate job. +It is the operational cost of producing the estimate, not the estimated benchmark runtime. + +### 6.3 measurement 推定入力となった計測方法や採取方式を保持する。 @@ -338,7 +369,7 @@ When the source benchmark Result JSON carries `input_info`, that auxiliary input This field stores how the measurement inputs used for estimation were obtained. -### 6.3 model +### 6.4 model 推定モデルの識別情報を保持する。 @@ -378,7 +409,7 @@ For example, `current_system.model` may retain either an `intra_system_scaling_m When needed, a side-specific `model` may contain `source_system`, `target_system`, and `system_compatibility_rule`. -### 6.4 assumptions +### 6.5 assumptions 推定時の仮定を保持する。 @@ -409,7 +440,7 @@ This field may include assumptions such as: - whether a communication-cost adjustment is applied - how problem size is increased -### 6.5 applicability +### 6.6 applicability 推定方式に必要な入力が十分だったか、不足があったか、フォールバックが行われたかを保持する。 @@ -462,7 +493,7 @@ In such a case, `estimate_metadata.requested_estimation_package` identifies the This field records the final applicability state of the estimate, whether fallback was used, and what was missing. -### 6.6 confidence +### 6.7 confidence 推定結果の信頼度や品質指標を保持する。 diff --git a/result_server/templates/_usage_report_performance_telemetry_section.html b/result_server/templates/_usage_report_performance_telemetry_section.html index a99fcd6b..0dbd7c2d 100644 --- a/result_server/templates/_usage_report_performance_telemetry_section.html +++ b/result_server/templates/_usage_report_performance_telemetry_section.html @@ -1,32 +1,48 @@ {% set performance_telemetry = performance_telemetry|default({ "summary": { "result_count": 0, + "ignored_result_count": 0, "timing_record_count": 0, "profiled_result_count": 0, + "regular_run_timing_count": 0, + "profiled_run_timing_count": 0, + "estimate_record_count": 0, + "estimate_timing_record_count": 0, "build_cache_record_count": 0, "build_cache_hit_count": 0, "build_cache_miss_count": 0, "build_cache_store_count": 0, "avg_build_time": "-", "avg_queue_time": "-", - "avg_run_time": "-" + "avg_run_time": "-", + "avg_regular_run_time": "-", + "avg_profiled_run_time": "-", + "avg_estimate_time": "-" }, "rows": [] }, true) %}

Execution Timing Overview

-

Best-effort timing and build-cache telemetry from stored Result JSON. These values summarize observed CI stages; profiler overhead requires a paired non-profile run.

+

Operator view for choosing trigger scope/frequency and improving CI and build-cache flow. It summarizes observed timing and build-cache telemetry from benchmark Result JSON; profiler overhead requires a paired non-profile run.

Timing Records

-

{{ performance_telemetry.summary.timing_record_count }} with timing / {{ performance_telemetry.summary.result_count }} results

+

{{ performance_telemetry.summary.timing_record_count }} with timing / {{ performance_telemetry.summary.result_count }} benchmark results

Average Timing

build {{ performance_telemetry.summary.avg_build_time }} / queue {{ performance_telemetry.summary.avg_queue_time }} / run {{ performance_telemetry.summary.avg_run_time }}

+
+

Run Split

+

regular {{ performance_telemetry.summary.avg_regular_run_time }} / profiled {{ performance_telemetry.summary.avg_profiled_run_time }}

+
+
+

Estimation Runtime

+

{{ performance_telemetry.summary.estimate_timing_record_count }} with timing / {{ performance_telemetry.summary.estimate_record_count }} estimates; avg {{ performance_telemetry.summary.avg_estimate_time }}

+

Build Cache

{{ performance_telemetry.summary.build_cache_hit_count }} hit / {{ performance_telemetry.summary.build_cache_miss_count }} miss / {{ performance_telemetry.summary.build_cache_store_count }} stored

@@ -43,6 +59,8 @@

Build Cache

Results Average Timing Latest Timing + Run Split + Estimation Build Cache Latest Result @@ -65,7 +83,19 @@

Build Cache

build {{ row.latest_build_time }} queue {{ row.latest_queue_time }} - run {{ row.latest_run_time }} + {{ row.latest_run_kind }} run {{ row.latest_run_time }} + + + regular {{ row.avg_regular_run_time }} + {{ row.regular_run_timing_count }} timing records + profiled {{ row.avg_profiled_run_time }} + {{ row.profiled_run_timing_count }} timing records + + + {{ row.estimate_count }} estimates + {{ row.estimate_timing_count }} timing records + avg {{ row.avg_estimate_time }} + latest {{ row.latest_estimate_elapsed_time }} {{ row.build_cache_hit_count }} hit / {{ row.build_cache_miss_count }} miss diff --git a/result_server/templates/usage_report.html b/result_server/templates/usage_report.html index 28dfdf45..16d442d3 100644 --- a/result_server/templates/usage_report.html +++ b/result_server/templates/usage_report.html @@ -160,7 +160,7 @@ white-space: normal; } .performance-telemetry-table { - min-width: 1080px; + min-width: 1420px; table-layout: fixed; } .performance-telemetry-table th:nth-child(1) { width: 140px; } @@ -168,8 +168,10 @@ .performance-telemetry-table th:nth-child(3) { width: 150px; } .performance-telemetry-table th:nth-child(4) { width: 180px; } .performance-telemetry-table th:nth-child(5) { width: 180px; } - .performance-telemetry-table th:nth-child(6) { width: 170px; } - .performance-telemetry-table th:nth-child(7) { width: 220px; } + .performance-telemetry-table th:nth-child(6) { width: 190px; } + .performance-telemetry-table th:nth-child(7) { width: 160px; } + .performance-telemetry-table th:nth-child(8) { width: 170px; } + .performance-telemetry-table th:nth-child(9) { width: 220px; } .performance-telemetry-table td { vertical-align: top; white-space: normal; diff --git a/result_server/tests/test_performance_telemetry.py b/result_server/tests/test_performance_telemetry.py index 32cb5886..dfa03d88 100644 --- a/result_server/tests/test_performance_telemetry.py +++ b/result_server/tests/test_performance_telemetry.py @@ -13,6 +13,8 @@ def _write_json(path, data): def test_performance_telemetry_summarizes_timing_and_build_cache(tmp_path): + estimated_dir = tmp_path / "estimated" + estimated_dir.mkdir() _write_json( tmp_path / "result_20260902_010101_aaaaaaaa-bbbb-cccc-dddd-eeeeeeeeeeee.json", { @@ -45,12 +47,72 @@ def test_performance_telemetry_summarizes_timing_and_build_cache(tmp_path): "FOM": 1.0, }, ) + _write_json( + tmp_path / "result_20260901_030303_dddddddd-bbbb-cccc-dddd-eeeeeeeeeeee.json", + { + "code": "mtls-docker-runner", + "system": None, + }, + ) + _write_json( + tmp_path / "result_20260901_040404_eeeeeeee-bbbb-cccc-dddd-eeeeeeeeeeee.json", + { + "code": "diagnostic-tool", + "system": "Fugaku", + "pipeline_timing": {"build_time": 1}, + }, + ) + _write_json( + tmp_path / "result_20260901_050505_ffffffff-bbbb-cccc-dddd-eeeeeeeeeeee.json", + { + "code": "../qws", + "system": "Fugaku", + "pipeline_timing": {"build_time": 1}, + }, + ) + _write_json( + estimated_dir / "estimate_20260903_010101_11111111-bbbb-cccc-dddd-eeeeeeeeeeee.json", + { + "code": "qws", + "exp": "CASE1", + "estimate_metadata": { + "source_result": { + "system": "Fugaku", + }, + }, + "estimation_timing": { + "elapsed_time": 42, + "unit": "s", + }, + }, + ) + _write_json( + estimated_dir / "estimate_20260903_020202_22222222-bbbb-cccc-dddd-eeeeeeeeeeee.json", + { + "code": "diagnostic-tool", + "exp": "CASE0", + "estimate_metadata": { + "source_result": { + "system": "Fugaku", + }, + }, + "estimation_timing": { + "elapsed_time": 999, + "unit": "s", + }, + }, + ) - telemetry = build_performance_telemetry(str(tmp_path)) + telemetry = build_performance_telemetry(str(tmp_path), str(estimated_dir)) - assert telemetry["summary"]["result_count"] == 3 + assert telemetry["summary"]["result_count"] == 2 + assert telemetry["summary"]["ignored_result_count"] == 4 assert telemetry["summary"]["timing_record_count"] == 2 assert telemetry["summary"]["profiled_result_count"] == 1 + assert telemetry["summary"]["regular_run_timing_count"] == 1 + assert telemetry["summary"]["profiled_run_timing_count"] == 1 + assert telemetry["summary"]["estimate_record_count"] == 1 + assert telemetry["summary"]["estimate_timing_record_count"] == 1 assert telemetry["summary"]["build_cache_record_count"] == 2 assert telemetry["summary"]["build_cache_hit_count"] == 1 assert telemetry["summary"]["build_cache_miss_count"] == 1 @@ -58,33 +120,44 @@ def test_performance_telemetry_summarizes_timing_and_build_cache(tmp_path): assert telemetry["summary"]["avg_build_time"] == "1m" assert telemetry["summary"]["avg_queue_time"] == "1m" assert telemetry["summary"]["avg_run_time"] == "3.5m" + assert telemetry["summary"]["avg_regular_run_time"] == "5m" + assert telemetry["summary"]["avg_profiled_run_time"] == "2m" + assert telemetry["summary"]["avg_estimate_time"] == "42s" rows = {(row["code"], row["system"]): row for row in telemetry["rows"]} + assert set(rows) == {("qws", "Fugaku")} qws = rows[("qws", "Fugaku")] assert qws["result_count"] == 2 assert qws["timing_count"] == 2 assert qws["profiled_count"] == 1 assert qws["avg_build_time"] == "1m" assert qws["avg_run_time"] == "3.5m" + assert qws["avg_regular_run_time"] == "5m" + assert qws["avg_profiled_run_time"] == "2m" assert qws["latest_exp"] == "CASE1" assert qws["latest_build_time"] == "30s" assert qws["latest_queue_time"] == "1m" assert qws["latest_run_time"] == "2m" + assert qws["latest_run_kind"] == "profiled" + assert qws["estimate_count"] == 1 + assert qws["estimate_timing_count"] == 1 + assert qws["avg_estimate_time"] == "42s" + assert qws["latest_estimate_elapsed_time"] == "42s" + assert qws["latest_estimate_exp"] == "CASE1" assert qws["latest_build_cache_status"] == "hit" assert qws["build_cache_hit_count"] == 1 assert qws["build_cache_miss_count"] == 1 assert qws["build_cache_store_count"] == 1 - genesis = rows[("genesis", "RIKYU")] - assert genesis["timing_count"] == 0 - assert genesis["avg_build_time"] == "-" - assert genesis["latest_build_cache_status"] == "-" - def test_performance_telemetry_handles_missing_directory(tmp_path): telemetry = build_performance_telemetry(str(tmp_path / "missing")) assert telemetry["summary"]["result_count"] == 0 + assert telemetry["summary"]["ignored_result_count"] == 0 assert telemetry["summary"]["timing_record_count"] == 0 + assert telemetry["summary"]["estimate_record_count"] == 0 + assert telemetry["summary"]["estimate_timing_record_count"] == 0 assert telemetry["summary"]["avg_build_time"] == "-" + assert telemetry["summary"]["avg_estimate_time"] == "-" assert telemetry["rows"] == [] diff --git a/result_server/tests/test_portal_list_templates.py b/result_server/tests/test_portal_list_templates.py index be1a2bf5..67426567 100644 --- a/result_server/tests/test_portal_list_templates.py +++ b/result_server/tests/test_portal_list_templates.py @@ -669,6 +669,10 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality(): "result_count": 1, "timing_record_count": 1, "profiled_result_count": 0, + "regular_run_timing_count": 1, + "profiled_run_timing_count": 0, + "estimate_record_count": 1, + "estimate_timing_record_count": 1, "build_cache_record_count": 1, "build_cache_hit_count": 1, "build_cache_miss_count": 0, @@ -676,6 +680,9 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality(): "avg_build_time": "30s", "avg_queue_time": "1m", "avg_run_time": "2m", + "avg_regular_run_time": "2m", + "avg_profiled_run_time": "-", + "avg_estimate_time": "42s", }, "rows": [ { @@ -684,12 +691,22 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality(): "result_count": 1, "timing_count": 1, "profiled_count": 0, + "regular_run_timing_count": 1, + "profiled_run_timing_count": 0, + "estimate_count": 1, + "estimate_timing_count": 1, "avg_build_time": "30s", "avg_queue_time": "1m", "avg_run_time": "2m", + "avg_regular_run_time": "2m", + "avg_profiled_run_time": "-", + "avg_estimate_time": "42s", "latest_build_time": "30s", "latest_queue_time": "1m", "latest_run_time": "2m", + "latest_run_kind": "regular", + "latest_estimate_elapsed_time": "42s", + "latest_estimate_exp": "CASE0", "build_cache_hit_count": 1, "build_cache_miss_count": 0, "build_cache_store_count": 0, @@ -735,7 +752,10 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality(): assert "Evidence Snapshot" in html assert "Execution Timing Overview" in html + assert "Operator view for choosing trigger scope/frequency and improving CI and build-cache flow" in html assert "build 30s / queue 1m / run 2m" in html + assert "regular 2m / profiled -" in html + assert "1 with timing / 1 estimates; avg 42s" in html assert "1 hit / 0 miss" in html assert "Result / Quality" in html assert "Application/System Coverage" not in html diff --git a/result_server/tests/test_usage_report_view.py b/result_server/tests/test_usage_report_view.py index 056562ce..b6b485c8 100644 --- a/result_server/tests/test_usage_report_view.py +++ b/result_server/tests/test_usage_report_view.py @@ -42,7 +42,11 @@ def test_build_usage_report_context_builds_evidence_snapshot_context(monkeypatch monkeypatch.setattr( usage_report_view, "build_performance_telemetry", - lambda directory: {"summary": {"result_count": 0}, "rows": []}, + lambda directory, estimated_dir: { + "summary": {"result_count": 0}, + "rows": [], + "estimated_dir": estimated_dir, + }, ) monkeypatch.setattr( usage_report_view, @@ -62,5 +66,9 @@ def test_build_usage_report_context_builds_evidence_snapshot_context(monkeypatch assert context["filtered_periods"] == ["FY2025"] assert context["site_diagnostics"] == {"registered_system_count": 1} assert context["profile_usage_overview"] == {"available": False, "rows": []} - assert context["performance_telemetry"] == {"summary": {"result_count": 0}, "rows": []} + assert context["performance_telemetry"] == { + "summary": {"result_count": 0}, + "rows": [], + "estimated_dir": "received", + } assert context["evidence_snapshot"] == {"rows": []} diff --git a/result_server/utils/performance_telemetry.py b/result_server/utils/performance_telemetry.py index b63adf3e..4fec7a0f 100644 --- a/result_server/utils/performance_telemetry.py +++ b/result_server/utils/performance_telemetry.py @@ -3,7 +3,9 @@ from __future__ import annotations import os +import re from datetime import datetime +from pathlib import Path from typing import Any from utils.node_hours import extract_timestamp_from_filename @@ -11,17 +13,27 @@ TIMING_FIELDS = ("build_time", "queue_time", "run_time") +CODE_COMPONENT_RE = re.compile(r"[A-Za-z0-9][A-Za-z0-9_.-]*") +REPO_ROOT = Path(__file__).resolve().parents[2] -def build_performance_telemetry(received_dir: str) -> dict[str, Any]: - """Summarize available timing records without adding new result contracts.""" +def build_performance_telemetry(received_dir: str, estimated_dir: str | None = None) -> dict[str, Any]: + """Summarize available timing records for operator usage reports.""" records = _load_result_records(received_dir) rows_by_key: dict[tuple[str, str], dict[str, Any]] = {} totals = _empty_timing_totals() + regular_run_totals = _empty_scalar_total() + profiled_run_totals = _empty_scalar_total() + estimate_totals = _empty_scalar_total() summary = { - "result_count": len(records), + "result_count": 0, + "ignored_result_count": 0, "timing_record_count": 0, "profiled_result_count": 0, + "regular_run_timing_count": 0, + "profiled_run_timing_count": 0, + "estimate_record_count": 0, + "estimate_timing_record_count": 0, "build_cache_record_count": 0, "build_cache_hit_count": 0, "build_cache_miss_count": 0, @@ -30,9 +42,14 @@ def build_performance_telemetry(received_dir: str) -> dict[str, Any]: for record in records: data = record["data"] + if not _is_performance_record(data): + summary["ignored_result_count"] += 1 + continue + code = _clean(data.get("code")) or "unknown" system = _clean(data.get("system")) or "unknown" key = (code, system) + summary["result_count"] += 1 row = rows_by_key.setdefault( key, { @@ -41,6 +58,10 @@ def build_performance_telemetry(received_dir: str) -> dict[str, Any]: "result_count": 0, "timing_count": 0, "profiled_count": 0, + "regular_run_timing_count": 0, + "profiled_run_timing_count": 0, + "estimate_count": 0, + "estimate_timing_count": 0, "build_cache_hit_count": 0, "build_cache_miss_count": 0, "build_cache_store_count": 0, @@ -50,11 +71,20 @@ def build_performance_telemetry(received_dir: str) -> dict[str, Any]: "latest_build_time": "-", "latest_queue_time": "-", "latest_run_time": "-", + "latest_run_kind": "-", "latest_build_cache_status": "-", + "latest_estimate_file": "", + "latest_estimate_time": "-", + "latest_estimate_elapsed_time": "-", + "latest_estimate_exp": "-", "_timing_totals": _empty_timing_totals(), + "_regular_run_totals": _empty_scalar_total(), + "_profiled_run_totals": _empty_scalar_total(), + "_estimate_totals": _empty_scalar_total(), }, ) row["result_count"] += 1 + is_profiled = _has_profile_data(data) timing = _timing_values(data.get("pipeline_timing")) if timing: @@ -62,13 +92,26 @@ def build_performance_telemetry(received_dir: str) -> dict[str, Any]: summary["timing_record_count"] += 1 _add_timing_totals(row["_timing_totals"], timing) _add_timing_totals(totals, timing) + run_time = timing.get("run_time") + if run_time is not None: + if is_profiled: + row["profiled_run_timing_count"] += 1 + summary["profiled_run_timing_count"] += 1 + _add_scalar_total(row["_profiled_run_totals"], run_time) + _add_scalar_total(profiled_run_totals, run_time) + else: + row["regular_run_timing_count"] += 1 + summary["regular_run_timing_count"] += 1 + _add_scalar_total(row["_regular_run_totals"], run_time) + _add_scalar_total(regular_run_totals, run_time) if row["latest_result_file"] == record["filename"]: row["latest_build_time"] = _format_seconds(timing.get("build_time")) row["latest_queue_time"] = _format_seconds(timing.get("queue_time")) row["latest_run_time"] = _format_seconds(timing.get("run_time")) + row["latest_run_kind"] = "profiled" if is_profiled else "regular" - if _has_profile_data(data): + if is_profiled: row["profiled_count"] += 1 summary["profiled_result_count"] += 1 @@ -88,6 +131,9 @@ def build_performance_telemetry(received_dir: str) -> dict[str, Any]: row["build_cache_store_count"] += 1 summary["build_cache_store_count"] += 1 + if estimated_dir: + _merge_estimate_timing(rows_by_key, estimated_dir, summary, estimate_totals) + rows = [_finalize_row(row) for row in rows_by_key.values()] rows.sort(key=lambda row: (row["code"].lower(), row["system"].lower())) @@ -99,6 +145,9 @@ def build_performance_telemetry(received_dir: str) -> dict[str, Any]: "avg_build_time": _format_average(totals, "build_time"), "avg_queue_time": _format_average(totals, "queue_time"), "avg_run_time": _format_average(totals, "run_time"), + "avg_regular_run_time": _format_scalar_average(regular_run_totals), + "avg_profiled_run_time": _format_scalar_average(profiled_run_totals), + "avg_estimate_time": _format_scalar_average(estimate_totals), } ) @@ -109,25 +158,39 @@ def build_performance_telemetry(received_dir: str) -> dict[str, Any]: def _load_result_records(received_dir: str) -> list[dict[str, Any]]: + return _load_json_records(received_dir) + + +def _load_estimate_records(estimated_dir: str) -> list[dict[str, Any]]: + return _load_json_records(estimated_dir, prefix="estimate_") + + +def _load_json_records(directory: str, *, prefix: str = "") -> list[dict[str, Any]]: try: - filenames = [name for name in os.listdir(received_dir) if name.endswith(".json")] + filenames = [ + name + for name in os.listdir(directory) + if name.endswith(".json") and (not prefix or name.startswith(prefix)) + ] except OSError: filenames = [] records = [] for filename in filenames: - data = load_result_json(filename, received_dir) + data = load_result_json(filename, directory) if not isinstance(data, dict): continue + timestamp = extract_timestamp_from_filename(filename) records.append( { "filename": filename, - "timestamp": extract_timestamp_from_filename(filename), + "timestamp": timestamp, + "sort_key": timestamp or datetime.min, "timestamp_label": format_result_timestamp(filename), "data": data, } ) - records.sort(key=lambda record: record["timestamp"] or datetime.min, reverse=True) + records.sort(key=lambda record: record["sort_key"], reverse=True) return records @@ -152,13 +215,65 @@ def _add_timing_totals(totals: dict[str, dict[str, float | int]], timing: dict[s totals[field]["count"] = int(totals[field]["count"]) + 1 +def _empty_scalar_total() -> dict[str, float | int]: + return {"sum": 0.0, "count": 0} + + +def _add_scalar_total(total: dict[str, float | int], value: float) -> None: + total["sum"] = float(total["sum"]) + value + total["count"] = int(total["count"]) + 1 + + +def _merge_estimate_timing( + rows_by_key: dict[tuple[str, str], dict[str, Any]], + estimated_dir: str, + summary: dict[str, Any], + estimate_totals: dict[str, float | int], +) -> None: + for record in _load_estimate_records(estimated_dir): + data = record["data"] + if not _is_estimate_record(data): + continue + summary["estimate_record_count"] += 1 + + key = _estimate_row_key(data) + if key is None: + continue + row = rows_by_key.get(key) + if row is None: + continue + + row["estimate_count"] += 1 + elapsed_time = _estimate_elapsed_time(data) + if elapsed_time is not None: + row["estimate_timing_count"] += 1 + summary["estimate_timing_record_count"] += 1 + _add_scalar_total(row["_estimate_totals"], elapsed_time) + _add_scalar_total(estimate_totals, elapsed_time) + + current_sort_key = row.get("_estimate_sort_key") + if current_sort_key is None or current_sort_key < record["sort_key"]: + row["_estimate_sort_key"] = record["sort_key"] + row["latest_estimate_file"] = record["filename"] + row["latest_estimate_time"] = record["timestamp_label"] + row["latest_estimate_elapsed_time"] = _format_seconds(elapsed_time) + row["latest_estimate_exp"] = _clean(data.get("exp")) or "-" + + def _finalize_row(row: dict[str, Any]) -> dict[str, Any]: totals = row.pop("_timing_totals") + regular_run_totals = row.pop("_regular_run_totals") + profiled_run_totals = row.pop("_profiled_run_totals") + estimate_totals = row.pop("_estimate_totals") + row.pop("_estimate_sort_key", None) row.update( { "avg_build_time": _format_average(totals, "build_time"), "avg_queue_time": _format_average(totals, "queue_time"), "avg_run_time": _format_average(totals, "run_time"), + "avg_regular_run_time": _format_scalar_average(regular_run_totals), + "avg_profiled_run_time": _format_scalar_average(profiled_run_totals), + "avg_estimate_time": _format_scalar_average(estimate_totals), } ) return row @@ -172,6 +287,13 @@ def _format_average(totals: dict[str, dict[str, float | int]], field: str) -> st return _format_seconds(float(item["sum"]) / count) +def _format_scalar_average(total: dict[str, float | int]) -> str: + count = int(total["count"]) + if count == 0: + return "-" + return _format_seconds(float(total["sum"]) / count) + + def _format_seconds(value: float | None) -> str: if value is None: return "-" @@ -200,5 +322,66 @@ def _has_profile_data(data: dict[str, Any]) -> bool: return isinstance(profile_data, dict) and bool(profile_data) +def _is_performance_record(data: dict[str, Any]) -> bool: + code = _clean(data.get("code")) + system = _clean(data.get("system")) + if not code or not system: + return False + if not CODE_COMPONENT_RE.fullmatch(code): + return False + if not (REPO_ROOT / "programs" / code).is_dir(): + return False + return bool( + _timing_values(data.get("pipeline_timing")) + or _has_profile_data(data) + or _has_build_cache_data(data) + ) + + +def _is_estimate_record(data: dict[str, Any]) -> bool: + code = _clean(data.get("code")) + if not code or not CODE_COMPONENT_RE.fullmatch(code): + return False + return (REPO_ROOT / "programs" / code).is_dir() + + +def _estimate_row_key(data: dict[str, Any]) -> tuple[str, str] | None: + code = _clean(data.get("code")) + system = ( + _clean(_nested_value(data, "estimate_metadata", "source_result", "system")) + or _clean(_nested_value(data, "estimate_metadata", "future_source_result", "system")) + or _clean(_nested_value(data, "current_system", "benchmark", "system")) + or _clean(_nested_value(data, "current_system", "system")) + ) + if not code or not system: + return None + return (code, system) + + +def _estimate_elapsed_time(data: dict[str, Any]) -> float | None: + timing = data.get("estimation_timing") + if not isinstance(timing, dict): + return None + for field in ("elapsed_time", "elapsed_seconds", "duration_seconds", "duration"): + value = _as_float(timing.get(field)) + if value is not None: + return value + return None + + +def _has_build_cache_data(data: dict[str, Any]) -> bool: + build_cache = data.get("build_cache") + return isinstance(build_cache, dict) and bool(build_cache) + + +def _nested_value(data: dict[str, Any], *path: str) -> Any: + value: Any = data + for key in path: + if not isinstance(value, dict): + return None + value = value.get(key) + return value + + def _clean(value: Any) -> str: return str(value or "").strip() diff --git a/result_server/utils/usage_report_view.py b/result_server/utils/usage_report_view.py index 85af1a0a..36b36c22 100644 --- a/result_server/utils/usage_report_view.py +++ b/result_server/utils/usage_report_view.py @@ -34,7 +34,10 @@ def build_usage_report_context( "filtered_periods": filtered_periods, "site_diagnostics": build_site_diagnostics(), "profile_usage_overview": build_profile_usage_overview(received_dir, db_path), - "performance_telemetry": build_performance_telemetry(received_dir), + "performance_telemetry": build_performance_telemetry( + received_dir, + estimated_dir or received_dir, + ), "evidence_snapshot": build_evidence_snapshot( received_dir, estimated_dir or received_dir, diff --git a/scripts/estimation/run.sh b/scripts/estimation/run.sh index 7d1732f2..5c2456a3 100644 --- a/scripts/estimation/run.sh +++ b/scripts/estimation/run.sh @@ -18,6 +18,29 @@ if [[ ! -f "$estimate_script" ]]; then exit 0 fi +record_estimate_timing() { + local elapsed_time="$1" + shift + + local json_file + for json_file in "$@"; do + [[ -f "$json_file" ]] || continue + local tmp_file="${json_file}.timing.$$" + if ! jq --argjson elapsed_time "$elapsed_time" ' + .estimation_timing = ((.estimation_timing // {}) + { + schema_version: 1, + elapsed_time: $elapsed_time, + unit: "s", + recorded_by: "scripts/estimation/run.sh" + }) + ' "$json_file" > "$tmp_file"; then + rm -f "$tmp_file" + return 1 + fi + mv "$tmp_file" "$json_file" + done +} + # Run estimation for each result JSON found=0 for json_file in results/result[0-9]*.json; do @@ -30,7 +53,13 @@ for json_file in results/result[0-9]*.json; do jq . results/server_result_meta.json || true fi echo "Running estimation: $estimate_script $json_file" + marker_file=$(mktemp "${TMPDIR:-/tmp}/benchkit-estimate-marker.XXXXXX") + estimate_start=$SECONDS bash "$estimate_script" "$json_file" + estimate_elapsed=$((SECONDS - estimate_start)) + mapfile -t estimate_outputs < <(find results -maxdepth 1 -type f -name 'estimate*.json' -newer "$marker_file" | sort) + rm -f "$marker_file" + record_estimate_timing "$estimate_elapsed" "${estimate_outputs[@]}" done if [[ "$found" -eq 0 ]]; then diff --git a/scripts/tests/test_estimation_run_timing.sh b/scripts/tests/test_estimation_run_timing.sh new file mode 100644 index 00000000..57e756bc --- /dev/null +++ b/scripts/tests/test_estimation_run_timing.sh @@ -0,0 +1,58 @@ +#!/bin/bash +set -euo pipefail + +SCRIPT_DIR=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd) +REPO_DIR=$(cd "${SCRIPT_DIR}/../.." && pwd) + +if ! command -v jq >/dev/null 2>&1; then + echo "jq not found; skipping estimation run timing test" + exit 0 +fi + +TMP_DIR=$(mktemp -d) +trap 'rm -rf "${TMP_DIR}"' EXIT + +mkdir -p "${TMP_DIR}/programs/timingapp" "${TMP_DIR}/scripts/estimation" "${TMP_DIR}/results" +cp "${REPO_DIR}/scripts/estimation/run.sh" "${TMP_DIR}/scripts/estimation/run.sh" + +cat > "${TMP_DIR}/programs/timingapp/estimate.sh" <<'EOF' +#!/bin/bash +set -euo pipefail + +input_json="$1" +mkdir -p results +jq -n \ + --arg source_system "$(jq -r '.system' "$input_json")" \ + '{ + code: "timingapp", + exp: "CASE0", + estimate_metadata: { + source_result: { + system: $source_system + } + } + }' > results/estimate_timingapp_0.json +EOF +chmod +x "${TMP_DIR}/programs/timingapp/estimate.sh" + +cat > "${TMP_DIR}/results/result0.json" <<'JSON' +{ + "code": "timingapp", + "system": "TestSystem", + "Exp": "CASE0", + "FOM": 1.0 +} +JSON + +pushd "${TMP_DIR}" >/dev/null +bash scripts/estimation/run.sh timingapp >/dev/null +popd >/dev/null + +jq -e ' + .estimation_timing.schema_version == 1 and + .estimation_timing.elapsed_time >= 0 and + .estimation_timing.unit == "s" and + .estimation_timing.recorded_by == "scripts/estimation/run.sh" +' "${TMP_DIR}/results/estimate_timingapp_0.json" >/dev/null + +echo "estimation run timing test passed"