10

次のjHiccupの結果があります。

jしゃっくり分析グラフ

明らかに、グラフには数秒の大きなピークがあります。私のアプリは 100 ミリ秒ごとにログを出力します。ログを読むと、これほど大きな一時停止が見られることはありません。また、JVM 診断から GC で費やされた合計時間を確認でき、次のように表示されます。

Time: 
2013-03-12 01:09:04
Used: 
 1,465,483 kbytes
Committed: 
 2,080,128 kbytes
Max: 
 2,080,128 kbytes
GC time: 
     2 minutes on ParNew (4,329 collections)

8.212 seconds on ConcurrentMarkSweep (72 collections)

big-GC の合計時間は、72 の個別のコレクションにまたがって約 8 秒です。それらはすべて、一時停止を制限するための JVM ヒントごとに 200 ミリ秒未満です。

一方、独立したネットワーク ログ (wireshark) で、5 秒のネットワーク応答時間のインスタンスを 1 つだけ観察しました。これは一時停止が存在することを意味しますが、それらは GC ではなく、ブロックされたスレッドでも、プロファイラーまたはスレッド ダンプで確認できるものでもありません。

私の質問は、この動作をデバッグまたは調整するための最良の方法は何ですか?

さらに、jHiccup が測定を行う方法を理解したいと思います。明らかに、GC の一時停止時間ではありません。

4

1 に答える 1

28

あなたが jHiccup を使っていること、そしてそれが現実に基づいたしゃっくりを示しているように見えることをうれしく思います。

jHiccup は、JVM で実行されているアプリケーション スレッドでも見られる「しゃっくり」を観察します。理由を収集するのではなく、事実を報告するだけです。理由は、プロセスが完全にすぐに実行できるコードを実行できない原因となるものであれば何でもかまいません: GC の一時停止は一般的な原因ですが、キーボードの一時的な ^Z、または仮想化されたホスト間での「ライブ マイグレーション」のいずれかです。 OS またはハイパーバイザー レベル (存在する場合) でのスケジューリング プレッシャー、電源管理の狂気、スワッピングなど、さまざまな理由が考えられます。私は、Linux ファイル システムのプレッシャーと、Transparent Huge Page の「バックグラウンド」での最適化が、数秒の中断を引き起こすのを見てきました...

一時停止の原因を特定するための適切な最初のステップは、jHiccup で「-c」オプションを使用することです。これは、別の制御プロセスを起動します (それ以外の場合はアイドル状態のワークロード)。アプリケーションと制御プロセスの両方で、サイズと時間に大まかな相関関係がある問題が発生している場合は、(プロセス ローカルではなく) システム レベルの理由を探していることがわかります。それらが相関しない場合は、JVM の内部が疑われることがわかります。これは、JVM が何か大きな問題のために一時停止していることを示している可能性が最も高いです。セーフポイントまでの時間が何らかの理由で (そしてほとんどの JVM では、セーフポイントまでの時間が長くなる原因が多数考えられます)。

jHiccup の測定は非常に単純なので、間違えることはほとんどありません。全体で 650 行未満の Java コードなので、自分でロジックを確認できます。jHiccup の HiccupRecorder スレッドは、繰り返し 1 ミリ秒間スリープ状態になり、ウェイクアップすると、1 ミリ秒を超える (スリープ前からの) 時間差をヒカップとして記録します。簡単な仮定としては、1 つの実行準備が整ったスレッド (HiccupRecorder) が 5 秒間実行されなかった場合、同じプロセス内の他のスレッドでも同様のサイズのヒカップが発生したということです。

上記のように、jHiccups の観察結果は、独立したネットワーク ログで裏付けられているようです。応答時間は 5 秒でした。すべての問題がネットワーク ログで観察されたわけではないことに注意してください。ネットワークロガーで観測されました。対照的に、jHiccup は他のアクティビティがなくても 1 秒あたり 1,000 回ウェイクアップを試みるため、1 ミリ秒を超えるヒカップは jHiccup から隠れることはできません。

これは GC ではないかもしれませんが、GC を除外する前に、GC のログをもう少し調べてみることをお勧めします。まず、一時停止を 200 ミリ秒に制限する JVM ヒントは、既知のすべての JVM では役に立ちません。一時停止のヒントは、「お願いします」と言うのと同じです。さらに、オプションに -XX:+PrintGCApplicationStoppedTime を含めない限り、GC ログを信じないでください (そして、その場合でもそれらを疑ってください)。このフラグを含めない限り、一時停止や一時停止の一部が非常に長くなり、報告されないことがあります。たとえば、GC が実際に何らかの作業を行った一時停止の 0.08 秒の部分のみを報告した場合、安全なポイントに到達するのに 15 秒かかる時折の長期カウント ループが原因で一時停止が発生するのを見てきました。「GC」の一部とは見なされない原因の一時停止もたくさんあります

――ギル。[jHiccupの作者]

于 2013-03-12T03:33:07.233 に答える