戯言

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

スポンサーサイト


上記の広告は1ヶ月以上更新のないブログに表示されています。
新しい記事を書く事で広告が消せます。

デバッグ用設定の戻し忘れで、Connection has already been closed.


こんなログが出てました。

catalina.out にはこんなログ
2015/02/08 19:46:39 org.apache.tomcat.jdbc.pool.ConnectionPool abandon
警告: Connection has been abandoned PooledConnection[org.apache.derby.impl.jdbc.EmbedConnection40@1059970 (XID = 1881168832), (SESSIONID = 131), (DATABASE = /javadb/werewolf), (DRDAID = null) ]:java.lang.Exception
	at org.apache.tomcat.jdbc.pool.ConnectionPool.getThreadDump(ConnectionPool.java:1063)
	at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:780)
	at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:619)
	at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:188)
	at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128)
	:
	:

例外発生時のスタックトレースはこんなログ

java.sql.SQLException: Connection has already been closed.
	at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
	at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:80)
	at com.sun.proxy.$Proxy6.commit(Unknown Source)
	at jp.werewolf.db.DBAccess.reDropInsertAndCreateIndexRecord(DBAccess.java:4334)
	:
	:

close漏れ発見のために、DBCP のコネクションの追跡機能で removeAbandoned=true、
logAbandoned=trueで運用していて、
close漏れの対応完了後もそのままにしていたところ、
裏で回しておくだけの長時間かかるトランザクションが、
タイムアウト時間以上かかってしまって、これらのエラーとなりました。

クエリがまだ実行中にもかかわらず、タイムアウト時間がきて
コネクションが回収されてしまうと、 abandon の警告ログが出ます。
で、さらに回収後にクエリを実行して Connection has already been closed. と
なったようです。

タイムアウト時間を延ばそうかとも思ったのですが、
abandon の機能自体を無効にしました。

調査後もデバッグ用の設定のままにしていた凡ミスです。




スポンサーサイト

コネクションプール利用時のConnection.setAutoCommit(false)のワナ


Connection.setAutoCommit() でちょっとハマりました。

とあるトランザクション制御が必要ない単一のクエリで、
デフォルトの true が効かずに、autoCommitが意図せずに false に
なっている場合があって、こちらの期待通りの動きをしない可能性がありました。


どういうことかというと・・・、

トランザクション制御が必要なクエリでは、
autoCommit を false に設定していますが、クエリ実行後に、このトランザクションは終了して、
Connection も close するので、false になるのはこのトランザクションのみで、
他のトランザクションへの影響はないと思っていました。

ですが、一旦 false に設定すると、別のクエリで、Connection を取得した
場合に、false の設定のままとなっていて、
マルチスレッド環境で、複数のクエリが動いた場合に、
期待とおりでない動作をするケースがあったようです。

ざっくり書くと、トランザクション制御が必要なクエリを実行するメソッドは、こんな感じで書いていました。

public void トランザクション制御が必要となるクエリの実行(){
	Connection conn = null;
	try {
		conn = createConnection();
		conn.setAutoCommit(false);
			:
			:
			// トランザクション制御するクエリ実行
			:
			:
		conn.commit();
	} catch (SQLException e) {
		conn.rollback();
	} finally {
		conn.close();
	}
}
public void トランザクション制御が必要ないクエリの実行(){
	Connection conn = null;
	try {
		conn = createConnection();
			:
			:
		// トランザクション制御しないクエリ実行
			:
	} finally {
		conn.close();
	}
}

createConnection() というコネクション払出し用のメソッドを作っていて、
その中身はこんな感じです。

public Connection createConnection() throws SQLException {
	try{
		InitialContext ic = new InitialContext();
		DataSource ds = (DataSource)ic.lookup("java:comp/env/jdbc/・・・・");
		Connection conn = ds.getConnection();
		
		return conn;
	}
	catch (NamingException ex){
		// 例外処理(略)
	}
}
「トランザクション制御が必要となるクエリの実行()」が呼ばれ、終了した時点で、
autoCommit は false のままとなってます。

その後、別のトランザクションで、「トランザクション制御が必要ないクエリの実行()」を
呼出した場合に、新たにcreateConnection() を呼び出すのですが、
返ってくる Connection オブジェクトの autoCommit は false になっていました。

単一クエリの実行では、(自動コミットされると思っているので)commit()を
明示的に呼び出していないので、close()が呼ばれるまでの間、
コミットされていない状態になってしまっていました。
createConnection() で return する前に、true 設定するようにしておきました。



では、なぜ、コネクションを切ってるのに、次のコネクションに設定が残ってるのか。
よくよく考えたら、コネクションプールを使ってるからでした。
予めコネクションを作ってプールしといて、必要なときに払いだしているのだから、
当たり前といえば当たり前。

一応、こんな感じのソースで確認しました。

コネクションプールを使う場合
public Connection createConnection() throws SQLException {
	try{
		// DBCPを利用
		InitialContext ic = new InitialContext();
		DataSource ds = (DataSource)ic.lookup("java:comp/env/jdbc/・・・・");
		Connection conn = ds.getConnection();
		
		// 一旦クエリ実行時に false にセットすると、次からは払いだした時点でfalseになる。
		System.out.println("autoCommit=" + conn.getAutoCommit());

		return conn;
	}
	catch (NamingException ex){
		// 例外処理(略)
	}
}
コネクションプールを使わない場合
public Connection createConnection() throws SQLException {
	try{
		// CPを利用しない
		Class.forName("org.apache.derby.jdbc.EmbeddedDriver");
		Connection conn = DriverManager.getConnection("jdbc:derby:/.../....",name, pass);
		
		// 常に true になることを確認。
		System.out.println("autoCommit=" + conn.getAutoCommit());

		return conn;
	}
	catch (ClassNotFoundException ex){
		// 例外処理(略)
	}
}



INFO: task <プロセス名>:<PID> blocked for more than 120 seconds.とコンソール表示され、OSごと無応答になる


INFO: task <プロセス名>:<PID> blocked for more than 120 seconds.とコンソール表示され、OSごと無応答になる。

まだトラブル2を解決できていない時に、だましだましでサーバを動かしていたら、
10時間くらい経過したあたりで、カーネルがハングして、
こんなメッセージが数行コンソールに出てサーバが固まっていました。

INFO: task ****:<PID> blocked for more than 120 seconds.
Not tainted *****************
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

再起動しても、時間が経つとまた発生して、3回くらいこれで鯖落ちしました。

一応 /proc/sys/kernel/hung_task_timeout_secs は 0 にしておきましたが、
これってハングしたタスクを確認するタイミングの指定であって、
ハングする問題自体を解決するわけではないですよね?
(誤りのご指摘歓迎します)

ハードウェア性能的な問題かと頭をよぎり、やばいなーと思ってて、
対策の見当がついていなかったんですが、
トラブル2を解決したあたりから、
このトラブルも自然に起きなくなりました。

デッドロックなどで急激にIO負荷がかかっていたのが原因? 

よくわからんです。

まーいいや、発生しなくなったっぽいです。

==2015/2/17追記======
頻度は低くなったものの、たまに発生してました。

ちょっとカーネルパラメータ弄って様子見中。





上記広告は1ヶ月以上更新のないブログに表示されています。新しい記事を書くことで広告を消せます。