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:
When you pass above arguments you will see the below output to be printed in garbage collection logs:
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:
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.
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:
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:
This command instructs the runtime to only guarantee a safepoint every 300 seconds (i.e. 5 minutes).
