Java プロセスが CPU 負荷かけているぞ!いますぐ確認するべき手順を紹介します!

はじめに

とある日、本番運用バッチサーバーで CPU が100%になり、アラートが発生しました。

本番環境で CPU 100% なんて、もうあせりますよね><

起動中のバッチ処理を確認しても、数秒で終わる軽い処理のみで重い処理は動いていませんでした。

うーん、起動中のバッチ処理が要因ではないとすると、何のプロセスが要因で CPU 負荷をかけているのだろう?という状態でした。

ということで、この時に確認した「なんのプロセスが CPU に負荷をかけているか」の手順を紹介します!

 TOP コマンドで CPU 負荷かけているプロセスを確認しよう!

まず、バッチサーバーにログインし、top コマンドにてサーバー上で動作しているプロセスを確認します。

デフォルトだと、COMMAND 部分に java や php しか表示されないので、「c オプション」を指定してコマンド詳細が見れるようにします。

一番上の PID: 2521 の /etc/alternatives/java プロセスが、%CPU: 127.0となっています。

この Java プロセスが、CPU 負荷かけているのが一目瞭然ですね><

コマンド内容みると、-DJENKINS_HOME=/var/lib/jenkins とあるので、どうやら Jenkins のプロセスのようです。

うーん、Jenkins で実行中のジョブ確認しても、重い処理は実行されていない状態でした。Jenkins のなんのプロセスが負荷かけているのだろう???

もうちょっと詳しく見てみないとわかりませんね。

ということで、負荷をかけている jenkins の該当 Java プロセスのスレッド情報を確認します。

CPU 負荷かけているJavaプロセスのスレッド情報を確認しよう!

  • CPU負荷かけているスレッドIDを確認

topコマンドにて 「H オプション」を指定し、上記で確認した CPU 負荷かけている該当 Javaプロセス (PID: 2521) に関するスレッドIDを確認します。

上記結果のようにスレッドID が一覧として出力されます。

「%CPU」部分見て、CPU 浪費しているスレッドIDをピックアップします。

 

  • スレッドダンプ確認用に、スレッドIDを16進数に変換

スレッドダンプ出力した結果では、スレッドIDが16進数で出力されるため、スレッドID (上記だと13422/13423/13407) を16進数に変換したものを用意してメモしておきます。

これで、スレッドダンプ確認の準備ができました。

それでは、スレッドダンプ出力します。

 

  • Java プロセスのスレッドダンプ出力

jstack コマンドにて、指定されたPIDのJava プロセスに関するスレッドのスタックトレースを出力できます。

大元のJavaプロセスのPID: 2521 を指定して jstack コマンドを実行します。

 

  • 出力したダンプファイルで、CPU負荷かけているスレッドを確認

Javaプロセスに関するスレッド情報が全て出力されるので、負荷をかけている該当スレッドIDを検索します。

上記結果の「346e」を例にして確認します。

16進数に変換したCPU負荷かけているスレッドIDに、先頭に「0x」を付与して「0x346e」で検索します。

上記で出力したダンプファイルを開いて、「0x346e」を検索します。

すると、nid=0x346e の部分がヒットし、下記のようなスタックトレースが確認できます。

これが CPU 負荷かけているスレッドのスタックトレースですね!

 

  • スタックトレースから原因調査

スタックトレース確認すると /view/job/{該当ジョブ名}/ と Jenkins の該当ジョブまで確認できます。

しかし、このジョブは起動中ではありませんでした。

むむむ。。。起動中でないのになんでプロセスが残っているのか、しかもこれがかなり負荷をかけているとは。。。

スタックトレースを見ると、’Calendar.setTimeInMillis‘ やら ‘GregorianCalendar.add‘ とあるので、カレンダーが関連していそうです。

Jenkins でカレンダーというと、つまり日付など設定するところ、、、

は!!!

ジョブの「起動スケジュール」だ!!!

ということで、Jenkinsの該当ジョブの起動スケジュールの設定が関係していそうですね。

根本原因は Jenkins のバグだった

  • 根本原因が判明

上記スレッド情報から調査した結果、どうやら Jenkins のバグ のようでした。

該当ジョブの起動スケジュールがこのバグを踏んでしまっていました。

30 22 28-31 * * これは有効なCron構文ですが、Jenkins Time Trigger Classは、ジョブの正確な次の実行がいつであるかを検証できませんでした。

とコメント蘭にあるので、起動スケジュールに月末指定などすると CPU 100% になるバグがあるようですね。日付が見つからず無限ループしているのですかね。これでCPU100%とは。。。><

  • 対応として

該当ジョブの起動スケジュールが原因ということで、スタックトレースに出ていた該当 Jenkins ジョブの起動スケジュールを削除し、Jenkins 再起動することで CPU 負荷も解消できました。ふーお疲れ様です。

おわりに

一例にはなりますが、Javaプロセスで負荷かけているスレッド情報を詳しく確認することで根本原因調査ができました。

起動スケジュールの設定だけで CPU 100% になるという Jenkins のバグだったとは、思いもよらない結果でしたね。


--------------------------
システム開発のご要望・ご相談はこちらから

コメントを残す

メールアドレスが公開されることはありません。