From 2fc2b34f88485b1f1a2cda3cfde8771cb6ca5e41 Mon Sep 17 00:00:00 2001 From: yoshifuminakamura Date: Wed, 9 Sep 2026 16:00:57 +0900 Subject: [PATCH] Track scheduler queue timing metadata Signed-off-by: yoshifuminakamura --- ..._report_performance_telemetry_section.html | 17 +++++- .../tests/test_performance_telemetry.py | 25 ++++++++- .../tests/test_portal_list_templates.py | 10 ++++ result_server/utils/performance_telemetry.py | 54 ++++++++++++++++++- scripts/collect_timing.sh | 9 ++-- scripts/result.sh | 3 ++ .../tests/test_process_and_send_results.sh | 2 + .../tests/test_result_common_json_contract.sh | 6 +++ scripts/tests/test_result_profile_data.sh | 3 ++ 9 files changed, 119 insertions(+), 10 deletions(-) diff --git a/result_server/templates/_usage_report_performance_telemetry_section.html b/result_server/templates/_usage_report_performance_telemetry_section.html index 80c784cf..12250808 100644 --- a/result_server/templates/_usage_report_performance_telemetry_section.html +++ b/result_server/templates/_usage_report_performance_telemetry_section.html @@ -6,6 +6,7 @@ "profiled_result_count": 0, "regular_run_timing_count": 0, "profiled_run_timing_count": 0, + "scheduler_queue_timing_count": 0, "estimate_record_count": 0, "estimate_timing_record_count": 0, "build_cache_record_count": 0, @@ -14,6 +15,7 @@ "build_cache_store_count": 0, "avg_build_time": "-", "avg_queue_time": "-", + "avg_scheduler_queue_time": "-", "avg_run_time": "-", "avg_regular_run_time": "-", "avg_profiled_run_time": "-", @@ -33,7 +35,10 @@

Timing Records

Average Timing

-

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

+

+ build {{ performance_telemetry.summary.avg_build_time }} / reported queue {{ performance_telemetry.summary.avg_queue_time }} / run {{ performance_telemetry.summary.avg_run_time }} + scheduler queue {{ performance_telemetry.summary.avg_scheduler_queue_time|default('-') }} / {{ performance_telemetry.summary.scheduler_queue_timing_count|default(0) }} explicit records +

Run Split

@@ -78,11 +83,19 @@

Build Cache

build {{ row.avg_build_time }} reported queue {{ row.avg_queue_time }} + scheduler queue {{ row.avg_scheduler_queue_time|default('-') }} / {{ row.scheduler_queue_timing_count|default(0) }} explicit records run {{ row.avg_run_time }} build {{ row.latest_build_time }} - reported queue {{ row.latest_queue_time }} + + reported queue {{ row.latest_queue_time }} + {% if row.latest_queue_time_source|default('-') != '-' %}/ {{ row.latest_queue_time_source }}{% endif %} + + + scheduler queue {{ row.latest_scheduler_queue_time|default('-') }} + {% if row.latest_scheduler_queue_time_source|default('-') != '-' %}/ {{ row.latest_scheduler_queue_time_source }}{% endif %} + {{ row.latest_run_kind }} run {{ row.latest_run_time }} diff --git a/result_server/tests/test_performance_telemetry.py b/result_server/tests/test_performance_telemetry.py index 4dae810f..65d1a156 100644 --- a/result_server/tests/test_performance_telemetry.py +++ b/result_server/tests/test_performance_telemetry.py @@ -28,7 +28,14 @@ def test_performance_telemetry_summarizes_timing_and_build_cache(tmp_path, monke "Exp": "CASE1", "FOM": 1.0, "profile_data": {"tool": "ncu"}, - "pipeline_timing": {"build_time": 30, "queue_time": 60, "run_time": 120}, + "pipeline_timing": { + "build_time": 30, + "queue_time": 60, + "queue_time_source": "not_measured", + "scheduler_queue_time": 240, + "scheduler_queue_time_source": "runner_metadata", + "run_time": 120, + }, "build_cache": {"status": "hit", "stored": False}, }, ) @@ -39,7 +46,12 @@ def test_performance_telemetry_summarizes_timing_and_build_cache(tmp_path, monke "system": "DemoSystem", "Exp": "CASE0", "FOM": 1.0, - "pipeline_timing": {"build_time": 90, "queue_time": 60, "run_time": 300}, + "pipeline_timing": { + "build_time": 90, + "queue_time": 60, + "queue_time_source": "not_measured", + "run_time": 300, + }, "build_cache": {"status": "miss", "stored": True}, }, ) @@ -113,6 +125,7 @@ def test_performance_telemetry_summarizes_timing_and_build_cache(tmp_path, monke assert telemetry["summary"]["result_count"] == 2 assert telemetry["summary"]["ignored_result_count"] == 4 assert telemetry["summary"]["timing_record_count"] == 2 + assert telemetry["summary"]["scheduler_queue_timing_count"] == 1 assert telemetry["summary"]["profiled_result_count"] == 1 assert telemetry["summary"]["regular_run_timing_count"] == 1 assert telemetry["summary"]["profiled_run_timing_count"] == 1 @@ -124,6 +137,7 @@ def test_performance_telemetry_summarizes_timing_and_build_cache(tmp_path, monke assert telemetry["summary"]["build_cache_store_count"] == 1 assert telemetry["summary"]["avg_build_time"] == "1m" assert telemetry["summary"]["avg_queue_time"] == "1m" + assert telemetry["summary"]["avg_scheduler_queue_time"] == "4m" assert telemetry["summary"]["avg_run_time"] == "3.5m" assert telemetry["summary"]["avg_regular_run_time"] == "5m" assert telemetry["summary"]["avg_profiled_run_time"] == "2m" @@ -134,14 +148,19 @@ def test_performance_telemetry_summarizes_timing_and_build_cache(tmp_path, monke demoapp = rows[("demoapp", "DemoSystem")] assert demoapp["result_count"] == 2 assert demoapp["timing_count"] == 2 + assert demoapp["scheduler_queue_timing_count"] == 1 assert demoapp["profiled_count"] == 1 assert demoapp["avg_build_time"] == "1m" + assert demoapp["avg_scheduler_queue_time"] == "4m" assert demoapp["avg_run_time"] == "3.5m" assert demoapp["avg_regular_run_time"] == "5m" assert demoapp["avg_profiled_run_time"] == "2m" assert demoapp["latest_exp"] == "CASE1" assert demoapp["latest_build_time"] == "30s" assert demoapp["latest_queue_time"] == "1m" + assert demoapp["latest_queue_time_source"] == "not measured" + assert demoapp["latest_scheduler_queue_time"] == "4m" + assert demoapp["latest_scheduler_queue_time_source"] == "runner metadata" assert demoapp["latest_run_time"] == "2m" assert demoapp["latest_run_kind"] == "profiled" assert demoapp["estimate_count"] == 1 @@ -161,8 +180,10 @@ def test_performance_telemetry_handles_missing_directory(tmp_path): assert telemetry["summary"]["result_count"] == 0 assert telemetry["summary"]["ignored_result_count"] == 0 assert telemetry["summary"]["timing_record_count"] == 0 + assert telemetry["summary"]["scheduler_queue_timing_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_scheduler_queue_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 d90c6c09..35e7b789 100644 --- a/result_server/tests/test_portal_list_templates.py +++ b/result_server/tests/test_portal_list_templates.py @@ -674,6 +674,7 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality(): "profiled_result_count": 0, "regular_run_timing_count": 1, "profiled_run_timing_count": 0, + "scheduler_queue_timing_count": 0, "estimate_record_count": 1, "estimate_timing_record_count": 1, "build_cache_record_count": 1, @@ -682,6 +683,7 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality(): "build_cache_store_count": 0, "avg_build_time": "30s", "avg_queue_time": "1m", + "avg_scheduler_queue_time": "-", "avg_run_time": "2m", "avg_regular_run_time": "2m", "avg_profiled_run_time": "-", @@ -696,16 +698,21 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality(): "profiled_count": 0, "regular_run_timing_count": 1, "profiled_run_timing_count": 0, + "scheduler_queue_timing_count": 0, "estimate_count": 1, "estimate_timing_count": 1, "avg_build_time": "30s", "avg_queue_time": "1m", + "avg_scheduler_queue_time": "-", "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_queue_time_source": "not measured", + "latest_scheduler_queue_time": "-", + "latest_scheduler_queue_time_source": "-", "latest_run_time": "2m", "latest_run_kind": "regular", "latest_estimate_elapsed_time": "42s", @@ -758,6 +765,9 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality(): assert "Operator view for choosing trigger scope/frequency and improving CI and build-cache flow" in html assert "reported queue values may not include scheduler-side wait" in html assert "build 30s / reported queue 1m / run 2m" in html + assert "scheduler queue - / 0 explicit records" in html + assert "reported queue 1m" in html + assert "not measured" 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 diff --git a/result_server/utils/performance_telemetry.py b/result_server/utils/performance_telemetry.py index 4fec7a0f..24214604 100644 --- a/result_server/utils/performance_telemetry.py +++ b/result_server/utils/performance_telemetry.py @@ -15,6 +15,14 @@ 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] +TIMING_SOURCE_LABELS = { + "not_measured": "not measured", + "timestamp_files": "timestamp files", + "runner_metadata": "runner metadata", + "scheduler_metadata": "scheduler metadata", + "scheduler_logs": "scheduler logs", + "gitlab_metadata": "GitLab metadata", +} def build_performance_telemetry(received_dir: str, estimated_dir: str | None = None) -> dict[str, Any]: @@ -25,10 +33,12 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N regular_run_totals = _empty_scalar_total() profiled_run_totals = _empty_scalar_total() estimate_totals = _empty_scalar_total() + scheduler_queue_totals = _empty_scalar_total() summary = { "result_count": 0, "ignored_result_count": 0, "timing_record_count": 0, + "scheduler_queue_timing_count": 0, "profiled_result_count": 0, "regular_run_timing_count": 0, "profiled_run_timing_count": 0, @@ -57,6 +67,7 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N "system": system, "result_count": 0, "timing_count": 0, + "scheduler_queue_timing_count": 0, "profiled_count": 0, "regular_run_timing_count": 0, "profiled_run_timing_count": 0, @@ -70,6 +81,9 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N "latest_exp": _clean(data.get("Exp")) or "-", "latest_build_time": "-", "latest_queue_time": "-", + "latest_queue_time_source": "-", + "latest_scheduler_queue_time": "-", + "latest_scheduler_queue_time_source": "-", "latest_run_time": "-", "latest_run_kind": "-", "latest_build_cache_status": "-", @@ -81,17 +95,25 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N "_regular_run_totals": _empty_scalar_total(), "_profiled_run_totals": _empty_scalar_total(), "_estimate_totals": _empty_scalar_total(), + "_scheduler_queue_totals": _empty_scalar_total(), }, ) row["result_count"] += 1 is_profiled = _has_profile_data(data) - timing = _timing_values(data.get("pipeline_timing")) - if timing: + raw_timing = data.get("pipeline_timing") + timing = _timing_values(raw_timing) + scheduler_queue_time = _scheduler_queue_time(raw_timing) + if timing or scheduler_queue_time is not None: row["timing_count"] += 1 summary["timing_record_count"] += 1 _add_timing_totals(row["_timing_totals"], timing) _add_timing_totals(totals, timing) + if scheduler_queue_time is not None: + row["scheduler_queue_timing_count"] += 1 + summary["scheduler_queue_timing_count"] += 1 + _add_scalar_total(row["_scheduler_queue_totals"], scheduler_queue_time) + _add_scalar_total(scheduler_queue_totals, scheduler_queue_time) run_time = timing.get("run_time") if run_time is not None: if is_profiled: @@ -108,6 +130,13 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N 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_queue_time_source"] = _timing_source_label( + _nested_value(raw_timing, "queue_time_source") + ) + row["latest_scheduler_queue_time"] = _format_seconds(scheduler_queue_time) + row["latest_scheduler_queue_time_source"] = _timing_source_label( + _nested_value(raw_timing, "scheduler_queue_time_source") + ) row["latest_run_time"] = _format_seconds(timing.get("run_time")) row["latest_run_kind"] = "profiled" if is_profiled else "regular" @@ -144,6 +173,7 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N "total_run_time": _format_seconds(totals["run_time"]["sum"]), "avg_build_time": _format_average(totals, "build_time"), "avg_queue_time": _format_average(totals, "queue_time"), + "avg_scheduler_queue_time": _format_scalar_average(scheduler_queue_totals), "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), @@ -205,6 +235,23 @@ def _timing_values(raw_timing: Any) -> dict[str, float]: return timing +def _scheduler_queue_time(raw_timing: Any) -> float | None: + if not isinstance(raw_timing, dict): + return None + for field in ("scheduler_queue_time", "scheduler_queue_seconds"): + value = _as_float(raw_timing.get(field)) + if value is not None: + return value + return None + + +def _timing_source_label(value: Any) -> str: + source = _clean(value).lower().replace("-", "_") + if not source: + return "-" + return TIMING_SOURCE_LABELS.get(source, "provided") + + def _empty_timing_totals() -> dict[str, dict[str, float | int]]: return {field: {"sum": 0.0, "count": 0} for field in TIMING_FIELDS} @@ -265,11 +312,13 @@ def _finalize_row(row: dict[str, Any]) -> dict[str, Any]: regular_run_totals = row.pop("_regular_run_totals") profiled_run_totals = row.pop("_profiled_run_totals") estimate_totals = row.pop("_estimate_totals") + scheduler_queue_totals = row.pop("_scheduler_queue_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_scheduler_queue_time": _format_scalar_average(scheduler_queue_totals), "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), @@ -333,6 +382,7 @@ def _is_performance_record(data: dict[str, Any]) -> bool: return False return bool( _timing_values(data.get("pipeline_timing")) + or _scheduler_queue_time(data.get("pipeline_timing")) is not None or _has_profile_data(data) or _has_build_cache_data(data) ) diff --git a/scripts/collect_timing.sh b/scripts/collect_timing.sh index 9a0c2deb..33d19758 100644 --- a/scripts/collect_timing.sh +++ b/scripts/collect_timing.sh @@ -1,9 +1,10 @@ #!/bin/bash # collect_timing.sh - Collect timing information from timestamp files -# Reads build/run/queue timestamp files and generates results/pipeline_timing.json +# Reads build/run timestamp files and generates results/pipeline_timing.json BUILD_TIME=0 QUEUE_TIME=0 +QUEUE_TIME_SOURCE="not_measured" RUN_TIME=0 timestamp_value() { @@ -42,15 +43,15 @@ if [ -f results/run_start ] && [ -f results/run_end ]; then fi fi -# Queue time: not measurable with current Jacamar/pjsub architecture -# (before_script/script all run inside the batch job, so queue_submit -# is recorded after the job has already started) +# Queue time is not measured here. Sites may attach explicit scheduler +# queue metadata separately as scheduler_queue_time. QUEUE_TIME=0 cat > results/pipeline_timing.json </dev/null || true) if [ -z "$pipeline_timing_json" ] || [ "$pipeline_timing_json" = "null" ]; then pipeline_timing_json='{"build_time":0,"queue_time":0,"run_time":0}' diff --git a/scripts/tests/test_process_and_send_results.sh b/scripts/tests/test_process_and_send_results.sh index 9dbf1e8a..4833baa6 100644 --- a/scripts/tests/test_process_and_send_results.sh +++ b/scripts/tests/test_process_and_send_results.sh @@ -150,6 +150,8 @@ jq -e ' (.pipeline_timing | type) == "object" and (.pipeline_timing.build_time | type) == "number" and (.pipeline_timing.queue_time | type) == "number" and + .pipeline_timing.queue_time_source == "not_measured" and + (.pipeline_timing.scheduler_queue_time == null or (.pipeline_timing.scheduler_queue_time | type) == "number") and (.pipeline_timing.run_time | type) == "number" and (.execution_trigger | type) == "object" ' "${TMP_DIR}/project/send_results_workspace/results/result0.json" >/dev/null diff --git a/scripts/tests/test_result_common_json_contract.sh b/scripts/tests/test_result_common_json_contract.sh index b7ac374b..77b31860 100644 --- a/scripts/tests/test_result_common_json_contract.sh +++ b/scripts/tests/test_result_common_json_contract.sh @@ -50,6 +50,9 @@ cat > "${TMP_DIR}/results/pipeline_timing.json" <<'EOF' { "build_time": "12", "queue_time": 0, + "queue_time_source": "not_measured", + "scheduler_queue_time": 45, + "scheduler_queue_time_source": "runner_metadata", "run_time": 34 } EOF @@ -163,6 +166,9 @@ jq -e ' .input_info.inputs[0].verification_status == "covered_by_source_commit" and .pipeline_timing.build_time == 12 and .pipeline_timing.queue_time == 0 and + .pipeline_timing.queue_time_source == "not_measured" and + .pipeline_timing.scheduler_queue_time == 45 and + .pipeline_timing.scheduler_queue_time_source == "runner_metadata" and .pipeline_timing.run_time == 34 ' "${RESULT_JSON}" >/dev/null diff --git a/scripts/tests/test_result_profile_data.sh b/scripts/tests/test_result_profile_data.sh index 71bc6764..cab9e7a4 100644 --- a/scripts/tests/test_result_profile_data.sh +++ b/scripts/tests/test_result_profile_data.sh @@ -22,6 +22,7 @@ cat > "${TMP_DIR}/results/pipeline_timing.json" <<'EOF' { "build_time": "12", "queue_time": 0, + "queue_time_source": "not_measured", "run_time": 34 } EOF @@ -114,6 +115,7 @@ jq -e ' .profile_data.run_count == 1 and .pipeline_timing.build_time == 12 and .pipeline_timing.queue_time == 0 and + .pipeline_timing.queue_time_source == "not_measured" and .pipeline_timing.run_time == 34 and .pipeline_id == 999 and .parent_pipeline_id == 888 and @@ -159,6 +161,7 @@ test ! -f "${TIMING_TMP}/results/timing.env" jq -e ' .build_time == 15 and .queue_time == 0 and + .queue_time_source == "not_measured" and .run_time == 0 ' "${TIMING_TMP}/results/pipeline_timing.json" >/dev/null