はじめに
とある日、本番運用バッチサーバーで CPU が100%になり、アラートが発生しました。
本番環境で CPU 100% なんて、もうあせりますよね＞＜
起動中のバッチ処理を確認しても、数秒で終わる軽い処理のみで重い処理は動いていませんでした。
うーん、起動中のバッチ処理が要因ではないとすると、何のプロセスが要因で CPU 負荷をかけているのだろう？という状態でした。
ということで、この時に確認した「なんのプロセスが CPU に負荷をかけているか」の手順を紹介します！
TOP コマンドで CPU 負荷かけているプロセスを確認しよう！
まず、バッチサーバーにログインし、top コマンドにてサーバー上で動作しているプロセスを確認します。
デフォルトだと、COMMAND 部分に java や php しか表示されないので、「c オプション」を指定してコマンド詳細が見れるようにします。
$ top -c Tasks: 125 total, 7 running, 86 sleeping, 0 stopped, 0 zombie Cpu(s): 95.8%us, 9.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 4040136k total, 2172772k used, 1867364k free, 9508k buffers Swap: 0k total, 0k used, 0k free, 60576k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2521 apache 20 0 3627m 816m 876 S 127.0 20.7 4060:43 /etc/alternatives/java -Djava.awt.headless=true -DJENKINS_HOME=/var/lib/jenkins -jar /usr/lib/ 29125 apache 20 0 602m 230m 17m R 13.3 5.8 0:01.48 /usr/bin/php 29263 apache 20 0 495m 125m 17m R 13.0 3.2 0:00.63 /usr/bin/php
一番上の 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を確認します。
$ top -n 1 -H -p 2521 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 13422 apache 20 0 3627m 932m 0 S 51.7 23.6 35:14.04 /etc/alternatives/java -Dcom.sun.akuma.Daemon=daemonized -Djava.awt.headless=true -DJENKINS 13423 apache 20 0 3627m 932m 0 S 47.7 23.6 69:37.58 /etc/alternatives/java -Dcom.sun.akuma.Daemon=daemonized -Djava.awt.headless=true -DJENKINS 13407 apache 20 0 3627m 932m 0 S 45.7 23.6 35:01.37 /etc/alternatives/java -Dcom.sun.akuma.Daemon=daemonized -Djava.awt.headless=true -DJENKINS
上記結果のようにスレッドID が一覧として出力されます。
「%CPU」部分見て、CPU 浪費しているスレッドIDをピックアップします。
-
スレッドダンプ確認用に、スレッドIDを16進数に変換
スレッドダンプ出力した結果では、スレッドIDが16進数で出力されるため、スレッドID (上記だと13422/13423/13407) を16進数に変換したものを用意してメモしておきます。
$ printf %x\\n 13422 346e $ printf %x\\n 13423 346f $ printf %x\\n 13407 345f
これで、スレッドダンプ確認の準備ができました。
それでは、スレッドダンプ出力します。
-
Java プロセスのスレッドダンプ出力
jstack コマンドにて、指定されたPIDのJava プロセスに関するスレッドのスタックトレースを出力できます。
大元のJavaプロセスのPID: 2521 を指定して jstack コマンドを実行します。
$ jstack 2521 > thread_dump.txt
-
出力したダンプファイルで、CPU負荷かけているスレッドを確認
Javaプロセスに関するスレッド情報が全て出力されるので、負荷をかけている該当スレッドIDを検索します。
上記結果の「346e」を例にして確認します。
16進数に変換したCPU負荷かけているスレッドIDに、先頭に「0x」を付与して「0x346e」で検索します。
上記で出力したダンプファイルを開いて、「0x346e」を検索します。
すると、nid=0x346e の部分がヒットし、下記のようなスタックトレースが確認できます。
"Handling GET /view/job/{該当ジョブ名}/descriptorByName/hudson.triggers.TimerTrigger/checkSpec from xxx.xxx.xxx.xxx :
RequestHandlerThread[#15]" #54 daemon prio=5 os_prio=0 tid=0x00007fe588006110
nid=0x346e runnable [0x00007fe575c6e000]
java.lang.Thread.State: RUNNABLE
at java.util.GregorianCalendar.computeFields(GregorianCalendar.java:2312)
at java.util.Calendar.setTimeInMillis(Calendar.java:1804)
at java.util.GregorianCalendar.add(GregorianCalendar.java:1048)
at hudson.scheduler.CronTab$CalendarField.addTo(CronTab.java:203)
at hudson.scheduler.CronTab.floor(CronTab.java:423)
at hudson.scheduler.CronTabList.previous(CronTabList.java:134)
at hudson.triggers.TimerTrigger$DescriptorImpl.updateValidationsForNextRun(TimerTrigger.java:109)
at hudson.triggers.TimerTrigger$DescriptorImpl.doCheckSpec(TimerTrigger.java:93)
at java.lang.invoke.LambdaForm$DMH/566427335.invokeVirtual_L3_L(LambdaForm$DMH)
at java.lang.invoke.LambdaForm$BMH/1291054401.reinvoke(LambdaForm$BMH)
at java.lang.invoke.LambdaForm$MH/516027262.invoker(LambdaForm$MH)
at java.lang.invoke.LambdaForm$MH/986430670.invokeExact_MT(LambdaForm$MH)
at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:627)
at org.kohsuke.stapler.Function$MethodFunction.invoke(Function.java:343)
at org.kohsuke.stapler.Function.bindAndInvoke(Function.java:184)
at org.kohsuke.stapler.Function.bindAndInvokeAndServeResponse(Function.java:117)
at org.kohsuke.stapler.MetaClass$1.doDispatch(MetaClass.java:129)
at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:58)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:715)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:845)
at org.kohsuke.stapler.MetaClass$5.doDispatch(MetaClass.java:248)
at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:58)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:715)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:845)
at org.kohsuke.stapler.MetaClass$5.doDispatch(MetaClass.java:248)
at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:58)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:715)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:845)
at org.kohsuke.stapler.MetaClass$5.doDispatch(MetaClass.java:248)
at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:58)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:715)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:845)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:649)
at org.kohsuke.stapler.Stapler.service(Stapler.java:238)
これが 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 のバグだったとは、思いもよらない結果でしたね。
