kitaru's diary

大学中退・子持ちのWebエンジニア@渋谷

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負荷の原因
  • 「こういう脆弱性もあるんだねー」と後輩くんのおかげで勉強させてもらいました。

参考