ヒカップアップ解析は追加されません

Question

次のような結果があります。

明らかにグラフに数秒の巨大なピークがあります。私のアプリは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) 

総ビッグGC時間は約72回の別々のコレクションに広がっ8秒です。これらのすべては、一時停止を制限するためにJVMのヒントごとに200ミリ秒以下です。

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

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

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

Answer 1

あなたはjHiccupを使用していることを嬉しく思うし、それは現実ベースのしゃっくりを示すようだ。

jHiccupは、JVM上で実行されているアプリケーションスレッドにも見られる「ヒカップス」を観察します。理由を集めるのではなく、事実だけを報告します。理由は、プロセスが完全に実行可能なコードを実行しない原因になる可能性があります。GCの一時停止は一般的な原因ですが、キーボードの一時的なZ、または仮想化されたホスト間での「ライブマイグレーション」同様に観察されます。OSやハイパーバイザーレベル（存在する場合）、電源管理の狂気、スワップなど、多くの理由が考えられます。私はLinuxのファイルシステムの圧力と透明な巨大なページの "背景"のデフラグメンテーションがマルチ秒のトラブルを引き起こすのを見た。 in jHiccup：別の制御プロセスを起動します（それ以外の場合はアイドルのワークロードが必要です）。アプリケーションと制御プロセスの両方に大きさと時間がおおよそ相関するヒザップが表示される場合は、システムレベル（プロセスローカルではなく）の理由を探していることがわかります。相関関係がない場合は、JVMの内部が疑わしいことを知っているでしょう。 GCやその他の何か、ロック・デバイアやクラスロード・デリベント・デオプティマイゼーションのように、何らかの理由で長い時間がかかりすぎると、いくつかのJVMで実際に長い時間がかかることがあります。ほとんどのJVMでは、長い安全間のポイントには多くの原因が考えられます）。

jヒップカップの測定はとても汚れていて、間違っているのは簡単ではありません。全体がJavaコードの650行未満であるので、あなた自身でロジックを見ることができます。 jHiccupのHiccupRecorderスレッドは、1msecの間、繰り返しスリープ状態になり、スリープ状態になると、（スリープ状態よりも前に）1msecの大きな時間差を記録します。簡単な前提は、実行準備が整っているスレッド（HiccupRecorder）が5秒間実行されなかった場合、同じプロセス内の他のスレッドも同様のサイズの問題を検出したことです。

上記のように、jHiccupsの観察結果は、5秒の応答時間を見た独立したネットワークログで確認されているようです。ネットワークログでは、実際に行われた要求しゃっくりはネットワークロガーによって観察されていました。対照的に、〜1msecより大きいひだまりはjHiccupから隠れることはありません。なぜなら、それは他の活動がなくても毎秒1000回ウェイクアップを試みるからです。

これはです。はGCではありませんが、GCを除外する前に、GCロギングをもう少し調べることをおすすめします。まず、ポーズを200msecに制限するJVMのヒントは、既知のすべてのJVMでは無用です。ポーズヒントは、「してください」と同じです。さらに、オプションで-XX：+ PrintGCApplicationStoppedTimeを指定しないとGCログを信じてはいけません。あなたがこのフラグを含まない限り、非常に長くなり、報告されない休止部分と休止部分があります。例えば。私は、時折長時間実行されるカウントされたループが、安全なポイントに達するのに15秒かかり、GCが実際に何らかの作業を行った箇所の0.08秒の部分しか報告しなかったために一時停止が発生するのを見ました。 "GC"の一部とはみなされず、GCのログフラグによって報告されなくなる原因もたくさんあります。

- Gil。 [jHiccupの作者]