Record GitLab job queue timing

.github/workflows/result-server-tests.yml

@@ -74,6 +74,7 @@ jobs:
           bash scripts/tests/test_bk_input_info.sh
           bash scripts/tests/test_build_cache.sh
           bash scripts/tests/test_build_environment_snapshot.sh
+          bash scripts/tests/test_ci_timing_context.sh
           bash scripts/tests/test_ncu_plan_generation.sh
           bash scripts/tests/test_result_profile_data.sh
           bash scripts/tests/test_process_and_send_results.sh

docs/cx/BENCHKIT_SPEC.md

@@ -365,6 +365,14 @@ Execution conditions are mainly formed by app-side `list.csv` and system-side `s
 site runner や scheduler log などから投入時刻と開始時刻を明示的に取得できる場合は、
 任意の `scheduler_queue_time` と `scheduler_queue_time_source` を追加し、
 reported queue timing とは別の値として扱う。
+`CI_JOB_STARTED_AT` と benchmark script 内の `run_start` の差から得る値は、
+厳密な scheduler 記録の submit/start 差ではないが、GitLab job が runner に拾われてから
+benchmark script が開始するまでの job queue time として読める。
+この場合は `scheduler_queue_time_source` に `gitlab_job_started_at` を入れる。
+1つの run job が複数の FOM block を出して複数の Result JSON を作る場合も、
+各 Result JSON は同じ job-level pipeline timing を持つ。
+これにより Portal の condition-level 表示は
+`Exp / node_count / numproc_node / nthreads / FOM_version` ごとに timing を参照できる。
 
 Benchmark results are produced by normalizing `run.sh` output into Result JSON through `result.sh`.
 
@@ -386,6 +394,14 @@ collection cannot measure scheduler wait, `queue_time_source` should be
 and start timestamps, optional `scheduler_queue_time` and
 `scheduler_queue_time_source` fields may be attached and should be treated as a
 separate measurement from reported queue timing.
+When the value is derived from `CI_JOB_STARTED_AT` and the in-script `run_start`
+timestamp, it is not a scheduler-recorded submit/start delta, but it can be
+read as job queue time from GitLab job pickup to benchmark script start. In that
+case, `scheduler_queue_time_source` should be `gitlab_job_started_at`.
+When one run job emits multiple FOM blocks and produces multiple Result JSON
+files, each Result JSON carries the same job-level pipeline timing. This lets
+Portal condition-level views read timing per
+`Exp / node_count / numproc_node / nthreads / FOM_version` row.
 
 ### 7.3 ソース出自情報 / Source Provenance
 

result_server/templates/_usage_report_performance_telemetry_section.html

@@ -29,7 +29,7 @@
 
 <section class="page-card table-card">
   <h2 class="section-title">Execution Timing Overview</h2>
-  <p class="section-intro">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; reported queue values may not include scheduler-side wait on every site.</p>
+  <p class="section-intro">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; reported queue values may not include scheduler-side wait on every site. Explicit scheduler queue values may be read as job queue time when sourced from GitLab job start to benchmark script start.</p>
 
   <div class="diagnostic-grid">
     <div class="diagnostic-card">
@@ -40,7 +40,7 @@ <h3>Timing Records</h3>
       <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 }}
-        <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>
+        <span class="profile-usage-subline">scheduler/job 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">
@@ -89,7 +89,7 @@ <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">scheduler/job 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>
@@ -99,7 +99,7 @@ <h3>Build Cache</h3>
               {% 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('-') }}
+              scheduler/job 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>

result_server/tests/test_portal_list_templates.py

@@ -786,8 +786,9 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality():
     assert "Execution Timing Overview" in html
     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 "may be read as job queue time" in html
     assert "build 30s / reported queue 1m / run 2m" in html
-    assert "scheduler queue - / 0 explicit records" in html
+    assert "scheduler/job queue - / 0 explicit records" in html
     assert "reported queue 1m" in html
     assert "not measured" in html
     assert "regular 2m / profiled -" in html

result_server/utils/performance_telemetry.py

@@ -21,6 +21,7 @@
     "runner_metadata": "runner metadata",
     "scheduler_metadata": "scheduler metadata",
     "scheduler_logs": "scheduler logs",
+    "gitlab_job_started_at": "GitLab job queue",
     "gitlab_metadata": "GitLab metadata",
 }
 

scripts/collect_timing.sh

@@ -6,15 +6,11 @@ BUILD_TIME=0
 QUEUE_TIME=0
 QUEUE_TIME_SOURCE="not_measured"
 RUN_TIME=0
+SCHEDULER_QUEUE_TIME=""
+SCHEDULER_QUEUE_TIME_SOURCE=""
 
-timestamp_value() {
-  local path="$1"
-  local value=""
-
-  if [ -f "$path" ]; then
-    value=$(cat "$path")
-  fi
-
+integer_value() {
+  local value="$1"
   case "$value" in
     ''|*[!0-9]*)
       printf ''
@@ -25,6 +21,29 @@ timestamp_value() {
   esac
 }
 
+timestamp_value() {
+  local path="$1"
+  local value=""
+
+  if [ -f "$path" ]; then
+    value=$(cat "$path")
+  fi
+
+  integer_value "$value"
+}
+
+json_integer_value() {
+  local path="$1"
+  local query="$2"
+  local value=""
+
+  [ -f "$path" ] || return 0
+  command -v jq >/dev/null 2>&1 || return 0
+
+  value=$(jq -r "$query" "$path" 2>/dev/null || true)
+  integer_value "$value"
+}
+
 # Build time = build_end - build_start
 if [ -f results/build_start ] && [ -f results/build_end ]; then
   bs=$(timestamp_value results/build_start)
@@ -43,17 +62,46 @@ if [ -f results/run_start ] && [ -f results/run_end ]; then
   fi
 fi
 
+# Scheduler/job queue time = run_start - CI_JOB_STARTED_AT when the run job
+# recorded GitLab job timing context before entering the benchmark script.
+if [ -f results/ci_timing_context.json ]; then
+  ci_job_started_epoch=$(json_integer_value results/ci_timing_context.json 'try (.ci_job_started_epoch // empty) catch empty')
+  rs=$(timestamp_value results/run_start)
+  if [ -n "$ci_job_started_epoch" ] && [ -n "$rs" ] && [ "$rs" -ge "$ci_job_started_epoch" ]; then
+    SCHEDULER_QUEUE_TIME=$((rs - ci_job_started_epoch))
+    SCHEDULER_QUEUE_TIME_SOURCE="gitlab_job_started_at"
+  fi
+fi
+
 # Queue time is not measured here. Sites may attach explicit scheduler
 # queue metadata separately as scheduler_queue_time.
 QUEUE_TIME=0
 
+if [ -n "$SCHEDULER_QUEUE_TIME" ]; then
 cat > results/pipeline_timing.json <<EOF
 {
   "build_time": $BUILD_TIME,
   "queue_time": $QUEUE_TIME,
   "queue_time_source": "$QUEUE_TIME_SOURCE",
+  "scheduler_queue_time": $SCHEDULER_QUEUE_TIME,
+  "scheduler_queue_time_source": "$SCHEDULER_QUEUE_TIME_SOURCE",
   "run_time": $RUN_TIME
 }
 EOF
+else
+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
+fi
 
-echo "Timing collected: build=${BUILD_TIME}s queue=${QUEUE_TIME}s run=${RUN_TIME}s"
+if [ -n "$SCHEDULER_QUEUE_TIME" ]; then
+  scheduler_queue_label="${SCHEDULER_QUEUE_TIME}s"
+else
+  scheduler_queue_label="not_measured"
+fi
+echo "Timing collected: build=${BUILD_TIME}s queue=${QUEUE_TIME}s scheduler_queue=${scheduler_queue_label} run=${RUN_TIME}s"

scripts/matrix_generate.sh

@@ -14,6 +14,7 @@ SYSTEM_INFO_FILE="config/system_info.csv"
 OUTPUT_FILE=".gitlab-ci.generated.yml"
 PARENT_PIPELINE_SOURCE="${CI_PIPELINE_SOURCE:-local}"
 PARENT_PIPELINE_ID="${CI_PIPELINE_ID:-}"
+PARENT_PIPELINE_CREATED_AT="${CI_PIPELINE_CREATED_AT:-}"
 
 source ./scripts/job_functions.sh
 
@@ -45,6 +46,7 @@ stages:
 variables:
   PARENT_PIPELINE_SOURCE: \"$PARENT_PIPELINE_SOURCE\"
   PARENT_PIPELINE_ID: \"$PARENT_PIPELINE_ID\"
+  PARENT_PIPELINE_CREATED_AT: \"$PARENT_PIPELINE_CREATED_AT\"
   BK_ESTIMATE_RUNNER_TAG: \"$ESTIMATE_RUNNER_TAG\"
 " >> "$OUTPUT_FILE"
 
@@ -156,6 +158,7 @@ ${job_prefix}_run:
     - echo \"Pre-created results directory on login node\"
   script:
     - echo \"Starting job\"
+    - bash scripts/record_ci_timing_context.sh run
     - ls -la $program_path/
     - BK_SYSTEM=\"$system\" BK_SNAPSHOT_STAGE=run bash scripts/collect_environment_snapshot.sh results/environment_snapshot_run.json
     - bash scripts/record_timestamp.sh results/run_start
@@ -204,6 +207,7 @@ ${job_prefix}_build_run:
     - echo \"Pre-created results directory on login node\"
   script:
     - echo \"Starting build and run\"
+    - bash scripts/record_ci_timing_context.sh build_run
     - BK_SYSTEM=\"$system\" BK_SNAPSHOT_STAGE=build_run bash scripts/collect_environment_snapshot.sh results/environment_snapshot_build_run.json
     - export BK_SYSTEM=\"$system\"
     - export BK_BENCHKIT_ROOT=\"\$PWD\"

scripts/record_ci_timing_context.sh

@@ -0,0 +1,79 @@
+#!/bin/bash
+set -euo pipefail
+
+stage="${1:-unknown}"
+output="${2:-results/ci_timing_context.json}"
+
+timestamp_to_epoch() {
+  local value="$1"
+  [ -n "$value" ] || return 1
+  date -u -d "$value" +%s 2>/dev/null
+}
+
+value_with_source() {
+  local name="$1"
+  local custom_name="CUSTOM_ENV_${name}"
+  if [ -n "${!name:-}" ]; then
+    printf '%s\t%s\n' "${!name}" "$name"
+    return 0
+  fi
+  if [ -n "${!custom_name:-}" ]; then
+    printf '%s\t%s\n' "${!custom_name}" "$custom_name"
+    return 0
+  fi
+  printf '\t\n'
+}
+
+if ! command -v jq >/dev/null 2>&1; then
+  echo "CI timing context not recorded: jq not found"
+  exit 0
+fi
+
+mkdir -p "$(dirname "$output")"
+
+ci_job_started_at=""
+ci_job_started_at_source=""
+ci_pipeline_created_at=""
+ci_pipeline_created_at_source=""
+parent_pipeline_created_at=""
+parent_pipeline_created_at_source=""
+
+IFS=$'\t' read -r ci_job_started_at ci_job_started_at_source < <(value_with_source "CI_JOB_STARTED_AT")
+IFS=$'\t' read -r ci_pipeline_created_at ci_pipeline_created_at_source < <(value_with_source "CI_PIPELINE_CREATED_AT")
+IFS=$'\t' read -r parent_pipeline_created_at parent_pipeline_created_at_source < <(value_with_source "PARENT_PIPELINE_CREATED_AT")
+
+ci_job_started_epoch=""
+if [ -n "$ci_job_started_at" ]; then
+  ci_job_started_epoch=$(timestamp_to_epoch "$ci_job_started_at" || true)
+fi
+
+jq -n \
+  --arg stage "$stage" \
+  --arg collected_at "$(date -u +%Y-%m-%dT%H:%M:%SZ)" \
+  --arg ci_job_started_at "$ci_job_started_at" \
+  --arg ci_job_started_at_source "$ci_job_started_at_source" \
+  --arg ci_job_started_epoch "$ci_job_started_epoch" \
+  --arg ci_pipeline_created_at "$ci_pipeline_created_at" \
+  --arg ci_pipeline_created_at_source "$ci_pipeline_created_at_source" \
+  --arg parent_pipeline_created_at "$parent_pipeline_created_at" \
+  --arg parent_pipeline_created_at_source "$parent_pipeline_created_at_source" \
+  '
+  {schema_version: 1, stage: $stage, collected_at: $collected_at}
+  + (if $ci_job_started_at != "" then {
+      ci_job_started_at: $ci_job_started_at,
+      ci_job_started_at_source: $ci_job_started_at_source
+    } else {} end)
+  + (if $ci_job_started_epoch != "" then {
+      ci_job_started_epoch: ($ci_job_started_epoch | tonumber)
+    } else {} end)
+  + (if $ci_pipeline_created_at != "" then {
+      ci_pipeline_created_at: $ci_pipeline_created_at,
+      ci_pipeline_created_at_source: $ci_pipeline_created_at_source
+    } else {} end)
+  + (if $parent_pipeline_created_at != "" then {
+      parent_pipeline_created_at: $parent_pipeline_created_at,
+      parent_pipeline_created_at_source: $parent_pipeline_created_at_source
+    } else {} end)
+  ' > "$output"
+
+echo "Recorded CI timing context: stage=${stage} ci_job_started_at=${ci_job_started_at:-not_available}"

scripts/result.sh

@@ -529,10 +529,10 @@ write_result_json() {
   local idx="$1"
   local fom_breakdown_block=""
 
-  # Build pipeline_timing block if pipeline_timing.json exists (only for first result to avoid duplication).
+  # Build pipeline_timing block if pipeline_timing.json exists.
   # Treat the file as data; never source generated timing files as shell.
   local timing_block=""
-  if [ "$idx" = "0" ] && [ -f results/pipeline_timing.json ]; then
+  if [ -f results/pipeline_timing.json ]; then
     local pipeline_timing_json
     pipeline_timing_json=$(jq -c '
       def num: if type == "number" then . else (tonumber? // 0) end;