How jvqq Traced a 12-Minute Payments Outage Through 3 Million Log Lines

The alert says checkout is slow. You have the last six hours of application logs as one JSON Lines file, 1 GiB and 3,073,492 lines, and a handful of questions to answer before anyone can fix anything. Which service? Since when? Which endpoint? Each question is a jq filter, and with jq the first one alone took half a minute.

This is a worked example. The log is generated by jvqq’s benchmark generator, and we planted an incident in it: from 03:10 to 03:22, about 60% of the billing service’s payment requests fail with 503 after 2 to 4 seconds. Everything else in the file is ordinary traffic, with its usual background of errors. The commands and output below are real, run with jvqq 0.1.0 and jq 1.7.1 on a two-core cloud VM.

Timings are wall-clock on two cores. The minute-by-minute output is shown on two lines to fit.

Which Service

Normal requests in this log finish within half a second, so anything over a second is suspect:

jvqq -c 'select(.latency_ms > 1000) | count_by(.service)' app.jsonl

{"billing":871}

2.0 seconds. Every slow request is in billing. The same question in jq is a reduce over inputs, and it gave the same answer in 30.6 seconds:

jq -cn 'reduce (inputs | select(.latency_ms > 1000)) as $x ({}; .[$x.service] += 1)' app.jsonl

Since When

group_by with a key and an aggregation gives one row per minute, sorted:

jvqq -r 'select(.latency_ms > 1000) | group_by(.ts[11:16]; {n: count}) | .[] | "\(.key)  \(.n)"' app.jsonl

The rows run from 03:10 82 to 03:21 71, between 59 and 84 a minute, and nothing before or after. It started at 03:10 and stopped before 03:22. 2.2 seconds.

Which Endpoint

Now only billing, only those twelve minutes, broken down by route with the request id taken off the path:

jvqq -c 'select(.service == "billing" and .ts[11:16] >= "03:10" and .ts[11:16] < "03:22")
  | group_by(.request.path | sub("/[0-9]+$"; ""); {n: count, errors: sum(if .status >= 500 then 1 else 0 end), ms: avg(.latency_ms)})
  | .[]' app.jsonl

Six routes look alike: 1,442 to 1,492 requests, 272 to 311 server errors, 242 to 254 ms on average. /v1/payments has 1,455 requests, 981 server errors and an average of 1,890 ms. The same query for the twelve minutes before, 02:58 to 03:10, shows /v1/payments at 276 errors and 251 ms, like everything else. 2.4 seconds each.

Four queries, nine seconds of waiting in all. jq took 30.6 seconds for the first one alone, and the third question needs a reduce that keeps a count, an error count and a running sum per route, which is where people give up and open Python.

One Thing That Tripped Us Up

Our first try at the third query put the error count inside the aggregation as errors: (select(.status >= 500) | count). It printed []. That’s by design, and the reference says so: the step that holds the aggregations runs once at the end, on null, so a select there has nothing to look at. Work on each line goes before the aggregation, or inside its argument, as in sum(if .status >= 500 then 1 else 0 end).

Memory

jvqq used about 30 MiB for each of these queries on the 1 GiB file. It reads the file in chunks, one batch per core, and keeps only the running counts per group.

The quick start has the first commands and the jvqq page the benchmarks.

jvqq is an independent tool, not a fork of jq and not affiliated with the jq project. It reads the jq language and is tested against jq 1.7.1’s output.