prod check: slow requests as spans, with their route, laid beside Tower's load

Check 5 listed traces over 5 s, which were all page traces holding minutes of
live updates or audio, so a slow request never showed. query.py's new `spans`
lists the matching spans with their own time; check 5 asks for ipx requests
over a second, steps over half a second, and says to set the hours beside
Tower's load: on 2026-10-18, 120 of 130 slow requests were the host stalling.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

.claude/skills/ipx-prod-check/SKILL.md

@@ -26,6 +26,7 @@ Q=.claude/skills/ipx-prod-check/query.py
 $Q logs    '<LogQL>'           [since]   # lines, newest first (500 at most)
 $Q metric  '<LogQL metric>'    [since]   # $range becomes `since`
 $Q traces  '<TraceQL>'         [since]   # slowest first
+$Q spans   '<TraceQL>'          [since]   # the matching spans, each with its own time, slowest first
 $Q trace   <trace id>                    # one trace as a tree, with its log lines
 $Q prom    '<PromQL>'          [since]   # Prometheus, now; $range becomes `since`
 ```
@@ -159,16 +160,30 @@ a count says something happened, the lines and traces say why.
    `feeds` above 0; none at all for over 10 minutes means the worker is stuck. And `pending` is
    the real queue (#113): files a scan will download on its own. Back-catalogue files are
    `held`, listed but not counted, so it is usually 0 or a handful.
-5. **Slow and failed traces.** All three services' (filter by `resource.service.name` for one).
+5. **Slow and failed traces.** Look at ipx's requests as spans, not traces: a trace started by a
+   tap in the page also holds that page's live updates and any audio it streamed, minutes long,
+   so a list of traces over a few seconds is nothing but those. `spans` lists each matching span
+   with its own time and route, slowest first:
    ```
-   $Q traces '{resource.deployment.environment.name="production" && duration > 5s}'
+   R='resource.deployment.environment.name="production" && resource.service.name="ipx"'
+   $Q spans "{$R && span.http.route != \"\" && span.http.route != \"/api/events\" && span.http.route !~ \"/media/.*\" && duration > 1s} | select(span.http.route)"
+   $Q spans "{$R && name=\"step\" && duration > 500ms} | select(span.of)"
    $Q traces '{resource.deployment.environment.name="production" && status = error}'
    $Q trace <id>
    ```
+   Group the first by hour and by route (`awk '{print substr($3,1,2), $NF}' | sort | uniq -c`),
+   then lay the hours beside Tower's (the Tower section): load over 100 with processes blocked
+   and memory under 4 GB is the host stalling, and every request of those minutes is slow with
+   it, ipx's queries included. On 2026-10-18 that was 120 of 130 requests over a second, up to 43 s.
+   What is left at quiet hours is ipx's own: open its trace and see which step holds the time. A
+   request far longer than its steps added up waited outside them, for a connection or a thread.
+   The second line finds steps over half a second wherever they ran; a step slow only once, first
+   thing after hours idle, is Postgres reading from disk what it no longer had in memory (All
+   Subscriptions' `entries_in`, a second where it is 60 ms warm).
+
    Scans (`scan`) are long by nature, since they fetch many feeds one after another: look for one
-   `feed` or `fetch` span holding most of it, or a `download` far slower than its size explains.
+   `feed` or `fetch` span holding most of it (`$Q spans '{... && name="feed" && duration > 10s}'`),
-   A web request over a second is worth a look; the trace shows whether the time is in the
+   or a `download` far slower than its size explains.
-   handler or a scan it waited on.
 
    Steps are `step` spans named by `of` (#187): an item list's `entries_in`, `sanitize`,
    `deadair`, `count_in`; the feed list's `catalogue`, `feed_list` and its queries; a `reap`'s
@@ -262,7 +277,7 @@ to see where the time went, Caddy's span with ipx's inside it. A slow page with
 Caddy or the network; a long one is ipx.
 
 ```sh
-$Q traces '{resource.service.name="ipx-web" && duration > 2s}'
+$Q spans '{resource.service.name="ipx-web" && span.url.path != "/api/events" && span.url.path !~ "/media/.*" && duration > 2s} | select(span.url.path)'
 $Q traces '{resource.service.name="ipx-web" && status = error}'
 ```
 

.claude/skills/ipx-prod-check/query.py

@@ -4,6 +4,7 @@
     query.py logs    '<LogQL log query>'    [since]   lines, newest first
     query.py metric  '<LogQL metric query>' [since]   one value per series; $range is `since`
     query.py traces  '<TraceQL query>'      [since]   matching traces, slowest first
+    query.py spans   '<TraceQL query>'      [since]   the matching spans, each with its own time
     query.py trace   <trace id>                       one trace's spans, as a tree
     query.py prom    '<PromQL query>'       [since]   one value per series, now; $range is `since`
 
@@ -58,6 +59,21 @@ def main():
             name = t.get("rootTraceName") or "(from the page)"
             print(f"{t.get('durationMs', 0):>8}ms  {when}Z  {t['traceID']}  {name}")
         print(f"-- {len(traces)} trace(s)", file=sys.stderr)
+    elif kind == "spans":
+        # The spans that matched, each with its own time: a trace's length says nothing about a
+        # slow request in it when the trace also holds a page's live updates or an audio stream.
+        r = fetch(f"http://tempo:3200/api/search?q={enc(q)}&start={int(start)}&end={int(now)}&limit=200&spss=20")
+        rows = []
+        for t in r.get("traces", []):
+            for ss in t.get("spanSets") or [t.get("spanSet") or {}]:
+                for sp in ss.get("spans", []):
+                    attrs = {a["key"]: next(iter(a["value"].values()), None) for a in sp.get("attributes", [])}
+                    what = attrs.get("http.route") or attrs.get("of") or sp.get("name") or ""
+                    rows.append((int(sp.get("durationNanos", 0)) / 1e6, int(sp["startTimeUnixNano"]), t["traceID"], what))
+        for ms, ts, tid, what in sorted(rows, reverse=True):
+            when = time.strftime("%m-%d %H:%M:%S", time.gmtime(ts / 1e9))
+            print(f"{ms:>8.0f}ms  {when}Z  {tid}  {what}")
+        print(f"-- {len(rows)} span(s)", file=sys.stderr)
     elif kind == "prom":
         # ipx's /metrics (#194), scraped as job ipx; through the network like the others.
         r = fetch(f"http://prometheus:9090/api/v1/query?query={enc(q.replace('$range', since))}&time={now}")