diff --git a/.claude/skills/ipx-prod-check/SKILL.md b/.claude/skills/ipx-prod-check/SKILL.md index e6d7bc0..cdef9f8 100644 --- a/.claude/skills/ipx-prod-check/SKILL.md +++ b/.claude/skills/ipx-prod-check/SKILL.md @@ -26,6 +26,7 @@ Q=.claude/skills/ipx-prod-check/query.py $Q logs '' [since] # lines, newest first (500 at most) $Q metric '' [since] # $range becomes `since` $Q traces '' [since] # slowest first +$Q spans '' [since] # the matching spans, each with its own time, slowest first $Q trace # one trace as a tree, with its log lines $Q prom '' [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 ``` + 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. - A web request over a second is worth a look; the trace shows whether the time is in the - handler or a scan it waited on. + `feed` or `fetch` span holding most of it (`$Q spans '{... && name="feed" && duration > 10s}'`), + or a `download` far slower than its size explains. 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}' ``` diff --git a/.claude/skills/ipx-prod-check/query.py b/.claude/skills/ipx-prod-check/query.py index 6b737ba..6754e29 100755 --- a/.claude/skills/ipx-prod-check/query.py +++ b/.claude/skills/ipx-prod-check/query.py @@ -4,6 +4,7 @@ query.py logs '' [since] lines, newest first query.py metric '' [since] one value per series; $range is `since` query.py traces '' [since] matching traces, slowest first + query.py spans '' [since] the matching spans, each with its own time query.py trace one trace's spans, as a tree query.py prom '' [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}")