Tomcat 7、JDK 7、Amazon Linux に Web アプリケーションがあります。これは、GC 構成用に用意されているものです。
-XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled"
「PrintGCDetails」が有効になっていません。
これは、数秒ごとに gc.log ファイルに出力されるものです (この時点でアプリケーションの負荷が 0 の場合、48 時間連続で - まったくアクティビティがなく、それでも以下が出力され、これらのスレッドによって使用される CPU は15%) (コンテキストについては以下を参照してください):
940568.925: [GC 7425641K(8277888K), 0.2201750 secs]
940572.415: [GC 7425641K(8277888K), 0.1782950 secs]
940574.101: [GC 7425641K(8277888K), 0.1736550 secs]
940577.545: [GC 7425647K(8277888K), 0.1779190 secs]
また、次の GC スレッドが CPU を占有していることがわかります (全体で約 15%)。
- システムにアクティビティがなく、
- これら以外の他のスレッドはアクティブではなく、これは 48 時間続き、この時点でシステムの負荷は 0でした。
- システムは過去 24 時間も負荷がゼロであり、その後これらのスレッドがアクティブになりました
- これらのスレッドがアクティブで CPU を占有しているときに、前の行が gc.log に出力されました。
- これは 2 日間続き、最終的にこの JVM で Web アプリケーションを 5 分間呼び出して負荷をかけた後、すべて停止しました。現在、これらのスレッドが CPU を使用していない (1% 未満) ことに気付きました。FULL GC が発生すると、問題は解決したようです。FULL GC は、システムに負荷がかかった後に発生しました。
- つまり、GC スレッドは、システムの負荷が 48 時間ゼロの状態でも 15% の CPU を使用し続けました。
これらはスレッドです：
"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x00007fad9402e000 nid=0x629d runnable
"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x00007fad94030000 nid=0x629e runnable
"Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x00007fad94031800 nid=0x629f runnable
"Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x00007fad94033800 nid=0x62a0 runnable
"Gang worker#4 (Parallel GC Threads)" prio=10 tid=0x00007fad94035800 nid=0x62a1 runnable
"Gang worker#5 (Parallel GC Threads)" prio=10 tid=0x00007fad94037000 nid=0x62a2 runnable
"Gang worker#6 (Parallel GC Threads)" prio=10 tid=0x00007fad94039000 nid=0x62a3 runnable
"Gang worker#7 (Parallel GC Threads)" prio=10 tid=0x00007fad9403b000 nid=0x62a4 runnable
"Gang worker#8 (Parallel GC Threads)" prio=10 tid=0x00007fad9403d000 nid=0x62a5 runnable
"Gang worker#9 (Parallel GC Threads)" prio=10 tid=0x00007fad9403e800 nid=0x62a6 runnable
"Gang worker#10 (Parallel GC Threads)" prio=10 tid=0x00007fad94040800 nid=0x62a7 runnable
"Gang worker#11 (Parallel GC Threads)" prio=10 tid=0x00007fad94042800 nid=0x62a8 runnable
"Gang worker#12 (Parallel GC Threads)" prio=10 tid=0x00007fad94044000 nid=0x62a9 runnable
"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x00007fad9418b000 nid=0x62ae runnable
"Gang worker#0 (Parallel CMS Threads)" prio=10 tid=0x00007fad94183000 nid=0x62aa runnable
"Gang worker#1 (Parallel CMS Threads)" prio=10 tid=0x00007fad94185000 nid=0x62ab runnable
"Gang worker#2 (Parallel CMS Threads)" prio=10 tid=0x00007fad94187000 nid=0x62ac runnable
"Gang worker#3 (Parallel CMS Threads)" prio=10 tid=0x00007fad94188800 nid=0x62ad runnable
質問 1: これらのスレッドが 15% の CPU を使用しているときに、gc ログが次のように記録されるのはなぜですか?
940568.925: [GC 7425641K(8277888K), 0.2201750 secs]
940572.415: [GC 7425641K(8277888K), 0.1782950 secs]
質問 2: 上記のログは CMS の障害 (マーク、スイープなど) を示していますか?
質問 3: Web アプリケーションに中程度の負荷をかけ、FULL GC が発生したときに問題が解決したのはなぜですか?
はい、printGCDetails を有効にして別の環境で問題を再現し、情報または解決策を返信します。以前に誰かがこれを見た場合は、会話に追加してください。
編集 1: これは、「PrintGCDetails」が有効になっているときのログです。
1376.326: [GC [1 CMS-initial-mark: 6481517K(7281088K)] 6536750K(8277888K), 0.0094620 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1376.336: [CMS-concurrent-mark-start]
1377.992: [CMS-concurrent-mark: 1.656/1.656 secs] [Times: user=6.62 sys=0.00, real=1.66 secs]
1377.992: [CMS-concurrent-preclean-start]
1378.005: [CMS-concurrent-preclean: 0.014/0.014 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1378.006: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 1413.110: [CMS-concurrent-abortable-preclean: 4.169/35.104 secs] [Times: user=4.23 sys=0.01, real=35.11 secs]
1413.111: [GC[YG occupancy: 55233 K (996800 K)]1413.111: [Rescan (parallel) , 0.0154040 secs]1413.126: [weak refs processing, 0.0001380 secs]1413.126: [class unloading, 0.0013450 secs]1413.128: [scrub symbol table, 0.0023140 secs]1413.130: [scrub string table, 0.0004850 secs] [1 CMS-remark: 6481517K(7281088K)] 6536751K(8277888K), 0.0201870 secs] [Times: user=0.20 sys=0.00, real=0.02 secs]
1413.131: [CMS-concurrent-sweep-start]
1414.151: [CMS-concurrent-sweep: 1.020/1.020 secs] [Times: user=1.02 sys=0.00, real=1.02 secs]
1414.151: [CMS-concurrent-reset-start]
1414.177: [CMS-concurrent-reset: 0.026/0.026 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
また、「CMSMaxAbortablePrecleanTime」は 35 秒に設定されています。ありがとう。