Profiling and tuning

"The service is slow" is a feeling. A profile is a measurement: where the CPU time went, where the allocations came from, what the collector was doing. This lesson is about getting that measurement with the tools that ship with the JDK — jcmd, jstat, GC logs and Java Flight Recorder — reading it without being misled, and then changing the small number of settings that actually matter.

The examples are from Java 21 in containers.

#The command-line tools

Four tools cover most live investigations, and all of them attach to a running JVM without restarting it:

The production engineering course uses each of them on a live incident: thread dumps for a hot thread and a deadlock, jstat for a leak. This lesson adds the two that explain performance: GC logs and JFR.

#Reading a GC log

Every production JVM should log GC activity. The cost is negligible, and it is the only record of what the collector did before an incident:

-Xlog:gc*:file=/var/log/app/gc.log:time,uptime:filecount=5,filesize=20M

A G1 log from a 2 GB heap holding about 537 MB of live data, under steady allocation, one line per event:

[0.231s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 114M->112M(2048M) 71.205ms
[5.752s][info][gc] GC(30) Concurrent Mark Cycle
[7.127s][info][gc] GC(30) Pause Remark 1821M->1821M(2048M) 1.618ms
[8.470s][info][gc] GC(36) Pause Young (Mixed) (G1 Evacuation Pause) 1217M->1118M(2048M) 76.891ms
[9.076s][info][gc] GC(39) Pause Young (Mixed) (G1 Evacuation Pause) (Evacuation Failure) 1943M->1900M(2048M) 62.940ms
[9.734s][info][gc] GC(42) Pause Full (G1 Compaction Pause) 2047M->533M(2048M) 577.885ms

Each pause line reads the same way: type, cause, heap before → after (capacity), duration.

• Pause Young (Normal) — a young collection. Cheap and frequent is normal.
• Concurrent Mark Cycle — G1 marking the old generation while the application runs, started when the heap passed its occupancy threshold.
• Pause Young (Mixed) — a young collection that also reclaims some old regions; the incremental way G1 cleans the old generation. 1,217 → 1,118 MB.
• Evacuation Failure — G1 ran out of free regions to copy live objects into. This is a warning sign: the heap is too full to collect incrementally.
• Pause Full (G1 Compaction Pause) — the fallback. The whole heap compacted in one stop-the-world pause: 2,047 → 533 MB in 578 ms.

That sequence — mixed collections not keeping up, an evacuation failure, then a full collection — is the most common G1 story in production, and its usual cause is not enough headroom above the live data. The same log also contained a Pause Full (System.gc()), caused by an explicit System.gc() call in the program; in a service, that line means some library is calling it, and -XX:+DisableExplicitGC is worth considering.

Counting pause causes over the whole run is a quick summary:

     39 Young (Normal) (G1 Evacuation Pause)
      6 Young (Mixed) (G1 Evacuation Pause)
      1 Young (Prepare Mixed) (G1 Evacuation Pause)
      1 Young (Concurrent Start) (G1 Evacuation Pause)
      1 Full (System.gc()
      1 Full (G1 Compaction Pause)

#Sampling, not instrumenting

There are two ways to find where time goes:

• Instrumentation records every method entry and exit. It is exact about call counts and wildly inaccurate about time, because the recording itself dominates short methods — and the JIT optimises instrumented code differently.
• Sampling looks at what each thread is doing every few milliseconds and counts. It is statistical, has low overhead, and a method that appears in 20% of samples is using about 20% of the time.

Production profiling is sampling. Java Flight Recorder is the JDK's built-in sampler, designed to run continuously in production with low overhead; async-profiler is a widely used open-source one that also sees native code and kernel time.

#Java Flight Recorder on a slow checkout

A checkout prices a cart of 20 lines: validate each SKU with a regular expression, format a receipt line, add it up. It handles about 92,000 carts a second, and should do better. Record it:

$ java -XX:StartFlightRecording=filename=rec.jfr,settings=profile Checkout
$ jfr view hot-methods rec.jfr
Method                                                                                    Samples Percent
----------------------------------------------------------------------------------------- ------- -------
java.util.regex.Pattern$BmpCharPropertyGreedy.match(Matcher, int, CharSequence)               206  23.44%
java.util.regex.Pattern$BmpCharProperty.match(Matcher, int, CharSequence)                     151  17.18%
java.lang.AbstractStringBuilder.ensureCapacityInternal(int)                                    64   7.28%
java.util.regex.Pattern.sequence(Pattern$Node)                                                 64   7.28%
java.util.Formatter$Conversion.isValid(char)                                                   52   5.92%
java.util.Formatter.parse(String)                                                              38   4.32%
java.util.regex.Pattern.newCharProperty(Pattern$CharPredicate)                                 34   3.87%
java.util.regex.Pattern.compile()                                                              30   3.41%

The obvious reading is "regex matching is the problem" — it tops the list with 40%. That reading is wrong, and the reason is the most important thing to understand about profiles.

hot-methods counts only the top frame of each sample: the method actually on the CPU. It says nothing about which of your calls led there. Counting instead every sample in which a method appears anywhere on the stack — the "inclusive" view that a flame graph draws as width — gives a different picture:

total samples: 860
inside Pattern.compile:    179 of 860 samples (20.8%)
inside String.format:      538 of 860 samples (62.5%)
inside Matcher.matches:    101 of 860 samples (11.7%)
inside Checkout.priceCart: 860 of 860 samples (100%)

String.format was 62.5% of the time, spread across many small Formatter methods, none of which looked large alone. Pattern.compile — recompiling the same pattern on every call — was another 21%. The regex matching that topped the leaf list was under 12% inclusive. The code:

static boolean validSku(String sku) {
    return Pattern.compile("^[A-Z]{3}-\\d{4}$").matcher(sku).matches();   // compiled on every call
}
static String formatLine(String sku, long cents) {
    return String.format("%s x1 = %d.%02d", sku, cents / 100, cents % 100);   // parses the format every call
}

Compiling the pattern once into a static final field and building the line with a StringBuilder:

before: 92064 carts/s
after:  444481 carts/s

Almost five times the throughput, from two lines the leaf profile pointed away from. A flame graph would have shown String.format as the widest block at a glance; that is what flame graphs are for.

JFR records far more than CPU samples: allocation samples (jdk.ObjectAllocationSample — which code allocates the most), GC events, lock contention (jdk.JavaMonitorEnter), file and socket I/O, and the old-object samples the finding memory leaks lesson uses. Running it continuously with a ring buffer — -XX:StartFlightRecording=disk=true,maxage=6h — means that when an incident happens, the last hours are already recorded and jcmd <pid> JFR.dump retrieves them.

#Containers: the settings that matter

The JVM sizes itself from the machine it believes it runs on. Since Java 10, it reads container limits. What the same image chooses under different limits:

--memory=512m --cpus=1                     availableProcessors=1  maxHeap=123 MB  GC=Copy
--memory=512m --cpus=2                     availableProcessors=2  maxHeap=123 MB  GC=Copy
--memory=2g --cpus=2                       availableProcessors=2  maxHeap=512 MB  GC=G1 Young Generation
--memory=4g --cpus=4                       availableProcessors=4  maxHeap=1024 MB  GC=G1 Young Generation
--memory=512m --cpus=2 MaxRAMPercentage=75 availableProcessors=2  maxHeap=371 MB  GC=Copy

Three things stand out:

• The default heap is a quarter of the container's memory. A service given a 512 MB container gets a 123 MB heap and leaves most of its memory unused — then fails with Java heap space while the container graph shows plenty free.
• A small container gets the Serial collector. "Copy" is Serial's young collector. With under about 1.8 GB of memory or a single CPU, the JVM does not consider the machine server-class, so it does not choose G1 — even with 2 CPUs.
• -XX:MaxRAMPercentage=75 gave a 371 MB heap in the same 512 MB container, leaving room for the non-heap memory the memory areas lesson measured.

And with container detection switched off, the JVM sees the host instead:

512m, -XX:-UseContainerSupport availableProcessors=8  maxHeap=1984 MB  GC=G1 Young Generation

A 1,984 MB heap in a 512 MB container: the process will be killed by the kernel long before the collector thinks the heap is full. Old JVMs — Java 8 before update 191 — behave like this by default.

#What to tune, and what not to

The flags worth setting for most services fit on one line:

-XX:MaxRAMPercentage=75 -XX:+HeapDumpOnOutOfMemoryError -Xlog:gc*:file=gc.log:time,uptime:filecount=5,filesize=20M

Then, only with evidence:

• Heap size — the one knob that fixes most GC problems. Size it for the live set plus headroom; the G1 log above failed for lack of headroom, not for lack of tuning.
• Collector — G1 by default; ZGC or Shenandoah when pause times matter and CPU is available; Parallel for batch jobs. Set explicitly in small containers, where the default is Serial.
• -XX:MaxGCPauseMillis for G1, to trade throughput for shorter pauses — a goal, not a guarantee.

What not to tune: survivor ratios, tenuring thresholds, region sizes, and the long lists of flags copied from articles about other applications on other JVM versions. Every such flag is a decision someone must re-validate on each upgrade, and most of them were defaults-era workarounds that the current collectors handle better on their own.