G1 garbage collector long pause no idea

Question

I am trying to tune my application for responsiveness, maximum permissible GC pause is 40 ms. Couldn't understand why this pause took approx 900 ms time. Application is low latency application meant to serve high QPS.

GC params: -Xmx5G -XX:+UseG1GC -XX:MaxGCPauseMillis=40

Logs:

2014-10-02T16:31:08.508+0530: 2072.186: [GC pause (young)  
Desired survivor size 148373504 bytes, new threshold 15 (max 15)  
- age   1:   10600184 bytes,   10600184 total  
- age   2:      67024 bytes,   10667208 total  
- age   3:      44560 bytes,   10711768 total  
- age   4:       3520 bytes,   10715288 total  
- age   5:       4080 bytes,   10719368 total  
- age   6:       4464 bytes,   10723832 total  
- age   7:       2568 bytes,   10726400 total  
- age   8:       4872 bytes,   10731272 total  
- age   9:       3216 bytes,   10734488 total  
- age  10:       2400 bytes,   10736888 total  
- age  11:       2024 bytes,   10738912 total  
- age  12:       3144 bytes,   10742056 total  
- age  13:       8584 bytes,   10750640 total  
- age  14:       2672 bytes,   10753312 total  
- age  15:        696 bytes,   10754008 total  
, 0.0384210 secs]  
   [Parallel Time: 15.2 ms, GC Workers: 15]  
      [GC Worker Start (ms): Min: 2072186.5, Avg: 2072186.5, Max: 2072186.6, Diff: 0.1]  
      [Ext Root Scanning (ms): Min: 1.0, Avg: 1.0, Max: 1.1, Diff: 0.1, Sum: 15.2]  
      [Update RS (ms): Min: 0.3, Avg: 0.4, Max: 0.4, Diff: 0.1, Sum: 5.7]  
         [Processed Buffers: Min: 1, Avg: 3.3, Max: 5, Diff: 4, Sum: 49]  
      [Scan RS (ms): Min: 0.5, Avg: 0.5, Max: 0.6, Diff: 0.1, Sum: 7.8]  
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]  
      [Object Copy (ms): Min: 12.8, Avg: 12.9, Max: 13.0, Diff: 0.2, Sum: 193.0]  
      [Termination (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.7]  
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.4]  
      [GC Worker Total (ms): Min: 14.9, Avg: 15.0, Max: 15.1, Diff: 0.2, Sum: 225.1]  
      [GC Worker End (ms): Min: 2072201.5, Avg: 2072201.5, Max: 2072201.6, Diff: 0.1]  
   [Code Root Fixup: 0.2 ms]  
   [Code Root Migration: 0.6 ms]  
   [Clear CT: 0.8 ms]  
   [Other: 21.6 ms]  
      [Choose CSet: 0.0 ms]  
      [Ref Proc: 14.2 ms]  
      [Ref Enq: 0.6 ms]  
      [Free CSet: 6.6 ms]  
   [Eden: 2244.0M(2244.0M)->0.0B(2571.0M) Survivors: 19.0M->10.0M Heap: 2443.7M(5120.0M)->191.4M(5120.0M)]  
 [Times: user=0.26 sys=0.00, real=0.90 secs]   
2014-10-02T16:31:09.406+0530: 2073.085: Total time for which application threads were stopped: 0.8992240 seconds  

java -version:
java version "1.7.0_60"
Java(TM) SE Runtime Environment (build 1.7.0_60-b19)
Java HotSpot(TM) 64-Bit Server VM (build 24.60-b09, mixed mode)

Please help me to understand what caused such long pause? And how to prevent it ?

Answer 1

From what I can tell, the process got blocked during gc, meaning it had to wait for ressources.

This line tells you the execution time:

[Times: user=0.26 sys=0.00, real=0.90 secs]

With

• user meaning pure cpu time.
• sys meaning kernel time.
• real meaning real world time.

The time messured by the java gc is below 40ms, see this line:

, 0.0384210 secs]  

Such a block can occur when:

• Doing IO heavy operations (e.g. Network, Disks)
• Another process on the system is causing high load on one of the needed ressources

In your case I'd figure that there must've been something else eating up CPU time, but it's hard to tell.

Addition:

Another thing that could have happened is that the gc tried to access memory that has already been swapped to the disk causing long blocking IO operations. I don't know how likely that is though, so I might be completely wrong here.