Skip to content

Commit b42b1a5

Browse files
Record GitLab job queue timing
Signed-off-by: yoshifuminakamura <nakamura@riken.jp>
1 parent bfbbd16 commit b42b1a5

12 files changed

Lines changed: 275 additions & 17 deletions

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -74,6 +74,7 @@ jobs:
7474
bash scripts/tests/test_bk_input_info.sh
7575
bash scripts/tests/test_build_cache.sh
7676
bash scripts/tests/test_build_environment_snapshot.sh
77+
bash scripts/tests/test_ci_timing_context.sh
7778
bash scripts/tests/test_ncu_plan_generation.sh
7879
bash scripts/tests/test_result_profile_data.sh
7980
bash scripts/tests/test_process_and_send_results.sh

‎docs/cx/BENCHKIT_SPEC.md‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -365,6 +365,14 @@ Execution conditions are mainly formed by app-side `list.csv` and system-side `s
365365
site runner や scheduler log などから投入時刻と開始時刻を明示的に取得できる場合は、
366366
任意の `scheduler_queue_time` と `scheduler_queue_time_source` を追加し、
367367
reported queue timing とは別の値として扱う。
368+
`CI_JOB_STARTED_AT` と benchmark script 内の `run_start` の差から得る値は、
369+
厳密な scheduler 記録の submit/start 差ではないが、GitLab job が runner に拾われてから
370+
benchmark script が開始するまでの job queue time として読める。
371+
この場合は `scheduler_queue_time_source` に `gitlab_job_started_at` を入れる。
372+
1つの run job が複数の FOM block を出して複数の Result JSON を作る場合も、
373+
各 Result JSON は同じ job-level pipeline timing を持つ。
374+
これにより Portal の condition-level 表示は
375+
`Exp / node_count / numproc_node / nthreads / FOM_version` ごとに timing を参照できる。
368376

369377
Benchmark results are produced by normalizing `run.sh` output into Result JSON through `result.sh`.
370378

@@ -386,6 +394,14 @@ collection cannot measure scheduler wait, `queue_time_source` should be
386394
and start timestamps, optional `scheduler_queue_time` and
387395
`scheduler_queue_time_source` fields may be attached and should be treated as a
388396
separate measurement from reported queue timing.
397+
When the value is derived from `CI_JOB_STARTED_AT` and the in-script `run_start`
398+
timestamp, it is not a scheduler-recorded submit/start delta, but it can be
399+
read as job queue time from GitLab job pickup to benchmark script start. In that
400+
case, `scheduler_queue_time_source` should be `gitlab_job_started_at`.
401+
When one run job emits multiple FOM blocks and produces multiple Result JSON
402+
files, each Result JSON carries the same job-level pipeline timing. This lets
403+
Portal condition-level views read timing per
404+
`Exp / node_count / numproc_node / nthreads / FOM_version` row.
389405

390406
### 7.3 ソース出自情報 / Source Provenance
391407

‎result_server/templates/_usage_report_performance_telemetry_section.html‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@
2929

3030
<section class="page-card table-card">
3131
<h2 class="section-title">Execution Timing Overview</h2>
32-
<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>
32+
<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>
3333

3434
<div class="diagnostic-grid">
3535
<div class="diagnostic-card">
@@ -40,7 +40,7 @@ <h3>Timing Records</h3>
4040
<h3>Average Timing</h3>
4141
<p>
4242
build {{ performance_telemetry.summary.avg_build_time }} / reported queue {{ performance_telemetry.summary.avg_queue_time }} / run {{ performance_telemetry.summary.avg_run_time }}
43-
<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>
43+
<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>
4444
</p>
4545
</div>
4646
<div class="diagnostic-card">
@@ -89,7 +89,7 @@ <h3>Build Cache</h3>
8989
<td>
9090
build {{ row.avg_build_time }}
9191
<span class="profile-usage-subline">reported queue {{ row.avg_queue_time }}</span>
92-
<span class="profile-usage-subline">scheduler queue {{ row.avg_scheduler_queue_time|default('-') }} / {{ row.scheduler_queue_timing_count|default(0) }} explicit records</span>
92+
<span class="profile-usage-subline">scheduler/job queue {{ row.avg_scheduler_queue_time|default('-') }} / {{ row.scheduler_queue_timing_count|default(0) }} explicit records</span>
9393
<span class="profile-usage-subline">run {{ row.avg_run_time }}</span>
9494
</td>
9595
<td>
@@ -99,7 +99,7 @@ <h3>Build Cache</h3>
9999
{% if row.latest_queue_time_source|default('-') != '-' %}/ {{ row.latest_queue_time_source }}{% endif %}
100100
</span>
101101
<span class="profile-usage-subline">
102-
scheduler queue {{ row.latest_scheduler_queue_time|default('-') }}
102+
scheduler/job queue {{ row.latest_scheduler_queue_time|default('-') }}
103103
{% if row.latest_scheduler_queue_time_source|default('-') != '-' %}/ {{ row.latest_scheduler_queue_time_source }}{% endif %}
104104
</span>
105105
<span class="profile-usage-subline">{{ row.latest_run_kind }} run {{ row.latest_run_time }}</span>

‎result_server/tests/test_portal_list_templates.py‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -786,8 +786,9 @@ def test_usage_report_evidence_snapshot_consolidates_coverage_and_quality():
786786
assert "Execution Timing Overview" in html
787787
assert "Operator view for choosing trigger scope/frequency and improving CI and build-cache flow" in html
788788
assert "reported queue values may not include scheduler-side wait" in html
789+
assert "may be read as job queue time" in html
789790
assert "build 30s / reported queue 1m / run 2m" in html
790-
assert "scheduler queue - / 0 explicit records" in html
791+
assert "scheduler/job queue - / 0 explicit records" in html
791792
assert "reported queue 1m" in html
792793
assert "not measured" in html
793794
assert "regular 2m / profiled -" in html

‎result_server/utils/performance_telemetry.py‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121
"runner_metadata": "runner metadata",
2222
"scheduler_metadata": "scheduler metadata",
2323
"scheduler_logs": "scheduler logs",
24+
"gitlab_job_started_at": "GitLab job queue",
2425
"gitlab_metadata": "GitLab metadata",
2526
}
2627

‎scripts/collect_timing.sh‎

Lines changed: 57 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -6,15 +6,11 @@ BUILD_TIME=0
66
QUEUE_TIME=0
77
QUEUE_TIME_SOURCE="not_measured"
88
RUN_TIME=0
9+
SCHEDULER_QUEUE_TIME=""
10+
SCHEDULER_QUEUE_TIME_SOURCE=""
911

10-
timestamp_value() {
11-
local path="$1"
12-
local value=""
13-
14-
if [ -f "$path" ]; then
15-
value=$(cat "$path")
16-
fi
17-
12+
integer_value() {
13+
local value="$1"
1814
case "$value" in
1915
''|*[!0-9]*)
2016
printf ''
@@ -25,6 +21,29 @@ timestamp_value() {
2521
esac
2622
}
2723

24+
timestamp_value() {
25+
local path="$1"
26+
local value=""
27+
28+
if [ -f "$path" ]; then
29+
value=$(cat "$path")
30+
fi
31+
32+
integer_value "$value"
33+
}
34+
35+
json_integer_value() {
36+
local path="$1"
37+
local query="$2"
38+
local value=""
39+
40+
[ -f "$path" ] || return 0
41+
command -v jq >/dev/null 2>&1 || return 0
42+
43+
value=$(jq -r "$query" "$path" 2>/dev/null || true)
44+
integer_value "$value"
45+
}
46+
2847
# Build time = build_end - build_start
2948
if [ -f results/build_start ] && [ -f results/build_end ]; then
3049
bs=$(timestamp_value results/build_start)
@@ -43,17 +62,46 @@ if [ -f results/run_start ] && [ -f results/run_end ]; then
4362
fi
4463
fi
4564

65+
# Scheduler/job queue time = run_start - CI_JOB_STARTED_AT when the run job
66+
# recorded GitLab job timing context before entering the benchmark script.
67+
if [ -f results/ci_timing_context.json ]; then
68+
ci_job_started_epoch=$(json_integer_value results/ci_timing_context.json 'try (.ci_job_started_epoch // empty) catch empty')
69+
rs=$(timestamp_value results/run_start)
70+
if [ -n "$ci_job_started_epoch" ] && [ -n "$rs" ] && [ "$rs" -ge "$ci_job_started_epoch" ]; then
71+
SCHEDULER_QUEUE_TIME=$((rs - ci_job_started_epoch))
72+
SCHEDULER_QUEUE_TIME_SOURCE="gitlab_job_started_at"
73+
fi
74+
fi
75+
4676
# Queue time is not measured here. Sites may attach explicit scheduler
4777
# queue metadata separately as scheduler_queue_time.
4878
QUEUE_TIME=0
4979

80+
if [ -n "$SCHEDULER_QUEUE_TIME" ]; then
5081
cat > results/pipeline_timing.json <<EOF
5182
{
5283
"build_time": $BUILD_TIME,
5384
"queue_time": $QUEUE_TIME,
5485
"queue_time_source": "$QUEUE_TIME_SOURCE",
86+
"scheduler_queue_time": $SCHEDULER_QUEUE_TIME,
87+
"scheduler_queue_time_source": "$SCHEDULER_QUEUE_TIME_SOURCE",
5588
"run_time": $RUN_TIME
5689
}
5790
EOF
91+
else
92+
cat > results/pipeline_timing.json <<EOF
93+
{
94+
"build_time": $BUILD_TIME,
95+
"queue_time": $QUEUE_TIME,
96+
"queue_time_source": "$QUEUE_TIME_SOURCE",
97+
"run_time": $RUN_TIME
98+
}
99+
EOF
100+
fi
58101

59-
echo "Timing collected: build=${BUILD_TIME}s queue=${QUEUE_TIME}s run=${RUN_TIME}s"
102+
if [ -n "$SCHEDULER_QUEUE_TIME" ]; then
103+
scheduler_queue_label="${SCHEDULER_QUEUE_TIME}s"
104+
else
105+
scheduler_queue_label="not_measured"
106+
fi
107+
echo "Timing collected: build=${BUILD_TIME}s queue=${QUEUE_TIME}s scheduler_queue=${scheduler_queue_label} run=${RUN_TIME}s"

‎scripts/matrix_generate.sh‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ SYSTEM_INFO_FILE="config/system_info.csv"
1414
OUTPUT_FILE=".gitlab-ci.generated.yml"
1515
PARENT_PIPELINE_SOURCE="${CI_PIPELINE_SOURCE:-local}"
1616
PARENT_PIPELINE_ID="${CI_PIPELINE_ID:-}"
17+
PARENT_PIPELINE_CREATED_AT="${CI_PIPELINE_CREATED_AT:-}"
1718

1819
source ./scripts/job_functions.sh
1920

@@ -45,6 +46,7 @@ stages:
4546
variables:
4647
PARENT_PIPELINE_SOURCE: \"$PARENT_PIPELINE_SOURCE\"
4748
PARENT_PIPELINE_ID: \"$PARENT_PIPELINE_ID\"
49+
PARENT_PIPELINE_CREATED_AT: \"$PARENT_PIPELINE_CREATED_AT\"
4850
BK_ESTIMATE_RUNNER_TAG: \"$ESTIMATE_RUNNER_TAG\"
4951
" >> "$OUTPUT_FILE"
5052

@@ -156,6 +158,7 @@ ${job_prefix}_run:
156158
- echo \"Pre-created results directory on login node\"
157159
script:
158160
- echo \"Starting job\"
161+
- bash scripts/record_ci_timing_context.sh run
159162
- ls -la $program_path/
160163
- BK_SYSTEM=\"$system\" BK_SNAPSHOT_STAGE=run bash scripts/collect_environment_snapshot.sh results/environment_snapshot_run.json
161164
- bash scripts/record_timestamp.sh results/run_start
@@ -204,6 +207,7 @@ ${job_prefix}_build_run:
204207
- echo \"Pre-created results directory on login node\"
205208
script:
206209
- echo \"Starting build and run\"
210+
- bash scripts/record_ci_timing_context.sh build_run
207211
- BK_SYSTEM=\"$system\" BK_SNAPSHOT_STAGE=build_run bash scripts/collect_environment_snapshot.sh results/environment_snapshot_build_run.json
208212
- export BK_SYSTEM=\"$system\"
209213
- export BK_BENCHKIT_ROOT=\"\$PWD\"
Lines changed: 79 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,79 @@
1+
#!/bin/bash
2+
set -euo pipefail
3+
4+
stage="${1:-unknown}"
5+
output="${2:-results/ci_timing_context.json}"
6+
7+
timestamp_to_epoch() {
8+
local value="$1"
9+
[ -n "$value" ] || return 1
10+
date -u -d "$value" +%s 2>/dev/null
11+
}
12+
13+
value_with_source() {
14+
local name="$1"
15+
local custom_name="CUSTOM_ENV_${name}"
16+
if [ -n "${!name:-}" ]; then
17+
printf '%s\t%s\n' "${!name}" "$name"
18+
return 0
19+
fi
20+
if [ -n "${!custom_name:-}" ]; then
21+
printf '%s\t%s\n' "${!custom_name}" "$custom_name"
22+
return 0
23+
fi
24+
printf '\t\n'
25+
}
26+
27+
if ! command -v jq >/dev/null 2>&1; then
28+
echo "CI timing context not recorded: jq not found"
29+
exit 0
30+
fi
31+
32+
mkdir -p "$(dirname "$output")"
33+
34+
ci_job_started_at=""
35+
ci_job_started_at_source=""
36+
ci_pipeline_created_at=""
37+
ci_pipeline_created_at_source=""
38+
parent_pipeline_created_at=""
39+
parent_pipeline_created_at_source=""
40+
41+
IFS=$'\t' read -r ci_job_started_at ci_job_started_at_source < <(value_with_source "CI_JOB_STARTED_AT")
42+
IFS=$'\t' read -r ci_pipeline_created_at ci_pipeline_created_at_source < <(value_with_source "CI_PIPELINE_CREATED_AT")
43+
IFS=$'\t' read -r parent_pipeline_created_at parent_pipeline_created_at_source < <(value_with_source "PARENT_PIPELINE_CREATED_AT")
44+
45+
ci_job_started_epoch=""
46+
if [ -n "$ci_job_started_at" ]; then
47+
ci_job_started_epoch=$(timestamp_to_epoch "$ci_job_started_at" || true)
48+
fi
49+
50+
jq -n \
51+
--arg stage "$stage" \
52+
--arg collected_at "$(date -u +%Y-%m-%dT%H:%M:%SZ)" \
53+
--arg ci_job_started_at "$ci_job_started_at" \
54+
--arg ci_job_started_at_source "$ci_job_started_at_source" \
55+
--arg ci_job_started_epoch "$ci_job_started_epoch" \
56+
--arg ci_pipeline_created_at "$ci_pipeline_created_at" \
57+
--arg ci_pipeline_created_at_source "$ci_pipeline_created_at_source" \
58+
--arg parent_pipeline_created_at "$parent_pipeline_created_at" \
59+
--arg parent_pipeline_created_at_source "$parent_pipeline_created_at_source" \
60+
'
61+
{schema_version: 1, stage: $stage, collected_at: $collected_at}
62+
+ (if $ci_job_started_at != "" then {
63+
ci_job_started_at: $ci_job_started_at,
64+
ci_job_started_at_source: $ci_job_started_at_source
65+
} else {} end)
66+
+ (if $ci_job_started_epoch != "" then {
67+
ci_job_started_epoch: ($ci_job_started_epoch | tonumber)
68+
} else {} end)
69+
+ (if $ci_pipeline_created_at != "" then {
70+
ci_pipeline_created_at: $ci_pipeline_created_at,
71+
ci_pipeline_created_at_source: $ci_pipeline_created_at_source
72+
} else {} end)
73+
+ (if $parent_pipeline_created_at != "" then {
74+
parent_pipeline_created_at: $parent_pipeline_created_at,
75+
parent_pipeline_created_at_source: $parent_pipeline_created_at_source
76+
} else {} end)
77+
' > "$output"
78+
79+
echo "Recorded CI timing context: stage=${stage} ci_job_started_at=${ci_job_started_at:-not_available}"

‎scripts/result.sh‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -529,10 +529,10 @@ write_result_json() {
529529
local idx="$1"
530530
local fom_breakdown_block=""
531531

532-
# Build pipeline_timing block if pipeline_timing.json exists (only for first result to avoid duplication).
532+
# Build pipeline_timing block if pipeline_timing.json exists.
533533
# Treat the file as data; never source generated timing files as shell.
534534
local timing_block=""
535-
if [ "$idx" = "0" ] && [ -f results/pipeline_timing.json ]; then
535+
if [ -f results/pipeline_timing.json ]; then
536536
local pipeline_timing_json
537537
pipeline_timing_json=$(jq -c '
538538
def num: if type == "number" then . else (tonumber? // 0) end;

0 commit comments

Comments
 (0)