API 執行期量測：DB pool、事件迴圈、同步 CPU、GC

Issue #2056。API 的每個 uvicorn worker 程序（worker 數由 WEB_CONCURRENCY 決定，SIT 預設 1，見 sit-deploy.md〈八、API 多 worker〉）在既有 access log 之外，各自記錄以下五類量測：

取得 DB 連線花多久，其中多少是純 pool queue 等待。
連線被持有多久，以及 pool 同時被占用幾條。
事件迴圈延遲，以及 loop thread 的 CPU 時間。
JSON／日誌等同步處理花了多少 CPU。
每次垃圾回收（GC）的起訖、代數、耗時與執行 GC 那條執行緒的 CPU（#2136）。

量測只觀察、不改變行為。它不調整 worker、pool 大小、session scope、快取或業務邏輯，也不改任何 API 回應。所有量測點都是 fail-open：量測本身出錯時，原本成功的請求照樣成功。

資料在哪裡

來源	粒度	位置
逐筆請求	每個 HTTP request 一筆	`api_access_log.timing_breakdown`（JSONB）。沿用既有 row 與背景 writer，不新增 DB 寫入。
時間窗	每 `api.runtime_metrics.window_seconds` 秒一行	API 容器 log，logger 為 `api.runtime_metrics`，訊息格式為 `runtime_metrics {json}`。關閉時另輸出一個 `"partial": true` 的最後窗。

timing_breakdown.schema_version 仍是 1。新欄位只是新增的 key，舊讀者可以忽略；admin 下鑽頁把 1 以外的版本視為不可顯示，所以版本號沒有變。Migration 147 以後、本變更以前寫入的 row 沒有這些 key，必須以 timing_breakdown ? 'db_pool' 篩選。

設定（root `config/core.yaml` → `api.runtime_metrics`）

鍵	預設	說明
`enabled`	`true`	只控制時間窗 monitor。逐筆欄位只要 access log 有啟用（`logging.access_log`）就會寫入 row。
`window_seconds`	`10`	依 2026-10-30 SIT 300 VU 壓測推導：首頁最短一波（300 VU 第 4 波）在 20.563 秒內完成，窗長取不超過其一半（10.28 秒）。各波資料與計算：issue #2056 留言。
`loop_lag_sample_interval_seconds`	`0.01`	沿用 Node.js `perf_hooks.monitorEventLoopDelay` 的預設 resolution。

數值無效（0、負數、非有限值或非數字）時，該鍵各自回退預設值（窗長 10 秒、取樣間隔 0.01 秒）；取樣間隔不小於窗長時，兩鍵一起回退。

逐筆欄位（`timing_breakdown`）

以下新欄位的時間單位一律是毫秒，四捨五入到 0.001；原有的 phases_ms 維持 0.01。

`db_pool`：請求自己的連線

欄位	意義
`acquire_count`	本請求向 pool 取得連線的次數，含失敗。
`acquire_ms`	取得連線總耗時，即整個 `Pool.connect()` 的 wall time。內含 pool queue 等待、建立 overflow 連線、重連失效連線、`pool_pre_ping`、checkout listener，以及連線歸還後等待被排程喚醒的時間。它不是純等待。
`queue_wait_ms`	純 pool queue 等待：阻塞在 pool queue `get(block=True)` 內的時間。尚有 overflow 名額時是非阻塞取得，記 0。
`acquire_outcomes`	依結果計數。`ok`；`timeout` 是 pool timeout；`cancelled` 是外部取消，例如 `/health` 的 deadline；`error` 是連線失敗等其他錯誤。
`pool_checked_out_at_acquire_max`	本請求每次開始取得時，pool 已借出的連線數（`checkedout()`，不含本次這一條），取最大值；沒有取得時為 `null`。等於 `pool_size + max_overflow` 代表當時 pool 已滿。
`hold_ms`	連線持有時間：從 pool `checkout` 事件到 `checkin` 事件。`checkout` 在取得完成、pre-ping 之後才觸發，所以這段不含取得時間，但含歸還時的 reset rollback。回應完成時仍未歸還的連線，只計到回應完成為止。
`held_at_response_complete`	回應最後一個 body chunk 送出時，本請求仍持有的連線數。這些連線之後才歸還，後段時間記在時間窗的 `request_post_response_hold_ms`。自 #2098 起 `get_db` 是 function scope：請求自己的 session 在回應序列化後、送出前就關閉歸還，所以請求自己的連線這個值應為 0；非 0 代表有路由在回傳後仍用到請求的 session（回歸），或是 detach 邊角。兩者合計（row 的 `hold_ms` 加窗內後段）不受順序影響。

`db_pool_spawned_tasks`：繼承本請求 context 的其他 task

欄位與 db_pool 相同，統計對象是回應完成前、由其他 task 進行的連線活動。這些 task 經由 ContextVar 繼承了本請求的 recorder，例如路由內 asyncio.gather 的 fan-out、以 asyncio.create_task 啟動的背景工作，以及 StreamingResponse／SSE 的 body 產生器。最後一種是因為 uvicorn 0.51 回報 ASGI spec 2.3，Starlette 在 spec 2.4 以下會從 task group 子 task 串流 body。它們不算進 db_pool，避免把背景工作誤算成請求本身的 DB 耗時；回應完成後才發生的活動則完全不寫進 row。

這個 key 只在有活動時寫入；沒有衍生 task 用到連線的請求，row 裡不會有它。例外：它的 held_at_response_complete 只計數，這些連線回應後的持有時間不進 request_post_response_in_use／request_post_response_hold_ms（那兩項只算請求自己的連線），完整持有時間記在時間窗的 by_source.request_spawned_task.hold。

「請求自己的 task」只有兩個：access-log middleware 所在的 task，以及 RequestTaskBindingMiddleware 綁定的路由 task。後者存在的原因是 SlowAPIMiddleware 屬於 BaseHTTPMiddleware，路由會在子 task 中執行；綁定 middleware 緊貼在 SlowAPI 內側，會在任何 dependency 之前執行。

`sync_cpu`：回應送出前的同步 CPU 片段

key 是片段名稱，值為 {count, wall_ms, cpu_ms}；整個 sync_cpu 只在至少有一個片段發生時才寫入：

response_cache.model_validate_json：快取命中時解析 Redis payload。
response_cache.model_dump_json：快取未命中時序列化並寫入 payload。
market_pulse.jsonable_encoder：首頁快取未命中時，把計算結果轉成可序列化的 dict。
db.json_serialize：請求本身寫入 JSON／JSONB 欄位時的 json.dumps。

CPU 時間取自 time.thread_time_ns()，wall time 取自 perf_counter_ns()。計時 API 只接受一般函式呼叫，量測範圍內不可能出現 await。wall_ms 明顯大於 cpu_ms 時，代表該執行緒在片段中被系統暫停（CPU 競爭或 swap）。

`post_response`：回應送出後的工作

access_log.build_and_mask：{wall_ms, cpu_ms}，涵蓋串接已送出的 body chunks、建立 access-log row，以及 header／body 遮罩（含 JSON 解析與重新編碼）。

這段工作發生在最後一個 body chunk 送出之後。遮罩與建立 row 不計入 duration_ms，因為 duration_ms 在建立 row 之前就已取值；串接 body chunks 則沿用原本的參數順序，發生在取值之前，所以同時算在 duration_ms 與這個片段裡（通常只占微秒級）。它在 access-log middleware 的 task 執行。自 #2098 起請求的 session 在回應送出前就已歸還（get_db 為 function scope），這段收尾不再與連線歸還競爭 loop。

時間窗欄位（`runtime_metrics` log）

{"schema_version":1,"pid":7,"window_started_at":"…","window_ended_at":"…","window_ms":10003.1,"partial":false,
 "event_loop":{"sample_interval_ms":10.0,
   "lag":{"sample_count":981,"sum_ms":2412.3,"mean_ms":2.459,"p50_ms":0.21,"p95_ms":9.8,"p99_ms":40.2,"max_ms":310.5},
   "loop_thread_cpu_ms":8120.4,"process_cpu_ms":8466.0},
 "db_pool":{"pool_size":10,"max_overflow":20,"checked_out_max":30,"acquiring_max":41,
   "by_source":{"request":{"acquire":{"outcomes":{"ok":290},"wall_ms":{"count":290,"sum_ms":…,"max_ms":…},"queue_wait_ms":{…}},
                           "hold":{"ms":{"count":288,"sum_ms":…,"max_ms":…},"invalidated":0,"detached":0},
                           "in_use":{"avg":12.4,"max":27}},
                "access_log_writer":{…},"health":{…}},
   "request_post_response_in_use":{"avg":3.2,"max":9},
   "request_post_response_hold_ms":{"count":120,"sum_ms":…,"max_ms":…}},
 "sync_cpu":{"access_log.build_and_mask":{"request_post_response":{"count":300,"wall_ms_sum":…,"cpu_ms_sum":…,"wall_ms_max":…}}}}

上例的數字只為示意格式，不是實測值。

pid：寫出這個窗的 worker 程序 id（#2105）。多 worker 時每個 worker 各自每 10 秒寫一行，同一時段會有多行；依 pid 分組後再看每個 worker 的 CPU 與 pool，db_pool.pool_size／max_overflow 也是該 worker 分到的份額，不是整個 API 的總額。
事件迴圈延遲：背景 task 反覆執行 asyncio.sleep(interval)，每次記錄「實際喚醒 − 預期喚醒」，時鐘是 time.monotonic，與 asyncio 排程 timer 用的時鐘相同。延遲代表 loop 晚了多久才執行已就緒的 callback，不等於 CPU 時間：同步 CPU 工作、GC 暫停、被 swap 出的分頁都會造成延遲。百分位採 nearest-rank。每次喚醒只產生一個樣本，所以一次 2 秒的阻塞只會留下一個 2000 ms 樣本，百分位會低估阻塞；sum_ms 才是全窗累計的延遲。每窗樣本數的上限由 window_seconds / interval + 1 推得；時鐘正常時不會碰到，若碰到，超出的樣本只計數不保存，記在 lag.dropped_sample_count。
loop_thread_cpu_ms ／ process_cpu_ms：本窗內 loop thread 的 CPU 時間，與整個程序（含 threadpool）的 CPU 時間。loop_thread_cpu_ms / window_ms 就是 loop thread 的 CPU 使用率，接近 1 代表該 worker 的 CPU 已飽和；多 worker 時按 pid 分開算，不要把不同 worker 的窗加總後除以單一窗長。
hold.invalidated／hold.detached：持有期間被標記失效（含 soft invalidation）的連線數；沒有正常 checkin、而是被 detach 收尾的連線數（例如未 close 就被 GC 回收）。
db_pool.by_source：來源固定為六種：request、request_post_response（請求自己的 task 在回應後才取得連線，例如 BackgroundTasks）、request_spawned_task、access_log_writer、health、other（啟動流程或不在請求內的工作）。in_use.avg 是窗內持有連線數對時間的積分除以窗長，即時間加權平均；跨窗持有的連線也按窗內時間計入。in_use.max 是窗內最大值。checked_out_max 是每次開始取得時 pool 回報的借出數（不含該次這一條）的最大值；acquiring_max 是同時在取得中的請求數，可視為 queue 長度的上界。
request_post_response_in_use：請求自己的連線在「回應已送出、尚未歸還」狀態下的數量，avg 是時間加權平均、max 是窗內最大值。與 in_use 一樣跨窗計算：一條連線在回應後 25 秒才歸還，10 秒窗會在它跨過的每個窗都記到約 1 條。
request_post_response_hold_ms：同一段「回應後持有」時間在歸還時整筆計入當下的窗，count／sum_ms／max_ms 用來看單次後段有多長。它是依完成時間分桶，不能拿 sum_ms / window_ms 當平均占用；占用請看 request_post_response_in_use。
sync_cpu：key 為片段名稱再依來源分組，值為累計 wall／CPU 與單次最大 wall。db.json_serialize 是 engine json_serializer 對 JSON／JSONB 綁定值的 json.dumps，主要來自 access-log writer 寫入 timing_breakdown 與 request_headers。
gc（#2136）：monitor 執行時以 gc.callbacks 記錄本 worker 的每一次 GC。monitor 停用（enabled: false）時不註冊 callback，也沒有這個 key。

"gc":{"min_event_ms":10.0,
  "by_generation":{"0":{"count":244,"sum_ms":61.2,"max_ms":1.9,"collected":5120,"uncollectable":0},
                   "2":{"count":1,"sum_ms":680.4,"max_ms":680.4,"collected":4025,"uncollectable":0}},
  "events":[{"started_at":"2026-11-03T15:48:35.419312+00:00","ended_at":"2026-11-03T15:48:36.099712+00:00",
             "generation":2,"duration_ms":680.4,"gc_thread_cpu_ms":679.8,"collected":4025,"uncollectable":0,
             "thread_ident":140213,"thread_native_id":7,"on_loop_thread":true}],
  "dropped_event_count":0,"unpaired_start_count":0,"unpaired_stop_count":0,"callback_error_count":0}

上例的數字只為示意格式，不是實測值。 - by_generation：每代的次數、耗時總和／最大值（ms）與 collected／uncollectable 物件數，每一次 GC 都計入。 - events：耗時不短於 min_event_ms 的單次 GC 明細。min_event_ms 就是 loop_lag_sample_interval_seconds（預設 10 ms）：比一次 lag 取樣還短的停頓，lag 本來就分辨不出來，只計入彙總。耗時以 time.monotonic_ns 相減；started_at／ended_at 是 UTC 牆鐘（started_at 取自開始時的 time.time_ns，ended_at = started_at + 耗時），用來和 request_started_at 對時。 - gc_thread_cpu_ms：執行這次 GC 的那條執行緒的 time.thread_time_ns 差值，不是 process CPU。on_loop_thread 表示該執行緒是否為事件迴圈執行緒；thread_native_id 是 OS 執行緒 id（Linux 的 TID，可對外部取樣），pid 見窗的頂層欄位。 - 明細上限：同一程序的 GC 不會同時進行，每筆至少 min_event_ms，所以一窗最多 window_seconds / loop_lag_sample_interval_seconds + 1 筆（與 lag 樣本上限同一推導）。超過時只計 dropped_event_count，彙總仍完整。這個上限限制的是筆數，不是位元組；每筆明細約 300 bytes，預設 10 秒窗／10 ms 間隔的理論上限 1,001 筆約 300 KB，只有整窗幾乎都在 GC 時才會接近。 - unpaired_start_count／unpaired_stop_count：只看到開始或只看到結束的次數（例如 callback 在某次 GC 途中才註冊）；callback_error_count：callback 內部例外次數。量測失敗一律吞下，不影響請求。

判讀：區分 pool 等待、連線持有、CPU 與其他等待

原則是逐筆配對、再做彙總。不可以把不同欄位各自的 p95 相減，來宣稱各階段的耗時。

先取出逐筆拆解。首頁走單一 task、單一 session，取得、SQL、同步片段在同一個 task 內依序發生，所以可以相減。若 row 有 db_pool_spawned_tasks，就有衍生 task 用過連線（例如並行 fan-out），這些量可能重疊，不可直接相減。

SELECT request_id,
       request_started_at,
       duration_ms,
       (timing_breakdown->'db_pool'->>'queue_wait_ms')::numeric AS queue_wait_ms,
       (timing_breakdown->'db_pool'->>'acquire_ms')::numeric
         - (timing_breakdown->'db_pool'->>'queue_wait_ms')::numeric AS acquire_other_ms,
       db_duration_ms AS cursor_ms,
       (SELECT COALESCE(SUM((v->>'wall_ms')::numeric), 0)
          FROM jsonb_each(timing_breakdown->'sync_cpu') AS s(k, v)) AS sync_wall_ms,
       (timing_breakdown->'db_pool'->>'hold_ms')::numeric AS hold_ms,
       (timing_breakdown->'db_pool'->>'held_at_response_complete')::int AS held_after_response,
       (timing_breakdown->'post_response'->'access_log.build_and_mask'->>'cpu_ms')::numeric
         AS log_build_cpu_ms
  FROM api_access_log
 WHERE path = '/api/market-pulse/latest'
   AND request_started_at >= :from_ts AND request_started_at < :to_ts
   AND timing_breakdown ? 'db_pool';

每一筆的 other_ms = duration_ms − queue_wait_ms − acquire_other_ms − cursor_ms − sync_wall_ms 是其餘等待：Redis I/O、FastAPI 內部的回應序列化、等待被 loop 排程等。之後再對這些逐筆數字或比例取中位數、分位數。

依 request_started_at 把每筆請求對到同一時間窗的 runtime_metrics，讀出該窗的 loop lag（sum_ms、p99_ms、max_ms）、loop thread CPU 使用率，以及各來源的 in_use。
判讀方式：

現象	指向
`queue_wait_ms` 占大宗，同窗 `checked_out_max` 達到 `pool_size + max_overflow`，`in_use.avg` 偏高	pool 等待。再看是哪個來源占住連線：各來源的 `in_use.avg`、`request_post_response_in_use.avg`、`access_log_writer`。
`queue_wait_ms` 小，但同窗 `request_post_response_in_use.avg` 大	回應後才歸還的連線占用可觀，屬持有時間問題，不是 SQL 本身慢。
`acquire_other_ms` 大，`queue_wait_ms` 小	建立連線、pre-ping 或重連慢，屬 DB 或網路端；可對照 `acquire.outcomes` 與 `hold.invalidated`。
`other_ms` 大，同窗 loop thread CPU 使用率接近 1、lag 也高	該 worker 的 CPU 飽和（多 worker 時看同一 `pid` 的窗）。可看 `sync_cpu` 與 `post_response` 占掉多少 CPU。
lag 高，但 loop thread CPU 使用率低	不是 CPU 造成的停頓，例如 GC、swap、阻塞的系統呼叫。應對照主機的 swap 與記憶體指標。
`queue_wait_ms` 高，且同窗 lag 也高	queue 等待含有「連線已歸還、但 loop 太忙沒排到」的時間，兩者必須一起看。

取出時間窗 log：

docker logs cortex-api 2>&1 | grep ' runtime_metrics {' | sed 's/^.* runtime_metrics //' > runtime-metrics.jsonl

已知限制

歸屬到 request 需要 access-log middleware 起 recorder。access log 關閉或路徑在 exclude_paths 時，請求不寫 row，但仍會起 recorder，連線照樣歸到 request；/health 的探測有明確標記，仍歸到 health。
被 GC 回收、沒有正常歸還的連線，SQLAlchemy 會在觸發 GC 的那個執行緒（可能是別的執行緒，也可能是 loop 執行緒上另一次更新的中途）發出 detach。這個收尾一律排回連線所屬的 event loop，以下一個 callback 執行，所以所有計數更新都在 loop 執行緒上依序進行；持有時間與回應後的後段時間都以 detach 發生的時間為終點，不會因 loop 卡住而灌水；但 in_use 與 request_post_response_in_use 這兩個占用計量要等 loop 跑到收尾才扣除，loop 卡多久就晚多久。若連線在收尾前就被重新借出（SQLAlchemy 先把連線放回 pool 才發 detach），舊的持有在重新借出時就以 detach 分類收尾；若重新借出甚至早於 detach 事件，終點只能取重新借出的時間，誤差不超過 detach 事件被延後發出的時間。回應恰好在 detach 與收尾之間完成時，那一筆 row 的持有時間同樣以 detach 時間為終點，不算進 held_at_response_complete，也不進回應後的占用與後段時間；只有 detach 與回應完成幾乎同時（通常差幾微秒；觸發 GC 的執行緒若剛好被切走，可到毫秒級）、那個執行緒還沒寫入 detach 時間時，那一筆仍可能算成回應後持有：持有時間多算這段，後段時間記為 0 ms，占用在收尾時扣回。只有在取得連線時沒有執行中的 loop（例如同步呼叫），或該 loop 已關閉時，才當場處理。
只量測 app_state.db_engine 這個共用 pool。自建的 engine 都不在範圍內：api/routes/stocks.py、題材 recap 預熱（services/theme_recap_cache.py）、題材報告鎖的 NullPool engine（services/theme_agent_service.py，在 /api/theme-agent 的快取未命中路徑上），以及 scheduler 程序。
FastAPI 在路由回傳後，會在框架內部依宣告的回傳型別檢查資料並轉成 JSON（pydantic validate 與 serialize_json）。這一步沒有逐筆計時，落在 other_ms；使用者 2026-10-31 核可不持續量測。依據是實測：本機 dev 的真實首頁回應 15,703 bytes，在 FastAPI 0.139.0 上連跑 2,000 次，CPU 中位數 22.8 µs、p95 31.0 µs（SIT 壓測時首頁回應只有 6,301 bytes）。量測腳本與輸出：issue #2056 留言。
讀取 JSONB 時 asyncpg 的 JSON 解碼沒有計時。
GC 事件與請求、sync_cpu 片段只能用時間與執行緒對齊：sync_cpu 片段沒有記錄起訖時間，一次 GC 落在某請求的 request_started_at 到結束之間，只代表兩者重疊，不能據此宣稱 GC 是在該片段內被觸發或該片段的耗時全來自 GC。sync_cpu 的 wall／CPU 仍會包含途中在同一執行緒發生的 GC。
GC 明細與彙總以「被收進哪一窗」分組：窗交界時，另一條執行緒剛好結束的 GC 可能落在相鄰的窗，但同一次 GC 的彙總與明細一定在同一窗。對時請用 started_at，不要用窗的起訖。
量測不改 GC 行為：不調整 threshold、不 disable／freeze、不主動 gc.collect()。
既有的 db_duration_ms 仍沿用原本的語意：繼承 recorder 的其他 task 在回應前執行的 SQL 也會計入。因此有 fan-out 時，它可能大於 db_pool.hold_ms。
queue_wait_ms 包含連線歸還後等待被排程的時間。CPU 飽和時，其中一部分其實是 loop 延遲。
時間窗只輸出在容器 log，保留期限依 docker log 設定而定。
量測開銷：tests/integration/test_db_instrumentation_pg.py::test_report_hook_and_monitor_cpu_cost 與 ::test_instrumentation_overhead_per_acquisition 會印出「每次取得的 hook CPU」、「lag monitor 的 loop thread CPU 占比」與「PG 取得＋歸還每輪耗時」，CI 的 PG 步驟以 -s 執行，數字可在 CI log 取得。本機 Docker on macOS 數次量測：hook CPU 約 3–5 µs／次，10 ms 取樣的 monitor 約占一顆核心 0.7%–1.1%。這只是參考值，不是門檻。

API 執行期量測：DB pool、事件迴圈、同步 CPU、GC

資料在哪裡

設定（root config/core.yaml → api.runtime_metrics）

逐筆欄位（timing_breakdown）

db_pool：請求自己的連線

db_pool_spawned_tasks：繼承本請求 context 的其他 task

sync_cpu：回應送出前的同步 CPU 片段

post_response：回應送出後的工作

時間窗欄位（runtime_metrics log）