Track scheduler queue timing metadata

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 @@ <h3>Timing Records</h3>
     </div>
     <div class="diagnostic-card">
       <h3>Average Timing</h3>
-      <p>build {{ performance_telemetry.summary.avg_build_time }} / reported queue {{ performance_telemetry.summary.avg_queue_time }} / run {{ performance_telemetry.summary.avg_run_time }}</p>
+      <p>
+        build {{ performance_telemetry.summary.avg_build_time }} / reported queue {{ performance_telemetry.summary.avg_queue_time }} / run {{ performance_telemetry.summary.avg_run_time }}
+        <span class="profile-usage-subline">scheduler queue {{ performance_telemetry.summary.avg_scheduler_queue_time|default('-') }} / {{ performance_telemetry.summary.scheduler_queue_timing_count|default(0) }} explicit records</span>
+      </p>
     </div>
     <div class="diagnostic-card">
       <h3>Run Split</h3>
@@ -78,11 +83,19 @@ <h3>Build Cache</h3>
           <td>
             build {{ row.avg_build_time }}
             <span class="profile-usage-subline">reported queue {{ row.avg_queue_time }}</span>
+            <span class="profile-usage-subline">scheduler queue {{ row.avg_scheduler_queue_time|default('-') }} / {{ row.scheduler_queue_timing_count|default(0) }} explicit records</span>
             <span class="profile-usage-subline">run {{ row.avg_run_time }}</span>
           </td>
           <td>
             build {{ row.latest_build_time }}
-            <span class="profile-usage-subline">reported queue {{ row.latest_queue_time }}</span>
+            <span class="profile-usage-subline">
+              reported queue {{ row.latest_queue_time }}
+              {% if row.latest_queue_time_source|default('-') != '-' %}/ {{ row.latest_queue_time_source }}{% endif %}
+            </span>
+            <span class="profile-usage-subline">
+              scheduler queue {{ row.latest_scheduler_queue_time|default('-') }}
+              {% if row.latest_scheduler_queue_time_source|default('-') != '-' %}/ {{ row.latest_scheduler_queue_time_source }}{% endif %}
+            </span>
             <span class="profile-usage-subline">{{ row.latest_run_kind }} run {{ row.latest_run_time }}</span>
           </td>
           <td>

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"] == []

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

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)
     )

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 <<EOF
 {
   "build_time": $BUILD_TIME,
   "queue_time": $QUEUE_TIME,
+  "queue_time_source": "$QUEUE_TIME_SOURCE",
   "run_time": $RUN_TIME
 }
 EOF

scripts/result.sh

@@ -541,6 +541,9 @@ write_result_json() {
         queue_time: ((.queue_time // 0) | num),
         run_time: ((.run_time // 0) | num)
       }
+      + (if (.queue_time_source? | type) == "string" then {queue_time_source: .queue_time_source} else {} end)
+      + ((try (.scheduler_queue_time? | tonumber) catch null) as $scheduler_queue_time | if $scheduler_queue_time == null then {} else {scheduler_queue_time: $scheduler_queue_time} end)
+      + (if (.scheduler_queue_time_source? | type) == "string" then {scheduler_queue_time_source: .scheduler_queue_time_source} else {} end)
     ' results/pipeline_timing.json 2>/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}'

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

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