diff --git a/docs/cx/BENCHKIT_SPEC.md b/docs/cx/BENCHKIT_SPEC.md index d05e83d..f13d126 100644 --- a/docs/cx/BENCHKIT_SPEC.md +++ b/docs/cx/BENCHKIT_SPEC.md @@ -373,6 +373,10 @@ benchmark script が開始するまでの job queue time として読める。 各 Result JSON は同じ job-level pipeline timing を持つ。 これにより Portal の condition-level 表示は `Exp / node_count / numproc_node / nthreads / FOM_version` ごとに timing を参照できる。 +`pipeline_timing.run_time_scope` はこの粒度を示し、現在の共通収集では `job` である。 +同じ job に profiler 実行が含まれる場合は、`pipeline_timing.profiled_run_included` +を `true` にできる。これは profiler artifact が個々の Result JSON に付くこととは別の +job-level timing marker であり、通常実行の baseline timing と混同しない。 Benchmark results are produced by normalizing `run.sh` output into Result JSON through `result.sh`. @@ -402,6 +406,11 @@ 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. +`pipeline_timing.run_time_scope` identifies that granularity; the current common +collector uses `job`. When the same job includes a profiler run, +`pipeline_timing.profiled_run_included` may be set to `true`. This is a +job-level timing marker, separate from attaching a profiler artifact to an +individual Result JSON, and should not be mixed into unprofiled baseline timing. ### 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 d5290a9..7f78c5f 100644 --- a/result_server/templates/_usage_report_performance_telemetry_section.html +++ b/result_server/templates/_usage_report_performance_telemetry_section.html @@ -6,6 +6,7 @@ "profiled_result_count": 0, "regular_run_timing_count": 0, "profiled_run_timing_count": 0, + "profiled_job_timing_count": 0, "profile_overhead_pair_count": 0, "scheduler_queue_timing_count": 0, "estimate_record_count": 0, @@ -109,6 +110,9 @@

Build Cache

{{ row.regular_run_timing_count }} timing records profiled {{ row.avg_profiled_run_time }} {{ row.profiled_run_timing_count }} timing records + {% if row.profiled_job_timing_count|default(0) %} + profiled job-only {{ row.profiled_job_timing_count }} timing records + {% endif %} overhead pairs {{ row.profile_overhead_pair_count|default(0) }} observed overhead {{ row.avg_profile_overhead_delta|default('-') }} / {{ row.avg_profile_overhead_ratio|default('-') }} {{ row.profile_overhead_status|default('-') }} @@ -118,6 +122,9 @@

Build Cache

regular {{ condition.avg_regular_run_time }} ({{ condition.regular_run_timing_count }}/{{ condition.regular_result_count }} timed) / profiled {{ condition.avg_profiled_run_time }} ({{ condition.profiled_run_timing_count }}/{{ condition.profiled_result_count }} timed) + {% if condition.profiled_job_timing_count|default(0) %} + profiled job-only timing {{ condition.profiled_job_timing_count }} + {% endif %} observed overhead {{ condition.avg_profile_overhead_delta }} / {{ condition.avg_profile_overhead_ratio }} {{ condition.profile_overhead_status }} {% endfor %} diff --git a/result_server/tests/test_performance_telemetry.py b/result_server/tests/test_performance_telemetry.py index 36642ff..03106db 100644 --- a/result_server/tests/test_performance_telemetry.py +++ b/result_server/tests/test_performance_telemetry.py @@ -251,6 +251,7 @@ def test_performance_telemetry_counts_profile_overhead_pairs(tmp_path, monkeypat "profiled_result_count": 1, "regular_run_timing_count": 1, "profiled_run_timing_count": 1, + "profiled_job_timing_count": 0, "avg_regular_run_time": "5m", "avg_profiled_run_time": "6m", "avg_profile_overhead_delta": "1m", @@ -260,6 +261,82 @@ def test_performance_telemetry_counts_profile_overhead_pairs(tmp_path, monkeypat ] +def test_performance_telemetry_excludes_profiled_job_timing_from_regular_baseline(tmp_path, monkeypatch): + repo_root = tmp_path / "repo" + (repo_root / "programs" / "demoapp").mkdir(parents=True) + monkeypatch.setattr(performance_telemetry, "REPO_ROOT", repo_root) + + common = { + "code": "demoapp", + "system": "DemoSystem", + "Exp": "CASE1", + "node_count": 1, + "numproc_node": 2, + "nthreads": 12, + "FOM_version": "solver-v1", + "FOM": 1.0, + } + _write_json( + tmp_path / "result_20260901_010101_aaaaaaaa-bbbb-cccc-dddd-eeeeeeeeeeee.json", + { + **common, + "pipeline_timing": {"run_time": 300, "run_time_scope": "job"}, + }, + ) + _write_json( + tmp_path / "result_20260902_010101_bbbbbbbb-bbbb-cccc-dddd-eeeeeeeeeeee.json", + { + **common, + "pipeline_timing": { + "run_time": 360, + "run_time_scope": "job", + "profiled_run_included": True, + }, + }, + ) + + telemetry = build_performance_telemetry(str(tmp_path)) + + assert telemetry["summary"]["result_count"] == 2 + assert telemetry["summary"]["timing_record_count"] == 2 + assert telemetry["summary"]["regular_run_timing_count"] == 1 + assert telemetry["summary"]["profiled_run_timing_count"] == 0 + assert telemetry["summary"]["profiled_job_timing_count"] == 1 + assert telemetry["summary"]["profile_overhead_pair_count"] == 0 + assert telemetry["summary"]["avg_regular_run_time"] == "5m" + assert telemetry["summary"]["avg_profiled_run_time"] == "-" + assert telemetry["summary"]["avg_profile_overhead_delta"] == "-" + assert telemetry["summary"]["avg_profile_overhead_ratio"] == "-" + + row = telemetry["rows"][0] + assert row["regular_run_timing_count"] == 1 + assert row["profiled_run_timing_count"] == 0 + assert row["profiled_job_timing_count"] == 1 + assert row["profile_overhead_pair_count"] == 0 + assert row["profile_overhead_status"] == "needs profiled result timing" + assert row["latest_run_kind"] == "profiled job" + assert row["run_conditions"] == [ + { + "label": "CASE1 / N1 P2 T12 / solver-v1", + "exp": "CASE1", + "node_count": "1", + "numproc_node": "2", + "nthreads": "12", + "fom_version": "solver-v1", + "regular_result_count": 2, + "profiled_result_count": 0, + "regular_run_timing_count": 1, + "profiled_run_timing_count": 0, + "profiled_job_timing_count": 1, + "avg_regular_run_time": "5m", + "avg_profiled_run_time": "-", + "avg_profile_overhead_delta": "-", + "avg_profile_overhead_ratio": "-", + "profile_overhead_status": "needs profiled result timing", + } + ] + + def test_performance_telemetry_keeps_benchmark_conditions_without_timing(tmp_path, monkeypatch): repo_root = tmp_path / "repo" (repo_root / "programs" / "demoapp").mkdir(parents=True) @@ -299,6 +376,7 @@ def test_performance_telemetry_keeps_benchmark_conditions_without_timing(tmp_pat "profiled_result_count": 0, "regular_run_timing_count": 0, "profiled_run_timing_count": 0, + "profiled_job_timing_count": 0, "avg_regular_run_time": "-", "avg_profiled_run_time": "-", "avg_profile_overhead_delta": "-", diff --git a/result_server/utils/performance_telemetry.py b/result_server/utils/performance_telemetry.py index 8397225..929f340 100644 --- a/result_server/utils/performance_telemetry.py +++ b/result_server/utils/performance_telemetry.py @@ -44,6 +44,7 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N "profiled_result_count": 0, "regular_run_timing_count": 0, "profiled_run_timing_count": 0, + "profiled_job_timing_count": 0, "profile_overhead_pair_count": 0, "estimate_record_count": 0, "estimate_timing_record_count": 0, @@ -74,6 +75,7 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N "profiled_count": 0, "regular_run_timing_count": 0, "profiled_run_timing_count": 0, + "profiled_job_timing_count": 0, "profile_overhead_pair_count": 0, "profile_overhead_status": "-", "avg_profile_overhead_delta": "-", @@ -108,9 +110,9 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N }, ) row["result_count"] += 1 - is_profiled = _has_profile_data(data) - run_kind = "profiled" if is_profiled else "regular" - _add_run_condition_result(row["_run_conditions"], data, run_kind) + has_profile_data = _has_profile_data(data) + result_kind = "profiled" if has_profile_data else "regular" + _add_run_condition_result(row["_run_conditions"], data, result_kind) raw_timing = data.get("pipeline_timing") timing = _timing_values(raw_timing) @@ -127,13 +129,20 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N _add_scalar_total(scheduler_queue_totals, scheduler_queue_time) run_time = timing.get("run_time") if run_time is not None: - _add_run_condition_timing(row["_run_conditions"], data, run_kind, run_time) - if is_profiled: + timing_kind = _run_timing_kind(data, raw_timing) + if timing_kind == "profiled_job": + row["profiled_job_timing_count"] += 1 + summary["profiled_job_timing_count"] += 1 + _add_run_condition_profiled_job_timing(row["_run_conditions"], data) + else: + _add_run_condition_timing(row["_run_conditions"], data, timing_kind, run_time) + + if timing_kind == "profiled": row["profiled_run_timing_count"] += 1 summary["profiled_run_timing_count"] += 1 _add_scalar_total(row["_profiled_run_totals"], run_time) _add_scalar_total(profiled_run_totals, run_time) - else: + elif timing_kind == "regular": row["regular_run_timing_count"] += 1 summary["regular_run_timing_count"] += 1 _add_scalar_total(row["_regular_run_totals"], run_time) @@ -150,9 +159,9 @@ def build_performance_telemetry(received_dir: str, estimated_dir: str | None = N _nested_value(raw_timing, "scheduler_queue_time_source") ) row["latest_run_time"] = _format_seconds(timing.get("run_time")) - row["latest_run_kind"] = run_kind + row["latest_run_kind"] = _run_timing_label(_run_timing_kind(data, raw_timing)) - if is_profiled: + if has_profile_data: row["profiled_count"] += 1 summary["profiled_result_count"] += 1 @@ -398,6 +407,14 @@ def _add_run_condition_timing( _add_scalar_total(condition[f"_{run_kind}_run_totals"], run_time) +def _add_run_condition_profiled_job_timing( + run_conditions: dict[tuple[str, ...], dict[str, Any]], + data: dict[str, Any], +) -> None: + condition = _ensure_run_condition(run_conditions, data) + condition["profiled_job_timing_count"] += 1 + + def _ensure_run_condition( run_conditions: dict[tuple[str, ...], dict[str, Any]], data: dict[str, Any], @@ -415,6 +432,7 @@ def _ensure_run_condition( "profiled_result_count": 0, "regular_run_timing_count": 0, "profiled_run_timing_count": 0, + "profiled_job_timing_count": 0, "_regular_run_totals": _empty_scalar_total(), "_profiled_run_totals": _empty_scalar_total(), } @@ -464,6 +482,7 @@ def _run_condition_rows(run_conditions: dict[tuple[str, ...], dict[str, Any]]) - "profiled_result_count": condition["profiled_result_count"], "regular_run_timing_count": condition["regular_run_timing_count"], "profiled_run_timing_count": condition["profiled_run_timing_count"], + "profiled_job_timing_count": condition["profiled_job_timing_count"], "avg_regular_run_time": _format_seconds(regular_avg), "avg_profiled_run_time": _format_seconds(profiled_avg), "avg_profile_overhead_delta": _format_overhead_delta(overhead), @@ -499,6 +518,10 @@ def _run_condition_status( ) -> str: if regular_avg is not None and profiled_avg is not None: return "observed from matching dimensions" + if condition["profiled_job_timing_count"] and regular_avg is not None: + return "needs profiled result timing" + if condition["profiled_job_timing_count"]: + return "needs unprofiled run timing" if condition["profiled_run_timing_count"] and condition["regular_result_count"]: return "needs regular run timing" if condition["regular_run_timing_count"] and condition["profiled_result_count"]: @@ -543,6 +566,10 @@ def _numeric_sort_value(value: str) -> tuple[int, float | str]: def _profile_overhead_status(row: dict[str, Any], pair_count: int) -> str: if pair_count: return "observed from matching dimensions" + if row["profiled_job_timing_count"] and row["regular_run_timing_count"]: + return "needs profiled result timing" + if row["profiled_job_timing_count"]: + return "profiled job timing only" if row["regular_run_timing_count"] and row["profiled_run_timing_count"]: return "needs matching run dimensions" if row["regular_run_timing_count"]: @@ -618,6 +645,44 @@ def _has_profile_data(data: dict[str, Any]) -> bool: return isinstance(profile_data, dict) and bool(profile_data) +def _run_timing_kind(data: dict[str, Any], raw_timing: Any) -> str: + includes_profiled_run = _timing_includes_profiled_run(raw_timing) + has_profile_data = _has_profile_data(data) + if includes_profiled_run is True and not has_profile_data: + return "profiled_job" + if includes_profiled_run is True or has_profile_data: + return "profiled" + return "regular" + + +def _run_timing_label(timing_kind: str) -> str: + if timing_kind == "profiled_job": + return "profiled job" + return timing_kind + + +def _timing_includes_profiled_run(raw_timing: Any) -> bool | None: + if not isinstance(raw_timing, dict): + return None + for field in ("profiled_run_included", "profiled_job"): + value = _as_bool(raw_timing.get(field)) + if value is not None: + return value + return None + + +def _as_bool(value: Any) -> bool | None: + if isinstance(value, bool): + return value + if isinstance(value, str): + normalized = value.strip().lower() + if normalized in {"1", "true", "yes", "on"}: + return True + if normalized in {"0", "false", "no", "off"}: + return False + return None + + def _is_performance_record(data: dict[str, Any]) -> bool: code = _clean(data.get("code")) system = _clean(data.get("system")) diff --git a/scripts/result.sh b/scripts/result.sh index acae8fe..009b12b 100644 --- a/scripts/result.sh +++ b/scripts/result.sh @@ -74,6 +74,16 @@ build_profile_data_summary() { ' 2>/dev/null || true } +has_profiler_archive() { + local archive + for archive in results/padata*.tgz; do + if [[ -f "$archive" ]]; then + return 0 + fi + done + return 1 +} + decode_base64_value() { if base64 --decode >/dev/null 2>&1 /dev/null || true) if [ -z "$pipeline_timing_json" ] || [ "$pipeline_timing_json" = "null" ]; then - pipeline_timing_json='{"build_time":0,"queue_time":0,"run_time":0}' + if [ "$profiled_run_included" = true ]; then + pipeline_timing_json='{"build_time":0,"queue_time":0,"run_time":0,"run_time_scope":"job","profiled_run_included":true}' + else + pipeline_timing_json='{"build_time":0,"queue_time":0,"run_time":0,"run_time_scope":"job"}' + fi fi timing_block=", \"pipeline_timing\": $pipeline_timing_json" diff --git a/scripts/tests/test_process_and_send_results.sh b/scripts/tests/test_process_and_send_results.sh index ac82a66..8e55678 100644 --- a/scripts/tests/test_process_and_send_results.sh +++ b/scripts/tests/test_process_and_send_results.sh @@ -163,6 +163,8 @@ jq -e ' .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 + .pipeline_timing.run_time_scope == "job" and + (.pipeline_timing | has("profiled_run_included") | not) and (.execution_trigger | type) == "object" ' "${TMP_DIR}/project/send_results_workspace/results/result0.json" >/dev/null jq -e ' diff --git a/scripts/tests/test_result_common_json_contract.sh b/scripts/tests/test_result_common_json_contract.sh index 77b3186..a47f355 100644 --- a/scripts/tests/test_result_common_json_contract.sh +++ b/scripts/tests/test_result_common_json_contract.sh @@ -169,7 +169,9 @@ jq -e ' .pipeline_timing.queue_time_source == "not_measured" and .pipeline_timing.scheduler_queue_time == 45 and .pipeline_timing.scheduler_queue_time_source == "runner_metadata" and - .pipeline_timing.run_time == 34 + .pipeline_timing.run_time == 34 and + .pipeline_timing.run_time_scope == "job" and + (.pipeline_timing | has("profiled_run_included") | not) ' "${RESULT_JSON}" >/dev/null jq -e ' diff --git a/scripts/tests/test_result_profile_data.sh b/scripts/tests/test_result_profile_data.sh index e685217..808226d 100644 --- a/scripts/tests/test_result_profile_data.sh +++ b/scripts/tests/test_result_profile_data.sh @@ -118,6 +118,8 @@ jq -e ' .pipeline_timing.queue_time == 0 and .pipeline_timing.queue_time_source == "not_measured" and .pipeline_timing.run_time == 34 and + .pipeline_timing.run_time_scope == "job" and + .pipeline_timing.profiled_run_included == true and .pipeline_id == 999 and .parent_pipeline_id == 888 and .execution_trigger.id == "qws-fugaku-watch" and @@ -136,7 +138,10 @@ jq -e ' .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 + .pipeline_timing.run_time == 34 and + .pipeline_timing.run_time_scope == "job" and + .pipeline_timing.profiled_run_included == true and + (.profile_data | type) == "null" ' "${RESULT_JSON_1}" >/dev/null NCU_RESULT_JSON="${TMP_DIR}/ncu/results/result0.json"