Reading the GC log

Goal

Create and read real GC logs with a small Java program — pause count, pause time, the effect of heap size, collector comparison, jstat, and jcmd.

Why it matters

When you receive "the service is slow," the first fork is whether it is GC or not. If the GC log shows no long pauses, the culprit is elsewhere (locks, pool exhaustion). You will see how to turn the log on and read it, and how heap size and collector affect pauses, using real numbers. The material Churn.java runs as java Churn <초> <유지MB> [반복당KB] (seconds, retained MB, and optional KB per iteration); it holds on to the retained MB and keeps discarding the rest.

Steps

1. Compile with mkdir -p /root/jvm/gc && cd /root/jvm/gc && javac -d . /opt/lab/fixtures/jvm/Churn.java. /root/jvm/gc/Churn.class is created and java -cp /root/jvm/gc Churn 1 0 prints done.
2. Create a GC log with java -Xmx256m -Xlog:gc:file=/root/jvm/gc/gc.log -cp /root/jvm/gc Churn 5 24. The log must contain a collector line starting with Using and Pause Young lines.
3. Create a detailed log with -Xlog:gc*:file=/root/jvm/gc/gc-detail.log (same load, 5 seconds and 24MB). Count the lines that contain Pause Young and end with ms (the pause completion lines) and write them to /root/jvm/gc/answer.txt as a single line, young_pauses=<n>.
4. Run the same load with -Xms64m -Xmx64m to create /root/jvm/gc/gc-64.log (-Xlog:gc*), and with -Xmx256m to create /root/jvm/gc/gc-256.log, then write two lines to /root/jvm/gc/compare.txt, xmx64_pauses=<n> and xmx256_pauses=<n> (counted the same way as in step 3). The 64M side must have more.
5. Find the longest pause in gc-256.log (on the lines with Pause, the last value ending in ms) and write it to /root/jvm/gc/pause.txt as max_pause_ms=<x> (to three decimal places, exactly as in the log).
6. Start java -Xmx128m -cp /root/jvm/gc Churn 12 24 in the background and capture 5 samples at 1-second intervals with jstat -gc <pid> 1000 5 > /root/jvm/gc/jstat.txt. It must contain a header (S0C, EC, YGC, FGC, and so on) and 5 data rows.
7. Run the same load with -XX:+UseSerialGC -Xlog:gc:file=/root/jvm/gc/gc-serial.log and with -XX:+UseG1GC -Xlog:gc:file=/root/jvm/gc/gc-g1.log (-Xmx128m, 5 seconds and 24MB), and write each maximum pause to /root/jvm/gc/collector.txt as two lines, serial_max_pause_ms=<x> and g1_max_pause_ms=<x>.
8. With Churn running in the background again, capture jcmd <pid> GC.heap_info > /root/jvm/gc/heap_info.txt and jcmd <pid> VM.flags > /root/jvm/gc/vm_flags.txt. heap_info must contain total and used, and vm_flags must contain -XX:MaxHeapSize=.

Notes

• Extracting the maximum pause: awk '/Pause/ && match($0,/[0-9.]+ms$/){v=substr($0,RSTART,RLENGTH-2)+0; if(v>m)m=v} END{print m}' gc-256.log
• Background pid: after java ... & PID=$!, run jstat -gc $PID 1000 5. The program ends on its own.
• Common mistake: with -Xlog:gc*, counting Pause Young matches both the start line and the completion line — count only the lines that end with ms.

Compile the material

Compile Churn.java in /root/jvm/gc to create Churn.class. java -cp /root/jvm/gc Churn 1 0 prints done.

It is javac -d . The class has no package, so you only need to give the directory to -cp.

Turn on the GC log

Run Churn 5 24 with -Xmx256m -Xlog:gc:file=/root/jvm/gc/gc.log. The log must contain a Using line and Pause Young lines.

-Xlog:gc:file= sends GC events to a file. The first line tells you which collector is in use.

Count pauses in the detailed log

Run the same load with -Xlog:gc*:file=/root/jvm/gc/gc-detail.log, and write the number of lines that contain Pause Young and end with ms to /root/jvm/gc/answer.txt as young_pauses=.

gc* leaves a single pause as two lines, [gc,start] and [gc]. To count only the completion lines, pick the lines that end with ms: grep -E 'Pause Young.*ms$' | wc -l

A smaller heap means more frequent pauses

Create gc-64.log with -Xms64m -Xmx64m and gc-256.log with -Xmx256m (both with -Xlog:gc*), and write xmx64_pauses= and xmx256_pauses= to compare.txt. The 64M side must have more.

If you fit the same amount of allocation into a smaller heap, eden fills quickly and Young GCs become more frequent. You count them the same way as in step 3.

The maximum pause, not the average

From gc-256.log, write the maximum of the last ms values on the Pause lines to /root/jvm/gc/pause.txt as max_pause_ms=.

The awk one-liner in the Notes section extracts the maximum. The value is exactly the log's three decimal places.

A live process with jstat

Start Churn 12 24 (-Xmx128m) in the background and capture jstat -gc 1000 5 > /root/jvm/gc/jstat.txt. It must contain a header and 5 data rows.

Grab the pid with java ... & PID=$! and run jstat -gc $PID 1000 5. The program ends on its own after 12 seconds, so take the 5 samples within that time.

Serial and G1 under the same load

Create gc-serial.log with -XX:+UseSerialGC and gc-g1.log with -XX:+UseG1GC (-Xmx128m, -Xlog:gc, Churn 5 24), and write serial_max_pause_ms= and g1_max_pause_ms= to collector.txt.

The first line of each log must be Using Serial / Using G1. For the maximum pause, use the awk from step 5 and change only the file.

Heap information and actual flags with jcmd

With Churn running in the background, capture jcmd GC.heap_info > /root/jvm/gc/heap_info.txt and jcmd VM.flags > /root/jvm/gc/vm_flags.txt.

You can find the pid with jcmd -l. VM.flags shows the values the JVM actually applied (-XX:MaxHeapSize=…) — this, not the config file, is the truth.