diff --git a/BACKLOG.md b/BACKLOG.md index 98d954fd..628c048a 100644 --- a/BACKLOG.md +++ b/BACKLOG.md @@ -92,7 +92,7 @@ CC-001/CC-002 were consumed by PR #24 fix bundle inline, with no standalone entr | CC-357 | 🟢 someday | **[skill as contract: machine-readable schema for skills]** 現有 skills/ 都是純 markdown prose（SKILL.md），沒有機器可讀的 input schema、output contract、tool_constraints、completion_condition。這使得 skill 無法被驗證、無法被工具自動發現、也無法像 dispatch_handover_v1 那樣由 validator 強制執行契約。本票引入 skill schema（YAML frontmatter 或 JSON sidecar），使 skill 具備：明確的輸入型別、輸出格式、允許/禁止工具清單、完成條件——平行於 brief-validate.sh 對 brief 的驗證角色。 | arch/DX | 2026-06-10 | — | — | design | | CC-358 | ✅ done | runner telemetry：`pmctl run-stats` per-adapter 成功率/失敗模式/fallback 分析（v1.0 readiness 證據；v0.11.0） | ops/memory | 2026-06-10 | — | P2 | design | | CC-359 | 🟢 someday | concept: backlog-driven batch dispatch with worktree isolation（PM manages `git worktree` lifecycle；executor-agnostic；human-in-the-loop merge；PR-only output） | arch/ops | 2026-06-11 | — | — | design | -| CC-364 | ⏸ deferred | **[perf: `pmctl trace tail --all` per-event jq spawn]** `pmctl trace tail --kind --all --json` is O(n) with a high per-event constant — ~20s for 338 events (~60ms/event), consistent with spawning a jq/subprocess per event rather than one streaming pass. Surfaced while diagnosing #270 context-telemetry test flakiness; the tests no longer depend on it (telemetry now honors `PM_DISPATCH_STATE_ROOT`, so the suite isolates state). Standalone reader-perf follow-up. **See**: pr:#270 | ops | 2026-06-12 | pr:#270 | P3 | hygiene | +| CC-364 | ✅ done | **[perf: `pmctl trace tail --all` per-event jq spawn]** `trace tail` scan phase reworked from two jq spawns per event (plus one per row in the human emitter) to a single `jq -R` streaming pass over the concatenated archive+active stream; ~24s→0.2s for 400 events, jq invocation count now fixed regardless of event count. Behavior parity preserved (filters, inclusive time window, malformed tolerance, chronological merge, limit/--all, compact-JSON byte identity). **See**: pr:#270, pr:#546 | ops | 2026-06-12 | pr:#270, pr:#546 | P3 | hygiene | | CC-369 | ⏸ deferred | Windows state store 真實 ACL via icacls（parked: CC-370；border case relative to profile ACL protection） | ops/portability | 2026-06-13 | — | — | hygiene | | CC-370 | ⏸ deferred | **[native Windows support deferred to post-core platform phase]** 核心功能開發期間正式只支援 Linux + WSL2（WSL2 視為 Linux）；原生 Windows Git Bash 非官方支援，使用者走 WSL2。理由是專注：開發期同時扛多平台會排擠核心功能（CI 只測 Linux，每次碰 Windows 都要人工驗證 + gate churn，見 #272/#273）。已合併的 portability 程式碼保留（綠且成本低），但不再新增 Windows 分支，直到核心定型（v0.5.0+）後的專屬平台階段。Parks: CC-038, CC-104d/e/f/g/j/k/r/s, CC-369。**See**: DECISIONS.md 2026-06-13 defer-native-windows-support-during-core-dev | ops/portability | 2026-06-13 | — | — | design | | CC-377 | ⏸ deferred | adapter: Google Antigravity（`agy`）executor（DEFERRED：headless CLI 1.0.8 不成熟；resume: newer agy with `--output-format stream-json`；umbrella: CC-333） | arch/portability | 2026-06-13 | — | P2 | design | @@ -1530,12 +1530,18 @@ Fix：文件化 `GOPATH=/tmp/gopath go build` 慣例到 brief self_verify go bui --- -## CC-364 — perf: `pmctl trace tail --all` per-event jq spawn（deferred） +## CC-364 — perf: `pmctl trace tail --all` per-event jq spawn ✅ 2026-08-27 -**See**: pr:#270 +**See**: pr:#270, pr:#546 `pmctl trace tail --kind --all --json` is O(n) with a high per-event constant — measured ~20s for 338 events (~60ms/event), consistent with spawning a `jq` (or equivalent subprocess) per event rather than a single streaming pass. Discovered while diagnosing the #270 context-telemetry test flakiness: `context.queried` / `context.reuse_scanned` events accumulate in a partition, and the readback assertions called `trace tail --all`, so reads degraded as the partition grew. The tests were de-coupled from this — context telemetry now honors `PM_DISPATCH_STATE_ROOT`, so the suite isolates all state into a throwaway root — leaving this as a standalone reader-performance follow-up, not a blocker. Fix: rework `trace tail` filtering/serialization as a single `jq` pass (or a streaming reader) over `events.jsonl`. +**Closure 2026-08-27 (pr:#546)**: scan phase is now one `jq -R` streaming pass over the concatenated `archive + active` stream — it classifies each line (malformed / filtered-out / kept) and emits kept rows as `\t\t`, using jq's cumulative `input_line_number` as the global read-order tiebreaker for events sharing a timestamp. Both emit helpers stream through one jq via `cut -f3`. Five module-global `_PMCTL_TRACE_*` vars and three per-line scan helpers removed. + +**Perf evidence**: 400 events `--all --json` ~24s → 0.2s (~100x). New `case_trace_tail_single_jq_pass` shims a counting `jq` onto PATH and asserts the invocation tally is equal (and non-zero) for a 20-event and a 200-event run — O(1) in event count; a per-event regression would make the 200-event tally ~10x the 20-event one. Behavior parity (filters, inclusive lexicographic window, malformed tolerance + `skipped N` warning, archive/active merge, limit/`--all`, compact-JSON byte identity) covered by the existing `test-pmctl-trace.sh` cases (14 passed) plus the new `case_trace_large_partition_streaming`. + +**Not done here**: `pmctl-run-stats.sh` (CC-358) has the same archive+active scan shape with a per-line jq spawn; deliberately out of scope (different jq program + shell-side aggregation), left a pointer comment. No follow-up ticket filed yet. + ## CC-435 — poll→通知機制 single-waiter guard：條件觸發，非既定後續票 🟢 someday **Problem**：`docs/spikes/CC-433.md` 判定 poll→通知機制遷移為 AMBER——mkfifo blocking read 技術可行且延遲大幅改善，但發現並發 waiter 讀同一個 fifo 會造成 byte-level 資料損毀的正確性風險（輪詢設計沒有這個問題）。CC-434 實作完成後與使用者進一步討論了兩個候選防護設計，重新盤點成本效益後決定不排入既定實作。 diff --git a/runtime/lib/pmctl-run-stats.sh b/runtime/lib/pmctl-run-stats.sh index e3908643..d5bc6ae3 100644 --- a/runtime/lib/pmctl-run-stats.sh +++ b/runtime/lib/pmctl-run-stats.sh @@ -1,11 +1,13 @@ #!/usr/bin/env bash # pmctl run-stats — per-adapter success/failure/fallback analysis over # events.jsonl (CC-358). Read-only consumer: never calls events_append or any -# state-writer write helper. Reuses the same per-line jq-extraction + ISO-8601 -# string comparison approach as pmctl_trace_tail (runtime/lib/pmctl-trace.sh) -# rather than inventing a second parser for the same file format. +# state-writer write helper. Uses the same ISO-8601 lexicographic string +# comparison and archive-inclusive scan model as pmctl trace tail +# (runtime/lib/pmctl-trace.sh) rather than inventing a second parser for the +# same file format. (trace tail itself now does a single streaming jq pass; +# this reader still extracts per line — a standalone follow-up, not CC-364.) # -# Archive-inclusive by default, matching pmctl_trace_tail's read_archives=1: +# Archive-inclusive by default, matching pmctl trace tail's read_archives=1: # rotated archive/events-*.jsonl.gz files are scanned alongside the active # events.jsonl so a --since window reaching past rotation still counts every # matching run. Falls back to active-file-only (and says so in `_meta`) only @@ -31,8 +33,7 @@ pmctl_run_stats_ensure_state_writer() { # Emits one TSV row per run.* event whose kind matches ^run\. — ts, kind, # run_id, adapter, note, exit_code, fallback_used(true/false) — or nothing -# when the line isn't a matching run event. One jq invocation per line (same -# per-event subprocess cost as pmctl_trace_scan_line). +# when the line isn't a matching run event. One jq invocation per line. pmctl_run_stats_extract_line() { local line="${1:-}" printf '%s\n' "$line" | jq -r ' diff --git a/runtime/lib/pmctl-trace.sh b/runtime/lib/pmctl-trace.sh index 8140ad37..952a639e 100644 --- a/runtime/lib/pmctl-trace.sh +++ b/runtime/lib/pmctl-trace.sh @@ -18,85 +18,67 @@ pmctl_trace_ensure_state_writer() { . "$repo_root/runtime/lib/state-writer.sh" } -pmctl_trace_scan_line() { - local line="${1:-}" compact fields - local event_id ts kind subject_id - - if ! compact="$(printf '%s\n' "$line" | jq -c 'if type == "object" then . else error("not object") end' 2>/dev/null)"; then - _PMCTL_TRACE_SKIPPED=$((_PMCTL_TRACE_SKIPPED + 1)) - return 0 - fi - - # Only the fields used for filtering are extracted into shell vars; the - # emitters re-read subject_type / actor / operation_id from the JSON itself. - if ! fields="$(printf '%s\n' "$compact" | jq -r '[.id // "", .ts // "", .kind // "", .subject_id // ""] | @tsv' 2>/dev/null)"; then - _PMCTL_TRACE_SKIPPED=$((_PMCTL_TRACE_SKIPPED + 1)) - return 0 - fi - IFS=$'\t' read -r event_id ts kind subject_id <<< "$fields" - - if [[ -n "${_PMCTL_TRACE_ID_FILTER:-}" && "$event_id" != "$_PMCTL_TRACE_ID_FILTER" ]]; then - return 0 - fi - if [[ -n "${_PMCTL_TRACE_KIND_FILTER:-}" && "$kind" != "$_PMCTL_TRACE_KIND_FILTER" ]]; then - return 0 - fi - if [[ -n "${_PMCTL_TRACE_SUBJECT_FILTER:-}" && "$subject_id" != "$_PMCTL_TRACE_SUBJECT_FILTER" ]]; then - return 0 - fi - if [[ -n "${_PMCTL_TRACE_SINCE_FILTER:-}" && ( -z "$ts" || "$ts" < "$_PMCTL_TRACE_SINCE_FILTER" ) ]]; then - return 0 - fi - if [[ -n "${_PMCTL_TRACE_UNTIL_FILTER:-}" && ( -z "$ts" || "$ts" > "$_PMCTL_TRACE_UNTIL_FILTER" ) ]]; then - return 0 - fi - - _PMCTL_TRACE_SEQ=$((_PMCTL_TRACE_SEQ + 1)) - printf '%s\t%012d\t%s\n' "$ts" "$_PMCTL_TRACE_SEQ" "$compact" >> "$_PMCTL_TRACE_RECORDS" -} - -pmctl_trace_scan_path() { - local path="${1:-}" line - - [[ -f "$path" ]] || return 0 - while IFS= read -r line || [[ -n "$line" ]]; do - pmctl_trace_scan_line "$line" - done < "$path" -} - -pmctl_trace_scan_gzip_path() { - local path="${1:-}" line - - [[ -f "$path" ]] || return 0 - while IFS= read -r line || [[ -n "$line" ]]; do - pmctl_trace_scan_line "$line" - done < <(gzip -dc "$path" 2>/dev/null) +# Single streaming jq program over the concatenated archive+active event stream +# (raw input, one JSON object per line). Replaces the former per-line pair of +# jq spawns: this runs once for the whole partition regardless of event count. +# +# For every input line it prints exactly one control line to stdout: +# "M" -> line is not a JSON object (skip + count) +# "E\t\t\t" -> line matched all active filters +# (nothing) -> valid object that a filter excluded +# +# is jq's cumulative input_line_number across the whole concatenated +# stream, so it is a global monotonic read-order sequence: archives first (in +# filename-sorted order), then the active file, each in line order. The caller +# uses it as the stable-sort tiebreaker for events sharing a timestamp. +# +# Filters are passed as --arg strings; an empty string means "no constraint". +# Timestamp comparisons are lexicographic on the ISO-8601 string, matching the +# shell `<` / `>` semantics this previously used, and an empty ts is excluded +# whenever a --since or --until bound is set. +pmctl_trace_filter_program() { + cat <<'JQ' + (try fromjson catch null) as $o + | if ($o | type) != "object" then "M" + else + ($o.ts // "") as $ts + | ($o.id // "") as $id + | ($o.kind // "") as $kind + | ($o.subject_id // "") as $sid + | if ($idf != "" and $id != $idf) then empty + elif ($kindf != "" and $kind != $kindf) then empty + elif ($subjf != "" and $sid != $subjf) then empty + elif ($sincef != "" and ($ts == "" or $ts < $sincef)) then empty + elif ($untilf != "" and ($ts == "" or $ts > $untilf)) then empty + else "E\t\($ts)\t\(input_line_number)\t\($o | tojson)" + end + end +JQ } +# emit helpers consume the sorted "\t\t" record file. +# The compact JSON is the third tab field and never contains a literal tab +# (jq -c escapes tabs inside strings), so `cut -f3` recovers it exactly. pmctl_trace_emit_json() { - local path="${1:-}" ts seq json + local path="${1:-}" - while IFS=$'\t' read -r ts seq json; do - : "$ts" "$seq" - printf '%s\n' "$json" - done < "$path" + [[ -s "$path" ]] || return 0 + cut -f3 "$path" } pmctl_trace_emit_human() { - local path="${1:-}" ts seq json + local path="${1:-}" - while IFS=$'\t' read -r ts seq json; do - : "$ts" "$seq" - printf '%s\n' "$json" | jq -r ' - (.ts // "") as $ts | - (.kind // "") as $kind | - (.subject_type // "") as $subject_type | - (.subject_id // "") as $subject_id | - (if (.actor? == null or .actor == "") then "[no-actor]" else .actor end) as $actor | - (if (.operation_id? == null or .operation_id == "") then "" else " op=\(.operation_id)" end) as $op | - "\($ts) \($kind) \($subject_type)/\($subject_id) \($actor)\($op)" - ' - done < "$path" + [[ -s "$path" ]] || return 0 + cut -f3 "$path" | jq -r ' + (.ts // "") as $ts | + (.kind // "") as $kind | + (.subject_type // "") as $subject_type | + (.subject_id // "") as $subject_id | + (if (.actor? == null or .actor == "") then "[no-actor]" else .actor end) as $actor | + (if (.operation_id? == null or .operation_id == "") then "" else " op=\(.operation_id)" end) as $op | + "\($ts) \($kind) \($subject_type)/\($subject_id) \($actor)\($op)" + ' } pmctl_trace_tail() { @@ -105,6 +87,7 @@ pmctl_trace_tail() { local limit=20 all=0 json=0 local proj_dir active_file archive_dir read_archives=1 local tmp_dir records sorted limited emit_file rc=0 + local skipped=0 program out_line _pmctl_trace_archive local -a archives=() if [[ -z "$repo_root" ]]; then @@ -225,31 +208,34 @@ pmctl_trace_tail() { return "$rc" fi - _PMCTL_TRACE_KIND_FILTER="$kind_filter" - _PMCTL_TRACE_SUBJECT_FILTER="$subject_filter" - _PMCTL_TRACE_ID_FILTER="$id_filter" - _PMCTL_TRACE_SINCE_FILTER="$since_filter" - _PMCTL_TRACE_UNTIL_FILTER="$until_filter" - _PMCTL_TRACE_RECORDS="$records" - _PMCTL_TRACE_SEQ=0 - _PMCTL_TRACE_SKIPPED=0 - - if [[ "$read_archives" -eq 1 ]]; then - for _pmctl_trace_archive in "${archives[@]}"; do - pmctl_trace_scan_gzip_path "$_pmctl_trace_archive" - done - unset _pmctl_trace_archive - fi - pmctl_trace_scan_path "$active_file" + program="$(pmctl_trace_filter_program)" + while IFS= read -r out_line; do + if [[ "$out_line" == "M" ]]; then + skipped=$((skipped + 1)) + else + printf '%s\n' "${out_line#E$'\t'}" >> "$records" + fi + done < <( + { + if [[ "$read_archives" -eq 1 ]]; then + for _pmctl_trace_archive in "${archives[@]}"; do + [[ -f "$_pmctl_trace_archive" ]] && gzip -dc "$_pmctl_trace_archive" 2>/dev/null + done + fi + [[ -f "$active_file" ]] && cat "$active_file" + } | jq -R -r \ + --arg idf "$id_filter" \ + --arg kindf "$kind_filter" \ + --arg subjf "$subject_filter" \ + --arg sincef "$since_filter" \ + --arg untilf "$until_filter" \ + "$program" + ) - if [[ "$_PMCTL_TRACE_SKIPPED" -gt 0 ]]; then - printf 'trace: skipped %s malformed row(s)\n' "$_PMCTL_TRACE_SKIPPED" >&2 + if [[ "$skipped" -gt 0 ]]; then + printf 'trace: skipped %s malformed row(s)\n' "$skipped" >&2 fi - unset _PMCTL_TRACE_KIND_FILTER _PMCTL_TRACE_SUBJECT_FILTER _PMCTL_TRACE_ID_FILTER - unset _PMCTL_TRACE_SINCE_FILTER _PMCTL_TRACE_UNTIL_FILTER _PMCTL_TRACE_RECORDS - unset _PMCTL_TRACE_SEQ _PMCTL_TRACE_SKIPPED - if [[ ! -s "$records" ]]; then rm -rf "$tmp_dir" return 0 diff --git a/tests/shell/test-pmctl-trace.sh b/tests/shell/test-pmctl-trace.sh index 3491eb15..e6c345e9 100755 --- a/tests/shell/test-pmctl-trace.sh +++ b/tests/shell/test-pmctl-trace.sh @@ -280,6 +280,105 @@ case_trace_active_archive_merge() { fi } +# Behavior: the single streaming jq pass introduced for CC-364 still emits +# every event once, in non-decreasing timestamp order, and skips exactly the +# malformed rows, at a partition size well above the other cases (so an +# accidental return to per-event jq spawning or a broken sort/tiebreak shows +# up here). Archive+active merge correctness is covered separately by +# case_trace_active_archive_merge; this case is active-only so it always +# executes regardless of gzip availability. +# Steps: write 240 well-formed run.completed events spread across three +# disjoint HH timestamp bands, interleaved with two malformed lines, all in +# one awk pass (no per-event jq spawn). Run `trace tail --all --json`, then +# assert: exit 0, 240 emitted rows, `sort -c` accepts the emitted timestamp +# sequence, and stderr reports "skipped 2 malformed row(s)". +case_trace_large_partition_streaming() { + local name="pmctl trace tail: large partition stays ordered in one streaming pass" + should_run "$name" || return 0 + local store proj out err status=0 count ordered malformed + store="$tmp_root/large-store" + proj="$(trace_project_dir "$store")" + { + printf '%s\n' '{"id":' + awk 'BEGIN { + n = 80 + split("01 02 03", band, " ") + for (b = 1; b <= 3; b++) { + for (i = 1; i <= n; i++) { + printf "{\"schema_version\":1,\"id\":\"evt-large-%s-%03d\",\"ts\":\"2026-06-06T%s:%02d:00Z\",\"kind\":\"run.completed\",\"subject_type\":\"run\",\"subject_id\":\"RUN-%s-%d\",\"actor\":\"pmctl\",\"payload\":{}}\n", band[b], i, band[b], i % 60, band[b], i + } + } + }' + printf '%s\n' 'not json at all' + } > "$proj/events.jsonl" + out="$tmp_root/large.out" + err="$tmp_root/large.err" + run_trace "$store" "$out" "$err" --all --json || status=$? + count="$(line_count "$out")" + # emitted timestamps must be non-decreasing across the whole stream + ordered="$(jq -r '.ts' "$out" | LC_ALL=C sort -c 2>&1 && echo OK)" + malformed="$(grep -c 'trace: skipped 2 malformed row(s)' "$err" || true)" + if [[ "$status" -eq 0 && "$count" == "240" && "$ordered" == "OK" && "$malformed" == "1" ]]; then + pass "$name" + else + fail "$name" "status=$status count=$count ordered=$ordered malformed=$malformed err=$(<"$err")" + fi +} + +# Behavior: the CC-364 performance contract holds -- `trace tail` invokes jq a +# fixed number of times for a whole event partition, not once per event, so a +# future return to per-event jq spawning is caught even though output stays +# byte-identical. +# Steps: shim a counting `jq` wrapper onto PATH (it tallies invocations then +# exec's the real jq), run `trace tail --all --json` once over a 20-event +# partition and once over a 200-event partition, and assert the invocation +# tally is identical for both (O(1) in event count) and non-zero. A per-event +# implementation would make the 200-event tally ~10x the 20-event one. +case_trace_tail_single_jq_pass() { + local name="pmctl trace tail: jq invocation count is O(1) in event count" + should_run "$name" || return 0 + local store proj shimdir real_jq tally small large status=0 + real_jq="$(type -P jq)" + store="$tmp_root/jqcount-store" + proj="$(trace_project_dir "$store")" + shimdir="$tmp_root/jqcount-shim" + tally="$tmp_root/jqcount.tally" + mkdir -p "$shimdir" + { + printf '%s\n' '#!/usr/bin/env bash' + printf 'printf x >> %q\n' "$tally" + printf 'exec %q "$@"\n' "$real_jq" + } > "$shimdir/jq" + chmod +x "$shimdir/jq" + + gen_events() { + awk -v n="$1" 'BEGIN { + for (i = 1; i <= n; i++) { + printf "{\"schema_version\":1,\"id\":\"evt-%04d\",\"ts\":\"2026-06-06T00:%02d:00Z\",\"kind\":\"run.completed\",\"subject_type\":\"run\",\"subject_id\":\"RUN-%d\",\"actor\":\"pmctl\",\"payload\":{}}\n", i, i % 60, i + } + }' + } + + gen_events 20 > "$proj/events.jsonl" + : > "$tally" + PATH="$shimdir:$PATH" PM_DISPATCH_STATE_ROOT="$store" "$PMCTL" trace tail --all --json \ + > "$tmp_root/jqcount-small.out" 2>/dev/null || status=$? + small="$(wc -c < "$tally" | tr -d ' ')" + + gen_events 200 > "$proj/events.jsonl" + : > "$tally" + PATH="$shimdir:$PATH" PM_DISPATCH_STATE_ROOT="$store" "$PMCTL" trace tail --all --json \ + > "$tmp_root/jqcount-large.out" 2>/dev/null || status=$? + large="$(wc -c < "$tally" | tr -d ' ')" + + if [[ "$status" -eq 0 && "$small" -gt 0 && "$small" == "$large" && + "$(line_count "$tmp_root/jqcount-large.out")" == "200" ]]; then + pass "$name" + else + fail "$name" "status=$status small=$small large=$large large_lines=$(line_count "$tmp_root/jqcount-large.out")" + fi +} + case_trace_empty_missing_store() { local name="pmctl trace tail: missing store exits 0 with empty stdout" should_run "$name" || return 0 @@ -322,6 +421,8 @@ case_trace_human_format case_trace_equal_ts_append_order case_trace_corrupt_row_tolerance case_trace_active_archive_merge +case_trace_large_partition_streaming +case_trace_tail_single_jq_pass case_trace_empty_missing_store case_trace_unknown_flag_usage