G1 garbage collector tuning

Question

I have an application running on Java 7 update 45 on Hotspot JVM. I am trying to tweak the parameters to work for a low latency application and below are the JVM parameters i set for this run. The timings in the individual steps in GC log (approx 25ms) does not add up to the pause time (>600ms). How do i know what is causing this pause time to be so high? In most of the collections they add up fine and are with in the pause time goal. I see such large pauses occasionally, one in 15-20 mins or so (not so regular though).

-server -Xmx2g -Xms2g -XX:PermSize=128m -XX:MaxPermSize=128m -XX:+UseG1GC -XX:MaxGCPauseMillis=30 -XX:ParallelGCThreads=9 -XX:ConcGCThreads=4 -XX:G1HeapRegionSize=4M -XX:InitiatingHeapOccupancyPercent=45 -XX:+PrintTLAB -XX:+AggressiveOpts -Xloggc:/integral/logs/gc.log -verbose:gc -XX:+PrintTenuringDistribution -XX:+PrintGCDateStamps -XX:+PrintAdaptiveSizePolicy -XX:+PrintGCDetails -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=3026 -Dcom.sun.management.jmxremote.local.only=false -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false"

2014-01-28T16:16:12.084+0000: 27507.054: Application time: 8.9506630 seconds
2014-01-28T16:16:12.084+0000: 27507.055: [GC pause (young)
Desired survivor size 81788928 bytes, new threshold 15 (max 15)
- age   1:    2299088 bytes,    2299088 total
- age   2:    1732832 bytes,    4031920 total
- age   3:    1748064 bytes,    5779984 total
- age   4:    1709368 bytes,    7489352 total
- age   5:    1732360 bytes,    9221712 total
- age   6:    1722776 bytes,   10944488 total
- age   7:    1712168 bytes,   12656656 total
- age   8:    1706240 bytes,   14362896 total
- age   9:    1692040 bytes,   16054936 total
- age  10:    1736008 bytes,   17790944 total
- age  11:    1566384 bytes,   19357328 total
- age  12:    1508456 bytes,   20865784 total
- age  13:    1491480 bytes,   22357264 total
- age  14:    1652136 bytes,   24009400 total
- age  15:    1502120 bytes,   25511520 total
 27507.055: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 12464, predicted base time: 7.97 ms, remaining time: 22.03 ms, target pause time: 30.00 ms]
 27507.055: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 298 regions, survivors: 9 regions, predicted young region time: 12.39 ms]
 27507.055: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 298 regions, survivors: 9 regions, old: 0 regions, predicted pause time: 20.36 ms, target pause time: 30.00 ms]
, 0.0236600 secs]
   [Parallel Time: 22.0 ms, GC Workers: 9]
      [GC Worker Start (ms): Min: 27507055.7, Avg: 27507057.0, Max: 27507058.7, Diff: 3.1]
      [Ext Root Scanning (ms): Min: 2.1, Avg: 3.8, Max: 5.2, Diff: 3.1, Sum: 34.4]
      [Update RS (ms): Min: 1.9, Avg: 2.3, Max: 3.0, Diff: 1.1, Sum: 20.8]
         [Processed Buffers: Min: 4, Avg: 11.7, Max: 23, Diff: 19, Sum: 105]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.2]
      [Object Copy (ms): Min: 12.9, Avg: 13.1, Max: 13.3, Diff: 0.3, Sum: 117.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.5, Max: 0.8, Diff: 0.8, Sum: 4.8]
      [GC Worker Total (ms): Min: 17.7, Avg: 19.9, Max: 21.5, Diff: 3.8, Sum: 178.8]
      [GC Worker End (ms): Min: 27507076.4, Avg: 27507076.9, Max: 27507077.2, Diff: 0.8]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.6 ms]
   [Eden: 1192.0M(1192.0M)->0.0B(1192.0M) Survivors: 36.0M->36.0M Heap: 1796.8M(2048.0M)->605.0M(2048.0M)]
 [Times: user=0.17 sys=0.00, real=0.64 secs] 
2014-01-28T16:16:12.719+0000: 27507.690: Total time for which application threads were stopped: 0.6354760 seconds