2

I have JVM option -XX:+PrintGCApplicationStoppedTime which prints real "GC stop the world time".

Example:

  • Total time for which application threads were stopped: 0.0018219 seconds
  • Total time for which application threads were stopped: 0.0016542 seconds
  • Total time for which application threads were stopped: 0.0015797 seconds

I need to calculate "GC stop the world" by java code. How can I do it ?

Artem Zatsev
  • 21
  • 1
  • 3

1 Answers1

4

Please note that PrintGCApplicationStoppedTime prints safepoint time rather than GC time.
See this answer for details.

You can get cumulative time of safepoints through JDK-specific (i.e. unsupported) MXBean. This value is equal to the sum of all numbers printed in Total time for which application threads were stopped messages.

sun.management.HotspotRuntimeMBean runtime =
        sun.management.ManagementFactoryHelper.getHotspotRuntimeMBean();

System.out.println("Safepoint time:  " + runtime.getTotalSafepointTime() + " ms");
System.out.println("Safepoint count: " + runtime.getSafepointCount());
Community
  • 1
  • 1
apangin
  • 92,924
  • 10
  • 193
  • 247
  • This code do the same as: for (GarbageCollectorMXBean gc : ManagementFactory.getGarbageCollectorMXBeans()) { log.info("Time: bean={} time={} count={}", gc.getName(), gc.getCollectionCount(), gc.getCollectionCount()); } I need exactly value from "Total time for which application threads were stopped: VALUE seconds" and "Stopping threads took: VALUE second. – Artem Zatsev Mar 03 '17 at 11:44
  • @ArtemZatsev No, `GarbageCollectorMXBean` values are different. 1) Concurrent GC time is not included in "application threads were stopped". 2) Safepoint pauses occur not only during GC, but also for [many other reasons](http://stackoverflow.com/questions/29666057/analysis-on-gc-logs/29673564#29673564). – apangin Mar 03 '17 at 14:14
  • It's not clear which value you want. The last one? Or all values? – apangin Mar 03 '17 at 14:16
  • @AndreiPangin I need value exactly as in "Total time for which application threads were stopped: 0.0018219 seconds". I need this "0.0018219" value. Maybe you have some ideas how to get it ? – Artem Zatsev Mar 06 '17 at 14:19
  • @ArtemZatsev Mmm. Seems like your intentions are not quite clear even to yourself. Look at the original question - there are three "application threads were stopped" messages. Which value do you want? The last one (0.0015797)? It may be useless if you miss previous two. You cannot get all values, because JVM does not save them anywhere. However, you can get cumulative value or the difference between two arbitrary points using the technique described in the answer. – apangin Mar 06 '17 at 17:37
  • @AndreiPangin Ok. But, maybe you know how to get correct stop the world time ? – Artem Zatsev Mar 07 '17 at 12:03
  • 2
    @ArtemZatsev This depends on what you mean by "correct". `runtime.getTotalSafepointTime()` returns quite precise stop-the-world counter. This is what I personally use for monitoring production systems. Just read this counter periodically and subtract two subsequent values. – apangin Mar 07 '17 at 15:18
  • GC log file can give you a history of STW pauses, but for some reason it does not suit you. If you'd like to receive synchronous notifications about STW pauses, you'll have to patch [`RuntimeService::record_safepoint_end()`](http://hg.openjdk.java.net/jdk8u/jdk8u/hotspot/file/e765322578aa/src/share/vm/services/runtimeService.cpp#l150) and rebuild HotSpot JVM from sources. – apangin Mar 07 '17 at 15:18
  • @AndreiPangin Understand. Thank You a lot ! – Artem Zatsev Mar 08 '17 at 11:38