Why does G1 collertor cost so much time for object copy

1k views Asked by At

My java options is :

java -Dsun.zip.disableMemoryMapping=true -Xmx18g -Xms8g -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:InitiatingHeapOccupancyPercent=45 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.log -XX:NewSize=1500m -XX:MaxNewSize=1500m

Here is my gc logs:

    2016-12-22T09:45:51.567+0800: 145356.468: [GC pause (G1 Evacuation Pause) (young), 4.0553815 secs]
        [Parallel Time: 4052.5 ms, GC Workers: 28]
          [GC Worker Start (ms): Min: 145356469.0, Avg: 145356469.4, Max: 145356469.9, Diff: 0.9]
          [Ext Root Scanning (ms): Min: 0.6, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 29.1]
          [Update RS (ms): Min: 12.0, Avg: 12.4, Max: 13.2, Diff: 1.2, Sum: 348.4]
             [Processed Buffers: Min: 9, Avg: 13.5, Max: 24, Diff: 15, Sum: 379]
          [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 2.3]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 1.1]
          [Object Copy (ms): Min: 28.7, Avg: 1927.0, Max: 4037.8, Diff: 4009.1, Sum: 53956.0]
          [Termination (ms): Min: 0.0, Avg: 2111.2, Max: 4009.0, Diff: 4009.0, Sum: 59114.4]
             [Termination Attempts: Min: 1, Avg: 2.2, Max: 5, Diff: 4, Sum: 63]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 2.0]
          [GC Worker Total (ms): Min: 4051.4, Avg: 4051.9, Max: 4052.4, Diff: 1.0, Sum: 113453.2]
          [GC Worker End (ms): Min: 145360521.3, Avg: 145360521.3, Max: 145360521.4, Diff: 0.1]
       [Code Root Fixup: 0.1 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.4 ms]
       [Other: 2.4 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 0.4 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.5 ms]
          [Humongous Register: 0.1 ms]
          [Humongous Reclaim: 0.0 ms]
          [Free CSet: 0.6 ms]
       [Eden: 1424.0M(1424.0M)->0.0B(1416.0M) Survivors: 76.0M->84.0M Heap: 3475.6M(8192.0M)->2071.7M(8192.0M)]
     [Times: user=54.84 sys=56.91, real=4.06 secs] 

My cpu has 40 cores, sometimes gc cause much time. I found most time spent in Object Copy, i wonder in which case, it will happen, and what can i do to optimize gc ...

[Object Copy (ms): Min: 28.7, Avg: 1927.0, Max: 4037.8, Diff: 4009.1, Sum: 53956.0] max is much bigger than min, maybe i can minus the gc workers ??

1

There are 1 answers

1
wangzhiju On

I use -XX:LargePageSizeInBytes=32m and move the service to another linux server (i found cpu running queue sometimes is big). And then no more than 1 sec gc was found .