戯言

つらつらと気づいたことを書いていきます。人狼とか。

java.sql.SQLTransactionRollbackException: 要求時間内にロックを獲得できませんでした と デッドロックが原因でロックを獲得できませんでした


プログラムは全く変えてないのに、OS,tomcatのバージョンをあげたら
突然デッドロックが発生するようになっちゃいました。

発生している例外はこれら。
java.sql.SQLTransactionRollbackException: 要求時間内にロックを獲得できませんでした。
java.sql.SQLTransactionRollbackException: デッドロックが原因でロックを獲得できませんでした。

実害としては、ロック解放待ちで、クエリの実行が待ち状態となり、
ブラウザが応答しないように見えるのでサーバが重くなったように感じます。

また、ロックを取得できなかった場合に発生する
java.sql.SQLTransactionRollbackException の例外発生時の処理が
適切でなかったために、
村番号が被ったりするなどの問題が発生しました。

発生の原因を探すのに大変苦労しましたが、
根本原因は凡ミスで、PreparedStatementのclose処理漏れ。

今まで問題が顕在化しなかった理由がよくわかりません。
tomcat のバージョンが変わったので、DBCP の処理に変更でもあったからなのだろうか・・・。

JDBCドライバは変更してないしなあ。
今まではGCで救われていたとか。

とにもかくにもプログラムが問題なので、修正しました。

問題があったソースはこんな感じでした。

selectした結果が1件ならupdateして、0件ならinsertするような処理です。

Connection conn = null;
PreparedStatement state = null;
ResultSet rs = null;

try {
	conn = createConnection();	// DBCPからConnectionを取得するためのメソッド
	conn.setAutoCommit(false);

	state = conn.prepareStatement("SELECT ・・・・");
	state.setString(1, HN);
	state.setString(2, TRIP);

	rs = state.executeQuery();
	rs.next();
	int count = rs.getInt("COUNT");

	// INSERT
	if (count == 0){
		query = "INSERT ・・・";
	}
	// UPDATE
	else if (count == 1){
		query = "UPDATE ・・・";
	} else {
		// 略	
	}

	state = conn.prepareStatement(query);
	state.execute();
	conn.commit();
		
} catch (SQLException ex) {
	ex.printStackTrace();
	try{
		if (conn != null) conn.rollback();
	}catch(SQLException e){
		e.printStackTrace();
	}

} finally {
	try {
		if (rs != null) rs.close();
	} catch (Exception ex) {
		ex.printStackTrace();
	}
	try {
		if (state != null) state.close();
	} catch (Exception ex) {
		ex.printStackTrace();
	}
	try {
		if (conn != null)conn.close();
	} catch (Exception ex) {
		ex.printStackTrace();
	}
}

一見finally句でcloseできているように見えます。

でもダメ。

9行目のPreparedStatementを閉じることなく
28行目で上書きしているので、
9行目のPreparedStatementがcloseされずに残ってしまうのです。

気づいてませんでした。

Statementなら、この書き方でもOKみたいだけど、
PreparedStatementの場合は、使いまわす前にcloseしないと、
オブジェクトが残ってしまうようです。

対応としては、16行目に、state.close()を追加するだけです。
念のためにrs.close()も追加しときました。

同じような問題で、
forループ中でprepareStatementを更新していて、
closeしていないパターンもありました。

Connection conn = null;
PreparedStatement state = null;

try {
	conn = createConnection();
	conn.setAutoCommit(false);

	for (数回の繰り返し){
		query = "INSERT ・・・"
		// ここでqueryをちょっと変更

		state = conn.prepareStatement(query);
		state.execute();
	}
	conn.commit();

} catch (SQLException ex) {
	ex.printStackTrace();
	try{
		if (conn != null) conn.rollback();
	}catch(SQLException e){
		e.printStackTrace();
	}

} finally {
	try {
		if (rs != null) rs.close();
	} catch (Exception ex) {
		ex.printStackTrace();
	}
	try {
		if (state != null) state.close();
	} catch (Exception ex) {
		ex.printStackTrace();
	}
	try {
		if (conn != null)conn.close();
	} catch (Exception ex) {
		ex.printStackTrace();
	}
}

finally句でConnection、ResultSet、Statementを全てcloseしていて、
close漏れはないと思い込んでいたので、
close漏れをなかなか発見できませんでした。

これを見つけるまでに時間がかかってしまったので、
発見前に別の対策をいろいろと打ったんですが、
close漏れが根本の問題でした。



発見前に打った対策にも、一応触れておくと。。。

ロックでトラぶっていたので、なるべくDBへのアクセスを減らして
ロックがかかるかもしれない処理を抑制しようということで、
一例としては、現在の村番号で最大の番号を取得する処理があるのですが、
あまり更新もないのに参照はいろんなところからされていて、
その参照のたびにデータベースにアクセスに行っていたので、
この無駄を省くために、
番号が変更になったとき(村が建ったとき)に村番号をstaticな変数に格納しておき、
最大番号を知りたい場合はその変数を見に行くようにしました。

など


また、DB関連の例外処理も不味かったです。
あまり例外が発生しなそうなところは、
catch時のルーチン内でとりあえずnullを返すような乱暴な作りにしちゃってましたが、
ユーザ向けメッセージを表示するなり、
throwして呼び出し元に返したりなど、
きちんと書き直しました。

手を抜くとやばいですね。






tomcatの起動時にjavaDB関連のクラスでClassNotFoundExceptionが発生する


tomcatのバージョンが上がり、DBCPの仕組みが変わったらしく、

  [アプリ名]/WEB-INF/lib

ではなく、

  [tomcatインストールディレクトリ]/lib

配下にJDBCドライバのjarファイルを置いておかないといけなくなったようです。

derby関連のjarファイルを、移動して解決しました。


DBCPの設定は

   [tomcatインストールディレクトリ]/conf/Catalina/localhost/[アプリ名].xml

で Resource 定義していたんですが、
設定中のJDBCドライバのクラスを探せなくて、
ClassNotFoundExceptionになったっぽいです。

tomcat7のマイナーバージョンを上げただけなんですが、
急に使えなくなったりするのね。

以前から、[tomcatインストールディレクトリ]/lib に置くのが正当だったようで。



2月1日のメンテでは、この問題を解決してトラブル終了と笑みを浮かべていたら、更なる問題が発生したわけですが・・・。

サーバ不調でご迷惑をおかけしました


2月1日のメンテナンス以来、サーバが不安定な状態が続き、ご迷惑をおかけしました。
2月9日時点で、ほぼ改善されたと思います。たぶん・・・。

今後のためにも、問題と対策について、整理しておきます。

まず、今回のメンテナンス作業では、OSやミドルソフトのバージョンアップのみで、プログラムの修正は行っていませんでした。

そのため、プログラムに原因はなく、サーバ環境設定の問題だと思い込んで解析をスタートしたのですが、これがダメでした。今回は、OS(またはtomcat)のバージョンが上がったことにより、もともと潜んでいたプログラム上の問題が顕在化するということが起きています。(下記のトラブル2)

もともとプログラムの作りが悪かったこと自体が問題ではあるのですが、(何故か)OSアップデート以前は同じプログラムで問題なく動作していました。

発生した問題は複数あります。もしかすると、OSやtomcatのバージョンアップとは無関係に発生したトラブルなのかもしれませんが、全てバージョンアップ作業後に初めて遭遇した問題です。


トラブル1
tomcatの起動時にjavaDB関連のクラスでClassNotFoundExceptionが発生する


トラブル2
java.sql.SQLTransactionRollbackException: 要求時間内にロックを獲得できませんでした
java.sql.SQLTransactionRollbackException: デッドロックが原因でロックを獲得できませんでした。
が発生する


トラブル3
INFO: task : blocked for more than 120 seconds.とコンソール表示され、OSごと無応答になる


それぞれのトラブルについては、別記事でアップします。