Add timing observation support for QWS

.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

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 へ投影するものである。

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.

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_<Exp>.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.

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("^(?<record_type>QWS_TIMER_SCHEMA(?:_[A-Z_]+)?)\\s*(?<rest>.*)$")?
+      | {
+          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 <qws-log-file> <exp> [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

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.

result_server/templates/result_detail.html

@@ -208,6 +208,10 @@ <h2>Scalar Metrics</h2>
 </div>
 {% 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 %}

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