Performance Troubleshooting & Incident Response Questions

Direct answer: The workload is write-heavy (four times more writes than reads, and eight times more write throughput than read throughput) and the disk metrics show queueing rather than raw saturation: await (the time each request waits, including time queued) is ten times svctm (the actual time the device spends servicing a request), even though %util is only 62.5 percent. Combined with 40 percent CPU I/O wait (wa), the most likely bottleneck is the storage device becoming a queueing point under this write load, not the CPU.

Structured elaboration:

• Read the ratio, not just %util. await at 25.0ms against svctm at 2.50ms gives a ratio of 25.0 / 2.50 = 10. That means, on average, roughly nine-tenths of the time a request spends "in flight" at the device, it's waiting in queue rather than actually being serviced, even though %util (62.5%) hasn't hit its ceiling.
• Put a number on the queue with Little's law, then reconcile it against %util, because those two figures are in tension and the tension is the finding. Completions are r/s + w/s = 250 per second and each request is resident at the device for await = 25.0ms, so the average number outstanding is 250 x 0.025 = 6.25 requests. A queue averaging 6.25 deep cannot coexist with a device that was idle 37.5% of the interval if arrivals were smooth, because a device with anything outstanding is by definition busy, and a steadily 6-deep queue would pin %util near 100. The only arrival pattern that produces both numbers is a bursty one: the device sits idle for part of each second and is then handed a clump of writes it has to drain. That is itself the diagnostic clue, and it points at a periodic writer (a flush, a checkpoint, a compaction, a log rotation) rather than steady user traffic, which is why the very next step below is to attribute the writes to a process. It also means 62.5% is a misleading headroom number: the device is not 37.5% spare, it is oversubscribed during the bursts and idle between them. The three fields are at least arithmetically consistent with each other, which is worth checking before trusting any of them: (50 + 200) x 2.50ms = 625ms of device-busy time per second, exactly the 62.5% reported.
• Treat svctm as a derived number, not a measurement. iostat computes it back out of %util and the completion rate rather than observing it, which makes it meaningless on any device that services requests in parallel (anything with a real queue depth: SSDs, NVMe, most array-backed volumes), and later sysstat releases dropped it from iostat -x output for that reason. On a current machine the fields to reach for are aqu-sz (average queue size, older builds call it avgqu-sz, and it is the same 6.25 derived above) together with r_await and w_await split by direction, since on a load that is 4-to-1 writes a single averaged await can be hiding fast reads behind very slow writes or the reverse.
• Confirm the write-heavy shape. w/s (200) is four times r/s (50); wkB/s (8192) is eight times rkB/s (1024). Whatever is generating load here is writing far more than it's reading.
• Cross-check against vmstat. CPU time shows wa=40 (40% of CPU cycles reported as idle are actually blocked on I/O), alongside us=40 and sy=10. High %wa corroborates that I/O, not compute, is where time is going. (Note: vmstat's b column, processes in uninterruptible sleep, is a point-in-time snapshot rather than an interval average, so seeing b=0 at the instant it was sampled doesn't contradict a high %wa measured as an average over the whole sampling interval.)
• Immediate action: identify what's generating the write volume, for example with pidstat -d 1 to attribute disk I/O to a specific process, and if a non-essential write-heavy job (a backup, compaction run, or log rotation) is running concurrently with user traffic, pause or deprioritize it to relieve pressure while you investigate further.
• Additional metrics to confirm: iotop for an interactive per-process view, lsof to see what has the device's files open, and a longer window of iostat -x samples (this was only a brief snapshot) to confirm the pattern is sustained rather than a short burst.

Worked example (alternate, for contrast): a healthy write-heavy device might report w/s around 120 and wsec/s (sectors written per second, one sector is typically 512 bytes) around 307200, with await around 12.5ms. Converting sectors to throughput: 307200 sectors/s times 512 bytes = 157,286,400 bytes/s, divided by 1,048,576 bytes per MB, gives about 150 MB/s of sustained write throughput. At 120 writes/sec that works out to roughly 1.25MB per write, consistent with large, sequential-style writes, and a 12.5ms await on that pattern is fast, not queued. That's what a device comfortably keeping up with a big-block write load looks like, in contrast to the given scenario's 10x await-to-svctm ratio, which is the actual signature of a device falling behind.

Trade-offs and pitfalls: it's tempting to read %util alone and conclude the disk still has headroom at 62.5%; %util measures how often the device was busy at all, not whether requests are queueing once it is, which is exactly why the await-to-svctm ratio matters more here. Acting on a single snapshot without a longer sampling window risks mistaking a brief burst for a sustained bottleneck.

Separate the two hypotheses by where the time is actually going: elevated GC (garbage collection, the JVM's automatic memory reclamation) shows up as measurable pause time and real CPU spent inside GC threads, while lock contention shows up as threads sitting BLOCKED waiting on a monitor (here, a monitor is the built-in lock object a thread must acquire to enter a synchronized block, not a monitoring or APM tool), with normal GC activity and often normal or even low CPU usage, since blocked threads aren't computing at all.

Metrics and tooling for the GC hypothesis

• GC logs (enabled with a flag like -Xlog:gc*) showing pause frequency, pause duration, and what percentage of wall-clock time the process spends paused.
• jstat -gcutil for live young/old generation occupancy and GC count and time.
• A heap-usage graph with a sawtooth pattern climbing close to max before every collection, and collections becoming more frequent and longer, points to memory pressure driving GC.
• A flame graph (a visualization where the width of each bar shows how much time was spent in that function, making hot code paths easy to spot) or APM (application performance monitoring) tool showing GC threads consuming a meaningful share of total CPU.

Metrics and tooling for the lock-contention hypothesis

• Thread dumps (as described for reading BLOCKED-thread patterns) showing many threads funneling to one lock holder.
• jstack or a JFR (Java Flight Recorder) contention profile giving monitor wait time per lock directly.
• Latency degrading WITHOUT a corresponding rise in CPU usage or GC time is the key signature, CPU can even look under-utilized because threads are idle waiting rather than computing.

Confirming which one applies

• GC: pause times line up directly with the timing of the latency spikes (a spike coincides with a stop-the-world pause), and reducing allocation rate or retuning the GC algorithm reduces pause time and latency together.
• Lock contention: the regression tracks with rising concurrency (more threads means more competition for the same lock) rather than with memory pressure, and repeated thread dumps taken during the slow window show the same BLOCKED pattern every time.

Worked example: p99 latency (99th percentile: the value below which 99% of requests fall) degrades from 80ms to 400ms under peak traffic. GC logs show average pause time unchanged at 15ms and pause frequency unchanged from the healthy baseline, ruling out GC as the driver. Three thread dumps taken 5 seconds apart during the slow window all show more than 30 threads BLOCKED on the same synchronized cache-refresh method, confirming lock contention: the cache lookup logic was holding a lock for the entire refresh instead of only while swapping the reference.

Trade-offs and pitfalls: the two causes can co-occur, heavy contention can force more object retention which then increases GC pressure, so treat the first hypothesis that fits the evidence as a starting point, not a final answer, and re-check after any fix lands. A common mistake is reading normal CPU utilization as proof it "must be locks" without checking a GC log, since a moderately sized heap can still produce infrequent but very long pauses that a coarse CPU average won't reveal.

Direct answer: With three signals moving together (CPU, GC pause time, and external API retries), the trap is treating them as three independent causes when they may really be A causing B causing C, or all three being downstream symptoms of a fourth thing, like a traffic burst. The plan has to establish which one moved first and then test the causal story directly, not just observe that they correlate.

Structured elaboration:

• Reconstruct a fine-grained timeline. Pull second-level, not minute-level, time series for CPU, GC pause events, and retry counts around a single spike, overlaid on the same axis. Whichever metric's rise leads the others, even by a few hundred milliseconds, is the more likely upstream cause, though leading correlation alone is still not proof.
• Check for a shared upstream cause. Look at request concurrency or queue depth in the same window. If it spikes before all three of the other metrics, none of CPU, GC, or retries is the root cause; they're co-symptoms of a traffic burst instead.
• Test each hypothesis independently, don't just rank them by correlation:
  • To test "a GC pause froze the app long enough to trip the external call's timeout," check whether retry timestamps cluster right after logged GC pause events, and whether the configured call timeout is short enough that a pause of that duration alone would trip it.
  • To test "the external API got slow first, which caused retries, which caused GC/CPU pressure," check the external API's own latency or status data during the spike window; if it was degraded before your CPU or GC metrics moved, that argues it's upstream.
  • To test "a third confounder like a traffic burst," check whether the spikes line up with a known pattern (a batch job, a caller's own retry storm, a marketing push) independent of CPU, GC, and the external API.
• Reproduce the leading hypothesis in isolation. If you suspect the external API, fault-inject several seconds of added latency into a shadow call to that same dependency in staging at similar concurrency, and see if you reproduce a comparable GC-pause and CPU signature. Reproducing the coupled symptom by injecting only one variable is strong confirmation.

Worked example: In one eight-second spike, retry timestamps for the external API start climbing about 1.5 seconds before GC pause time increases, and about 2 seconds before CPU jumps. Checking the external API's own status dashboard shows a brief documented degradation in that exact window. That ordering plus outside corroboration point to: the external API slowed down, your client retried aggressively, the resulting retry storm (more concurrent in-flight requests and objects) drove up allocation rate, and GC pressure and CPU followed as downstream effects. You confirm by fault-injecting three to four seconds of added latency on a shadow call to that dependency in staging at comparable concurrency and reproduce a similar GC-pause and CPU bump.

Trade-offs and pitfalls: leading-edge correlation in a single incident is suggestive, not conclusive; you want the same ordering to hold across multiple spikes before committing engineering effort to a fix. It's also easy to over-index on whichever metric is loudest (CPU usually pages first) instead of tracing it backward, and it's a mistake to assume all three symptoms must share one root cause; the isolation step protects against wrongly merging two coincidental problems into a single story. Once the retry storm is confirmed as the trigger, the fix is adding jittered exponential backoff and a retry budget (a cap on how much total traffic is allowed to be retries) or a circuit breaker (a safeguard that stops sending requests to a dependency once its failure rate crosses a threshold, so it gets a chance to recover instead of being retried into the ground) on that external call, so a downstream blip can't amplify into a retry storm again.

Direct answer: Detect an N+1 problem (a code pattern that issues one extra database query per row of an initial result set, instead of one batched query) by counting queries per request, either from an APM (application performance monitoring: a tool that traces where time goes inside a single request) trace showing many near-identical child spans under one request, or from a query-logging middleware; verify by correlating the query count with the size of the result set, since a true N+1 scales linearly with rows returned. The fix is to batch the follow-up lookups into a single query.

Structured elaboration:

• Detect: turn on query logging or APM tracing for the slow endpoint and look at one representative request. If you see the same query shape repeated dozens or hundreds of times in a single request trace, each differing only by an ID, that is the signature of an N+1.
• Verify: confirm the query count scales with the size of the collection being iterated (10 orders means roughly 10 extra queries, 500 orders means roughly 500), which rules out coincidence and confirms causation rather than just correlation.
• Fix: replace the per-row lookup with either an eager-load/join at the ORM level, or an explicit batched query (WHERE id IN (...)) that fetches every needed row in one round trip.
• Complexity estimate: the code change itself is usually small (a few lines swapping a loop-of-lookups for one batched call), so the engineering effort is low; the risk is behavioral, not size, since a batched IN-clause has to handle duplicate keys, missing keys, and very large ID lists (which may need chunking) correctly.
• Testing before deploy: unit-test that the batched fetch returns identical results to the old per-row approach for the same input, add a regression test asserting the query count stays flat (or grows sub-linearly) as the input size grows, and load-test the endpoint at production-like data volumes before shipping, since N+1 problems often only show up once table sizes exceed what a small staging dataset exercises.

Worked example (runnable):

query_count = 0

# Toy in-memory "database": 500 orders, each pointing at one of 50 customers.
orders = [{"id": i, "customer_id": i % 50} for i in range(500)]
customers_table = {cid: f"customer_{cid}" for cid in range(50)}

def get_customer(customer_id):
    # Simulates one round trip to the DB for a single customer row.
    global query_count
    query_count += 1
    return customers_table[customer_id]

def get_customers_batch(customer_ids):
    # Simulates one round trip that fetches many customer rows at once
    # (SELECT * FROM customers WHERE id IN (...)).
    global query_count
    query_count += 1
    return {cid: customers_table[cid] for cid in customer_ids}

# Both versions start from the same single "SELECT * FROM orders". Count it in
# BOTH, otherwise the comparison is not like for like: the "+1" in "N+1" IS
# this query, and counting it in one column and not the other flatters the fix.
ORDERS_QUERY = 1

# Naive (N+1) version
query_count = 0
result_n1 = []
for order in orders:
    customer_name = get_customer(order["customer_id"])  # one query per order
    result_n1.append((order["id"], customer_name))
total_n1_queries = ORDERS_QUERY + query_count
print(f"N+1 version:   {len(orders)} orders -> {ORDERS_QUERY} + {query_count} = {total_n1_queries} queries")

# Fixed (batched) version
query_count = 0
customer_ids = {o["customer_id"] for o in orders}
customer_map = get_customers_batch(customer_ids)  # one query for all needed customers
result_fixed = [(o["id"], customer_map[o["customer_id"]]) for o in orders]
total_fixed_queries = ORDERS_QUERY + query_count
print(f"Fixed version: {len(orders)} orders, {len(customer_ids)} distinct customers -> {ORDERS_QUERY} + {query_count} = {total_fixed_queries} queries")

assert result_n1 == result_fixed
print("Results identical:", result_n1 == result_fixed)

# The claim is that one scales with the collection and the other does not.
# Demonstrate it at several sizes instead of asserting it in prose.
for n_orders in (10, 100, 1000):
    sample = [{"id": i, "customer_id": i % 50} for i in range(n_orders)]
    query_count = 0
    for o in sample:
        get_customer(o["customer_id"])
    n1 = ORDERS_QUERY + query_count
    query_count = 0
    get_customers_batch({o["customer_id"] for o in sample})
    fixed = ORDERS_QUERY + query_count
    print(f"  {n_orders:>4} orders -> N+1: {n1:>4} queries, batched: {fixed} queries")

Output:

N+1 version:   500 orders -> 1 + 500 = 501 queries
Fixed version: 500 orders, 50 distinct customers -> 1 + 1 = 2 queries
Results identical: True
    10 orders -> N+1:   11 queries, batched: 2 queries
   100 orders -> N+1:  101 queries, batched: 2 queries
  1000 orders -> N+1: 1001 queries, batched: 2 queries

The naive version issues 1 + 500 = 501 queries (the one that fetches the orders, plus one per order, which is literally what the name "N+1" describes); the batched version issues 1 + 1 = 2 (one for the orders, one IN-clause fetch for the 50 distinct customers needed), while producing the identical output. The sweep is the part that matters as evidence: the naive count tracks the collection size exactly (11, 101, 1001) while the batched count stays at 2 regardless, and note that the batched count does not grow with the number of DISTINCT customers either, only the size of the IN list does. That constant-versus-linear shape, not the single 501-versus-2 figure, is what you assert in the regression test.

Trade-offs and pitfalls: a batched IN-clause can hit a parameter-count limit on very large ID lists, so real fixes usually chunk the batch (for example 500 IDs per query) rather than assuming unlimited batch size. Also verify the fix doesn't just move the N+1 one layer up: if the batched customer fetch itself triggers a further per-row lookup (for example customer addresses), you've moved the problem rather than solved it, so re-check query counts end to end after the change, not just at the layer you touched.

Direct answer: A slow 10% creep over four weeks with SLOs (service level objectives: the target reliability or latency thresholds a team commits to) still technically met is the hardest kind of performance problem, because there's no sharp before-and-after to bisect against. The investigation has to reconstruct its own timeline from whatever telemetry exists, form falsifiable hypotheses, and rank them by how cheaply they can be tested, rather than searching for a single dramatic root cause.

Structured elaboration:

• Build a coarse timeline retroactively. Overlay the p99 trend (p99 latency: the value below which 99% of requests fall, so it captures the slowest 1% and moves before the average does) against everything that happened across the four weeks: deploys, feature-flag ramps, data-volume growth, traffic-mix shifts, dependency version bumps. A slow creep is often several small contributing changes, so look for where the SLOPE changed, not just deploy timestamps.
• Identify and backfill telemetry gaps. Pin down exactly what's missing (retention window too short, a missing per-endpoint tag, no historical resource utilization) and check whether raw logs, sampled traces, or infrastructure-level metrics (which often retain longer than aggregated dashboards) still exist for the earlier weeks even if the dashboard doesn't show them. Reprocessing raw data beats accepting "we don't know."
• Test hypotheses in cheapest-to-verify order, and don't let convenience bias the ranking:
  • GC (garbage collection) hypothesis: on a managed runtime, check whether GC pause frequency or duration trended up, often the result of a slowly growing heap footprint (an expanding cache, for example).
  • CPU hypothesis: check whether average per-instance CPU utilization crept up over the window even without traffic growing proportionally, which shows as more time in the run queue and disproportionately hits p99 before it visibly moves p50 (the median, i.e. the typical request).
  • Queueing hypothesis: check whether thread-pool queue depth or request concurrency rose gradually as traffic grew without matching capacity growth; queueing delay shows up first in the tail (p99) long before it's visible in the average, which is exactly why the SLO still looked fine.
• Add temporary headroom while you investigate. More capacity buys time without fixing anything, but it stops the trend from crossing the SLO before the investigation finishes, and add the missing telemetry now so this class of "we can't tell" doesn't recur.
• Close the loop once a fix is identified. Validate it in pre-production against the same traffic shape or a replay if possible, not just a smoke test, then roll it out gradually to production while watching the same p99 metric at each stage, so a regression is caught before full exposure rather than repeating this entire slow-burn cycle.

Worked example: Backfilled infrastructure metrics show average per-instance CPU utilization crept from 35% to 52% over the four weeks while request volume grew only about 8% in the same period, which rules out "it's simply proportional to more traffic." Thread-pool queue depth, previously near zero at p99, starts showing nonzero queueing specifically in the last ten days. Cross-referencing the deploy log shows a feature flag for a new response-enrichment step ramped from 5% to 100% of traffic across exactly that four-week window, gradually adding CPU cost per request. GC metrics stay flat the entire time, ruling that hypothesis out. The team validates by disabling the flag for a subset in a pre-production replay at matching load and confirms p99 drops back to baseline, then rolls the fix out gradually while watching p99 at each rollout stage.

Trade-offs and pitfalls: "the SLO is still technically met" is a trap, since a slow burn quietly spends error budget (the amount of unreliability a team is allowed to spend against its SLO before owing reliability work) and customer complaints often arrive before the SLO alarm does, so don't wait for a formal breach to act. Ranking hypotheses by which data happens to be available, rather than by actual plausibility, biases the investigation toward whichever metric was retained longest, not necessarily the real cause.