【トラブル大捜査線】失われたコネクションを追え！：現場から学ぶWebアプリ開発のトラブルハック（7）（1/3 ページ）

本連載は、現場でのエンジニアの経験から得られた、APサーバをベースとしたWebアプリ開発における注意点やノウハウについて解説するハック集である。現在起きているトラブルの解決や、今後の開発の参考として大いに活用していただきたい。（編集部）

» 2007年09月25日 00時00分公開

[金子崇之，NTTデータ先端技術]

【第1話】今回の原因追究は簡単に思われた

　前回の記事「【真夏の夜のミステリー】Tomcatを殺したのは誰だ？」では、WebサーバとTomcatの間の接続において、スレッド数の不整合により発生したトラブル事例を紹介した。

　今回はTomcatとDBサーバの間のトラブル事例を紹介しよう。

■アプリケーション中からDBコネクションを処理するケース

　アプリケーションサーバとDBサーバとの間のトラブルと聞いてすぐに思い付くのは、DBコネクションのクローズ漏れだ。しかし、O/Rマッピングツールなどのフレームワークが普及したことで、コネクションのオープン／クローズをアプリケーションのコード中から行う必要性は減っている。そのため、クローズ漏れに遭遇する機会も減っている。

　今回問題が発生したシステムでは、ベンチマークを行うためのプログラムを組んでおり、サーブレットを中心としてロジックが実装されていた。つまり、上記のようなフレームワークを使わず、アプリケーション中から直接DBコネクションを処理していた。現在では、なかなかお目に掛かれないアプリケーションの組み方だ。しかし、そういうケースもまれにあるということをご理解いただいたうえで、以降の記事を読んでいただけるとありがたい。

■担当者「突然応答を返さなくなる」

　トラブルの第一報は、「負荷を掛けていると、突然応答を返さなくなる」という知らせだった。例によって、これだけでは何のことかまったく分からない。早速、現場に行き、ベンチマーク担当者からヒアリングを行った。その結果、以下のような状況であることが分かった。

Apache、Tomcat、PostgreSQLを使用した環境であり、それぞれ1台構成である
負荷を掛けていると、突然、まったく応答を返さなくなる
直接Tomcatにアクセスしても、やはり応答は返らない
負荷の量を増やすと、事象が発生するまでの時間が速くなる
問題が発生したときには、CPU負荷も下がってしまい、まったく動いてないように見える
Full GCは発生しておらず、GCは問題になっていないように見える

　調査対象は試験環境であり、かつ問題も再現性があるため、原因追究は簡単に思われた。

【第2話】もはやお馴染み、“トラブル切り分けフロー”

　早速、Webアプリの問題点を「見える化」する7つ道具を利用し、トラブル切り分けフローに従い分析を行うことにした。

図1　トラブル切り分けフロー（連載第1回のものを再掲）

　「0:基本データ分析」と「1:GC分析」はすでに終わっており、問題はないことが確認できている。そこで、次のステップである「2:スレッドダンプ解析」に取り掛かることにした。

■2:スレッドダンプ解析

　Java環境で無応答な事象の原因を追求するときには、スレッドダンプ解析が最も有効だ。ここでスレッドダンプについて、見方を簡単におさらいしておこう。例として、リスト1のような処理を多数のスレッドで実行したとき、得られるスレッドダンプはリスト2のようになる。

リスト1　ロックを取得する処理

01: package ctest.list;

            02: import java.util.List;

            

            ……省略……

            

08: public class ListTestWorker extends Worker {



……省略……



19:         public void execute() throws Exception {

20:                 synchronized(list) {

21:                         list.add(element);

22:                 }

23:         }



……省略……



40: }

リスト2　スレッドダンプ例

"Thread-80" prio=6 tid=0x02cf0f48 nid=0x824 runnable [0x042ef000..0x042ef9e8]

    at java.util.ArrayList.add(ArrayList.java:351)

    at ctest.list.ListTestWorker.execute(ListTestWorker.java:21)

    - locked <0x230d0fa8> (a java.util.ArrayList)

    at ctest.Worker.run(Worker.java:16)

    at java.lang.Thread.run(Thread.java:595)



"Thread-79" prio=6 tid=0x02cf03a8 nid=0xcd4 waiting for monitor entry [0x042af000..0x042afa68]

    at ctest.list.ListTestWorker.execute(ListTestWorker.java:20)

    - waiting to lock <0x230d0fa8> (a java.util.ArrayList)

    at ctest.Worker.run(Worker.java:16)

    at java.lang.Thread.run(Thread.java:595)



"Thread-78" prio=6 tid=0x02cf03a8 nid=0xcd4 waiting for monitor entry [0x042af000..0x042afa68]

    at ctest.list.ListTestWorker.execute(ListTestWorker.java:20)

    - waiting to lock <0x230d0fa8> (a java.util.ArrayList)

    at ctest.Worker.run(Worker.java:16)

    at java.lang.Thread.run(Thread.java:595)



……省略……

　スレッドダンプからは、ロックの使用状況を知ることができる。Thread-80はArrayListのロックを獲得（locked）している。そのほかのスレッドはロック獲得待ち（waiting to lock）であることが分かる。ロック待ちのスレッドが待っている行はListTestWorke.javarの20行目、ロック対象となるオブジェクトは「0x230d0fa8」という値で識別されるjava.util.ArrayListであることが分かる。

　複数のスレッドが同じオブジェクトを操作するとき、整合性を保つためにはロックが必要だ。同じロックを多数のスレッドが獲得しようとしている場合、スレッド数が多過ぎる、ロックの保持期間が長いなど、そのロック付近に並行処理上の問題があるケースが多い。

　また、2つ以上のロックを獲得しようとするような処理の場合、デッドロックになってしまう場合もある。

図2　ロックで問題となるパターン

　複数回のスレッドダンプを比較してスレッドごとの状態変化を確認するのも、無応答の解析には有効だ。まったく状態が変化していないスレッドの場合、やはりその処理の近辺に問題が隠れている場合がある。

■いざ、スレッドダンプ！

　前置きが長くなってしまったが、無応答の状態でスレッドダンプを取得してみた。すると、リスト3のようにGenericObjectPool#borrowObjectメソッドで待っているスレッドが多数検出された。

リスト3　ロック状態のスレッド（拡大したものはこちら）

"http-8080-Processor24" daemon prio=6 tid=0x03b62560 nid=0x150 in Object.wait() [0x04bff000..0x04bffbe8]

                    at java.lang.Object.wait(Native Method)

    at java.lang.Object.wait(Object.java:474)

    at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:810)

    - locked <0x230ef618> (a org.apache.commons.pool.impl.GenericObjectPool)

    at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)

    at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)

    at jp.co.intellilink.online.SearchBean.doExec(SearchBean.java:128)

    at org.apache.jsp.online.search_jsp._jspService(search_jsp.java:43)

    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)

    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)



……省略……