Large 'sync' value for ParallelGCFailedAllocation

3
votes

Sometimes I see long pauses in my gc.log

2014-07-18T18:42:26.137+0400: 7846.980: [GC [PSYoungGen: 86267K->10032K(87744K)] 251198K-175254K(272512K), 0.0066190 secs] [Times: user=0.08 sys=0.00, real=0.01 secs]

Total time for which application threads were stopped: 0.6394170 seconds

Total time for which application threads were stopped: 0.0014570 seconds

But these pauses don't affect GC time and CPU usage time.

Safepoint statistics (+XX:PrintSafePointStatistics):

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count 7846.348: ParallelGCFailedAllocation [ 370 0 2 ] [ 0 0 630 1 7 ] 0

(sync time = 630ms) What does 'sync' mean in this context?

2
performancegarbage-collectionjvm

2 Answers

8
votes

sync here is the total time spent to reach a safepoint. In other words, it is the latency between the safepoint request and the moment when all runnable Java threads are finally blocked.

The safepoint synchronization may sometimes take too long due to one of the following reasons:

  • The application does not receive enough CPU time because the OS is busy with intensive disk I/O or when it starts swapping or when another high-priority process takes all CPU time.
  • Some Java thread performs long non-interruptible operation, e.g. copies large amount of data using System.arraycopy(), clone(), ByteBuffer.get() etc.
  • MappedByteBuffer I/O.

To log the names of the threads that could not get blocked on a safepoint in 500 ms use

-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=500
0
votes

There's another option now: async-profiler has an option to attach to a JVM and only record samples while threads are stopping for a safepoint: -ttsp