From 10ceab5f7ce7e46847e08d0cb4be3c28d44010ae Mon Sep 17 00:00:00 2001 From: yoshifuminakamura Date: Sun, 13 Sep 2026 14:26:19 +0900 Subject: [PATCH] Add timing observation support for QWS Signed-off-by: yoshifuminakamura --- .github/workflows/result-server-tests.yml | 2 + docs/cx/BENCHKIT_SPEC.md | 27 ++- docs/guides/developer-reference.md | 6 +- programs/qws/README.md | 10 + programs/qws/parse_timing.sh | 171 ++++++++++++++ programs/qws/run.sh | 16 +- result_server/templates/result_detail.html | 4 + .../tests/test_result_detail_template.py | 30 +++ result_server/utils/result_detail_view.py | 57 +++++ scripts/bk_functions.sh | 218 ++++++++++++++++++ scripts/result.sh | 94 +++++++- scripts/tests/test_bk_timing_observations.sh | 89 +++++++ scripts/tests/test_qws_timing_artifact.sh | 78 +++++++ .../tests/test_result_common_json_contract.sh | 72 +++++- 14 files changed, 869 insertions(+), 5 deletions(-) create mode 100644 programs/qws/parse_timing.sh create mode 100644 scripts/tests/test_bk_timing_observations.sh create mode 100644 scripts/tests/test_qws_timing_artifact.sh diff --git a/.github/workflows/result-server-tests.yml b/.github/workflows/result-server-tests.yml index fe007191..8d9c21b6 100644 --- a/.github/workflows/result-server-tests.yml +++ b/.github/workflows/result-server-tests.yml @@ -72,6 +72,8 @@ jobs: bash scripts/tests/test_bk_profiler.sh bash scripts/tests/test_bk_fetch_source.sh bash scripts/tests/test_bk_input_info.sh + bash scripts/tests/test_bk_timing_observations.sh + bash scripts/tests/test_qws_timing_artifact.sh bash scripts/tests/test_build_cache.sh bash scripts/tests/test_build_environment_snapshot.sh bash scripts/tests/test_ci_timing_context.sh diff --git a/docs/cx/BENCHKIT_SPEC.md b/docs/cx/BENCHKIT_SPEC.md index a377a3fe..9d9d54ce 100644 --- a/docs/cx/BENCHKIT_SPEC.md +++ b/docs/cx/BENCHKIT_SPEC.md @@ -532,7 +532,32 @@ A site-local path is location information, not a durable input identity. Large datasets and collaboration-derived inputs may still be staged on site-local shared storage, but Result provenance should prefer dataset identity, recipe, manifest, and digest over paths. Detailed local paths should not be exposed on the public surface unless they are necessary. -### 7.4.1 Public Reuse Packets +### 7.4.1 Detailed Timing Observations + +Benchkit は、アプリが出力する詳細 timer table や profiler から得た timing evidence を、任意の `timing_observations` として Result JSON に保持できることが望ましい。 +これは `fom_breakdown` とは別の観測レイヤである。 +`fom_breakdown.sections` / `fom_breakdown.overlaps` は、推定や reuse に使うと決めた section / overlap 投影を表す。 +一方、`timing_observations` は、その前段の詳細測定 artifact と要約を表し、未レビューの nested timer、inclusive timer、overlap window を additive section として扱わない。 + +`timing_observations` は最初の段階では任意項目であり、存在しない result を ingest failure として扱わない。 +同じ job から複数 result が出る場合は、各 observation に `result_exp` などの result scope を添えてよい。 +Result JSON には小さな summary と file reference を置き、巨大な profiler report や詳細 table は artifact として保持する。 + +将来、アプリ変更なしで詳細 timing を採取する場合は、profiler adapter が同じ `timing_observations` 経路へ summary と artifact reference を渡す。 +その observation を `fom_breakdown` へ昇格するかどうかは、app / profiler ごとの mapping review によって決める。 + +Benchkit should also preferably be able to retain detailed timer tables and profiler-derived timing evidence as optional `timing_observations` in Result JSON. +This is an observation layer separate from `fom_breakdown`. +`fom_breakdown.sections` and `fom_breakdown.overlaps` represent section or overlap projections intentionally selected for estimation or reuse, while `timing_observations` records detailed measurement artifacts and summaries before that projection is reviewed. + +At the initial stage, `timing_observations` is optional, and results without it are not treated as ingest failures. +When one job emits multiple results, each observation may carry a result scope such as `result_exp`. +Result JSON should keep a compact summary and file reference; large profiler reports or full timer tables should remain artifacts. + +For app-change-free collection, profiler adapters may feed summaries and artifact references into the same `timing_observations` path. +Promoting an observation into `fom_breakdown` remains a separate mapping review for the app or profiler output. + +### 7.4.2 Public Reuse Packets Benchkit は、公開可能な Result JSON から public-only reuse packet を生成できることが望ましい。 これは raw Result JSON の代替ではなく、AI agent や人間が再利用可否を判断しやすいように、公開できる evidence だけを Markdown と machine-readable manifest へ投影するものである。 diff --git a/docs/guides/developer-reference.md b/docs/guides/developer-reference.md index 6fbc2e7c..e62cd15e 100644 --- a/docs/guides/developer-reference.md +++ b/docs/guides/developer-reference.md @@ -279,4 +279,8 @@ Portal quality visibility currently lives in: - result detail quality rows - `/results/usage` current-state quality summaries -Treat missing `source_info`, `fom_breakdown`, or artifact references as internal improvement candidates, not upload-time or pull-request gates. +Treat missing `source_info`, `fom_breakdown`, or artifact references as follow-up improvement candidates, not upload-time or pull-request gates. +Detailed timing artifacts may be recorded through `timing_observations` before +they are promoted to `fom_breakdown`; do not treat every detailed timer or +profiler region as an additive estimation section without an app-specific +mapping review. diff --git a/programs/qws/README.md b/programs/qws/README.md index d4362953..2d5b6bfb 100644 --- a/programs/qws/README.md +++ b/programs/qws/README.md @@ -10,6 +10,12 @@ depend on QWS-local variables or dummy section names. the section names and the section-package mapping locally. QWS production runs do not emit section timing metadata until those timings are measured by QWS itself. +`parse_timing.sh` records the current QWS timing table and optional +`QWS_TIMER_SCHEMA_*` markers as `results/qws_timing_.json` artifacts when +they are present, then registers them through Benchkit's common +`timing_observations` manifest. These artifacts are measurement evidence only; +they are not converted into `SECTION:` / `OVERLAP:` records until the QWS-owned +timer IDs and overlap windows are reviewed as reusable section metadata. Current reference sections are: @@ -48,3 +54,7 @@ Common Benchkit code should handle: - section and overlap composition - current/future system Estimate JSON construction - result-server artifact upload and portal rendering + +Benchkit-local QWS glue may normalize QWS output into app artifacts, but should +not decide that a nested or inclusive timer is an additive section without a +QWS-side mapping. diff --git a/programs/qws/parse_timing.sh b/programs/qws/parse_timing.sh new file mode 100644 index 00000000..431811ee --- /dev/null +++ b/programs/qws/parse_timing.sh @@ -0,0 +1,171 @@ +#!/bin/bash +# parse_timing.sh - Normalize QWS timing output into a small JSON artifact. + +set -euo pipefail + +qws_extract_fom_from_log() { + local log_file="$1" + + awk ' + /etime for sovler/ || /etime for solver/ { + count += 1 + if (count == 2) { + printf "%.3f\n", $5 + 0 + exit + } + } + ' "$log_file" +} + +qws_extract_timing_table() { + local log_file="$1" + + awk ' + function is_number(value) { + return value ~ /^[-+]?([0-9]+([.][0-9]*)?|[.][0-9]+)([eE][-+]?[0-9]+)?$/ + } + /^[[:space:]]*rank[[:space:]]+func_id[[:space:]]+calls[[:space:]]+total[(]s[)][[:space:]]+average[(]s[)]/ { + in_table = 1 + next + } + in_table && /^[[:space:]]*end[[:space:]]*$/ { + in_table = 0 + next + } + in_table && NF >= 5 && $1 ~ /^[0-9]+$/ && $3 ~ /^[0-9]+$/ && is_number($4) && is_number($5) { + printf "%s\t%s\t%s\t%.12g\t%.12g\n", $1, $2, $3, $4 + 0, $5 + 0 + } + ' "$log_file" +} + +qws_timing_schema_json() { + local log_file="$1" + + awk '/^QWS_TIMER_SCHEMA/ { print }' "$log_file" | jq -Rsc ' + def kv_token: + split(":") as $parts + | select(($parts | length) >= 2) + | {key: $parts[0], value: ($parts[1:] | join(":"))}; + [ + split("\n")[] + | select(length > 0) + | capture("^(?QWS_TIMER_SCHEMA(?:_[A-Z_]+)?)\\s*(?.*)$")? + | { + record_type: .record_type, + fields: ( + .rest + | split(" ") + | map(select(length > 0) | kv_token) + | from_entries + ) + } + ] + ' +} + +qws_timing_table_json() { + local log_file="$1" + + qws_extract_timing_table "$log_file" | jq -Rnc ' + [ + inputs + | split("\t") + | select(length == 5) + | { + rank: (.[0] | tonumber), + id: .[1], + calls: (.[2] | tonumber), + total_seconds: (.[3] | tonumber), + average_seconds: (.[4] | tonumber) + } + ] + ' +} + +qws_emit_timing_artifact_json() { + local log_file="$1" + local exp="$2" + local fom="${3:-}" + local schema_json + local timers_json + local source_log_name + + if [[ ! -f "$log_file" ]]; then + echo "QWS timing log was not found: ${log_file}" >&2 + return 1 + fi + + source_log_name=$(basename "$log_file") + schema_json=$(qws_timing_schema_json "$log_file") + timers_json=$(qws_timing_table_json "$log_file") + + jq -n \ + --arg exp "$exp" \ + --arg source_log "$source_log_name" \ + --arg fom "$fom" \ + --argjson schema "$schema_json" \ + --argjson timers "$timers_json" ' + def number_text: + test("^[-+]?([0-9]+([.][0-9]*)?|[.][0-9]+)([eE][-+]?[0-9]+)?$"); + { + schema_version: 1, + producer: "qws", + kind: "qws_timing_observation", + exp: $exp, + source_log: $source_log, + schema: $schema, + timers: $timers, + summary: { + timer_count: ($timers | length), + schema_record_count: ($schema | length), + has_timing_table: (($timers | length) > 0), + has_overlap_probe_schema: ( + any($schema[]?; .record_type == "QWS_TIMER_SCHEMA" and .fields.target == "overlap_probe") + ) + } + } + + (if ($fom | number_text) then {fom_seconds: ($fom | tonumber)} else {} end) + ' +} + +qws_write_timing_artifact() { + local log_file="$1" + local exp="$2" + local output_file="$3" + local fom="${4:-}" + local tmp_file + + if [[ ! -f "$log_file" ]]; then + echo "QWS timing artifact skipped; log was not found: ${log_file}" >&2 + return 0 + fi + if ! command -v jq >/dev/null 2>&1; then + echo "QWS timing artifact skipped; jq is not available" >&2 + return 0 + fi + if ! grep -Eq '^[[:space:]]*rank[[:space:]]+func_id[[:space:]]+calls[[:space:]]+total[(]s[)][[:space:]]+average[(]s[)]|^QWS_TIMER_SCHEMA' "$log_file"; then + return 0 + fi + + mkdir -p "$(dirname "$output_file")" + tmp_file=$(mktemp "${output_file}.tmp.XXXXXX") + if qws_emit_timing_artifact_json "$log_file" "$exp" "$fom" > "$tmp_file"; then + mv "$tmp_file" "$output_file" + else + rm -f "$tmp_file" + echo "QWS timing artifact skipped; failed to parse ${log_file}" >&2 + fi +} + +if [[ "${BASH_SOURCE[0]}" == "$0" ]]; then + if [[ $# -lt 2 || $# -gt 4 ]]; then + echo "Usage: $0 [output-json] [fom-seconds]" >&2 + exit 2 + fi + + if [[ $# -ge 3 ]]; then + qws_write_timing_artifact "$1" "$2" "$3" "${4:-}" + else + qws_emit_timing_artifact_json "$1" "$2" + fi +fi diff --git a/programs/qws/run.sh b/programs/qws/run.sh index 747455e1..ee634547 100644 --- a/programs/qws/run.sh +++ b/programs/qws/run.sh @@ -15,6 +15,7 @@ qws_case1_args=(32 6 4 3 1 1 1 2 -1 -1 6 50) qws_case7_args=(32 6 4 3 1 2 2 2 -1 -1 6 50) source "${PWD}/scripts/bk_functions.sh" +source "${PWD}/programs/qws/parse_timing.sh" qws_profiler_tool=$(bk_resolve_profiler_tool fapp QWS_PROFILER_TOOL) qws_profiler_level=$(bk_resolve_profiler_level detailed QWS_PROFILER_LEVEL) # QWS synthetic estimation metadata is disabled for production runs. Keep @@ -23,6 +24,7 @@ qws_profiler_level=$(bk_resolve_profiler_level detailed QWS_PROFILER_LEVEL) # source "${PWD}/programs/qws/estimate.sh" mkdir -p results && : > results/result +bk_reset_timing_observations record_qws_runtime_parameter_inputs() { bk_reset_input_info @@ -54,9 +56,21 @@ print_results() { local outfile=$1 local exp=$2 local np=$3 + local artifact_file="../results/qws_timing_${exp}.json" + local artifact_path="results/qws_timing_${exp}.json" ./check.sh "$outfile" "data/$exp" local fom - fom=$(grep etime "$outfile" | awk 'NR==2{printf("%5.3f\n",$5)}') + fom=$(qws_extract_fom_from_log "$outfile") + qws_write_timing_artifact "$outfile" "$exp" "$artifact_file" "$fom" + if [[ -f "$artifact_file" ]]; then + BK_TIMING_OBSERVATIONS_FILE="../results/timing_observations.json" \ + BK_TIMING_OBSERVATION_ITEMS_FILE="../results/.timing_observation_items.jsonl" \ + bk_record_timing_observation \ + --artifact "$artifact_path" \ + --artifact-file "$artifact_file" \ + --result-exp "$exp" \ + --producer qws + fi bk_emit_result --fom "$fom" --fom-unit s --fom-version DDSolverJacobi --exp "$exp" --nodes "$nodes" --numproc-node "$np" --nthreads "$nthreads" # Disabled: this emitted synthetic section timings and dummy estimation # artifacts. Re-enable only after QWS provides real app-side timings. diff --git a/result_server/templates/result_detail.html b/result_server/templates/result_detail.html index 62ccab5e..d1ee5ed3 100644 --- a/result_server/templates/result_detail.html +++ b/result_server/templates/result_detail.html @@ -208,6 +208,10 @@

Scalar Metrics

{% endif %} +{% if timing_observation_rows %} +{{ render_titled_key_value_table("Timing Observations", timing_observation_rows, "meta-table") }} +{% endif %} + {% if build_rows %} {{ render_titled_key_value_table("Build Information", build_rows, "build-table") }} {% endif %} diff --git a/result_server/tests/test_result_detail_template.py b/result_server/tests/test_result_detail_template.py index 5073785e..b317404a 100644 --- a/result_server/tests/test_result_detail_template.py +++ b/result_server/tests/test_result_detail_template.py @@ -119,6 +119,28 @@ def app(): "container image SHA-256 matched", ], }, + "timing_observations": { + "schema_version": 1, + "observations": [ + { + "id": "qws-case0-timers", + "kind": "detailed-timing", + "producer": "qws", + "format": "qws_timing_observation/v1", + "result_exp": "CASE0", + "artifact": { + "type": "file_reference", + "path": "results/qws_timing_CASE0.json", + }, + "summary": { + "timer_count": 14, + "schema_record_count": 3, + "has_overlap_probe_schema": True, + }, + "note": "not projected to fom_breakdown", + } + ], + }, } FULL_QUALITY = { @@ -182,6 +204,12 @@ def test_meta_info_section(self, app): assert "build inputs hash matched" in html assert "rccs-cloud" in html assert "slurm" in html + assert "Timing Observations" in html + assert "qws-case0-timers" in html + assert "producer=qws" in html + assert "artifact=results/qws_timing_CASE0.json" in html + assert "timers=14" in html + assert "overlap probe schema=yes" in html assert "Build Tools" in html assert "gcc (GCC) 11.5.0" in html assert "Back to Results" in html @@ -205,6 +233,8 @@ def test_public_surface_meta_omits_operator_fields(self, app): assert "Cached Binary Created At" not in html assert "Allocation Project ID" not in html assert "Runner" not in html + assert "Timing Observations" not in html + assert "qws_timing_CASE0" not in html assert "rccs-cloud" not in html assert "gh200-runner" not in html diff --git a/result_server/utils/result_detail_view.py b/result_server/utils/result_detail_view.py index 1bd52c9b..3d497af3 100644 --- a/result_server/utils/result_detail_view.py +++ b/result_server/utils/result_detail_view.py @@ -111,6 +111,9 @@ def build_result_detail_context( "profile_rows": _build_profile_rows(profile_data), "quality_rows": [] if public_surface else _build_quality_rows(quality), "profile_artifact_rows": _build_profile_artifact_rows(result, padata_filenames or []), + "timing_observation_rows": ( + [] if public_surface else _build_timing_observation_rows(result.get("timing_observations")) + ), "build_cache_rows": [] if public_surface else _build_build_cache_rows(result.get("build_cache")), "environment_rows": ( [] if public_surface else _build_environment_rows(result.get("environment_snapshot")) @@ -373,6 +376,60 @@ def _environment_snapshot_hash(environment_snapshot): return str(environment_snapshot.get("hash") or "").strip() +def _build_timing_observation_rows(timing_observations): + if not isinstance(timing_observations, dict): + return [] + + observations = timing_observations.get("observations") + if not isinstance(observations, list): + return [] + + rows = [] + for index, observation in enumerate(observations, start=1): + if not isinstance(observation, dict): + continue + label = str(observation.get("id") or f"Observation {index}") + rows.append({"label": label, "value": _format_timing_observation(observation)}) + return rows + + +def _format_timing_observation(observation): + parts = [] + for label, value in ( + ("producer", observation.get("producer")), + ("kind", observation.get("kind")), + ("format", observation.get("format")), + ): + value = str(value or "").strip() + if value: + parts.append(f"{label}={value}") + + artifact = observation.get("artifact") + artifact = artifact if isinstance(artifact, dict) else {} + artifact_path = str(artifact.get("path") or "").strip() + if artifact_path: + parts.append(f"artifact={artifact_path}") + + summary = observation.get("summary") + summary = summary if isinstance(summary, dict) else {} + timer_count = summary.get("timer_count") + schema_record_count = summary.get("schema_record_count") + if timer_count not in (None, ""): + parts.append(f"timers={timer_count}") + if schema_record_count not in (None, ""): + parts.append(f"schema records={schema_record_count}") + if summary.get("has_overlap_probe_schema") is True: + parts.append("overlap probe schema=yes") + elif summary.get("has_overlap_probe_schema") is False: + parts.append("overlap probe schema=no") + + note = str(observation.get("note") or "").strip() + if note: + parts.append(note) + + return "; ".join(parts) if parts else "recorded" + + def _build_scalar_rows(scalar_metrics): if len(scalar_metrics.keys()) < 2: return [] diff --git a/scripts/bk_functions.sh b/scripts/bk_functions.sh index 1632601e..2eb1bd44 100644 --- a/scripts/bk_functions.sh +++ b/scripts/bk_functions.sh @@ -1597,6 +1597,224 @@ bk_record_runtime_parameter_input() { bk_record_input "$@" } +bk_reset_timing_observations() { + _bk_reset_timing_file="${BK_TIMING_OBSERVATIONS_FILE:-results/timing_observations.json}" + _bk_reset_timing_items_file="${BK_TIMING_OBSERVATION_ITEMS_FILE:-results/.timing_observation_items.jsonl}" + rm -f "$_bk_reset_timing_file" "$_bk_reset_timing_items_file" +} + +_bk_safe_timing_observation_artifact_path() { + case "$1" in + results/*.json) ;; + *) return 1 ;; + esac + + case "$1" in + /*|*"/../"*|../*|*"/.."|*\\*) return 1 ;; + esac +} + +_bk_record_timing_observation_items_file() { + _bk_timing_info_file="$1" + _bk_timing_jsonl_file="$2" + + { + printf '{\n' + printf ' "schema_version": 1,\n' + printf ' "observations": [\n' + _bk_timing_first=1 + while IFS= read -r _bk_timing_item; do + [ -n "$_bk_timing_item" ] || continue + if [ "$_bk_timing_first" -eq 0 ]; then + printf ',\n' + fi + printf ' %s' "$_bk_timing_item" + _bk_timing_first=0 + done < "$_bk_timing_jsonl_file" + printf '\n' + printf ' ]\n' + printf '}\n' + } > "$_bk_timing_info_file" +} + +# bk_record_timing_observation - Register an optional detailed timing artifact. +# +# Detailed timing observations are raw or lightly normalized measurement +# evidence. They are kept separate from SECTION/OVERLAP metadata, which is the +# current estimation-oriented projection of app timings. +bk_record_timing_observation() { + _bk_timing_id="" + _bk_timing_kind="detailed-timing" + _bk_timing_producer="" + _bk_timing_format="" + _bk_timing_result_exp="" + _bk_timing_artifact_path="" + _bk_timing_artifact_file="" + _bk_timing_summary_json="" + _bk_timing_note="" + + while [ $# -gt 0 ]; do + case "$1" in + --id) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: --id requires a value" >&2 + return 1 + fi + shift + _bk_timing_id="$1" + ;; + --kind) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: --kind requires a value" >&2 + return 1 + fi + shift + _bk_timing_kind="$1" + ;; + --producer) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: --producer requires a value" >&2 + return 1 + fi + shift + _bk_timing_producer="$1" + ;; + --format) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: --format requires a value" >&2 + return 1 + fi + shift + _bk_timing_format="$1" + ;; + --result-exp) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: --result-exp requires a value" >&2 + return 1 + fi + shift + _bk_timing_result_exp="$1" + ;; + --artifact|--artifact-path) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: $1 requires a value" >&2 + return 1 + fi + shift + _bk_timing_artifact_path="$1" + ;; + --artifact-file) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: --artifact-file requires a value" >&2 + return 1 + fi + shift + _bk_timing_artifact_file="$1" + ;; + --summary-json) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: --summary-json requires a value" >&2 + return 1 + fi + shift + _bk_timing_summary_json="$1" + ;; + --note) + if [ $# -lt 2 ]; then + echo "bk_record_timing_observation: --note requires a value" >&2 + return 1 + fi + shift + _bk_timing_note="$1" + ;; + *) + echo "bk_record_timing_observation: unknown option: $1" >&2 + return 1 + ;; + esac + shift + done + + if [ -z "$_bk_timing_artifact_path" ]; then + echo "bk_record_timing_observation: --artifact is required" >&2 + return 1 + fi + if ! _bk_safe_timing_observation_artifact_path "$_bk_timing_artifact_path"; then + echo "bk_record_timing_observation: artifact must be a safe results/*.json path" >&2 + return 1 + fi + + if [ -z "$_bk_timing_artifact_file" ]; then + _bk_timing_artifact_file="$_bk_timing_artifact_path" + fi + if [ ! -f "$_bk_timing_artifact_file" ]; then + echo "bk_record_timing_observation: skipped missing artifact $_bk_timing_artifact_file" >&2 + return 0 + fi + if ! command -v jq >/dev/null 2>&1; then + echo "bk_record_timing_observation: skipped because jq is not available" >&2 + return 0 + fi + + _bk_timing_artifact_json=$(jq -c 'if type == "object" then . else {} end' "$_bk_timing_artifact_file" 2>/dev/null || printf '{}') + _bk_timing_artifact_summary=$(printf '%s' "$_bk_timing_artifact_json" | jq -c '.summary // {} | if type == "object" then . else {} end') + if [ -z "$_bk_timing_summary_json" ]; then + _bk_timing_summary_json="$_bk_timing_artifact_summary" + elif ! _bk_timing_summary_json=$(printf '%s' "$_bk_timing_summary_json" | jq -c 'if type == "object" then . else error("summary must be an object") end' 2>/dev/null); then + echo "bk_record_timing_observation: --summary-json must be a JSON object" >&2 + return 1 + fi + + if [ -z "$_bk_timing_id" ]; then + _bk_timing_id=$(basename "$_bk_timing_artifact_path" .json) + fi + if [ -z "$_bk_timing_producer" ]; then + _bk_timing_producer=$(printf '%s' "$_bk_timing_artifact_json" | jq -r '.producer // empty') + fi + if [ -z "$_bk_timing_result_exp" ]; then + _bk_timing_result_exp=$(printf '%s' "$_bk_timing_artifact_json" | jq -r '.exp // empty') + fi + if [ -z "$_bk_timing_format" ]; then + _bk_timing_artifact_kind=$(printf '%s' "$_bk_timing_artifact_json" | jq -r '.kind // empty') + _bk_timing_artifact_schema=$(printf '%s' "$_bk_timing_artifact_json" | jq -r '.schema_version // empty') + if [ -n "$_bk_timing_artifact_kind" ] && [ -n "$_bk_timing_artifact_schema" ]; then + _bk_timing_format="${_bk_timing_artifact_kind}/v${_bk_timing_artifact_schema}" + elif [ -n "$_bk_timing_artifact_kind" ]; then + _bk_timing_format="$_bk_timing_artifact_kind" + fi + fi + + _bk_timing_info_file="${BK_TIMING_OBSERVATIONS_FILE:-results/timing_observations.json}" + _bk_timing_items_file="${BK_TIMING_OBSERVATION_ITEMS_FILE:-results/.timing_observation_items.jsonl}" + mkdir -p "$(dirname "$_bk_timing_info_file")" "$(dirname "$_bk_timing_items_file")" || return 1 + + jq -n -c \ + --arg id "$_bk_timing_id" \ + --arg kind "$_bk_timing_kind" \ + --arg producer "$_bk_timing_producer" \ + --arg format "$_bk_timing_format" \ + --arg result_exp "$_bk_timing_result_exp" \ + --arg artifact_path "$_bk_timing_artifact_path" \ + --arg note "$_bk_timing_note" \ + --argjson summary "$_bk_timing_summary_json" ' + { + id: $id, + kind: $kind, + artifact: { + type: "file_reference", + path: $artifact_path + }, + summary: $summary + } + + (if $producer != "" then {producer: $producer} else {} end) + + (if $format != "" then {format: $format} else {} end) + + (if $result_exp != "" then {result_exp: $result_exp} else {} end) + + (if $note != "" then {note: $note} else {} end) + ' >> "$_bk_timing_items_file" + + _bk_record_timing_observation_items_file "$_bk_timing_info_file" "$_bk_timing_items_file" +} + # Write a compact, tool-neutral manifest for the profiler archive. Result JSON # generation reads this manifest to expose summary fields without opening every # raw profiler artifact. For fapp, run_events contains counter names; for ncu it diff --git a/scripts/result.sh b/scripts/result.sh index 8ab6e7ab..2690c8e7 100644 --- a/scripts/result.sh +++ b/scripts/result.sh @@ -756,6 +756,51 @@ if ! input_info_block=$(build_input_info_block); then exit 1 fi +build_timing_observations_block() { + local timing_observations_file="results/timing_observations.json" + + if [ ! -f "$timing_observations_file" ]; then + printf '%s' "" + return 0 + fi + + local timing_observations_json + if ! timing_observations_json=$(jq -cS ' + def safe_artifact_path: + type == "string" + and startswith("results/") + and endswith(".json") + and (contains("\\") | not) + and (contains("/../") | not) + and (startswith("../") | not) + and (endswith("/..") | not); + + if type == "object" + and (.observations | type) == "array" + and all(.observations[]; type == "object") + and all(.observations[]; (.artifact.path? | safe_artifact_path)) + then + . + else + error("timing_observations must be a JSON object with safe observations") + end + ' "$timing_observations_file" 2>/dev/null); then + echo "ERROR: results/timing_observations.json must be a valid timing observations object with safe results/*.json artifacts" >&2 + return 1 + fi + + if [ -z "$timing_observations_json" ] || [ "$timing_observations_json" = "null" ]; then + echo "ERROR: results/timing_observations.json must not be empty" >&2 + return 1 + fi + + printf '%s' "$timing_observations_json" +} + +if ! timing_observations_block=$(build_timing_observations_block); then + exit 1 +fi + filter_input_info_block_for_result() { local result_exp="$1" @@ -803,6 +848,45 @@ filter_input_info_block_for_result() { ' 2>/dev/null || true } +filter_timing_observations_block_for_result() { + local result_exp="$1" + + if [ -z "$timing_observations_block" ]; then + printf '%s' "" + return 0 + fi + if [ -z "$result_exp" ] || [ "$result_exp" = "null" ]; then + printf '%s' "$timing_observations_block" + return 0 + fi + + printf '%s' "$timing_observations_block" | jq -cS --arg exp "$result_exp" ' + def scope_values: + [ + .result_exp?, + .Exp?, + .exp?, + .result_scope?.Exp?, + .result_scope?.exp?, + .result_scope?.experiment?, + .result?.Exp?, + .result?.exp?, + .result?.experiment? + ] + | map(select(. != null and . != "") | tostring); + + (.observations | map(select((scope_values | length) == 0 or (scope_values | index($exp))))) as $items + | (.observations | map(select((scope_values | length) > 0)) | length) as $scoped_count + | if ($items | length) > 0 then + .observations = $items + elif $scoped_count > 0 then + empty + else + . + end + ' 2>/dev/null || true +} + profiled_run_included=false if has_profiler_archive; then profiled_run_included=true @@ -912,6 +996,14 @@ write_result_json() { \"input_info\": ${result_input_info_block}" fi + local timing_observations_json_block="" + local result_timing_observations_block="" + result_timing_observations_block=$(filter_timing_observations_block_for_result "$exp") + if [ -n "$result_timing_observations_block" ]; then + timing_observations_json_block=", + \"timing_observations\": ${result_timing_observations_block}" + fi + # Attach the profiler summary that matches this FOM index. fapp exposes # counter events, while ncu exposes the Nsight Compute option preset. local profile_data_block="" @@ -963,7 +1055,7 @@ write_result_json() { "nthreads": "$nthreads", "description": "$description", "confidential": "$confidential", - "source_info": $source_info_block${input_info_json_block}${profile_data_block}${fom_breakdown_block}${timing_block}${mode_block}${trigger_block}${build_job_block}${run_job_block}${pipeline_id_block}${parent_pipeline_id_block}${execution_trigger_block}${environment_snapshot_json_block}${build_cache_json_block} + "source_info": $source_info_block${input_info_json_block}${timing_observations_json_block}${profile_data_block}${fom_breakdown_block}${timing_block}${mode_block}${trigger_block}${build_job_block}${run_job_block}${pipeline_id_block}${parent_pipeline_id_block}${execution_trigger_block}${environment_snapshot_json_block}${build_cache_json_block} } EOF diff --git a/scripts/tests/test_bk_timing_observations.sh b/scripts/tests/test_bk_timing_observations.sh new file mode 100644 index 00000000..c62c2675 --- /dev/null +++ b/scripts/tests/test_bk_timing_observations.sh @@ -0,0 +1,89 @@ +#!/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 timing observations test" + exit 0 +fi + +TMP_DIR=$(mktemp -d) +trap 'rm -rf "${TMP_DIR}"' EXIT + +source "${REPO_DIR}/scripts/bk_functions.sh" + +pushd "${TMP_DIR}" >/dev/null +mkdir -p results + +cat > results/detail_CASE0.json <<'JSON' +{ + "schema_version": 1, + "producer": "demoapp", + "kind": "demo_timer_table", + "exp": "CASE0", + "summary": { + "timer_count": 3, + "schema_record_count": 1, + "has_overlap_probe_schema": false + }, + "timers": [ + {"id": "solve", "total_seconds": 1.0} + ] +} +JSON + +bk_record_timing_observation \ + --artifact results/detail_CASE0.json \ + --note "not projected to fom_breakdown" + +cat > results/detail_CASE1.json <<'JSON' +{ + "schema_version": 2, + "producer": "profiler-x", + "kind": "call_tree", + "exp": "CASE1", + "summary": { + "timer_count": 20, + "schema_record_count": 0 + } +} +JSON + +bk_record_timing_observation \ + --id profiler-case1 \ + --artifact results/detail_CASE1.json \ + --kind sampled-profile \ + --format sampled-profile/v1 \ + --summary-json '{"timer_count":20,"sampled":true}' + +jq -e ' + .schema_version == 1 and + (.observations | length) == 2 and + .observations[0].id == "detail_CASE0" and + .observations[0].producer == "demoapp" and + .observations[0].format == "demo_timer_table/v1" and + .observations[0].result_exp == "CASE0" and + .observations[0].artifact.path == "results/detail_CASE0.json" and + .observations[0].summary.timer_count == 3 and + .observations[0].note == "not projected to fom_breakdown" and + .observations[1].id == "profiler-case1" and + .observations[1].kind == "sampled-profile" and + .observations[1].format == "sampled-profile/v1" and + .observations[1].producer == "profiler-x" and + .observations[1].summary.sampled == true +' results/timing_observations.json >/dev/null + +if bk_record_timing_observation --artifact ../outside.json >/dev/null 2>&1; then + echo "bk_record_timing_observation accepted an unsafe artifact path" >&2 + exit 1 +fi + +bk_reset_timing_observations +test ! -e results/timing_observations.json +test ! -e results/.timing_observation_items.jsonl + +popd >/dev/null + +echo "timing observations test passed" diff --git a/scripts/tests/test_qws_timing_artifact.sh b/scripts/tests/test_qws_timing_artifact.sh new file mode 100644 index 00000000..1c0fbd01 --- /dev/null +++ b/scripts/tests/test_qws_timing_artifact.sh @@ -0,0 +1,78 @@ +#!/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 QWS timing artifact test" + exit 0 +fi + +TMP_DIR=$(mktemp -d) +trap 'rm -rf "${TMP_DIR}"' EXIT + +mkdir -p "${TMP_DIR}/results" + +source "${REPO_DIR}/programs/qws/parse_timing.sh" + +cat > "${TMP_DIR}/qws_case0.log" <<'EOF' +etime for sovler = 1.23456000000000e-01 sec. +etime for sovler = 3.56000000000000e-01 sec. +print timing + rank func_id calls total(s) average(s) + 0 prec_s_ 10 2.405930e-02 2.405930e-03 + 0 bicgstab_dd_mix_ 10 3.560000e-01 3.560000e-02 + 0 overlap_probe_window 20 1.250000e-02 6.250000e-04 +end +EOF + +test "$(qws_extract_fom_from_log "${TMP_DIR}/qws_case0.log")" = "0.356" +qws_write_timing_artifact "${TMP_DIR}/qws_case0.log" CASE0 "${TMP_DIR}/results/qws_timing_CASE0.json" 0.356 + +jq -e ' + .schema_version == 1 and + .producer == "qws" and + .kind == "qws_timing_observation" and + .exp == "CASE0" and + .source_log == "qws_case0.log" and + .fom_seconds == 0.356 and + .summary.timer_count == 3 and + .summary.schema_record_count == 0 and + .summary.has_timing_table == true and + .summary.has_overlap_probe_schema == false and + .timers[1].id == "bicgstab_dd_mix_" and + .timers[1].calls == 10 and + .timers[1].total_seconds == 0.356 +' "${TMP_DIR}/results/qws_timing_CASE0.json" >/dev/null + +cat > "${TMP_DIR}/qws_overlap.log" <<'EOF' +QWS_TIMER_SCHEMA version:qws-overlap-v1 target:overlap_probe conventional_timers:on probe_mode:coarse_phase unit:sec direction_order:xf,xb,yf,yb,zf,zb,tf,tb +QWS_TIMER_SCHEMA_SECTION id:bicgstab_dd_mix_ kind:parent aggregation:inclusive +QWS_TIMER_SCHEMA_SECTION id:bicgstab_dd_mix_ddd_d_ kind:compute aggregation:exclusive parent:bicgstab_dd_mix_ +QWS_TIMER_SCHEMA_OVERLAP_WINDOW id:prec_ddd.sap.o.ddd_in_accum_addsub compute:ddd_in,accum_addsub comm:halo_recv active_rule:npe_direction_ne_1 group_model:max_active_directions send_wait:after_window +QWS_TIMER_SCHEMA_MEASUREMENT hidden_recv_completion:upper_bound_on_coalesced_or_calc_end active_directions:not_collapsed producer_aggregation:none + rank func_id calls total(s) average(s) + 0 bicgstab_dd_mix_ 10 4.240000e-01 4.240000e-02 + 0 overlap_probe_recv_pending_window 12 2.400000e-02 2.000000e-03 +end +EOF + +qws_emit_timing_artifact_json "${TMP_DIR}/qws_overlap.log" CASE1 0.424 > "${TMP_DIR}/results/qws_timing_CASE1.json" + +jq -e ' + .summary.timer_count == 2 and + .summary.schema_record_count == 5 and + .summary.has_overlap_probe_schema == true and + .schema[0].record_type == "QWS_TIMER_SCHEMA" and + .schema[0].fields.version == "qws-overlap-v1" and + .schema[0].fields.target == "overlap_probe" and + .schema[0].fields.probe_mode == "coarse_phase" and + .schema[1].record_type == "QWS_TIMER_SCHEMA_SECTION" and + .schema[1].fields.id == "bicgstab_dd_mix_" and + .schema[3].record_type == "QWS_TIMER_SCHEMA_OVERLAP_WINDOW" and + .schema[3].fields.compute == "ddd_in,accum_addsub" and + .schema[4].record_type == "QWS_TIMER_SCHEMA_MEASUREMENT" +' "${TMP_DIR}/results/qws_timing_CASE1.json" >/dev/null + +echo "QWS timing artifact test passed" diff --git a/scripts/tests/test_result_common_json_contract.sh b/scripts/tests/test_result_common_json_contract.sh index ae0dab5b..4bcabbf2 100644 --- a/scripts/tests/test_result_common_json_contract.sh +++ b/scripts/tests/test_result_common_json_contract.sh @@ -59,6 +59,44 @@ cat > "${TMP_DIR}/results/input_info.json" <<'EOF' } EOF +cat > "${TMP_DIR}/results/timing_observations.json" <<'EOF' +{ + "schema_version": 1, + "observations": [ + { + "id": "demo-case0-timers", + "kind": "detailed-timing", + "producer": "demoapp", + "format": "demo_timer_table/v1", + "result_exp": "CASE0", + "artifact": { + "type": "file_reference", + "path": "results/demo_timing_CASE0.json" + }, + "summary": { + "timer_count": 3, + "schema_record_count": 1 + } + }, + { + "id": "demo-case1-timers", + "kind": "detailed-timing", + "producer": "demoapp", + "format": "demo_timer_table/v1", + "result_exp": "CASE1", + "artifact": { + "type": "file_reference", + "path": "results/demo_timing_CASE1.json" + }, + "summary": { + "timer_count": 4, + "schema_record_count": 0 + } + } + ] +} +EOF + cat > "${TMP_DIR}/results/pipeline_timing.json" <<'EOF' { "build_time": "12", @@ -180,6 +218,11 @@ jq -e ' .input_info.inputs[0].dataset_id == "demo-case0" and .input_info.inputs[0].result_exp == "CASE0" and .input_info.inputs[0].verification_status == "covered_by_source_commit" and + .timing_observations.schema_version == 1 and + (.timing_observations.observations | length) == 1 and + .timing_observations.observations[0].id == "demo-case0-timers" and + .timing_observations.observations[0].artifact.path == "results/demo_timing_CASE0.json" and + .timing_observations.observations[0].summary.timer_count == 3 and .pipeline_timing.build_time == 12 and .pipeline_timing.queue_time == 0 and .pipeline_timing.queue_time_source == "not_measured" and @@ -196,7 +239,10 @@ jq -e ' (.input_info.inputs | length) == 1 and .input_info.inputs[0].dataset_id == "demo-case1" and .input_info.inputs[0].kind == "runtime-parameters" and - .input_info.inputs[0].arguments == ["--case", "1"] + .input_info.inputs[0].arguments == ["--case", "1"] and + (.timing_observations.observations | length) == 1 and + .timing_observations.observations[0].id == "demo-case1-timers" and + .timing_observations.observations[0].summary.timer_count == 4 ' "${RESULT_JSON1}" >/dev/null jq -e ' @@ -242,6 +288,30 @@ jq -e ' .execution_trigger.reason == "repo_ref:https://example.test/demoapp.git@main" ' "${RESULT_JSON}" >/dev/null +cat > "${TMP_DIR}/results/timing_observations.json" <<'EOF' +{ + "schema_version": 1, + "observations": [ + { + "id": "unsafe-timing", + "artifact": { + "type": "file_reference", + "path": "../outside-timing.json" + }, + "summary": {} + } + ] +} +EOF + +pushd "${TMP_DIR}" >/dev/null +if bash "${REPO_DIR}/scripts/result.sh" demoapp DemoSystem cross demoapp_DemoSystem_build demoapp_DemoSystem_run 4242 >/dev/null 2>result-error.log; then + echo "result.sh accepted an unsafe timing observation artifact path" >&2 + exit 1 +fi +grep -q "safe results/.*\\.json artifacts" result-error.log +popd >/dev/null + PUBLIC_TMP_DIR="${TMP_DIR}/public-access" FAKE_BIN="${PUBLIC_TMP_DIR}/bin" mkdir -p "${PUBLIC_TMP_DIR}/results" "${FAKE_BIN}"