• Post Reply Bookmark Topic Watch Topic
  • New Topic
programming forums Java Mobile Certification Databases Caching Books Engineering Micro Controllers OS Languages Paradigms IDEs Build Tools Frameworks Application Servers Open Source This Site Careers Other all forums
this forum made possible by our volunteer staff, including ...
Marshals:
  • Campbell Ritchie
  • Liutauras Vilda
  • Jeanne Boyarsky
  • Devaka Cooray
  • Paul Clapham
Sheriffs:
  • Tim Cooke
  • Knute Snortum
  • Bear Bibeault
Saloon Keepers:
  • Ron McLeod
  • Tim Moores
  • Stephan van Hulst
  • Piet Souris
  • Ganesh Patekar
Bartenders:
  • Frits Walraven
  • Carey Brown
  • Tim Holloway

Total time for which application threads were stopped

 
jim terry
Greenhorn
Posts: 22
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator



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).
 
With a little knowledge, a cast iron skillet is non-stick and lasts a lifetime.
  • Post Reply Bookmark Topic Watch Topic
  • New Topic
Boost this thread!