Oninit® Snooper — Examples

Each example assumes the operator has the snoop running and has captured a few seconds of traffic to snoop.log:

oni_snoop --listen 0.0.0.0:9089 --upstream 198.51.100.42:19089 \
    2>snoop.log &
SPID=$!
# ...reproduce the workload of interest...
kill -INT $SPID; wait $SPID

1. Find the slowest round trips

The closing ONI_EOT of a server response carries the full round-trip latency in round_us (column 7). One awk pass picks the slow ones:

$ awk -F'\t' '$5=="ONI_EOT" && $4=="<" && $7+0 > 100000 {
    printf "%8d us  conn=%s\n", $7, $3
  }' snoop.log
   142057 us  conn=4
  1830204 us  conn=5
   180953 us  conn=8
   100412 us  conn=11

Then pull the SQL text for one of those connections:

$ awk -F'\t' '$3=="5" && ($5=="ONI_PREPARE" || $5=="ONI_COMMAND")' snoop.log
2026-04-29T01:06:39.210066Z  3529872  5  >  ONI_COMMAND  48  -  0  484  sql="CREATE DATABASE oninit WITH BUFFERED LOG"

Conn 5's slow round trip was a CREATE DATABASE — expected, not a bug.

2. Catch a server pause mid-response

Round-trip totals don't always tell the right story. A 200 ms response might be one server-think pause followed by 1 ms of streaming, or it might be 200 PFPDU emissions evenly spaced. The gap_us column (9) reveals the difference: it's μs since the previous PFPDU on the same connection / direction.

$ awk -F'\t' '$4=="<" && $9+0 > 10000 {
    printf "%8s us pause before %s on conn %s at %s\n", $9, $5, $3, $1
  }' snoop.log | head
   34412 us pause before ONI_EOT on conn 1 at 2026-04-29T01:04:15.683375Z
   42890 us pause before ONI_TUPLE on conn 6 at 2026-04-29T01:06:41.510088Z

A 42 ms gap between two TUPLE rows on the same fetch is the server pausing mid-response — classic latch wait or buffer-cache miss.

3. Reconstruct one statement's lifecycle

Every PFPDU on one connection in temporal order is a single awk:

$ awk -F'\t' '$3=="6"' snoop.log
... ONI_LOGIN_ASC    495  -  -    -
... ONI_PROTOCOLS    12   -  -    33441
... ONI_PROTOCOLS    14   262 -    460
... ONI_COMMAND      48   -  0    33458  sql="CREATE TABLE t(id SERIAL, n VARCHAR(20))"
... ONI_EOT          2    -  20   20
... ONI_EOT          2    368 388  40945
... ONI_EXECUTE      2    -  562  542
... ONI_DONE         16   1336 1909 1521  rows=0 warn=0
... ONI_PREPARE      40   -  0    42198  sql="SELECT id, n FROM t"
... ONI_NDESCRIBE    2    -  707  688
... ONI_DESCRIBE     52   253 973  486
... ONI_OPEN         2    -  1141 421
... ONI_NFETCH       8    -  1596 441
... ONI_TUPLE        20   230 1840 464   v0=1 v1='hello'
... ONI_DONE         16   245 1855 15    rows=1 warn=0
... ONI_CLOSE        2    -  2057 447

The full DDL+DML+SELECT story for one client session, in order, with per-step timing. The ONI_TUPLE summary now carries the actual column values — v0=1 v1='hello' — decoded against the immediately preceding ONI_DESCRIBE on this connection.

4. Steady-state capture with --only

For long-running observation the TUPLE / EOT chatter dominates the log. Limit the capture to statement boundaries and errors so the file stays compact and grep-friendly:

oni_snoop --listen 0.0.0.0:9089 --upstream 198.51.100.42:19089 \
    --out /var/log/oni_snoop.log \
    --only=ONI_PREPARE,ONI_COMMAND,ONI_DONE,ONI_ERR,ONI_PUTERR

Per-connection timing state still tracks the full stream — round_us, stmt_us, and gap_us on the surviving rows reflect timing across the actual conversation, not the filtered subset. Drop the --only for full-fidelity captures during incident investigation.

The startup banner records the active filter so a downstream reader can tell filtered absence from real absence:

# oni_snoop  listen=0.0.0.0:9089  upstream=198.51.100.42:19089
# only=ONI_PREPARE,ONI_COMMAND,ONI_DONE,ONI_ERR,ONI_PUTERR
# wall_ts	mono_us	conn	dir	token	len	round_us	stmt_us	gap_us	summary

5. Find every error the server returned

$ grep $'\tONI_ERR\t' snoop.log
2026-04-29T01:09:14.118273Z  ...  3  <  ONI_ERR  82  517  517  517  sqlcode=-201 isam=0 msg="A syntax error has occurred."

The full SQLCODE, ISAM code, and server-supplied message text are in the summary column. Combine with example 3 to see exactly what the client sent that triggered each error.

6. Per-statement latency report

For a longer-running capture, group by SQL text and report percentiles. The first awk pass extracts (sql, round_us) pairs; the rest is whatever stats tooling the operator prefers.

$ awk -F'\t' '
    $5=="ONI_PREPARE" || $5=="ONI_COMMAND" {
      sub(/^sql="/, "", $10); sub(/"$/, "", $10);
      q[$3] = $10
    }
    $5=="ONI_DONE" && q[$3] != "" {
      print $7 "\t" q[$3]
    }
  ' snoop.log | sort -n | head -20
372    select @@version_comment limit 1
214    SELECT 1
253    SHOW DATABASES
846    SELECT name FROM sysdatabases ORDER BY name
1336   CREATE TABLE t(id SERIAL, n VARCHAR(20))
940    INSERT INTO t(n) VALUES('hello')
510176 CREATE DATABASE oninit WITH BUFFERED LOG

Pipe through datamash, awk, or any stats tool to group by SQL and produce p50 / p95 / p99 buckets.

7. Watch a live conversation

For interactive observation just tee the snoop output and filter live with tail -f or grep --line-buffered:

oni_snoop --listen 0.0.0.0:9089 --upstream 198.51.100.42:19089 \
    2>&1 \
    | grep --line-buffered $'\tONI_PREPARE\t\\|\tONI_COMMAND\t\\|\tONI_ERR\t'

Shows every prepared statement, immediate command, and server error in real time and ignores the rest of the noise.