Search code examples
javamultithreadinggarbage-collectiongarbage

Understanding GC logs - app thread were stopped


Taking a look at GC log file, its self-explanatory to understand that app was stopped for 0.0011450 seconds (stop-the-world)

Total time for which application threads were stopped: 0.0011450 seconds

However, please help me understand whether below lines also means stop-the-world? Or it just shows the time taken by each thread, what does real=TIME means (last line below)?

Finished work stealing in 3th thread: 13.706 sec
Finished work stealing in 2th thread: 17.325 sec
Finished work stealing in 4th thread: 17.052 sec
Finished work stealing in 0th thread: 17.325 sec
Finished work stealing in 1th thread: 17.324 sec
2015-08-19T03:20:32.882-0400: 321985.669: [CMS-concurrent-mark: 20.519/20.624 secs] (CMS-concurrent-mark yielded 6 times)
 [Times: user=138.91 sys=0.10, real=20.62 secs] 

Solution

  • This oracle blog post is the first result when googling "CMS-concurrent-mark" and explains the various CMS phases.

    Running the log through GCviewer would also list STW and non-STW phases separately.

    And since you already have turned on application-stopped-time logging the lack of a stopped time logging entry should be a dead giveaway whether it's a STW-pause or not.

    what does real=TIME means (last line below)?

    This output is equivalent to output you would get from time for example. Also see this SO answer. Or this one specifically referring to CMS logs.