GC pauses are not on the heap-usage graph

Summary

The JVM heap manages short-lived objects (Young) and long-lived objects (Old) separately, and the GC log (-Xlog:gc) records, line by line, when that cleanup happened and how long it paused the application. When a service slows down, this is the first log to open.

Why this was needed

The title of this course, "the heap has room but the service stopped," actually refers to two kinds of incidents. One is this module's incident — the heap usage graph says 60%, yet response times suddenly spike by 3 seconds. The cause was a GC pause. When there is a lot to clean up, the JVM stops all application threads (stop-the-world) and cleans. Having free heap and having fast cleanup are different matters. The other is the next module's incident — the heap and GC are fine, yet every thread is blocked. The first tool for telling them apart is the GC log. If the log shows no long pauses, GC is not the culprit.

The reason this course covers the JVM is demand in the Korean market. In the 2026-09-11 job-posting tally, Java accounted for 160 of all postings (16.7%), but at 6 Korean companies it was 108 postings (38.0%), more than four times the overseas share (8.3%). What postings mean by "JVM tuning experience" and "incident analysis" starts from this module.

How it works

Heap size is set with -Xms (initial/minimum) and -Xmx (maximum) from the java command documentation. The documentation says it is common on server deployments to set the two to the same value — to avoid the GC caused by the heap growing after startup. If you give no value, it is decided at runtime according to the system configuration, and the rules are -XX:MaxRAMPercentage (default 25%) and -XX:InitialRAMPercentage (default 1.5625%). That means on a machine with 8GB of memory, if you specify nothing, the maximum heap is 2GB. In a container, this "machine memory" is read from the cgroup limit (you measure this yourself in module 4).

The collectors are described in three groups in the available collectors documentation. Serial does all GC with a single thread and has no inter-thread communication cost, so it suits small data (the documentation says up to about 100MB), and you enable it with -XX:+UseSerialGC. Parallel is the throughput collector, where several threads share the GC work. G1 does most of its work concurrently with the application (mostly concurrent); it is designed to meet a pause-time goal with high probability while still keeping throughput, and it is the default on server-class machines. There is no single right answer for which is better — the answer is to run the same load and measure the pause times, which is what you do in the lab.

You turn on logging with unified logging, -Xlog. The documentation's conversion table says the old PrintGCDetails corresponds to -Xlog:gc*. -Xlog:gc:file=gc.log writes one line per GC event to a file, and -Xlog:gc*:file=gc.log also records per-phase detail. Actual output looks like this (JDK 21, measured).

[0.002s][info][gc] Using G1
[0.029s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 16M->4M(32M) 1.683ms
[0.030s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 19M->4M(32M) 1.005ms

How to read it — the bracket is the time elapsed since the JVM started, GC(0) is the GC number, Pause Young is a young generation pause, 16M->4M(32M) is before cleanup → after cleanup (total heap), and the last value is the pause time. With -Xlog:gc* turned on, initialization information such as Heap Max Capacity: 64M is added at the top, and a single pause is split into two lines, [gc,start] and [gc]. A Full GC is printed as Pause Full — if you see this often, it means the Old region keeps filling up, which means either a leak or a heap that is too small.

You inspect a live process with jstat. jstat -gc <pid> 1000 5 prints heap statistics 5 times at 1-second intervals. The documentation defines the column names — S0C/S1C survivor space capacity, EC/EU eden capacity and usage, OC/OU Old capacity and usage, YGC/YGCT Young GC count and time, FGC/FGCT Full GC count and time, and GCT total GC time. If YGC rises by tens per second, there is too much allocation; if FGC rises, Old is filling up.

jcmd sends diagnostic commands to a JVM started on the same machine by the same user. jcmd -l returns the list of JVMs, jcmd <pid> GC.heap_info returns a heap summary, and jcmd <pid> VM.flags returns the flags actually in effect (including -XX:MaxHeapSize=). When "the config file says 4g" and "the value the JVM actually uses" differ, VM.flags is the judge.

What it looks like in the field

The most common case is a service with logging never turned on. You cannot turn it on after an incident. The second is setting -Xmx to all of the machine's memory — the JVM also uses metaspace, thread stacks, the code cache, and direct buffers outside the heap, so if the heap reaches the machine's memory, the OS kills the process. The third is looking at pause time as an average. Behind a 5ms average, an 800ms Full GC hides three times a day. You have to look at the maximum and the distribution. That is why the lab extracts the maximum pause from the log.

What you will do in the next lab

You compile /opt/lab/fixtures/jvm/Churn.java, create a log with -Xlog:gc, count Young pauses in the -Xlog:gc* detailed log, compare the pause counts of -Xmx64m and -Xmx256m, extract the maximum pause time, observe a live process with jstat -gc, compare Serial and G1 under the same load, and get heap information and the flags actually in effect with jcmd.