Safepoint
Lot of us know that JVM pauses entire application for garbage collection. But there are also other reasons for which JVM pauses application. For certain VM operations, certain JVMTI operations and JIT actions JVM pauses the application. Here are few such cases:

  • Unloading of classes
  • Moving Objects around to fix memory defragmentation
  • Code Deoptimization
  • Flushing code cache
  • Class redefinition (e.g. hot swap or instrumentation)
  • Biased lock revocation

:
:

In order to pause all the application threads needs to be safely stopped. The point in which application threads are safely stopped are called ‘Safepoint’. Apt name isn’t it?

You can learn how much time application threads are stopped in Safepoint, by passing following arguments to JVM:

XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

When you pass above arguments you will see the below output to be printed in garbage collection logs:

16.827: Total time for which application threads were stopped: 0.0010093 seconds, Stopping threads took: 0.0001973 seconds

Above statement basically tells that after 16.827 seconds since application was started, application threads were stopped for 1 millisecond (i.e. 0.0010093 seconds) and amount of time it took to stop the threads was: 197.3 microseconds (i.e. 0.0001973 seconds). This pause time is acceptable. But sometimes we have seen cases where application threads are stopped for several seconds. Example:

4279.344: Total time for which application threads were stopped: 12.4744981 seconds, Stopping threads took: 12.3604520 seconds

Here you can notice application threads to be stopped for 12.47 seconds and it took 12.36 seconds to stop the running threads. This is a very high pause time. (Note: It might be hard to keep track of safepoint duration, especially when you are parsing thousands/millions of log statements. That’s when garbage collection log analysis tools like GCeasy comes handy. GCeasy tool catches and reports safepoints that pauses for long duration.)

Now we learned how to measure safepoint duration. Next step is to learn the reasons that are triggering these safepoints.

-XX:+PrintSafepointStatistics  -XX:PrintSafepointStatisticsCount=1

When you pass above JVM arguments to your application, reasons that are triggering safepoints will be reported in the GC logs. Below output to will be printed in garbage collection logs:

vmop[threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
 
7044.693: RevokeBias [ 423 2 4 ] [ 11608 0 11611 3 98 ] 2

Now let’s try to understand this statement:

7044.693 – number of seconds since JVM has been started this safepoint operation has occurred.

RevokeBias – vmop – is the VM operation for which threads are moved to this safepoint.

423 – total – Total number of threads that are stopped in safepoint

2 – initially_running – Number of threads which contributed to the “spin” time explained in below section

4 – wait_to_block – Number of threads which contributed to the “block” time explained in below section

Next part shows the breakdown of timing in milliseconds at various stages to arrive to safe point.

11608 – spin – time it took for all spinning/executing threads to reach safepoint (in milliseconds)

0 – block – time it took for all the Blocked threads to reach safepoint (in milliseconds)

11611 – sync – total time it took for all threads to reach safepoint (in milliseconds)

3 – cleanup – time spent in internal VM cleanup activities (in milliseconds)

98 – vmop – time spent in the operation itself (RevokeBias in this case).

2 – page_trap_count – Page trap count

no vm operation

If you see “no vm operation” to be printed in ‘vmop’ field, then it’s called as “guaranteed safepoint”. It’s triggered by JVM runtime itself to process all queued-up operations that are not urgent. It can be controlled by passing ‘GuaranteedSafepointInterval’ JVM argument:

-XX:GuaranteedSafepointInterval=300000

This command instructs the runtime to only guarantee a safepoint every 300 seconds (i.e. 5 minutes).

Reference article: Total time for which application threads were stopped