A HotSpot JVM prints this garbage-collection log line: `[3.216s][info][gc] GC(7) Pause Young (Normal) (G1 Evacuation Pause) 512M->96M(1024M) 14.221ms`. Walk through what each field on that line means.
answer
- uptime · level · tags · GC(id)
- Pause = stop-the-world; Concurrent = not a pause
- before->after(capacity)
- "Allocation Failure" is normal, not an error
- cause in parentheses answers *why now*
basics
~20 s[3.216s] is uptime, info the log level, gc the tag, GC(7) the collection's id. It was a young pause caused by G1 evacuation. Heap used went 512M before to 96M after, of 1024M total, taking 14.221 ms stop-the-world.
solid answer
~50 sReading left to right: `[3.216s]` is a decorator — JVM uptime when the line was written; `[info]` is the log level and `[gc]` the tag selector that produced it. `GC(7)` is the collection id, which lets you correlate every sub-line (phases, heap breakdown, CPU) belonging to the same collection. `Pause` means stop-the-world, as opposed to a `Concurrent` line that runs alongside the application. `Young (Normal)` is what was collected — the young generation, in the ordinary (not mixed, not initial-mark) flavour. `(G1 Evacuation Pause)` is the *cause*: G1 filled eden and evacuated the live objects out. Then `512M->96M(1024M)`: heap **used** before the collection, heap used after, and current heap **capacity**. So ~416M of garbage died, 96M survived. `14.221ms` is the wall-clock pause duration. Nothing here indicates a problem: this is a healthy, cheap young collection.
go deeper
Be able to name every field in order and state that before->after(capacity) is used-heap before, used-heap after, and current capacity, and that the pause is stop-the-world.
Add the causes you have seen and what each implies, and distinguish Pause lines from Concurrent lines when totalling pause time.
Read a sequence rather than a line: derive interval, survivor volume and trend, and know to pull gc+cpu when Real exceeds User+Sys.
Frame it as observability: which decorators and tags a fleet standardises on so GC lines can be correlated with request traces and incident timelines.
## Where the line comes from Since JDK 9 all HotSpot logging goes through *unified logging*, controlled by `-Xlog`. A GC line has three parts: decorators in square brackets, then the message. Decorators are chosen by you (`time`, `uptime`, `level`, `tags`, `pid`, `tid`); the default for `-Xlog:gc` is uptime, level and tags, which is exactly what the example shows. ## Field by field **`[3.216s]`** — the `uptime` decorator: seconds since JVM start. Add the `time` decorator if you need wall-clock timestamps to line up GC events with application logs or an incident timeline. Uptime alone is fine for measuring intervals between collections. **`[info]`** — the log level. GC lines you normally read are `info`; `debug` and `trace` levels expose per-phase and per-region detail and are opt-in because they are much noisier. **`[gc]`** — the tag set. Sub-systems tag their output: `gc`, `gc+heap`, `gc+cpu`, `gc+age`, `gc+ergo`, `gc+phases`. `-Xlog:gc*` selects all of them; `-Xlog:gc` selects only the top-level summary lines like this one. **`GC(7)`** — the collection sequence number, counting from 0 for the life of the JVM. Every line emitted for that collection carries the same id, so with `gc*` enabled you can gather the phase breakdown, the region counts and the CPU line for collection 7 even though they are interleaved with other output. **`Pause`** — this collection stopped every application thread. The counterpart is `Concurrent`, e.g. `Concurrent Mark Cycle`, which runs while application threads keep going and therefore is *not* a pause even though it appears in the log and takes wall-clock time. Beginners routinely add up concurrent durations and report a pause budget that never happened. **`Young (Normal)`** — the scope. In a G1 log you will also see `Young (Mixed)`, where some old regions are collected alongside the young ones, `Young (Prepare Mixed)`, `Young (Concurrent Start)`, and `Full`, which collects and compacts the entire heap. In Serial and Parallel logs the same slot reads simply `Young` or `Full`. **`(G1 Evacuation Pause)`** — the *cause*, i.e. why the JVM decided to collect now. Common causes and what they mean: - `G1 Evacuation Pause` / `Allocation Failure` — normal: a thread wanted memory and eden had none left. The word *failure* alarms people; it is the ordinary trigger of every young collection, not an error. - `G1 Humongous Allocation` — an object at least half a region in size forced a collection. - `Metadata GC Threshold` — class metadata space, not the Java heap, needed room. - `System.gc()` — application or a library called it explicitly. Worth chasing down. - `GCLocker Initiated GC` — a collection was deferred because a thread was inside a JNI critical section. - `Ergonomics` — the collector's own heuristics decided to act. **`512M->96M(1024M)`** — used-before → used-after (current capacity). The drop tells you how much died; the after value approximates the *live set* at that moment for a young collection (plus whatever old-generation data was already there). The capacity in parentheses is the currently committed heap, which can grow toward `-Xmx` or shrink; if it is far below `-Xmx`, the heap has not expanded yet. **`14.221ms`** — wall-clock duration of the stop-the-world portion. This is what your latency percentiles feel. It is *not* CPU time: the `gc+cpu` tag prints `User`, `Sys` and `Real` separately, and a Real much larger than User+Sys means the machine, not the collector, was the problem (CPU starvation, swapping, slow disk on the log write). ## Reading it as a whole One line rarely means anything; a sequence does. From consecutive lines you get the interval between collections, how much was allocated in between, how much survived each time, and whether the after-values trend upward. This single line says: at 3.2 seconds in, a routine young collection reclaimed ~416 MB in 14 ms. Healthy.
- The cause on a line reads `(Allocation Failure)`. Does that mean the JVM is running out of memory?No. Allocation Failure simply means a thread requested space in eden and eden was full, which is the normal trigger for every young collection. A healthy application produces thousands of them. Genuine exhaustion shows up as repeated Full GCs that reclaim almost nothing, and ultimately as an OutOfMemoryError.
- What is the difference between the number in parentheses and `-Xmx`?The parenthesised value is the currently *committed* heap capacity, which the JVM grows and shrinks between `-Xms` and `-Xmx` according to its heuristics. `-Xmx` is only the ceiling. Seeing a small capacity early in a run usually means the heap has simply not expanded yet, not that your maximum was ignored.
saying these in an interview costs you the question
- Reading `Allocation Failure` as an error or an imminent OutOfMemoryError.
- Treating `512M->96M(1024M)` as though the last number were the heap *used*, rather than the committed capacity.
- Adding `Concurrent ...` durations into a pause-time budget — they do not stop application threads.
- Assuming the duration is CPU time consumed by GC rather than wall-clock stop-the-world time.