1

Java's garbage collector (GC) does not always stop the main thread. It may block all threads, or just run in parallel without pausing the other threads.

I can measure the total garbage collection time either by using garbageCollectorMXBean.getCollectionTime(); at the end of the program, or by running the VM with -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -verbose:gc.

However, I want to measure the portion of GCs during which the main thread is blocked (i.e. paused), so that I can measure the exact time that the main thread has been running. Is it possible to measure it?

Ali
  • 443
  • 4
  • 15
  • Please edit the question to clarify whether you want to measure GC pauses or the running time of the main thread. These are two completely different metrics, and one does not derive from the other. – apangin Jul 09 '17 at 21:52
  • The time 1) when the main thread was not stopped by GC, or 2) was not in a VM safepoint, or 3) was actually running on a CPU - these are all different times. – apangin Jul 09 '17 at 21:57

4 Answers4

3

I guess your question boils down to measuring the "the exact time that the main thread has been running". In order to get to know this you don't need to measure the blocking time of the garbage collector.

The time a thread has been running corresponds to its CPU time. If you also want to consider the time waiting for I/O, then this approach won't work for you, but then the time the garbage collector pauses your thread should be negligible anyways.

I put together a simple proof of concept for you:

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;
import java.util.concurrent.TimeUnit;

public class CpuTime
{
    public static void main(String[] args) {

        // We obtain the thread mx bean and check if it support CPU time measuring.
        final ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
        if (!threadMxBean.isThreadCpuTimeSupported())
            throw new IllegalStateException("CPU time not supported on this platform");

        // This is important because the default value is platform-dependent.
        threadMxBean.setThreadCpuTimeEnabled(true);

        // Now we start the measurement ...
        final long threadId = Thread.currentThread().getId();
        final long wallTimeStart = System.nanoTime();
        final long cpuTimeStart = threadMxBean.getThreadCpuTime(Thread.currentThread().getId());

        // ... and do stupid things to give the garbage collector some work.
        for (int i = 0; i < 1_000_000_000; i++) {
            Long l = new Long(i);
        }

        // Finally we measure the cpu and wall time.
        final long wallTime = System.nanoTime() - wallTimeStart;
        final long cpuTime = threadMxBean.getThreadCpuTime(threadId) - cpuTimeStart;

        System.out.println("CPU time:  " + TimeUnit.NANOSECONDS.toMillis(cpuTime));
        System.out.println("Wall time: " + TimeUnit.NANOSECONDS.toMillis(wallTime));
    }
}

Please note that this approach needs some tweaking for absolutely precise results. It should however get you started.

Björn Zurmaar
  • 826
  • 1
  • 9
  • 22
  • Thanks, very impressive. Nevertheless, my program is a data-management algorithm with lots of CPU & IO. The problem is that lots of data is read from IO, which is causing the GC to be very active, but also there is considerable amount of computation, which makes it complicated to measure the exact times :-( – Ali Jul 09 '17 at 00:40
  • Take a look at https://github.com/aragozin/jvm-tools it is "productionized" version of this snippet showing you both CPU and Allocation rate per thread in real time. It tracks GC too. – Alexey Ragozin Jul 09 '17 at 04:07
2

Use -XX:+PrintGCApplicationStoppedTime and/or -XX:+PrintGCApplicationConcurrentTime

apangin
  • 92,924
  • 10
  • 193
  • 247
  • Unfortunately `-XX:+PrintGCApplicationStoppedTime` does not exactly what its name suggests. See e.g. https://stackoverflow.com/questions/29666057/analysis-on-gc-logs/29673564#29673564. Also this does not work on a per thread basis, does it? – Björn Zurmaar Jul 09 '17 at 12:45
  • @BjörnZurmaar Yes, I know (at least, because I've written the answer you are referring to :) Java developers are usually interested in a pause time, no matter if it is a GC pause or not. But it's not quite clear what was meant in the original question - I asked for clarification. – apangin Jul 09 '17 at 22:07
  • It was one of the reasons to link to this answer that you were the author. I just referred to it to make this question's author aware of this. =) – Björn Zurmaar Jul 09 '17 at 22:32
1

Besides GC logs and MBean, there also JVM's perf counter exposing relevant information.

jcmd.exe PID PerfCounter.print | grep "sun.rt.safepointTime" command would show your cumulative elapsed time JVM was in Stop-the-World state since its start.

Alexey Ragozin
  • 8,081
  • 1
  • 23
  • 23
0

You may want to look at jHiccup, https://www.azul.com/jhiccup/ (free and open source). This measures the effect of everything other than your application on your application's performance. You can use this data to calculate the aggregate time that the main thread has not been running due to JVM, etc. effects (like GC). However, this won't measure pauses of the main thread caused by it being blocked by other application threads.

Speakjava
  • 3,177
  • 13
  • 15