diff --git a/.github/workflows/result-server-tests.yml b/.github/workflows/result-server-tests.yml index 5c90cb3..fe00719 100644 --- a/.github/workflows/result-server-tests.yml +++ b/.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 diff --git a/docs/cx/BENCHKIT_SPEC.md b/docs/cx/BENCHKIT_SPEC.md index b97548c..d05e83d 100644 --- a/docs/cx/BENCHKIT_SPEC.md +++ b/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 diff --git a/result_server/templates/_usage_report_performance_telemetry_section.html b/result_server/templates/_usage_report_performance_telemetry_section.html index 9d8e52c..d5290a9 100644 --- a/result_server/templates/_usage_report_performance_telemetry_section.html +++ b/result_server/templates/_usage_report_performance_telemetry_section.html @@ -29,7 +29,7 @@

Execution Timing Overview

-

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.

+

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.

@@ -40,7 +40,7 @@

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 }} - scheduler queue {{ performance_telemetry.summary.avg_scheduler_queue_time|default('-') }} / {{ performance_telemetry.summary.scheduler_queue_timing_count|default(0) }} explicit records + scheduler/job queue {{ performance_telemetry.summary.avg_scheduler_queue_time|default('-') }} / {{ performance_telemetry.summary.scheduler_queue_timing_count|default(0) }} explicit records

@@ -89,7 +89,7 @@

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 + scheduler/job queue {{ row.avg_scheduler_queue_time|default('-') }} / {{ row.scheduler_queue_timing_count|default(0) }} explicit records run {{ row.avg_run_time }} @@ -99,7 +99,7 @@

Build Cache

{% if row.latest_queue_time_source|default('-') != '-' %}/ {{ row.latest_queue_time_source }}{% endif %} - 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 %} {{ row.latest_run_kind }} run {{ row.latest_run_time }} diff --git a/result_server/tests/test_portal_list_templates.py b/result_server/tests/test_portal_list_templates.py index 245c63a..aec1c7a 100644 --- a/result_server/tests/test_portal_list_templates.py +++ b/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 diff --git a/result_server/utils/performance_telemetry.py b/result_server/utils/performance_telemetry.py index b0820f1..8397225 100644 --- a/result_server/utils/performance_telemetry.py +++ b/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", } diff --git a/scripts/collect_timing.sh b/scripts/collect_timing.sh index 33d1975..fddf8f9 100644 --- a/scripts/collect_timing.sh +++ b/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 < results/pipeline_timing.json <> "$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\" diff --git a/scripts/record_ci_timing_context.sh b/scripts/record_ci_timing_context.sh new file mode 100644 index 0000000..7f90bd3 --- /dev/null +++ b/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}" diff --git a/scripts/result.sh b/scripts/result.sh index 508f539..acae8fe 100644 --- a/scripts/result.sh +++ b/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; diff --git a/scripts/tests/test_ci_timing_context.sh b/scripts/tests/test_ci_timing_context.sh new file mode 100644 index 0000000..eb8da5c --- /dev/null +++ b/scripts/tests/test_ci_timing_context.sh @@ -0,0 +1,86 @@ +#!/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 CI timing context test" + exit 0 +fi + +TMP_DIR=$(mktemp -d) +trap 'rm -rf "${TMP_DIR}"' EXIT + +mkdir -p "${TMP_DIR}/results" + +export CI_JOB_STARTED_AT="2026-09-10T03:14:48Z" +export CI_PIPELINE_CREATED_AT="2026-09-10T03:14:17Z" +export PARENT_PIPELINE_CREATED_AT="2026-09-10T03:14:09Z" + +expected_job_started_epoch=$(date -u -d "$CI_JOB_STARTED_AT" +%s) + +bash "${REPO_DIR}/scripts/record_ci_timing_context.sh" run "${TMP_DIR}/results/ci_timing_context.json" >/dev/null + +jq -e \ + --argjson expected_job_started_epoch "$expected_job_started_epoch" \ + ' + .schema_version == 1 and + .stage == "run" and + .ci_job_started_at == "2026-09-10T03:14:48Z" and + .ci_job_started_at_source == "CI_JOB_STARTED_AT" and + .ci_job_started_epoch == $expected_job_started_epoch and + .ci_pipeline_created_at == "2026-09-10T03:14:17Z" and + .parent_pipeline_created_at == "2026-09-10T03:14:09Z" + ' "${TMP_DIR}/results/ci_timing_context.json" >/dev/null + +printf '%s\n' "$((expected_job_started_epoch - 20))" > "${TMP_DIR}/results/build_start" +printf '%s\n' "$((expected_job_started_epoch - 10))" > "${TMP_DIR}/results/build_end" +printf '%s\n' "$((expected_job_started_epoch + 317))" > "${TMP_DIR}/results/run_start" +printf '%s\n' "$((expected_job_started_epoch + 377))" > "${TMP_DIR}/results/run_end" + +pushd "${TMP_DIR}" >/dev/null +bash "${REPO_DIR}/scripts/collect_timing.sh" >/dev/null +popd >/dev/null + +jq -e ' + .build_time == 10 and + .queue_time == 0 and + .queue_time_source == "not_measured" and + .scheduler_queue_time == 317 and + .scheduler_queue_time_source == "gitlab_job_started_at" and + .run_time == 60 +' "${TMP_DIR}/results/pipeline_timing.json" >/dev/null + +mkdir -p "${TMP_DIR}/custom/results" +unset CI_JOB_STARTED_AT +export CUSTOM_ENV_CI_JOB_STARTED_AT="2026-09-10T03:20:00Z" +bash "${REPO_DIR}/scripts/record_ci_timing_context.sh" build_run "${TMP_DIR}/custom/results/ci_timing_context.json" >/dev/null +jq -e ' + .stage == "build_run" and + .ci_job_started_at == "2026-09-10T03:20:00Z" and + .ci_job_started_at_source == "CUSTOM_ENV_CI_JOB_STARTED_AT" and + (.ci_job_started_epoch | type) == "number" +' "${TMP_DIR}/custom/results/ci_timing_context.json" >/dev/null + +mkdir -p "${TMP_DIR}/invalid/results" +cat > "${TMP_DIR}/invalid/results/ci_timing_context.json" <<'EOF' +{ + "schema_version": 1, + "stage": "run", + "ci_job_started_epoch": 200 +} +EOF +printf '100\n' > "${TMP_DIR}/invalid/results/run_start" +printf '120\n' > "${TMP_DIR}/invalid/results/run_end" +pushd "${TMP_DIR}/invalid" >/dev/null +bash "${REPO_DIR}/scripts/collect_timing.sh" >/dev/null +popd >/dev/null + +jq -e ' + .run_time == 20 and + (.scheduler_queue_time? == null) and + (.scheduler_queue_time_source? == null) +' "${TMP_DIR}/invalid/results/pipeline_timing.json" >/dev/null + +echo "CI timing context test passed" diff --git a/scripts/tests/test_process_and_send_results.sh b/scripts/tests/test_process_and_send_results.sh index ce7d3ca..ac82a66 100644 --- a/scripts/tests/test_process_and_send_results.sh +++ b/scripts/tests/test_process_and_send_results.sh @@ -28,6 +28,15 @@ printf '%s\n' 100 > "${TMP_DIR}/project/results/build_start" printf '%s\n' 105 > "${TMP_DIR}/project/results/build_end" printf '%s\n' 110 > "${TMP_DIR}/project/results/run_start" printf '%s\n' 120 > "${TMP_DIR}/project/results/run_end" +cat > "${TMP_DIR}/project/results/ci_timing_context.json" <<'EOF' +{ + "schema_version": 1, + "stage": "run", + "ci_job_started_at": "1970-01-01T00:01:40Z", + "ci_job_started_at_source": "CI_JOB_STARTED_AT", + "ci_job_started_epoch": 100 +} +EOF cat > "${TMP_DIR}/project/results/environment_snapshot_run.json" <<'EOF' { "schema_version": 1, @@ -151,7 +160,8 @@ jq -e ' (.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.scheduler_queue_time == 10 and + .pipeline_timing.scheduler_queue_time_source == "gitlab_job_started_at" 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_profile_data.sh b/scripts/tests/test_result_profile_data.sh index cab9e7a..e685217 100644 --- a/scripts/tests/test_result_profile_data.sh +++ b/scripts/tests/test_result_profile_data.sh @@ -16,6 +16,7 @@ fi cat > "${TMP_DIR}/results/result" <<'EOF' FOM:9.9999999999999995e-07 FOM_unit:s FOM_version:test Exp:CASE0 node_count:1 numproc_node:1 nthreads:2 +FOM:1.25 FOM_unit:s FOM_version:test Exp:CASE1 node_count:1 numproc_node:2 nthreads:2 EOF cat > "${TMP_DIR}/results/pipeline_timing.json" <<'EOF' @@ -127,6 +128,17 @@ jq -e ' ' "${RESULT_JSON}" >/dev/null test ! -f "${TMP_DIR}/timing_env_was_sourced" +RESULT_JSON_1="${TMP_DIR}/results/result1.json" +test -f "${RESULT_JSON_1}" +jq -e ' + .Exp == "CASE1" and + .numproc_node == "2" 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 +' "${RESULT_JSON_1}" >/dev/null + NCU_RESULT_JSON="${TMP_DIR}/ncu/results/result0.json" test -f "${NCU_RESULT_JSON}" jq -e '