2017-03-02 3 views
1

私は最近アップグレードされたアプリケーションで作業しています。私は非常に説明できない新しい動作を見ています。コレクションのパターンはまあまあですが、数秒以内に10個のG1避難コレクション(ヤング)を連続して実行します。彼らはエデンの記憶をクリアしているようだが、なぜそれがすぐに満ちているのか分からない。ラピッドヤングG1避難コレクション

これは複雑な問題ですか、何か間違っていますか? (あまりにも多くの詳細を投稿した場合は、編集して削除することができます)。

-XX:+UseG1GC -Xms10240m -Xmx10240m -XX:NewRatio=2 -XX:NewSize=1792m -XX:G1ReservePercent=30 -XX:+AggressiveOpts 

GCViewer あなたはこのスクリーンショットを見れば、あなたは若い世代のコレクションが矢継ぎ早に起こるほぼ固体青い線を見ることができます。

 

    2017-03-02T12:27:08.527-0800: 48187.087: [GC pause (G1 Evacuation Pause) (young) 
    Desired survivor size 299892736 bytes, new threshold 15 (max 15) 
    - age 1: 6684488 bytes, 6684488 total 
    - age 2: 15234432 bytes, 21918920 total 
    - age 3: 5530024 bytes, 27448944 total 
    - age 4: 5502152 bytes, 32951096 total 
    - age 5: 4490976 bytes, 37442072 total 
    - age 6: 1736456 bytes, 39178528 total 
    - age 7: 2849184 bytes, 42027712 total 
    - age 8: 2600504 bytes, 44628216 total 
    - age 9: 1793032 bytes, 46421248 total 
    - age 10: 1996752 bytes, 48418000 total 
    - age 11:  876104 bytes, 49294104 total 
    - age 12: 2233720 bytes, 51527824 total 
    - age 13: 1218392 bytes, 52746216 total 
    - age 14:  903760 bytes, 53649976 total 
    - age 15: 1774480 bytes, 55424456 total 
    , 0.0369978 secs] 
     [Parallel Time: 32.2 ms, GC Workers: 8] 
      [GC Worker Start (ms): Min: 48187087.1, Avg: 48187087.2, Max: 48187087.3, Diff: 0.2] 
      [Ext Root Scanning (ms): Min: 4.4, Avg: 6.5, Max: 12.0, Diff: 7.7, Sum: 51.9] 
      [Update RS (ms): Min: 4.0, Avg: 8.5, Max: 9.6, Diff: 5.6, Sum: 68.3] 
      [Processed Buffers: Min: 8, Avg: 13.4, Max: 19, Diff: 11, Sum: 107] 
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.9] 
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] 
      [Object Copy (ms): Min: 15.4, Avg: 16.6, Max: 17.8, Diff: 2.4, Sum: 132.5] 
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 
      [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8] 
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8] 
      [GC Worker Total (ms): Min: 31.9, Avg: 31.9, Max: 32.0, Diff: 0.2, Sum: 255.6] 
      [GC Worker End (ms): Min: 48187119.1, Avg: 48187119.2, Max: 48187119.3, Diff: 0.1] 
     [Code Root Fixup: 0.4 ms] 
     [Code Root Purge: 0.0 ms] 
     [Clear CT: 0.7 ms] 
     [Other: 3.7 ms] 
      [Choose CSet: 0.0 ms] 
      [Ref Proc: 0.8 ms] 
      [Ref Enq: 0.0 ms] 
      [Redirty Cards: 0.2 ms] 
      [Humongous Register: 0.2 ms] 
      [Humongous Reclaim: 0.1 ms] 
      [Free CSet: 1.8 ms] 
     [Eden: 4508.0M(4508.0M)->0.0B(4516.0M) Survivors: 68.0M->64.0M Heap: 7036.0M(10.0G)->2524.1M(10.0G)] 
    [Times: user=0.26 sys=0.00, real=0.04 secs] 

 

    2017-03-02T12:27:09.078-0800: 48187.638: [GC pause (G1 Evacuation Pause) (young) 
    Desired survivor size 301989888 bytes, new threshold 15 (max 15) 
    - age 1:  31144 bytes,  31144 total 
    - age 2: 6631192 bytes, 6662336 total 
    - age 3: 15225176 bytes, 21887512 total 
    - age 4: 5530024 bytes, 27417536 total 
    - age 5: 5501976 bytes, 32919512 total 
    - age 6: 4490976 bytes, 37410488 total 
    - age 7: 1736456 bytes, 39146944 total 
    - age 8: 2849184 bytes, 41996128 total 
    - age 9: 2600504 bytes, 44596632 total 
    - age 10: 1793032 bytes, 46389664 total 
    - age 11: 1996752 bytes, 48386416 total 
    - age 12:  876104 bytes, 49262520 total 
    - age 13: 2233720 bytes, 51496240 total 
    - age 14: 1218392 bytes, 52714632 total 
    - age 15:  903760 bytes, 53618392 total 
    , 0.0320568 secs] 
     [Parallel Time: 28.0 ms, GC Workers: 8] 
      [GC Worker Start (ms): Min: 48187638.4, Avg: 48187638.5, Max: 48187638.6, Diff: 0.2] 
      [Ext Root Scanning (ms): Min: 3.8, Avg: 5.4, Max: 11.2, Diff: 7.4, Sum: 43.4] 
      [Update RS (ms): Min: 2.4, Avg: 7.4, Max: 8.7, Diff: 6.3, Sum: 59.2] 
      [Processed Buffers: Min: 7, Avg: 11.6, Max: 15, Diff: 8, Sum: 93] 
      [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 1.9] 
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] 
      [Object Copy (ms): Min: 13.6, Avg: 14.6, Max: 15.0, Diff: 1.3, Sum: 116.5] 
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 
      [Termination Attempts: Min: 1, Avg: 1.9, Max: 3, Diff: 2, Sum: 15] 
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8] 
      [GC Worker Total (ms): Min: 27.6, Avg: 27.7, Max: 27.8, Diff: 0.3, Sum: 221.9] 
      [GC Worker End (ms): Min: 48187666.2, Avg: 48187666.3, Max: 48187666.3, Diff: 0.1] 
     [Code Root Fixup: 0.3 ms] 
     [Code Root Purge: 0.0 ms] 
     [Clear CT: 0.7 ms] 
     [Other: 3.0 ms] 
      [Choose CSet: 0.0 ms] 
      [Ref Proc: 0.5 ms] 
      [Ref Enq: 0.0 ms] 
      [Redirty Cards: 0.2 ms] 
      [Humongous Register: 0.2 ms] 
      [Humongous Reclaim: 0.1 ms] 
      [Free CSet: 1.6 ms] 
     [Eden: 4516.0M(4516.0M)->0.0B(4520.0M) Survivors: 64.0M->60.0M Heap: 7040.1M(10.0G)->2521.7M(10.0G)] 
    [Times: user=0.23 sys=0.00, real=0.03 secs] 

 

    2017-03-02T12:27:09.618-0800: 48188.179: [GC pause (G1 Evacuation Pause) (young) 
    Desired survivor size 301989888 bytes, new threshold 15 (max 15) 
    - age 1:  47960 bytes,  47960 total 
    - age 2:  26736 bytes,  74696 total 
    - age 3: 6628208 bytes, 6702904 total 
    - age 4: 15151304 bytes, 21854208 total 
    - age 5: 5530024 bytes, 27384232 total 
    - age 6: 5501976 bytes, 32886208 total 
    - age 7: 4490976 bytes, 37377184 total 
    - age 8: 1736456 bytes, 39113640 total 
    - age 9: 2849184 bytes, 41962824 total 
    - age 10: 2600504 bytes, 44563328 total 
    - age 11: 1792992 bytes, 46356320 total 
    - age 12: 1996752 bytes, 48353072 total 
    - age 13:  876104 bytes, 49229176 total 
    - age 14: 2233720 bytes, 51462896 total 
    - age 15: 1218392 bytes, 52681288 total 
    , 0.0347669 secs] 
     [Parallel Time: 30.5 ms, GC Workers: 8] 
      [GC Worker Start (ms): Min: 48188179.0, Avg: 48188179.0, Max: 48188179.1, Diff: 0.1] 
      [Ext Root Scanning (ms): Min: 4.0, Avg: 6.2, Max: 14.5, Diff: 10.5, Sum: 49.9] 
      [Update RS (ms): Min: 0.7, Avg: 8.2, Max: 10.1, Diff: 9.4, Sum: 65.9] 
      [Processed Buffers: Min: 6, Avg: 12.5, Max: 22, Diff: 16, Sum: 100] 
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.9] 
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] 
      [Object Copy (ms): Min: 14.4, Avg: 15.4, Max: 15.8, Diff: 1.4, Sum: 123.1] 
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 
      [Termination Attempts: Min: 1, Avg: 1.6, Max: 3, Diff: 2, Sum: 13] 
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9] 
      [GC Worker Total (ms): Min: 30.2, Avg: 30.2, Max: 30.3, Diff: 0.1, Sum: 241.8] 
      [GC Worker End (ms): Min: 48188209.2, Avg: 48188209.3, Max: 48188209.3, Diff: 0.2] 
     [Code Root Fixup: 0.3 ms] 
     [Code Root Purge: 0.0 ms] 
     [Clear CT: 0.7 ms] 
     [Other: 3.3 ms] 
      [Choose CSet: 0.0 ms] 
      [Ref Proc: 0.6 ms] 
      [Ref Enq: 0.0 ms] 
      [Redirty Cards: 0.4 ms] 
      [Humongous Register: 0.2 ms] 
      [Humongous Reclaim: 0.1 ms] 
      [Free CSet: 1.5 ms] 
     [Eden: 4520.0M(4520.0M)->0.0B(4520.0M) Survivors: 60.0M->60.0M Heap: 7041.7M(10.0G)->2525.3M(10.0G)] 
    [Times: user=0.24 sys=0.00, real=0.03 secs] 

 

    2017-03-02T12:27:10.264-0800: 48188.825: [GC pause (G1 Evacuation Pause) (young) 
    Desired survivor size 301989888 bytes, new threshold 15 (max 15) 
    - age 1:  48824 bytes,  48824 total 
    - age 2:  18672 bytes,  67496 total 
    - age 3:  17312 bytes,  84808 total 
    - age 4: 6627608 bytes, 6712416 total 
    - age 5: 15149168 bytes, 21861584 total 
    - age 6: 5530024 bytes, 27391608 total 
    - age 7: 5501976 bytes, 32893584 total 
    - age 8: 4490848 bytes, 37384432 total 
    - age 9: 1736456 bytes, 39120888 total 
    - age 10: 2849184 bytes, 41970072 total 
    - age 11: 2600504 bytes, 44570576 total 
    - age 12: 1792992 bytes, 46363568 total 
    - age 13: 1996752 bytes, 48360320 total 
    - age 14:  876104 bytes, 49236424 total 
    - age 15: 2233720 bytes, 51470144 total 
    , 0.0343310 secs] 
     [Parallel Time: 28.8 ms, GC Workers: 8] 
      [GC Worker Start (ms): Min: 48188825.2, Avg: 48188825.3, Max: 48188825.5, Diff: 0.3] 
      [Ext Root Scanning (ms): Min: 3.9, Avg: 5.9, Max: 12.0, Diff: 8.1, Sum: 47.5] 
      [Update RS (ms): Min: 2.9, Avg: 8.0, Max: 9.3, Diff: 6.3, Sum: 63.6] 
      [Processed Buffers: Min: 8, Avg: 11.8, Max: 21, Diff: 13, Sum: 94] 
      [Scan RS (ms): Min: 0.1, Avg: 0.3, Max: 0.4, Diff: 0.3, Sum: 2.3] 
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1] 
      [Object Copy (ms): Min: 13.0, Avg: 14.2, Max: 14.9, Diff: 1.9, Sum: 113.3] 
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 
      [Termination Attempts: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 12] 
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7] 
      [GC Worker Total (ms): Min: 28.3, Avg: 28.4, Max: 28.6, Diff: 0.4, Sum: 227.5] 
      [GC Worker End (ms): Min: 48188853.7, Avg: 48188853.8, Max: 48188853.8, Diff: 0.1] 
     [Code Root Fixup: 0.4 ms] 
     [Code Root Purge: 0.0 ms] 
     [Clear CT: 0.6 ms] 
     [Other: 4.5 ms] 
      [Choose CSet: 0.0 ms] 
      [Ref Proc: 1.7 ms] 
      [Ref Enq: 0.1 ms] 
      [Redirty Cards: 0.3 ms] 
      [Humongous Register: 0.3 ms] 
      [Humongous Reclaim: 0.1 ms] 
      [Free CSet: 1.7 ms] 
     [Eden: 4520.0M(4520.0M)->0.0B(4524.0M) Survivors: 60.0M->56.0M Heap: 7045.3M(10.0G)->2522.1M(10.0G)] 
    [Times: user=0.23 sys=0.00, real=0.03 secs] 

 

    2017-03-02T12:27:10.866-0800: 48189.426: [GC pause (G1 Evacuation Pause) (young) 
    Desired survivor size 301989888 bytes, new threshold 15 (max 15) 
    - age 1:  579088 bytes,  579088 total 
    - age 2:  9904 bytes,  588992 total 
    - age 3:  18376 bytes,  607368 total 
    - age 4:  14720 bytes,  622088 total 
    - age 5: 6624344 bytes, 7246432 total 
    - age 6: 11726288 bytes, 18972720 total 
    - age 7: 5529984 bytes, 24502704 total 
    - age 8: 5492072 bytes, 29994776 total 
    - age 9: 4482976 bytes, 34477752 total 
    - age 10: 1736360 bytes, 36214112 total 
    - age 11: 2848368 bytes, 39062480 total 
    - age 12: 2600504 bytes, 41662984 total 
    - age 13: 1792992 bytes, 43455976 total 
    - age 14: 1996752 bytes, 45452728 total 
    - age 15:  876104 bytes, 46328832 total 
    , 0.0350574 secs] 
     [Parallel Time: 29.2 ms, GC Workers: 8] 
      [GC Worker Start (ms): Min: 48189427.4, Avg: 48189427.5, Max: 48189427.6, Diff: 0.2] 
      [Ext Root Scanning (ms): Min: 4.0, Avg: 5.8, Max: 11.5, Diff: 7.5, Sum: 46.0] 
      [Update RS (ms): Min: 3.3, Avg: 8.2, Max: 9.6, Diff: 6.3, Sum: 65.8] 
      [Processed Buffers: Min: 7, Avg: 13.0, Max: 22, Diff: 15, Sum: 104] 
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.9] 
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] 
      [Object Copy (ms): Min: 13.2, Avg: 14.4, Max: 14.9, Diff: 1.7, Sum: 114.8] 
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.3, Diff: 0.3, Sum: 2.1] 
      [Termination Attempts: Min: 1, Avg: 3.8, Max: 7, Diff: 6, Sum: 30] 
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4] 
      [GC Worker Total (ms): Min: 28.8, Avg: 28.9, Max: 29.0, Diff: 0.2, Sum: 231.1] 
      [GC Worker End (ms): Min: 48189456.4, Avg: 48189456.4, Max: 48189456.4, Diff: 0.1] 
     [Code Root Fixup: 0.3 ms] 
     [Code Root Purge: 0.0 ms] 
     [Clear CT: 0.7 ms] 
     [Other: 4.8 ms] 
      [Choose CSet: 0.0 ms] 
      [Ref Proc: 1.4 ms] 
      [Ref Enq: 0.2 ms] 
      [Redirty Cards: 0.3 ms] 
      [Humongous Register: 0.9 ms] 
      [Humongous Reclaim: 0.1 ms] 
      [Free CSet: 1.5 ms] 
     [Eden: 4524.0M(4524.0M)->0.0B(4524.0M) Survivors: 56.0M->56.0M Heap: 7046.1M(10.0G)->2525.3M(10.0G)] 
    [Times: user=0.24 sys=0.00, real=0.03 secs] 

 

    2017-03-02T12:27:11.515-0800: 48190.075: [GC pause (G1 Evacuation Pause) (young) 
    Desired survivor size 301989888 bytes, new threshold 15 (max 15) 
    - age 1:  827320 bytes,  827320 total 
    - age 2:  16496 bytes,  843816 total 
    - age 3:  2352 bytes,  846168 total 
    - age 4:  18176 bytes,  864344 total 
    - age 5:  14528 bytes,  878872 total 
    - age 6: 6577816 bytes, 7456688 total 
    - age 7: 11698856 bytes, 19155544 total 
    - age 8: 5520560 bytes, 24676104 total 
    - age 9: 5492032 bytes, 30168136 total 
    - age 10: 4482976 bytes, 34651112 total 
    - age 11: 1736360 bytes, 36387472 total 
    - age 12: 2848368 bytes, 39235840 total 
    - age 13: 2600504 bytes, 41836344 total 
    - age 14: 1792992 bytes, 43629336 total 
    - age 15: 1996752 bytes, 45626088 total 
    , 0.0353327 secs] 
     [Parallel Time: 28.5 ms, GC Workers: 8] 
      [GC Worker Start (ms): Min: 48190075.8, Avg: 48190075.9, Max: 48190076.1, Diff: 0.3] 
      [Ext Root Scanning (ms): Min: 3.3, Avg: 6.0, Max: 11.7, Diff: 8.4, Sum: 47.7] 
      [Update RS (ms): Min: 3.1, Avg: 7.5, Max: 8.7, Diff: 5.6, Sum: 60.4] 
      [Processed Buffers: Min: 6, Avg: 13.0, Max: 23, Diff: 17, Sum: 104] 
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.9] 
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] 
      [Object Copy (ms): Min: 12.8, Avg: 14.0, Max: 14.7, Diff: 1.9, Sum: 111.8] 
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 
      [Termination Attempts: Min: 1, Avg: 1.4, Max: 2, Diff: 1, Sum: 11] 
      [GC Worker Other (ms): Min: 0.0, Avg: 0.4, Max: 2.1, Diff: 2.1, Sum: 2.9] 
      [GC Worker Total (ms): Min: 28.0, Avg: 28.1, Max: 28.2, Diff: 0.3, Sum: 224.8] 
      [GC Worker End (ms): Min: 48190103.9, Avg: 48190104.0, Max: 48190104.1, Diff: 0.2] 
     [Code Root Fixup: 0.4 ms] 
     [Code Root Purge: 0.0 ms] 
     [Clear CT: 0.7 ms] 
     [Other: 5.7 ms] 
      [Choose CSet: 0.0 ms] 
      [Ref Proc: 2.6 ms] 
      [Ref Enq: 0.0 ms] 
      [Redirty Cards: 0.3 ms] 
      [Humongous Register: 0.2 ms] 
      [Humongous Reclaim: 0.1 ms] 
      [Free CSet: 1.9 ms] 
     [Eden: 4524.0M(4524.0M)->0.0B(4512.0M) Survivors: 56.0M->60.0M Heap: 7049.3M(10.0G)->2529.7M(10.0G)] 
    [Times: user=0.23 sys=0.00, real=0.04 secs] 

答えて

0

彼らはエデンのメモリをクリアしているように見えるが、それはそうすぐにいっぱいだ、なぜ私は理解していません。

あなたはすでに指定したログから識別できるすべてを特定しました。アプリケーションがオブジェクトを割り当てるため、世代がいっぱいになります。どのオブジェクト?それを特定するためには、割り当てプロファイラを使用する必要があります。

コレクションのパターンはまあまあだが、数秒以内に10個のG1避難コレクション(ヤング)を連続して実行します。

しかし、それは特に過剰には見えません。ギガバイトのメモリをクリーニングするために、GCで毎秒30〜80msを費やしています。これはまだ92%の最小ミューテータ使用率です。

あなたのアプリケーションはちょうどバースト的ですか?

+0

ありがとうございます。はい、アプリケーションは非常にバースト的だと私は信じています。最終的には、私はデータベースにバインドされていることがわかりました(Tomcatアプリケーションに接続できる十分な接続ではありません)。これはガベージコレクションの問題ではありませんでした。 –

関連する問題