どのコマンドが遅い・落ちる？を jq だけで見える化｜実行ログをJSONLに1行ずつ残すラッパー

TL;DR

• エージェントや定期ジョブが「何を、何秒かけて、成功したか」を、ラッパー1本で JSONL に残します。
• 集計は jq -s だけ。外部サービスもDBも要りません。
• bash 5.2 / jq 1.7 で動作確認済み。bc が無い環境でも動くよう、計算は jq に寄せています。

構成

ラッパー

runlog.sh

#!/usr/bin/env bash
# 任意のコマンドを実行し、所要時間・終了コードを JSONL に1行追記する
# 使い方: RUNLOG=runs.jsonl ./runlog.sh <label> <command...>
set -uo pipefail
log="${RUNLOG:-runs.jsonl}"; label="$1"; shift
start=$(date +%s.%N)
"$@"; rc=$?
end=$(date +%s.%N)
jq -nc --arg label "$label" --arg at "$(date -Iseconds)" \
      --argjson s "$start" --argjson e "$end" --argjson rc "$rc" \
      '{at:$at,label:$label,sec:((($e-$s)*100|round)/100),rc:$rc}' >> "$log"
exit $rc

• 元のコマンドの終了コードをそのまま返すので、CIや && の連結を壊しません。
• 時刻は date +%s.%N、差分と丸めは jq 側で計算しています。最初は bc で計算していましたが、入っていない環境で JSON が壊れたため変えました。

実行例

$ for i in 1 2 3; do ./runlog.sh build sleep 0.3; done
$ ./runlog.sh test sh -c 'sleep 0.1; exit 2'; echo rc=$?
rc=2
$ ./runlog.sh test true
$ cat runs.jsonl
{"at":"2026-01-01T12:00:00+09:00","label":"build","sec":0.3,"rc":0}
{"at":"2026-01-01T12:00:00+09:00","label":"build","sec":0.3,"rc":0}
{"at":"2026-01-01T12:00:00+09:00","label":"build","sec":0.3,"rc":0}
{"at":"2026-01-01T12:00:00+09:00","label":"test","sec":0.1,"rc":2}
{"at":"2026-01-01T12:00:00+09:00","label":"test","sec":0,"rc":0}

at の値は例として固定の時刻に置き換えています。それ以外は実際の出力です。

集計

$ jq -s 'group_by(.label)|map({label:.[0].label,runs:length,
    fail:(map(select(.rc!=0))|length),
    avg_sec:((map(.sec)|add/length*100|round)/100)})' -c runs.jsonl
[{"label":"build","runs":3,"fail":0,"avg_sec":0.3},{"label":"test","runs":2,"fail":1,"avg_sec":0.05}]

発展

• label にジョブ名やエージェントのタスク名を入れておけば、「どの作業が遅いか」がすぐ分かります。
• ファイルは追記だけなので、日付ごとに分ける（RUNLOG=runs-$(date +%F).jsonl）と扱いやすくなります。

参考

• jq Manual: https://jqlang.github.io/jq/manual/