Analyzing Gc Logs

Java GC log analysis

PSYoungGen refers to the garbage collector in use for the minor
collection. PS stands for Parallel Scavenge.

Ref: Java Garbage Collection Log messages

Analyzing gc logs

Unfortunately PrintGCApplicationStoppedTime is misleading name for this JVM option.

In fact it prints the time spent inside safepoints. Safepoint pauses occur not only due to Garbage Collection, but for many other reasons:

Deoptimization
Biased lock revocation
Thread dump
Heap inspection
Class redifinition
etc. (see the list)

Safepoints may happen periodically even without a requested VM operation in order to deflate idle monitors, perform certain JIT cleanup and so on.
See -XX:GuaranteedSafepointInterval VM option (1000 milliseconds by default).

Use -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 to dump more information about safepoints.

Know of any Java garbage collection log analysis tools?

IBM's GC toolkit does exactly what you ask.

https://www.ibm.com/developerworks/java/jdk/tools/gcmv/

I'm not sure if it's compatible with GC logs from Sun's JVM though.

JVM G1 GC logs analyze

Heap layout printed at the bottom of GC log indicates that your Java process has terminated.

Heap layout is printed in two situations: before/after GC, if -XX:+PrintHeapAtGC is specified, and before JVM exits. In your case it is obviously the latter.

JVM exited almost immediately after start (it was running only for 281 milliseconds). Most likely, it either failed to start an application (check the VM output), or it did something very simple, i.e. just launched a new subprocess.

Note that a new JVM process overwrites the previosly written log file.

G1 garbage collector log analyzer

Try GCViewer.

The fork on GitHub includes support for newer Garbage Collectors (including G1).

How to interpret GC Activity graph in JProfiler?

By default, my understanding is that the sum/integrale of the GC Activity curve is an estimate of the total percent of cpu used to collect data.

It should be, yes.

So here that would mean much less than the max 2%

max is deceptive here. If you make your sampling interval small enough the maximum will be 100% of a time slice spent on GCing. That is when that slice is smaller than a GC pause duration. So those peaks are already averages over some larger time slices.

How should I understand that ?

That your application probably isn't spending much time on GC. But your graph only covers a relatively small amount of time, so it might not reflect major collections or concurrent cycles. Interpreting the JVM's GC logs will provide more details if you care about latency and not just throughput.