13

過去数日間、サーバー上の JVM が OldGen の GC で 100% の CPU 時間を費やしている状態になっているのを確認しています。

A. ヒープに十分なスペースが残っているため、その必要はありません。

B. 彼らは何も回収していません。

スタック トレースを見て、ProcessExplorer の ThreadID をスタック ダンプの ThreadID と関連付けることで、それらが GC にあることがわかります。各 GC スレッドは約 4% の CPU を占有しています。

サーバーは 16 ギガ ヒープ (32 ギガの物理 RAM) を実行し、8 つのコアを備えています。稼働時間は通常約 30 日で、再起動は MS のパッチ適用要件のためだけに必要ですが、現在は 20 日でクラッシュしています。

これは、期間、時間スケール = 19 日のグラフです。 http://i45.tinypic.com/257qalu.png

これは、そのグラフのテールのズームです http://i48.tinypic.com/2duiccw.png

ご覧のとおり、持続時間は劇的に増加します。

これは、GC 後のヒープ使用量のグラフです。 http://i48.tinypic.com/znna4h.png

典型的なメモリ リークの場合、オレンジ色のピークがどんどん高くなり、ピークがなくなると予想されますが、このグラフが示すように、十分なヒープ スペースが残っています。

各サーバーのヒープ ダンプを取得しましたが、特に目立った問題はありません。いくつかの ehCache ストアがあり、アプリケーション コード、つまり「通常のもの」を見ることができます。

約 20 日前に行った最大の変更は、内部キャッシュを、ハード参照 (および明らかなメモリ リーク) を使用する無制限のハッシュマップからソフト参照で構成されるものに変更するベンダー パッチを実装することでした。原因、つまり、どういうわけか、ポイントの後にこれらのソフト参照を管理する際に大きなオーバーヘッドがあるのでしょうか?

次にどこを見るべきかについて誰かアイデアを持っていますか、または誰かが私のソフト参照理論を確認できますか?

これが私のjvm.argsです：

java.args=-server -Xms16000m -Xmx16000m -Dsun.io.useCanonCaches=false -XX:MaxPermSize=350m -Xloggc:e:/gcLogs/eRGCLogs.txt -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps - XX:+PrintGCDateStamps -XX:+UseParallelGC -XX:+UseParallelOldGC -Dnet.sf.ehcache.sizeof.filter=D:/jo3/java_ehCacheOpenSource/sizeOfExclusions.config -Xbatch -Dcoldfusion.rootDir={application.home}/.. / -Dcoldfusion.libPath={application.home}/../lib -Dcoldfusion.classPath={application.home}/../lib/updates,{application.home}/../lib,{application.home} /../gateway/lib/,{application.home}/../wwwroot/WEB-INF/flex/jars,{application.home}/../wwwroot/WEB-INF/cfform/jars,d:/ jo3/java,d:/JO3/java_ehCacheOpenSource/,D:/jo3/java_ehCacheMonitorProbe

私たちは Coldfusion を使用しています。これは、Java の上にある大規模なフレームワークのようなものです。

JVM バージョン: 1.6.0_29

要求どおり、「通常の」GC ログは次のようになります。

2013-03-19T22:11:36.670+1100: 1288665.702: [GC [PSYoungGen: 4695800K->471119K(4722112K)] 9301727K->5077046K(15644800K)、0.3584434 秒、ユーザー = 0.3584434 秒] sys0 = リアルタイム。 0.36秒] 2013-03-19T22：14：55.078+1100：1288864.099：[GC [PSyounggen：4783104K（4783104K）] 9327990K-> 5103936K（0.3789 SEC]、0.3789 SECS] 、実数 = 0.38 秒] 2013-03-19T22:17:46.749+1100: 1289035.760: [GC [PSYoungGen: 4654489K->517299K(4673792K)] 9260416K->5123227K(15596480K)、8 秒 80 ユーザー [Time] 0.41 秒 5 sys=0.00, real=0.41 秒] 2013-03-19T22:21:08.762+1100: 1289237.763: [GC [PSYoungGen: 4673779K->522660K(4738880K)] 9279707K->5143831K(15661568K) [Time 0.68K] user=5.97 sys=0.00, real=0.40 秒] 2013-03-19T22:23:42.683+1100: 1289391.675: [GC [PSYoungGen: 4582628K->530998K(4590976K)] 9203799K->5186242K(15513664K), 0.4317352 秒] [時間: user=6.24 sys=0.00, real=0.43 秒] 2013-03-19T22:26:11.096+1100: [0YoungGC0: 12805GC. 4590966K->518331K(4724096K)] 9246210K->5206959K(15646784K), 0.3914401 秒] [時間: user=5.99 sys=0.00, real=0.39 秒] 2013-03-19T22:27:44.076:3.095GC [PSYoungGen: 2602730K->447527K(4732864K)] 7291358K->5208743K(15655552K), 0.3725317 秒] [時間: user=5.80 sys=0.00, real=0.37 秒] 2013-03-19T22:27:82.414. ：[Full GC（System）[Psyounggen：447527K-> 0K（4732864K）] [PAROLDGEN：4761215K-> 4628296K（10922688K）] 5208743K-> 4628296K（15655552K）[PSPERMGEN：PSPERMGEN：PSPERMGEN：[PSPERMGEN] ] [時間: user=57.70 sys=0.06, real=4.30 秒] 2013-03-19T22:30:37.950+1100: 1289806.920: [GC [PSYoungGen: 4004416K->70948K(4690432K)] 8632712K->4699245K(15613120K), 0.1062227 秒] [時間: user=0.76 sys=0.00, real=0.11 秒] 2013-03-19T22:33:27.154+1100: [Gen 128PS19976] 4054116K->109175K(4092352K)] 8682413K->4737472K(15015040K), 0.1347919 秒] [時間: user=1.03 sys=0.00, real=0.13 秒] 2013-03-19T22:36:32.120:120GC [PSYoungGen: 4092343K->147318K(4712320K)] 8720640K->4775615K(15635008K), 0.1593523 秒] [時間: user=1.58 sys=0.00, real=0.16 秒] 24092343K->147318K(4712320K)] 8720640K->4775615K(15635008K), 0.1593523 秒] [時間: user=1.58 sys=0.00, real=0.16 秒] 24092343K->147318K(4712320K)] 8720640K->4775615K(15635008K), 0.1593523 秒] [時間: user=1.58 sys=0.00, real=0.16 秒] 2

障害モードの場合、GC ログは次のようになります。

2013-03-22T10:03:47.619+1100: 1504185.901: [GC [PSYoungGen: 0K->0K(5452736K)] 4413907K->4413907K(16375424K), 0.0114248 秒] [0.0114248 秒: user=0.160 = sys = real0. 0.01 秒] 2013-03-22T10:03:47.631+1100: 1504185.912: [フル GC [PSYoungGen: 0K->0K(5452736K)] [ParOldGen: 4413907K->4412613K(10922688K)] 4413907K4(1613907->4) PSPermGen: 358399K->358278K(358400K)]、5.4435442 秒] [時間: user=73.74 sys=0.14、real=5.44 秒] 2013-03-22T10:03:53.145+1100: 1504191.426: [GC [PSYoung219 K-6K-6K-6 >7734K(5449088K)] 4681833K->4422114K(16371776K)、0.0298728 秒] [時間: ユーザー=0.34 sys=0.00、実数=0.03 秒] 2013-03-22T10:03:53.175+1100: [フル GC4:6191. PSYoungGen: 7734K->0K(5449088K)] [ParOldGen: 4414379K->4415189K(10922688K)] 4422114K->4415189K(16371776K) [PSPermGen: 358399K->358371K(358400K)]、6033684 秒] [時間: user=36.33 sys=0.00, real=2.60 秒] 2013-03-22T10:03:55.788+1100: 1504194.069: [GC [PSYoungGen: 94969K->826K(5451328K)] 4510158K0->5K4(6 16374016K)、0.0133588 秒] [時間: user=0.16 sys=0.00、real=0.01 秒] 2013-03-22T10:03:55.802+1100: 1504194.082: [フル GC [PSYoungGen: 826K->0K(5451328K)] [ ParOldGen: 4415189K->4415348K(10922688K)] 4416015K->4415348K(16374016K) [PSPermGen: 358399K->358389K(358400K)]、2.7156884 秒] [Times: user=38.121, sys2.7 = real0]4415189K->4415348K(10922688K)] 4416015K->4415348K(16374016K) [PSPermGen: 358399K->358389K(358400K)], 2.7156884 秒] [時間: user=38.11 sys=0.201, real]4415189K->4415348K(10922688K)] 4416015K->4415348K(16374016K) [PSPermGen: 358399K->358389K(358400K)], 2.7156884 秒] [時間: user=38.11 sys=0.201, real]

4

1 に答える 1

5

多くの人がコメントで言及しているように、PermGen のスペース不足が原因である可能性が非常に高いです。これは、コード全体での文字列の過剰なインターンによって引き起こされる可能性があり、PermGen の「爆発」につながる可能性があります。また、多くのクラスのロード (通常はバックグラウンドで実行するフレームワークを介して) もこれを引き起こす可能性があります。

また、言及されたコメントの 1 つとして、CMS コレクション (コンカレント マークとスイープ) を使用すると、問題が古い世代の容量にあると仮定して、Stop the World GC を減らすことができます。また、現在の問題に関係なく、遅延を減らすことでパフォーマンスを向上させることもできます.

また、GC ログのフラグメントを投稿すると、正しい方向を示すのに役立ちます。

jstatツールについては、次の方法で使用して有用な情報を取得できます。

jstat -gcutil <pid> <interval>

私は通常、1000ミリ秒間隔を使用します。-gcutilGC 使用率 (%) が表示されるため、100% に近づいている世代があるかどうかを確認できます。

jstat -gc <pid> ...古い世代の正確な容量を使用して取得することもできます。

編集：GCログを確認した後

GC ログによると、PermGen がいっぱいになっているという元の前提が確認されます。10:03:47から10:03:55までの時間範囲で、PermGenが常に最大値に達しており、GC が何らかの方法で約 10 ～ 100 KB のデータを削除していることがわかります。

以下を参照してください。

2013-03-22T10:03:47.631+1100: 1504185.912: [Full GC [... [PSPermGen: 358399K->358278K(358400K)]...
2013-03-22T10:03:53.175+1100: 1504191.456: [Full GC [... [PSPermGen: 358399K->358371K(358400K)]...
2013-03-22T10:03:55.802+1100: 1504194.082: [Full GC [... [PSPermGen: 358399K->358389K(358400K)]...

Old 世代と Young 世代を見ると、どちらも最大値に達していないことがわかります。OldGen は 10GB のうち 4GB を消費しているため、それが原因ではありません。

収集したデータからは、PermGen がいっぱいになる速度がプロセスの稼働時間と一致しているかどうかわかりません。つまり、PermGen は 20 日ではなく 1 日でいっぱいになるはずです。そのため、決定的な解決策とは言えませんが、いくつかの推奨事項を以下に示します。

  1. コードを調べて、Stringのintern()メソッドを悪用していないことを確認します。正当な理由もなくコード内で広く使用している場合、これが根本的な原因である可能性があります。
  2. クラスを動的に生成する場合は、使用しているフレームワークを確認してください。これにより、PermGen スペースも消費されますが、ある程度は消費されます。
  3. 可能であれば、プロセスを毎週再起動して、このダウンタイムを防ぎます
  4. PermGen スペースを増やすことを検討してください。ただし、増やすと 20 日間の期間が長くなる可能性があるため、監視してください。ただし、問題は解決しません。PermGen は、プロセスが十分長く実行された後も、非常に静的なままである必要があります。
  5. Coldfusion PermGen という文字列を使用して Google で検索を実行すると、問題を報告する多くのヒットが生成されました。調査に集中するために、それらをフォローしてみてください。
于 2013-03-22T19:27:49.063 に答える