Investigate Slow Upstream Responses

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/<run>/ holds customer content: delete it when done.

Background

Log format (proxy/config/http.conf, access_log_format):

[06/Oct/2026:09:28:17 +0000] <request_id> <status> <request_time> <req>:<bytes> <url>  cache=<HIT|MISS|-> ip=… st=<upstream_response_time> lrs=… up=<addr> 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).
• <request_id> is passed to node as X-Request-ID, so the same id appears in the container's log (app/request-logger.js):

  [time] [yellow] <id> <url> GET
  [time] [yellow] <id> +12ms <req.log step>
  [time] [yellow] <id> <status> <duration-s> <url> elu=<0..1> slowest=+<ms>ms:"<step>"

  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 <id> Connection closed by client <url> 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:

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

S=<scratchpad>
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

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 <host>       # 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:

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 <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:

ssh blot "docker logs --timestamps blot-container-yellow 2>&1 | grep <id>"

All of a host's completion lines, slowest first:

ssh blot "docker logs blot-container-yellow 2>&1 | grep -E '^\[[^]]+\] \[yellow\] [0-9a-f]{32} [0-9]{3} [0-9.]+ https?://<host>' | 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 <time> to find what was running on that upstream and investigate that instead.
• slow only on first hit, fast after → cold cache (process-local LRUs start empty after each deploy). Only a concern if the site is slow on cold renders by an unusual margin.
• only crawlers, only uncached long-tail URLs (404s, /page/N, /search) → still a real cost, but the fix may be cheaper 404s or caching rather than faster renders.

Brief for a sonnet subagent (one per candidate, run in parallel, background). Make it self-contained: the context above (host, containers, deploy time, log formats, what elu means, read-only rule, no probes), the candidate's slow lines with ids from --detail, its slow/all, and ask for: app duration/elu and st − duration per id, the code path for that route with file:line, whether cost scales with entry count, regular vs one-off, ranked likely causes with confidence, under ~400 words.