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?

Answer 1

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;
}

Answer 2

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.

Answer 3

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.

Answer 4

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.

Answer 5

There are different GC algorithms that behave differently. I recently read a good article on the subject that I can recommend if you'd like to know more.

You can launch your application with the following command line options -verbose:gc -XX:+PrintGCDateStamps -XX:+PrintGCDetails and get information about GC.

Here's an example of the log message:

2012-12-17T03:02:15.590-0500: [GC [PSYoungGen: 40934K->2670K(29440K)] 48211K->14511K(73152K), 0.5745260 secs] [Times: user=0.08 sys=0.01, real=0.58 secs]

Answer 6

Similar to @Steve McLeod's answer that uses ManagementFactory, since Java 8 this can also be written in a single line using Java streams:

long collectionTime = ManagementFactory.getGarbageCollectorMXBeans().stream().mapToLong(mxBean -> mxBean.getCollectionTime()).sum();