Почему G1 стоит столько времени на копирование объекта?

Ниже мой дс журнал:Почему G1 стоит столько времени на копирование объекта?

2016-08-16T01:45:35.968+0000: 62265.934: [GC pause (G1 Evacuation Pause) (young) 
Desired survivor size 473956352 bytes, new threshold 15 (max 15) 
- age 1: 12641224 bytes, 12641224 total 
- age 2: 3092400 bytes, 15733624 total 
- age 3: 1914704 bytes, 17648328 total 
- age 4:  204696 bytes, 17853024 total 
- age 5:  389896 bytes, 18242920 total 
- age 6:  101528 bytes, 18344448 total 
- age 7: 1106168 bytes, 19450616 total 
- age 8:  344336 bytes, 19794952 total 
- age 9:  301328 bytes, 20096280 total 
- age 10:  309576 bytes, 20405856 total 
- age 11:  305464 bytes, 20711320 total 
- age 12:  32672 bytes, 20743992 total 
- age 13:  41264 bytes, 20785256 total 
- age 14:  50960 bytes, 20836216 total 
- age 15:  56904 bytes, 20893120 total 
62265.934: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 7520, predicted base time: 185.93 ms, remaining time: 14.07 ms, target pause time: 200.00 ms] 
62265.934: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1793 regions, survivors: 9 regions, predicted young region time: 7.32 ms] 
62265.934: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1793 regions, survivors: 9 regions, old: 0 regions, predicted pause time: 193.25 ms, target pause time: 200.00 ms] 
2016-08-16T01:45:36.626+0000: 62266.592: [SoftReference, 0 refs, 0.0208511 secs]2016-08-16T01:45:36.647+0000: 62266.613: [WeakReference, 21 refs, 0.0101522 secs]2016-08-16T01:45:36.657+0000: 62266.623: [FinalReference, 5106 refs, 0.0153084 secs]2016-08-16T01:45:36.673+0000: 62266.639: [PhantomReference, 24 refs, 0 refs, 0.0473559 secs]2016-08-16T01:45:36.720+0000: 62266.686: [JNI Weak Reference, 0.0000260 secs], 0.7593297 secs] 
    [Parallel Time: 655.2 ms, GC Workers: 20] 
     [GC Worker Start (ms): Min: 62265934.2, Avg: 62265936.5, Max: 62265953.3, Diff: 19.0] 
     [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 8.7, Diff: 8.7, Sum: 17.9] 
     [Update RS (ms): Min: 0.0, Avg: 0.6, Max: 1.4, Diff: 1.4, Sum: 12.9] 
     [Processed Buffers: Min: 0, Avg: 6.2, Max: 24, Diff: 24, Sum: 125] 
     [Scan RS (ms): Min: 0.1, Avg: 0.3, Max: 0.5, Diff: 0.3, Sum: 6.2] 
     [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5] 
     [Object Copy (ms): Min: 0.0, Avg: 256.0, Max: 650.0, Diff: 650.0, Sum: 5119.2] 
     [Termination (ms): Min: 0.0, Avg: 394.2, Max: 637.9, Diff: 637.9, Sum: 7883.4] 
     [Termination Attempts: Min: 1, Avg: 2.5, Max: 9, Diff: 8, Sum: 51] 
     [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.4, Sum: 3.8] 
     [GC Worker Total (ms): Min: 635.7, Avg: 652.2, Max: 654.6, Diff: 18.9, Sum: 13043.7] 
     [GC Worker End (ms): Min: 62266588.5, Avg: 62266588.7, Max: 62266588.9, Diff: 0.4] 
    [Code Root Fixup: 0.2 ms] 
    [Code Root Purge: 0.0 ms] 
    [Clear CT: 1.4 ms] 
    [Other: 102.5 ms] 
     [Choose CSet: 0.0 ms] 
     [Ref Proc: 96.4 ms] 
     [Ref Enq: 1.6 ms] 
     [Redirty Cards: 1.1 ms] 
     [Humongous Register: 0.2 ms] 
     [Humongous Reclaim: 0.0 ms] 
     [Free CSet: 2.6 ms] 
    [Eden: 7172.0M(7172.0M)->0.0B(928.0M) Survivors: 36.0M->60.0M Heap: 7522.8M(11.7G)->375.5M(11.7G)] 
[Times: user=8.15 sys=3.37, real=0.76 secs]

И мои варианты Явы:

-server -Xms8G -Xmx12G -XX:+UnlockDiagnosticVMOptions -XX:G1HeapRegionSize=4m -Xss512K -XX:+HeapDumpOnOutOfMemoryError -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:ParallelGCThreads=20 -XX:ConcGCThreads=5 -XX:InitiatingHeapOccupancyPercent=70 -XX:+ParallelRefProcEnabled -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintReferenceGC -XX:+PrintAdaptiveSizePolicy -XX:+PrintTenuringDistribution -Xloggc:./gc.log

Кроме того, мой процессор имеет 16 cores.So после того, как я уменьшить ParallelGCThreads до 15, это вырезать молодым gc время наполовину. Но до сих пор эта проблема happend.And следующее новый журнал дс:

2016-08-22T07:42:58.651+0000: 65778.814: [GC pause (G1 Evacuation Pause) (young) 
Desired survivor size 322961408 bytes, new threshold 15 (max 15) 
- age 1: 6522744 bytes, 6522744 total 
- age 2: 2609200 bytes, 9131944 total 
- age 3: 1348504 bytes, 10480448 total 
- age 4:  557144 bytes, 11037592 total 
- age 5:  251744 bytes, 11289336 total 
- age 6:  972272 bytes, 12261608 total 
- age 7:  500232 bytes, 12761840 total 
- age 8: 2242544 bytes, 15004384 total 
- age 9:  116296 bytes, 15120680 total 
- age 10:  280728 bytes, 15401408 total 
- age 11:  85728 bytes, 15487136 total 
- age 12:  394272 bytes, 15881408 total 
- age 13:  295568 bytes, 16176976 total 
- age 14:  728600 bytes, 16905576 total 
- age 15: 1356328 bytes, 18261904 total 
65778.814: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 8112, predicted base time: 62.52 ms, remaining time: 137.48 ms, target pause time: 200.00 ms] 
65778.814: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1223 regions, survivors: 5 regions, predicted young region time: 7.95 ms] 
65778.814: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1223 regions, survivors: 5 regions, old: 0 regions, predicted pause time: 70.46 ms, target pause time: 200.00 ms] 
2016-08-22T07:43:02.747+0000: 65782.910: [SoftReference, 0 refs, 0.0021318 secs]2016-08-22T07:43:02.749+0000: 65782.912: [WeakReference, 4 refs, 0.0013452 secs]2016-08-22T07:43:02.750+0000: 65782.913: [FinalReference, 4029 refs, 0.0025002 secs]2016-08-22T07:43:02.753+0000: 65782.916: [PhantomReference, 11 refs, 0 refs, 0.0027905 secs]2016-08-22T07:43:02.756+0000: 65782.919: [JNI Weak Reference, 0.0000197 secs], 4.1088277 secs] 
    [Parallel Time: 4094.4 ms, GC Workers: 15] 
     [GC Worker Start (ms): Min: 65778814.7, Avg: 65778817.2, Max: 65778820.8, Diff: 6.1] 
     [Ext Root Scanning (ms): Min: 0.0, Avg: 0.6, Max: 1.5, Diff: 1.5, Sum: 9.2] 
     [Update RS (ms): Min: 0.0, Avg: 1.1, Max: 1.9, Diff: 1.9, Sum: 16.0] 
     [Processed Buffers: Min: 0, Avg: 8.7, Max: 27, Diff: 27, Sum: 130] 
     [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 3.0] 
     [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5] 
     [Object Copy (ms): Min: 4059.8, Avg: 4081.9, Max: 4090.2, Diff: 30.4, Sum: 61228.9] 
     [Termination (ms): Min: 0.0, Avg: 7.4, Max: 28.2, Diff: 28.2, Sum: 111.1] 
     [Termination Attempts: Min: 1, Avg: 1.3, Max: 3, Diff: 2, Sum: 19] 
     [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 1.6] 
     [GC Worker Total (ms): Min: 4087.8, Avg: 4091.4, Max: 4094.0, Diff: 6.2, Sum: 61370.5] 
     [GC Worker End (ms): Min: 65782908.5, Avg: 65782908.6, Max: 65782908.7, Diff: 0.2] 
    [Code Root Fixup: 0.2 ms] 
    [Code Root Purge: 0.0 ms] 
    [Clear CT: 0.8 ms] 
    [Other: 13.5 ms] 
     [Choose CSet: 0.0 ms] 
     [Ref Proc: 9.5 ms] 
     [Ref Enq: 0.8 ms] 
     [Redirty Cards: 0.8 ms] 
     [Humongous Register: 0.1 ms] 
     [Humongous Reclaim: 0.0 ms] 
     [Free CSet: 1.8 ms] 
    [Eden: 4892.0M(4892.0M)->0.0B(388.0M) Survivors: 20.0M->20.0M Heap: 5284.2M(8192.0M)->392.7M(8192.0M)] 
[Times: user=0.00 sys=62.51, real=4.11 secs]

источник

2016-08-16 bychjzh

Хотя G1 коллектор пытается чтить время Макс GC, это не жесткий предел, и он может легко пойти за это время. В одном случае может быть большой объект для копирования, или, по крайней мере, один из потоков потребовал много времени, чтобы выполнить его копии.

Если у вас менее 20 процессоров или другой процесс, что означает, что у вас меньше 20 бесплатных CPU, поток GC может быть расписано довольно долго, прежде чем он получит шанс снова и снова запустить.

Если посмотреть на

user=8.15 sys=3.37, real=0.76 secs

Это наводит на мысль вы использовали 11,52 секунду CPU в 0,76 секунде, что означает, что вы только имели около 15,1 процессоров, работающими одновременно, так что про 5 из них не может работать в среднем.

Я бы постарался сократить количество процессоров до 15, чтобы у вас не было больше потоков, чем у вас есть свободные процессоры.

источник

2016-08-16 07:30:04

Спасибо за ваш ответ! На самом деле мой процессор 16 ядер, я уменьшил 'ParallelGCThreads' до 15, он сократил юное время gc наполовину, здорово! Но эта проблема все еще случается, может ли это вызвать какой-либо другой фактор? – bychjzh

@bychjzh можете ли вы включить журнал после того, как вы настроили cpus? –

@bychjzh У вас есть «[Times: user = 0.00 sys = 62.51, real = 4.11 secs]», который указывает, что все время было потрачено на ядро, скорее всего, оно сильно менялось. Я бы проверял, что у вас много свободной памяти. –

Почему G1 стоит столько времени на копирование объекта?

ответ

Смежные вопросы