Measuring time spent on GC in JVM

Question

Suppose I am testing a Java server application. I know how much time it takes to finish the test. Now I'd like to know how much was spent on GC during that test. How can I do it?

Solution 1

The simplest way is to use the -Xloggc and -XX:-PrintGCTimeStamps options when starting up your JVM. I think it prints out how long garbage collection takes.

http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html

Solution 2

I guess that when GC (Garbage Collector) is working the application stops and resumes when GC finishes

I don't think that is a safe assumption. Are you sure the garbage collector is not working in parallel with your application code?

To measure the time spent in collecting garbage you can query the Garbage Collector MXBean.

Try this:

public static void main(String[] args)  {
    System.out.println("collectionTime = " + getGarbageCollectionTime());
}

private static long getGarbageCollectionTime() {
    long collectionTime = 0;
    for (GarbageCollectorMXBean garbageCollectorMXBean : ManagementFactory.getGarbageCollectorMXBeans()) {
        collectionTime += garbageCollectorMXBean.getCollectionTime();
    }
    return collectionTime;
}

Solution 3

This performance metric is recorded by the JVM, and made accessible through JMX. For interactive monitoring, connect to the running JVM with JConsole, and in the "VM Summary" Tab it will say something like:

Garbage collector: Name = 'Copy', Collections = 26, Total time spent = 0.183 seconds Garbage collector: Name = 'MarkSweepCompact', Collections = 2, Total time spent = 0.168 seconds

You can also query JMX programatically.

Solution 4

Another convenient solution is to run jstat -gc (documentation) against your process when your tests are done. That will give you nice aggregated output on exactly how much time has been spent in GC during the lifetime of your JVM.

Solution 5

Enable garbage collection logs. As documented, you can use -verbose:gc, -XX:+PrintGCDetails and -XX:+PrintGCTimeStamps flags. -Xloggc flag can be used to direct those to a file.

Resulting logs are human-readable, but for most benefit you probably want them to be run through an analyzer. Such tools are listed in this thread.

View more solutions

Comments

[Pedro Dusso]

This answer is super. I have being executing many tests over GC and the values provided by the GarbageCollectorMXBean are absolutely the same compared to the log written by the JVM args.

[cdalxndr]

When does getGarbageCollectorMXBeans() return multiple mx beans?

[cdalxndr]

When does getGarbageCollectorMXBeans() return multiple mx beans?

[Markus Weninger]

I cannot test it at the moment, but I am pretty sure this happens if two different collectors are used for minor and major collections respectivly.