アプリケーション実行時間の最初の5時間に2分ごとにTomcatフルGCを受信

Question

非常に大量のWebサイトで使用されているTomcatサーバーのクラスタがあります。アプリケーションが再ロードされた後の最初の5〜6時間は、Full GCが2分ごとに実行され、5〜20秒の間のどこかでアプリケーションを一時停止することがわかりました。 5〜6時間後、Tomcatが再起動されるまで完全なGCは実行されなくなります。トラフィックレベルは、ピーク時まで問題なく通過する要因ではありません。

サーバは当社のJavaのoptsのは、しかし、ここでは日常的にして再生されているCentOSに5を実行しているRAMの32ギガバイトを持つすべてのデュアルクアッドコアですが、以下のサンプルのGCログに対応して設定されている：

-server -Xmx27g -Xms27g -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+PrintTenuringDistribution -Dsun.rmi.dgc.client.gcInterval=900000 -Dsun.rmi.dgc.server.gcInterval=900000 -XX:NewSize=8g -XX:SurvivorRatio=16 -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails 

我々はそれがうまく実行されます来週のために、このサーバーを再起動しない場合はすぐに適用した後から

ログのサンプルは

191.955: [Full GC 191.958: [CMS: 1815877K->1158107K(19922944K), 3.0376720 secs] 3118102K->1158107K(27845568K), [CMS Perm : 83787K->46767K(83960K)], 3.0415080 secs] [Times: user=2.95 sys=0.10, real=3.04 secs] 

215.501: [GC 215.504: [ParNew 
Desired survivor size 238583808 bytes, new threshold 15 (max 15) 
- age 1: 50457968 bytes, 50457968 total 
: 7456799K->111048K(7922624K), 0.0617110 secs] 8614906K->1269155K(27845568K), 0.0661400 secs] [Times: user=0.68 sys=0.00, real=0.07 secs] 

215.577: [GC 215.579: [ParNew 
Desired survivor size 238583808 bytes, new threshold 15 (max 15) 
- age 1:  66288 bytes,  66288 total 
- age 2: 50219144 bytes, 50285432 total 
: 114868K->66525K(7922624K), 0.0381810 secs] 1272975K->1224632K(27845568K), 0.0413630 secs] [Times: user=0.46 sys=0.00, real=0.04 secs] 

236.177: [GC 236.180: [ParNew 
Desired survivor size 238583808 bytes, new threshold 15 (max 15) 
- age 1: 45071064 bytes, 45071064 total 
- age 2:  26112 bytes, 45097176 total 
- age 3: 34785960 bytes, 79883136 total 
: 7523165K->110355K(7922624K), 0.0921350 secs] 8681272K->1268462K(27845568K), 0.0969290 secs] [Times: user=0.95 sys=0.01, real=0.10 secs] 

... 

316.456: [GC 316.459: [ParNew 
Desired survivor size 238583808 bytes, new threshold 15 (max 15) 
- age 1: 41430416 bytes, 41430416 total 
- age 3: 22728376 bytes, 64158792 total 
- age 5: 19599960 bytes, 83758752 total 
- age 6: 21847616 bytes, 105606368 total 
- age 7: 27667592 bytes, 133273960 total 
- age 8:  10904 bytes, 133284864 total 
- age 9: 31824256 bytes, 165109120 total 
: 7650333K->215213K(7922624K), 0.1332630 secs] 8808440K->1373320K(27845568K), 0.1380590 secs] [Times: user=1.45 sys=0.01, real=0.14 secs] 

338.851: [GC 338.854: [ParNew 
Desired survivor size 238583808 bytes, new threshold 15 (max 15) 
- age 1: 40678840 bytes, 40678840 total 
- age 2: 27075936 bytes, 67754776 total 
- age 4: 20399720 bytes, 88154496 total 
- age 6: 19271008 bytes, 107425504 total 
- age 7: 21655032 bytes, 129080536 total 
- age 8: 27118800 bytes, 156199336 total 
- age 9:  10904 bytes, 156210240 total 
- age 10: 31747808 bytes, 187958048 total 
: 7671853K->285541K(7922624K), 0.1456470 secs] 8829960K->1443648K(27845568K), 0.1503540 secs] [Times: user=1.62 sys=0.01, real=0.15 secs] 

343.376: [Full GC 343.378: [CMS: 1158107K->1312570K(19922944K), 3.4129290 secs] 2884580K->1312570K(27845568K), [CMS Perm : 83964K->47203K(83968K)], 3.4168600 secs] [Times: user=3.87 sys=0.02, real=3.41 secs] 

**Last Full GC** 

20517.892: [GC 20517.898: [ParNew 
Desired survivor size 238583808 bytes, new threshold 15 (max 15) 
- age 1: 33948208 bytes, 33948208 total 
- age 2:  88280 bytes, 34036488 total 
- age 3: 19872472 bytes, 53908960 total 
- age 4: 16072608 bytes, 69981568 total 
- age 5: 15718712 bytes, 85700280 total 
- age 6: 15771016 bytes, 101471296 total 
- age 7: 16895976 bytes, 118367272 total 
- age 8: 24233728 bytes, 142601000 total 
: 7618727K->200950K(7922624K), 0.1728420 secs] 16794482K->9376705K(27845568K), 0.1822350 secs] [Times: user=2.21 sys=0.01, real=0.18 secs] 

20526.469: [Full GC 20526.475: [CMS: 9175755K->9210800K(19922944K), 33.1161300 secs] 13632232K->9210800K(27845568K), [CMS Perm : 83967K->53332K(83968K)], 33.1254170 secs] [Times: user=33.12 sys=0.02, real=33.12 secs] 


**Log samples after Full GC no longer runs** 

74412.335: [GC 74412.340: [ParNew 
Desired survivor size 238583808 bytes, new threshold 11 (max 15) 
- age 1: 43614032 bytes, 43614032 total 
- age 2: 41194144 bytes, 84808176 total 
- age 3: 27392888 bytes, 112201064 total 
- age 5: 22753896 bytes, 134954960 total 
- age 7: 24439608 bytes, 159394568 total 
- age 8: 24015704 bytes, 183410272 total 
- age 9: 24080848 bytes, 207491120 total 
- age 10: 24715800 bytes, 232206920 total 
- age 11: 21844024 bytes, 254050944 total 
: 7813778K->312911K(7922624K), 0.3329150 secs] 24426351K->16967791K(27845568K), 0.3416730 secs] [Times: user=3.69 sys=0.02, real=0.35 secs] 

74445.007: [GC 74445.012: [ParNew 
Desired survivor size 238583808 bytes, new threshold 11 (max 15) 
- age 1: 42690688 bytes, 42690688 total 
- age 2: 37055848 bytes, 79746536 total 
- age 3: 37107464 bytes, 116854000 total 
- age 4: 26223088 bytes, 143077088 total 
- age 6: 22478672 bytes, 165555760 total 
- age 8: 24259744 bytes, 189815504 total 
- age 9: 23862672 bytes, 213678176 total 
- age 10: 23911864 bytes, 237590040 total 
- age 11: 24496888 bytes, 262086928 total 
: 7769547K->344030K(7922624K), 0.3088470 secs] 24424428K->17021685K(27845568K), 0.3175830 secs] [Times: user=3.57 sys=0.01, real=0.32 secs] 

74475.169: [GC 74475.175: [ParNew 
Desired survivor size 238583808 bytes, new threshold 10 (max 15) 
- age 1: 42011656 bytes, 42011656 total 
- age 2: 33147608 bytes, 75159264 total 
- age 3: 32391640 bytes, 107550904 total 
- age 4: 36516584 bytes, 144067488 total 
- age 5: 25940856 bytes, 170008344 total 
- age 7: 22037464 bytes, 192045808 total 
- age 9: 24130040 bytes, 216175848 total 
- age 10: 23724672 bytes, 239900520 total 
- age 11: 23329640 bytes, 263230160 total 
: 7803184K->331046K(7922624K), 0.3091600 secs] 24480839K->17033619K(27845568K), 0.3179630 secs] [Times: user=3.56 sys=0.01, real=0.32 secs] 

リロード。

ご協力いただければ幸いです。

編集：この問題は、WARファイルが再配布された場合にのみ表示されます。自分自身でTomcatを再起動しても、この問題は発生しません。

Answer 1

VisualGCプラグインがインストールされたjvisualvmを使用して、インスタンスの1つに接続しようとします。これは、JVMの各プールの初期メモリの分布と、それが時間外にどのように変化するかを示します。また、メモリサンプラとプロファイラがあり、与えられた時間にメモリ状態を判断するのに役立ちます。

また、私はあなたが使用しているJVMパラメータ（27Gb？あなたは何らかの種類のメモリキャッシュをプロセス中に保持していますか？）を思いついたのかどうかはわかりませんが、通常は最小限のものから始め、それは問題が特定された後でなければなりません（例えば小さな新しいプールなど）。自動的に「サーバ」モードで起動すべきメモリのjavaのあなたの量に

-Xmx.. -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -Xloggc:/tmp/gc.log -XX:+HeapDumpOnOutOfMemoryError 

をし、それは、動的に限り、十分なメモリがあるように必要なメモリプールを割り当て、通常はかなり良いです：ちょうどのようなもので、それを起動してみてください。

Answer 2

ここで何が起こっているのかに関する理論は、あなたのehcacheの統計から来る可能性があります。

CMSコレクタが完全GCを起動するタイミングを理解することが重要です。以下は、他のコレクターとは異なり[Reference]

真である古い世代がいっぱいになると、CMSコレクタは古い 世代の収集を開始しません。以前のレベルに基づいて、GCを実行するときにその代わりに、 はそれはそれは

を発生する前に、それは を完了できるように十分に早く収集を開始しようとする基本的にCMSコレクタは、決定を行い、どれだけ速くそれが充填されます。これは、将来の休止時間を短縮するためにこれを実行しています。

アプリケーションの起動後早期にこれらのすべてのコレクションが表示されている場合、JVMはメモリのフラッドが割り当てられていると判断する可能性があります。そのため、頻繁にGCが実行され、ここでOOMエラーが発生します。GCの統計を見ると、消費された27GBのヒープ・ヒープのうち1.8GBしかない場合、最初のフル・コレクションが開始されます。最後は27GBの9.2GBで発生します。

この時点で、完全なGCが停止しているとき、コレクタはストレス下ではないと判断し、メモリ割り当てが一定になっていると判断しました。 5〜6時間の時点で、アプリケーションのキャッシュに完全なデータが格納されており、必要に応じてさらに多くのメモリを割り当てられていない可能性があります。ヒット、ミス、キャッシュのサイズに関する統計情報を時間とともに表示し、そのサイズをそのように監視するツールを作成することができます。成長が止むところで、GCの停止時間に対応しているかどうかを確認できます。個人的に私は家庭用のツールだけを使用していますが、自分のサイトで入手できるEHCache Monitorツールのようなものを試すことができます。

また、IBM Diagnostic toolsまたはMATなどのツールを使用してGCログを実行して、その時間にアプリケーションが取得するスループットの内訳を把握しましたか。 CMSコレクタを使用すると、すべての一時停止が全世界で止まるわけではないので、いくつかの休止時間が早くなる可能性があります。