use-analysis

name	use-analysis
description	Perform a Brendan Gregg USE method analysis on perf-lab benchmark results. Use when analyzing benchmark output directories for performance bottlenecks.
argument-hint	<results-dir>
allowed-tools	Read, Grep, Glob, Bash, Agent

USE Method Analysis for perf-lab benchmark results

Perform a Brendan Gregg USE method (Utilization, Saturation, Errors) analysis on the benchmark results in the given directory.

Results directory: $ARGUMENTS

If no directory is provided, ask the user which results directory to analyze.

Step 1: Discover available results

Glob for all files under <results-dir>/target-host/:

• vmstat-*.log — system-wide memory, swap, CPU, I/O
• pidstat-*.log — per-process CPU (the app JVM)
• mpstat-*.log — per-CPU utilization breakdown
• wrk-*.log — load generator throughput & errors (measurement run)
• wrk-warmup-*.log — warmup run results
• load-test-*.log — application stdout/stderr (startup, errors, warnings)
• postgres-pidstat-*.log — database process CPU
• lgtm-pidstat-*.log — OTel LGTM stack CPU
• metrics.json — run configuration (JVM args, CPU pinning, etc.)
• lscpu.txt — CPU/NUMA topology

Identify all runtimes tested (e.g., quarkus3-jvm, spring4-jvm) from the filenames.

Step 2: Load context

Read metrics.json to understand:

• JVM memory settings (config.jvm.memory, config.jvm.args)
• CPU affinity assignments (config.resources.cpu.app, .db, .otel, .load_gen)
• Number of iterations

Read lscpu.txt to understand NUMA topology — which CPUs map to which NUMA nodes.

Column Reference (CRITICAL — do not guess column positions)

mpstat columns

The mpstat header is always:

HH:MM:SS AM/PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle

When parsing with awk (fields are 1-indexed, after time+AM/PM):

• $1 = time, $2 = AM/PM, $3 = CPU number (or "all")
• $4 = %usr, $5 = %nice, $6 = %sys, $7 = %iowait, $8 = %irq, $9 = %soft
• $10 = %steal, $11 = %guest, $12 = %gnice, $13 = %idle

WARNING: $7 is %iowait, NOT %sys. $6 is %sys. $NF (last field) is %idle. Always verify against the header line.

Example awk for per-CPU averages:

awk '$2=="AM" && ($3==CPU1 || $3==CPU2) && $1 >= "HH:MM:SS" && $1 <= "HH:MM:SS" {
    cpu=$3; usr=$4; sys=$6; idle=$NF
    sum_usr[cpu]+=usr; sum_sys[cpu]+=sys; sum_idle[cpu]+=idle; n[cpu]++
}
END {
    for (c in sum_usr) printf "CPU %d: usr=%.1f%% sys=%.1f%% idle=%.1f%% (n=%d)\n",
        c, sum_usr[c]/n[c], sum_sys[c]/n[c], sum_idle[c]/n[c], n[c]
}' mpstat-*.log

vmstat columns

procs -----------memory---------- ---swap-- -----io---- -system-- -------cpu-------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st gu

Fields (1-indexed): $1=r, $2=b, $3=swpd, $4=free, $5=buff, $6=cache, $7=si, $8=so, $9=bi, $10=bo, $11=in, $12=cs, $13=us, $14=sy, $15=id, $16=wa, $17=st, $18=gu

Note: The first data line after the header is a historical average since boot — skip it. Real per-second samples start from the second data line.

pidstat columns

Old format (pidstat -u -p PID 1):

HH:MM:SS   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command

New format (pidstat -u -w -t -p PID 1) — produces TWO alternating blocks per second:

CPU block:

HH:MM:SS   UID      TGID       TID    %usr %system  %guest   %wait    %CPU   CPU  Command

Context switch block:

HH:MM:SS   UID      TGID       TID   cswch/s nvcswch/s  Command

The TGID line (TID="-") shows the process aggregate. TID lines (TGID="-") prefixed with |__ show individual threads.

Identifying the measurement window

The measurement window is the last ~30 seconds of active load before the application is killed. To find it:

1. Look at app-pinned CPUs in mpstat — find when they drop to ~0% (load ends)
2. Count back 30 seconds from that point — that's the measurement window
3. The warmup period (2 minutes) precedes the measurement window

Do NOT use the first seconds of mpstat data — those may be startup/warmup. Do NOT guess the window — always verify by finding the load-end transition in mpstat or vmstat.

Cross-validate with JFR: if JFR was enabled, the number of samples should be approximately duration_seconds × sample_rate_hz × num_cpus. For 10s at 100Hz on 4 CPUs: ~4000 samples = ~100% CPU utilization.

Step 3: For each runtime, analyze each resource using USE

3a. CPU (Application)

Source: pidstat-<runtime>-*.log and mpstat-<runtime>-*.log

• Utilization: Average %usr + %sys for the app process (pidstat). Per-CPU breakdown for app-pinned CPUs (mpstat). Use the awk pattern above with the correct measurement window timestamps.
• Saturation: Run queue depth from vmstat (r column, $1). Check if app CPUs show high %sys (kernel overhead). Context switch rate from vmstat (cs column, $12).
• Errors: N/A for CPU.

Flag if: app CPUs >80% utilized, %sys > %usr (unusual kernel overhead), or run queue consistently > number of app CPUs.

3b. CPU (Database)

Source: postgres-pidstat-<runtime>-*.log and mpstat-<runtime>-*.log (DB-pinned CPUs)

• Utilization: Sum of postgres worker CPU usage. Per-CPU breakdown for DB-pinned CPUs.
• Saturation: Are DB CPUs near 100%?
• Errors: N/A.

Flag if: DB CPUs are saturated (indicates DB is the bottleneck, not the app).

3c. CPU (OTel/LGTM)

Source: lgtm-pidstat-<runtime>-*.log and mpstat-<runtime>-*.log (OTel-pinned CPUs)

• Utilization: LGTM process CPU. Per-CPU for OTel-pinned CPUs.
• Saturation: High CPU on OTel CPUs.
• Errors: Check load-test-*.log for OTel export failures ("Connection was closed", "Failed to export").

Flag if: OTel CPUs saturated, or export errors present (telemetry backpressure affecting the app).

3d. CPU (Load Generator)

Source: mpstat-<runtime>-*.log (load-gen-pinned CPUs)

• Utilization: Per-CPU for load-gen CPUs.
• Saturation: If load-gen CPUs are saturated, wrk itself is the bottleneck and results are invalid.
• Errors: N/A.

Flag if: load-gen CPUs >70% (wrk may be unable to generate enough load).

3e. Memory / Swap

Source: vmstat-<runtime>-*.log

• Utilization: free and cache columns. Track free memory over time.
• Saturation: si (swap-in) and so (swap-out) columns. swpd (swap used) over time. This is the most critical saturation signal.
• Errors: OOM kills (check dmesg if accessible, or sudden process death in logs).

Flag if: swpd > 0 at any point, or si/so > 0 during the measurement window. Correlate with NUMA topology — if the system has multiple NUMA nodes, system-wide free memory can be misleading (one node may be exhausted while another has plenty).

3f. Network / I/O

Source: vmstat-<runtime>-*.log (bi/bo columns), wrk-*.log

• Utilization: Block I/O rates from vmstat.
• Saturation: b column in vmstat (processes blocked on I/O). wa (I/O wait) in CPU columns.
• Errors: Socket errors in wrk output (Socket errors: line — connection errors, timeouts).

Flag if: I/O wait >5%, blocked processes >0 sustained, or wrk reports socket errors.

Step 4: Throughput comparison

From wrk-<runtime>-*.log, extract:

• Requests/sec
• Average latency, max latency, stdev
• Any socket errors

Present a comparison table across runtimes.

Step 4b: Per-operation normalized metrics

When comparing runtimes with different throughput levels, raw aggregate metrics (total context switches, total I/O, total interrupts) are misleading because the higher-throughput runtime naturally generates more total activity. In addition to raw values, present key metrics normalized per request (operation):

• CPU time per request: total %CPU / tps (in µs/req), broken down into user vs kernel
• Context switches per request: cs / tps
• Interrupts per request: in / tps
• Disk I/O per request: bo / tps (KB/req), bi / tps (KB/req)
• Network: socket errors per request (if any)

Present as a comparison table:

| Metric (per request) | Runtime A | Runtime B | Ratio |
|----------------------|-----------|-----------|-------|
| Total CPU            | ... µs    | ... µs    | ...x  |
| User CPU             | ... µs    | ... µs    | ...x  |
| Kernel CPU           | ... µs    | ... µs    | ...x  |
| Context switches     | ...       | ...       | ...x  |
| Interrupts           | ...       | ...       | ...x  |
| Disk write           | ... KB    | ... KB    | ...x  |

This per-operation view reveals whether a runtime is inherently more or less efficient, independent of the throughput it achieves.

Step 5: Summary report

Present findings in this structure:

## USE Analysis: <results-dir>

### Configuration
- JVM: ...
- CPU pinning: App=..., DB=..., OTel=..., LoadGen=...
- NUMA topology: ...

### Throughput
| Runtime | Req/sec | Avg Latency | Max Latency | Errors |
|---------|---------|-------------|-------------|--------|

### Per-Runtime Findings

#### <runtime-name>
| Resource | Utilization | Saturation | Errors | Verdict |
|----------|-------------|------------|--------|---------|
| App CPU  | ...         | ...        | ...    | OK/FLAG |
| DB CPU   | ...         | ...        | ...    | OK/FLAG |
| OTel CPU | ...         | ...        | ...    | OK/FLAG |
| LoadGen  | ...         | ...        | ...    | OK/FLAG |
| Memory   | ...         | ...        | ...    | OK/FLAG |
| I/O      | ...         | ...        | ...    | OK/FLAG |

Key observations:
- ...

### Bottleneck Summary
- Primary bottleneck: ...
- Secondary concerns: ...
- Recommendations: ...

Important notes

• Always check the measurement window (the 30s wrk run), not the warmup. Identify the measurement window by finding the load-end transition in mpstat (app CPUs dropping to ~0%), then counting back 30 seconds.
• NEVER hardcode or guess mpstat/vmstat column positions. Always read the header line first and map column names to positions. The column reference in "Step 2.5" above is the canonical mapping — use it.
• vmstat values are in KB by default.
• The first vmstat data line is a historical average since boot — always skip it.
• If swap activity occurs, determine whether it's during warmup only or also during measurement — warmup-only swap may not affect the reported throughput.
• Cross-reference NUMA node assignments with CPU pinning to detect potential NUMA-related memory issues.
• Note if --drop-fs-caches was used (check metrics.json).
• When AM/PM time format is used, ensure awk comparisons account for it (e.g., $1 >= "09:45:40" && $2 == "AM").