Javaアプリが暴走してCPUの負荷があがった時にやったこと
検証用APサーバ(Tomcat)のロードアベレージが上がりっぱなしになって一向に下がらない状態に陥ったのでその時にやったこと。
ざっくりの流れ
- CPUに負荷かけてるプロセスの確認
- スレッドダンプの採取
- CPUに負荷かけてるスレッドの特定
- スタックトレース読んで分析する
top コマンドで問題のプロセス特定
↓↓こんな感じだった↓↓明らかにJavaのWebアプリが原因(常に85%以上CPU食ってる状態)
$ top top - 18:27:24 up 285 days, 3:05, 3 users, load average: 5.33, 5.36, 4.93 Tasks: 70 total, 1 running, 69 sleeping, 0 stopped, 0 zombie Cpu(s): 10.1%us, 0.9%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 89.0%st Mem: 617044k total, 522324k used, 94720k free, 4812k buffers Swap: 0k total, 0k used, 0k free, 79684k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1722 root 20 0 1422m 394m 6004 S 96.5 65.5 53:50.89 jsvc 6 root 20 0 0 0 0 S 3.4 0.0 11:35.37 events/0 1929 hoge 20 0 2592 1000 784 R 0.3 0.2 0:24.33 top 1 root 20 0 2892 868 664 S 0.0 0.1 0:01.76 init 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd --- (以下略) ---
まずはThreaddump採取
CPUを食っているスレッドの特定
- LWP 別のCPU負荷を確認、LWP:24846 の負荷が大きいことが分かる
- 後で使うのでこのIDを16進数に変換する(24846 => 0x610e)
* LWP: Linux上のプロセスよりも小さい実行単位、スレッドのようなもの
上記スレッドをThreaddumpで探す
- 上記16進数にしたLWPのID(0x610e)がスレッドダンプ内の"nid=xxxxx" と対応する
- なのでスレッドダンプしたファイルをそのIDで検索してやれば、問題の処理のスタックトレースが見つかる
- 後は頑張って分析する
$ less /tmp/thraed_dump.txt 2014-08-13 18:58:19 Full thread dump Java HotSpot(TM) Server VM (20.5-b03 mixed mode): ------- (中略) ------- "http-28080-exec-20" daemon prio=10 tid=0x62a68000 nid=0x610e runnable [0x00cb3000] java.lang.Thread.State: RUNNABLE at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$6.isSatisfiedBy(Pattern.java:4763) at java.util.regex.Pattern$CharProperty.match(Pattern.java:3345) at java.util.regex.Pattern$Curly.match0(Pattern.java:3782) at java.util.regex.Pattern$Curly.match(Pattern.java:3744) at java.util.regex.Pattern$Start.match(Pattern.java:3055) at java.util.regex.Matcher.search(Matcher.java:1105) at java.util.regex.Matcher.find(Matcher.java:535) ...
結果的に判明したこと
- 後輩君がテスト用データとして"aaaaaa..." という7万文字連続 'a' というテストデータを入れた
- 正規表現エンジンさんが7万の'a'をアホみたたいにパースし続けていたのがCPU負荷の原因
- 「こういう脆弱性もあるんだねー」と後輩くんのおかげで勉強させてもらいました。