The symptom. On the lab host, a stripped-down OrderService request handler (SlowOrderService, eight worker threads) delivers 172-208 requests/s and each request spends 38-46 ms in the handler. The target is more than 240 req/s. Nobody has a hypothesis, only opinions: "it is the string building", "it is that lock", "it is the payment gateway".

The program was written with five deliberately different problems: an O(n squared) duplicate check (CPU), string concatenation in a loop (allocation), one global lock held for 1 ms (contention), a 30 ms blocking downstream call (waiting), and a static list that never shrinks (leak). Each is invisible to some profilers and obvious to others. This page uses the real JFR recording of that program, real thread dumps and a real class histogram to show which tool answers which question - and a decision flow for the two classic incidents, "CPU is high" and "memory keeps growing".

A profile is a statistical sample of where threads are. What it samples decides what it can see.

Java Flight Recorder ships with the JDK (open source since JDK 11), is designed to be always-on-capable and exposes jcmd, jfr command-line tools and Mission Control for GUI analysis. In JDK 21 there is also jfr view for canned tabular views - used throughout this page.

SlowOrderService, 8 worker threads, baseline: 176.6 and 195.1 req/s in two early runs, then 208.3 and 172.2 req/s with timing instrumentation - on a host that was running other jobs. Per request: 38.4 ms and 46.3 ms wall, 5.9 and 7.2 ms CPU, 454 KB allocated.

Hypothesis: the CPU part of the request (6-7 ms) is spent in one hot spot; removing it will cut CPU per request sharply and raise throughput. (Spoiler: the first half is right, the second half only partly.)

Record 20 s under load with settings=profile and ask for hot methods:

Method-level view hides the call path. A flame graph aggregates the full stacks: each rectangle is a frame, its width the number of samples that included it, and the stack grows upward. The graph below is drawn directly from jfr print --json output of the same recording.

• ArrayList.indexOfRange is the leaf of 1,741 of 1,951 samples (89.2 %); walking up the stack: ArrayList.contains called from SlowOrderService.validate.
• The code is seen.contains(v) inside a loop over seen: O(n squared) - 2,500 elements means about 3 million comparisons per request.
• Second place: audit() at 7.3 % of samples. That is the 1 ms busy-wait inside a synchronized block (our stand-in for work done while holding a lock).
• The sleeping payment call has 1 sample in the entire CPU profile.

Replace the list with a HashSet (contains + add in O(1)). One variable, one flag in the lab program (-DfastValidate=true):

CPU per request fell 5x, wall time 15-30 %, throughput +17-43 % (the baseline was noisy: loaded host). But a 5x CPU win produced only a ~1.3x latency win. Why? Chapter 05.

After fix 1 each request uses 1.2 ms of CPU - yet it still takes 32.5 ms of wall time and the service is stuck at ~245-255 req/s. Eight threads, 255 req/s: each thread completes a request every 31 ms. The CPU is mostly idle. A second CPU profile would find nothing to fix.

Hypothesis: the missing 31 ms is waiting, not computing. A profile that samples only running threads cannot see waiting.

Evidence 1 - JFR sleep events. jdk.ThreadSleep records every Thread.sleep with its duration and stack. In the baseline recording there are 3,405 events, one per request, 30.1 ms each:

Evidence 2 - a poor-man's wall-clock profile. Take several thread dumps while the load runs and count where the worker threads are. Eight jcmd <pid> Thread.print dumps x eight workers = 64 samples:

Evidence 3 - the CPU profile after the fix. The new recording (same program, both fixes):

• 48 of 64 thread samples (75 %) are in callPayment in state TIMED_WAITING (sleeping): the thread is parked inside a 30 ms downstream call.
• 11 samples (17 %) were in validate RUNNABLE - consistent with the CPU profile's 91 % share of CPU time, which is only ~15 % of wall time.
• Two samples were BLOCKED on audit() - lock contention shows only in a wall-clock or lock view.
• After fix 1, the CPU profile has 275 samples (was 1,951) and the top frame is audit() at 80.7 %: the busy-wait inside the lock - 1 ms per request - is now the "hot" code, even though the request is 97 % waiting.
• A wall-clock accounting per request: 30.1 ms payment wait + 1.2 ms CPU + ~1 ms other = ~32 ms. That is the floor for 8 blocking threads: 8 / 0.0315 = 254 req/s, matching the measured 254.6.

The remaining time is a blocking call. Options (each its own experiment, in other pages): more threads or virtual threads to overlap the waits (Concurrency), make the call async or cache it (Caching), reduce its latency with connection reuse and timeouts (Spring, HTTP & Network), or fan out in parallel (Distributed). Further CPU tuning would be wasted effort.

The model predicted the throughput to within 1 %. Profiling is not just "find the hot function": it is building a quantitative model of where each millisecond goes and checking it.

The baseline recording has 17 young collections in 20 seconds (18 GC events including one old-generation collection) for a service that does almost no work per request. Allocation per request is 454 KB.

Hypothesis: a few call sites produce most of the garbage; reducing them will cut allocation per request and the number of collections. Allocation is a CPU concern too: every byte must be zeroed, and every young GC pauses the application.

• 75.6 % of allocation pressure is a byte[] allocated by string concatenation - the render() method: out += "line-" + i + ";" copies the whole string every iteration (quadratic bytes for 300 appends).
• 10.9 % is Integer.valueOf - boxing in validate(); 6.4 % Arrays.copyOf - ArrayList growth.
• Notice that render() was only 1.2 % of the CPU profile (23 samples) but ~76 % of the allocation profile - a different profile type reorders the suspects.

Allocation per request dropped 3.4x from the baseline (and 3.4x relative to fix 1). Throughput did not move beyond the 254/s wait-bound ceiling, which is the honest result: the allocation fix reduces GC work and CPU headroom, not the 30 ms payment wait. It also reveals that fix 1 made allocation worse (454 to 531 KB) - HashSet nodes plus the same boxing; that regression would have been invisible without the allocation profile. See JVM Memory & GC for what the collector then does with it.

In the baseline, per-request wall time (38-46 ms) exceeds sleep (30.1 ms) plus CPU (5.9-7.2 ms) by 2.4-9 ms that no profile so far explains. Suspect: threads waiting for a lock or for a CPU on an oversubscribed host.

Hypothesis: the global AUDIT_LOCK serialises all eight workers for ~1 ms per request; with eight threads that is a queue.

• 105 contended acquisitions of audit(), average wait 18.1 ms, maximum 60.8 ms. Each wait is far longer than the 1 ms critical section: a lock convoy - while the holder is descheduled (loaded host), every other thread queues.
• The thread dump shows BLOCKED (on object monitor) at SlowOrderService.audit(SlowOrderService.java:52) while another thread holds the lock - the dump names the monitor address, so you can find the holder in the same dump (- locked <0x...>).
• Only 105 contentions in 3,405 requests (3 %): this lock is a tail problem, not the main cost. Averages hide it; p99 sees it (page 1).
• After fix 1 the contention nearly vanished: 3 events (avg 19 ms) in 5,092 requests. Less CPU saturation meant the lock holder was rarely descheduled while holding the lock. Contention is often a symptom of CPU pressure, not an independent cause.

This chapter changed nothing; the verification is the recording after fix 1: jfr view contention-by-site rec2.jfr shows audit(long) with count 3, avg 19.0 ms, max 25.1 ms. Verify any real lock fix the same way: contention count and avg wait should fall, and throughput at the same CPU should rise.

SlowOrderService finishes each run reporting "leaked entries: 3405" - one per request - because remember() appends an AuditEntry (with a 512-byte payload) to a static list that is never trimmed. In production the symptom would be: heap after GC creeping up, GC frequency rising, eventually java.lang.OutOfMemoryError: Java heap space.

Hypothesis: one application class's instance count rises monotonically between snapshots; a heap dump will show a single GC root path holding them.

• SlowOrderService$AuditEntry grew from 736 to 3,065 instances in 6 seconds (rank 12 to rank 5 in the histogram) while byte[] grew from 810 KB to 2.1 MB (the 512-byte payloads).
• A class histogram says what is growing, not who holds it. For that: open the dump in Eclipse MAT or JDK Mission Control and read the dominator tree (largest retained sizes) and path to GC roots. Here it would show a static field SlowOrderService.LEAK (an ArrayList) retaining all entries. MAT was not run in this sandbox; the workflow is described from its documented features.
• The heap dump file was 6.3 MB and written in 0.072 s for this tiny heap; a production dump of an 8 GB heap pauses the JVM for many seconds and needs equal free disk. Take it from an instance that has been drained from the load balancer.

Bound the structure (evict by size or age: a Caffeine cache with maximumSize/expireAfterWrite instead of a static list), or stop retaining it. Typical leak shapes: static maps used as caches, listeners/callbacks never deregistered, ThreadLocal values in pooled threads, unbounded queues, per-request objects stored in a session or MDC (see JVM Memory & GC).

A leak fix is proven when the after-GC floor of the heap stays flat over a soak test (hours) and the class count stops growing between histograms. Watch jvm.memory.used after a full GC / jvm.gc.live.data.size in production, not instantaneous usage.

Memorise the order of questions, not the commands. Each flow ends with one change followed by a re-measure.

Everything above comes from one 130-line, dependency-free program. Save it as SlowOrderService.java. (The baseline JFR recording was taken before the per-request timing helper timedRequest was added to the program; the request logic was identical.)

• Q: CPU is 20 % but latency is bad. What now?
  The service is waiting, not computing. Check saturation (pool pending, queues), take thread dumps or a wall-clock profile and a trace; a CPU flame graph will not show the wait. In the lab 75 % of thread samples were in a sleeping downstream call while CPU was 0.3 cores.
• Q: What are the four types of profile?
  CPU (running threads), allocation (who creates garbage), lock (who waits for whom) and wall-clock (where elapsed time goes, all thread states).
• Q: How do you read a flame graph?
  Width = proportion of samples including that frame; height = stack depth; look for wide plateaus at the top and walk down to find the call path that causes them; compare two graphs rather than reading one in isolation.
• Q: What is JFR and why use it in production?
  A built-in event recorder in the JVM with low overhead; it captures CPU samples, allocation, locks, GC and I/O events to a file that can be analysed with jfr or Mission Control. No agent or restart is needed (jcmd JFR.start).
• Q: BLOCKED vs WAITING vs TIMED_WAITING vs RUNNABLE?
  BLOCKED: waiting to enter a synchronized block; WAITING: waiting without timeout (wait/park); TIMED_WAITING: waiting with timeout (sleep, timed park); RUNNABLE: runnable - including threads inside native socket reads, so check the top frame.
• Q: How do you find a memory leak?
  Confirm the after-GC heap floor rises; diff two class histograms; heap dump and read the dominator tree and paths to GC roots; fix retention and verify with a soak test.
• Q: Heap is flat but the container grows to its limit. Where is the memory?
  Off-heap: direct buffers, thread stacks, metaspace, code cache, native allocations. Use Native Memory Tracking and compare with the container limit (page 12).
• Q: Why did the CPU fix not improve latency much?
  Because the CPU time was a small share of wall time; by Amdahl applying 5x to 15 % of the request gives ~1.14x. Do wall-clock accounting first.
• Q: Is a profiler safe to run in production?
  JFR with default settings is designed for it; heavier modes and heap dumps are not. Prefer short windows, one instance, and a drained instance for heap dumps.