--- name: investigate-slow-upstream-responses description: Scan the production openresty access log (/var/instance-ssd/logs/access.log) for requests with slow upstream response times (st=, the time the node containers took to answer), triage and rank them while setting aside routes that are slow by design (SSE, long polls, webhooks), then investigate the top candidates with the app logs and the render-probe script to tell a regularly pathological request from one that queued behind something else. Appends a short entry to this skill's findings log. Use when asked to look into slow upstream times, slow st= values, slow requests in the access log, or to re-run the slow upstream review. --- # Investigate slow upstream responses **Bar: 100ms.** Any page request whose `st=` is over 100ms is bad. Most blog renders take ~10ms, so 100ms+ means either the request is expensive or it waited behind one that was. Related: `node-response-time-review` ranks sites by app-side render time over a window. This skill starts from nginx's view (`st=`), separates queueing from real cost, and goes on to find out *why* with the render probe. ## Production access Host `ssh blot`. The operator has OK'd **read-only** commands for this skill (log reads, `docker logs`, `docker ps`, `redis-cli` read commands on specific keys, never `KEYS`). Nothing that writes, restarts or deletes. `npm run render-probe` starts a throwaway container on the host (data mounted read-only, own memory/CPU limit) and is part of this skill. Run one probe at a time, keep `--concurrency` low, and pass `--yes` only once the operator has agreed to probing in this session. Its output in `./data/render-probe//` holds customer content: delete it when done. ## Background Log format (`proxy/config/http.conf`, `access_log_format`): ``` [06/Oct/2026:09:28:17 +0000] : cache= ip=… st= lrs=… up= ua=… ``` - `st=-`: nginx cache hit, no upstream. `st=0.088, 0.049` / `up=a, b`: a retry on a second upstream (sum them). Ports: `8090` yellow (blogs), `8089` green (blot.im POSTs, webhooks), `8088` blue (dashboard and blot.im GETs; also the **backup** for blogs, so blog requests on blue mean yellow was down or failing, usually around a deploy). - `` is passed to node as `X-Request-ID`, so the same id appears in the container's log (`app/request-logger.js`): ``` [time] [yellow] GET [time] [yellow] +12ms [time] [yellow] elu=<0..1> slowest=+ms:"" ``` `st − duration` ≈ time the request queued before the app's middleware ran. `elu` is event-loop utilisation over the request: ~1 means the process was CPU-bound (this request *or another*), ~0 means it was waiting on I/O (Redis, disk). `slowest=` is the longest gap between the request's `req.log` steps and the step that ended it (only on requests that log steps, mostly blog renders; `(response finished)` means the gap was after the last step). A request that never finishes logs ` Connection closed by client ` instead. - `[EVENT LOOP] lag max=…` lines (`app/helper/eventLoopMonitor.js`) mark windows where the loop blocked >500ms. - Container logs are lost on every deploy. Check `docker ps` uptime first: the access log usually covers more time than the app logs do. Routes that are slow by design: the triage script sets these aside, so glance at the counts but don't investigate unless something looks off: | Route | Why | |---|---| | `blot.im/sites/*/status`, `…/import/status` | dashboard SSE (`helper/sse`) | | `webhooks.blot.im/connect` | webhook relay SSE (`app/clients/webhooks.js`) | | `*/draft/stream/*` | draft preview SSE | | `preview-of-*/__blot/preview/reload` | template preview SSE | | `blot.im/clients/{google-drive,dropbox}/webhook*` | sync work done inline | | `blot.im/clients/git/*`, `stripe/paypal-webhook`, rebuild, import, OAuth | real work inline | Add to `LONG_LIVED` / `INHERENT` in `triage.js` when you meet a new one. ## Method Use cheaper subagents (`model: "sonnet"`) for per-candidate digging. Keep triage, render probes and the write-up in the main agent. Probes run one at a time on the host, so don't let parallel subagents start them. ### 1. Pull the log and check the window ```bash S= ssh blot "docker ps --format '{{.Names}}\t{{.Status}}'" ssh blot "ls -la /var/instance-ssd/logs/" ssh blot "gzip -c /var/instance-ssd/logs/access.log" > $S/access.log.gz ``` (`gzip: file size changed while zipping` is harmless: the log is live.) Add the rotated `access.log-YYYYMMDD` for a longer window. Note when the app containers started; requests before then can only be judged from nginx. ### 2. Triage ```bash T=.claude/skills/investigate-slow-upstream-responses/triage.js node $T $S/access.log.gz # whole window node $T $S/access.log.gz --since 08:42:00 # since containers started node $T $S/access.log.gz --detail # one host's slow requests + ids node $T $S/access.log.gz --at 04:10:30 # everything in flight around a moment ``` It prints: - per-upstream counts, the share of slow page requests, and an st histogram; - **set aside**: long-lived/inherent routes with counts and median; - **stall clusters**: ≥3 slow page requests overlapping on one upstream (start = log time − st). The *suspect* is the longest. A cluster across many hosts that all finish within the same second is one blocked event loop: the suspect is the cause, the rest are victims. A cluster on one host is often a crawler burst on that host; - **URL groups** (host + route with dates/ids collapsed), ranked by total time over the bar. `slow/all` says how often that route is slow. `own` counts slow requests that were alone or the cluster suspect (likely their own cost). The rest overlapped something slower (likely queued); - **hosts** with ≥20 requests, by share of slow requests. Pick candidates: top URL groups with high `own`, hosts with a high slow share, and every cluster suspect over ~1s. Drop anything that only appears as a victim. Treat requests on **blue for a blog host** and anything in the first few minutes after a container start as deploy noise unless it continues afterwards. Check the root `TODO` ("Fix performance bugs on various sites") and the findings log below for already-known sites. ### 3. App-side cross-check Join the slow requests to the app's response lines by request id: ```bash J=.claude/skills/investigate-slow-upstream-responses/join-app-log.js ssh blot "for c in blue green yellow; do docker logs blot-container-\$c 2>&1; done | grep -E '^\[[^]]+\] \[[a-z-]+\] [0-9a-f]{32} ([0-9]{3} [0-9.]+ |Connection closed)'" > $S/app.log node $J $S/access.log.gz $S/app.log [--host ] ``` It splits slow requests into *mostly queued* (`st − app > st/2`) and *mostly own time*, then into CPU-bound (`elu ≥ 0.8`) and I/O-bound (`elu < 0.3`), counts the most common `slowest=` steps, and lists the slowest requests with st / app / queued / elu / slowest step. Only requests since the containers started can join; the access log copy must overlap that (pull it fresh if a deploy happened since). For one request id, every step it logged: ```bash ssh blot "docker logs --timestamps blot-container-yellow 2>&1 | grep " ``` All of a host's completion lines, slowest first: ```bash ssh blot "docker logs blot-container-yellow 2>&1 | grep -E '^\[[^]]+\] \[yellow\] [0-9a-f]{32} [0-9]{3} [0-9.]+ https?://' | awk '{print \$5, \$6, \$8, \$7}' | sort -k2 -rn | head" ``` Read it as: - **duration ≈ st, elu ~1, every request** → the render itself is CPU-heavy. Regularly pathological: probe it (step 4). - **duration ≈ st, elu low** → waiting on I/O: Redis round trips (count them with the probe), a slow Redis command (`redis-cli SLOWLOG GET 20`), disk, or an outbound fetch. - **duration ≪ st** → it queued. Use `--at