0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

Day 24

IBM Integration & Development Advent Calendar 2025

@keniooi(keniooi)inIBM

Libertyのトランザクションタイムアウトをためす

Posted at

目的

トランザクションのtotalTranLifetimeTimeout、DataSourceのqueryTimeout、requesetTimingのinterruptHungRequests をLibertyとDb2で試します。処理が長くなったときの動作について確認します。

環境の構築

で使用したものを更新しました。構築手順は以下です。

git clone https://github.com/pdprof/db-connections
cd db-connections/derby-docker/
# hostnameコマンドで返す値でアクセスできる場合
export ACCESS_HOST=`hostname`
./setup-docker.sh

Libertyを起動します。(Db2は既に起動しています）
注：他の Container をすでに動かしていてポートが競合する場合は止めます。

./ds-db2-start.sh

トランザクションタイムアウト - totalTranLifetimeTimeout

このサーバーで開始されたトランザクションの完了のために許容されるデフォルトの最大時間。

以下のようなコードでトランザクションを開始して、sleepで時間を経過させるだけでもトランザクションタイムアウト発生時の状態我確認できます。

LongTransaction.java
	@Resource
	UserTransaction ut;
    
	protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
		try {
			ut.begin();
			try {
				for (int i=0; i<13; i++) {
					Thread.sleep(10000);
					System.out.println("LONG : " + (i+1)*10 + " seconds elpased");
				}
			} catch (Exception e) {
				e.printStackTrace();
			}
			ut.commit();
			response.getWriter().append("LONG : transaction finshed in 130 seconds.");
		} catch (Exception e) {
			response.getWriter().append("LONG : " + e.getClass() + " caught");
			e.printStackTrace();
		}
		
	}

Libertyにアクセスします。

http://localhost:9080/db.connections/longtran

デフォルト 120秒のタイムアウト発生時のエラーです。エラー発生のポイントは以下です。

messages.log
[err] javax.transaction.RollbackException
[err] 	at com.ibm.tx.jta.impl.TransactionImpl.stage3CommitProcessing(TransactionImpl.java:1047)
[err] 	at [internal classes]
[err] 	at pdprof.db.connections.LongTransaction.doGet(LongTransaction.java:44)
[err] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
[err] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
[err] 	at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1262)
[err] 	at [internal classes]
[err] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
[err] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[err] 	at java.lang.Thread.run(Thread.java:821)
  • タイムアウトの120秒経過時にエラーは発生しない
  • commit もしくは rollback のタイミングでタイムアウトしていたことを検知してエラーになる

タイムアウトのタイミングで処理が止まるものと誤解していることが多いので注意しましょう。sleepしてるだけですが止まりません。

DataSourceのqueryTimeout

DataSourceのquery実行中にトランザクションのタイムアウトが発生しても同様で処理は中断されません。queryTimeoutは別に考える必要があります。

ここではDb2をもとに試しますが、タイムアウトについては以下に説明があります。

別に考える必要があるとはいったものの、tWASやLibertyの場合はタイムアウトの同期をとる設定があります。syncQueryTimeoutWithTransactionTimeout です。この設定の有無での違いについては以下にあります。

この動作を試します。
以下のコードでテーブルをロックして、その間にQueryをさせるような方法にします。

LockEmployee.java
	protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
		try {
			String sleepStr = request.getParameter("sleep"); // unit second
			int sleep = 110000;
			if (sleepStr != null) {
				try { sleep = Integer.parseInt(sleepStr) * 1000; } catch (Exception e) {};
			} else {
				sleepStr = "110";
			}
			ut.begin();LibertyとDb2でいろいろなタイムアウトを試しました。
			Connection con = ds.getConnection();
			con.createStatement().execute("lock table EMPLOYEE in exclusive mode");
			System.out.println("LOCK : Locking EMPLOYEE table start");
			System.out.println("LOCK : Sleep " + sleep/1000 + " seconds");
			int times = sleep / 10000;
			for (int i = 0; i<times; i++) {
				Thread.sleep(10000);
				System.out.println("LOCK : " + (i + 1)*10 + " seconds elapsed");
			}
			if((sleep%10000)>0) {
				Thread.sleep(sleep%10000);
				System.out.println("LOCK : " + sleepStr + " seconds elapsed");
			}
			ut.commit();
			response.getWriter().append("LOCK : Locking EMPLOYEE table ").append(sleepStr).append(" seconds elapsed and released it.");
		} catch (Exception e) {
			System.out.println("LOCK : " + e.getMessage());
			e.printStackTrace();
			response.getWriter().append("LOCK : " + e.getMessage());
		}
	}

SELECT文は以下で実行します。トランザクションタイムアウトを指定できるようにします。

SelectEmployee.java
	protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
		try {
			String timeoutStr = request.getParameter("timeout"); // unit second
			if (timeoutStr != null) {
				try { 
					int timeout = Integer.parseInt(timeoutStr);
					ut.setTransactionTimeout(timeout);
				} catch (Exception e) {
					timeoutStr = "default";
				};
			} else {
				timeoutStr = "default";
			}
			ut.begin();
			Connection con = ds.getConnection();
			System.out.println("SELECT : select * from EMPLOYEE table start");
			con.createStatement().executeQuery("select * from EMPLOYEE");
			System.out.println("SELECT : select * from EMPLOYEE table end");
			ut.commit();
			response.getWriter().append("SELECT : select * from EMPLOYEE table in transaction timeout with ").append(timeoutStr).append(".");
		} catch (Exception e) {
			System.out.println("SELECT : " + e.getMessage());
			e.printStackTrace();
			response.getWriter().append("SELECT : " + e.getMessage());
		}
	}

Lock待ちを確認

Docker環境でテストします。ロック開始で以下にアクセス

http://localhost:9080/db.connections/lock

ロック中にselectのため以下にアクセス

http://localhost:9080/db.connections/select

110秒のロックと

server.xml
<dataSource queryTimeout="112s" syncQueryTimeoutWithTransactionTimeout="false" id="PdprofDataSource" jdbcDriverRef="Db2Driver" jndiName="jdbc/derbyEmbedded" type="javax.sql.DataSource" >

の設定で queryTimeoutが発生せずに終了します。

queryTimeoutを確認

ロック時間を115秒にするのに以下にアクセス

http://localhost:9080/db.connections/lock?sleep=115

ロック開始後、すぐに以下にアクセス (queryTImeout 秒）

http://localhost:9080/db.connections/select

ロック開放前に queryTimeoutが発生します。

console.log
LOCK : 110 seconds elapsed
SELECT : Processing was cancelled due to an interrupt.. SQLCODE=-952, SQLSTATE=57014, DRIVER=4.32.28
[err] com.ibm.db2.jcc.am.SqlTimeoutException: Processing was cancelled due to an interrupt.. SQLCODE=-952, SQLSTATE=57014, DRIVER=4.32.28
[err] 	at com.ibm.db2.jcc.am.b7.a(b7.java:812)
[err] 	at com.ibm.db2.jcc.am.b7.a(b7.java:66)
[err] 	at com.ibm.db2.jcc.am.b7.a(b7.java:140)
[err] 	at com.ibm.db2.jcc.am.ResultSet.completeSqlca(ResultSet.java:4385)
[err] 	at com.ibm.db2.jcc.am.ResultSet.earlyCloseComplete(ResultSet.java:4367)
[err] 	at com.ibm.db2.jcc.t4.ab.a(ab.java:1658)
[err] 	at com.ibm.db2.jcc.t4.ab.q(ab.java:1620)
[err] 	at com.ibm.db2.jcc.t4.ab.l(ab.java:741)
[err] 	at com.ibm.db2.jcc.t4.ab.d(ab.java:110)
[err] 	at com.ibm.db2.jcc.t4.p.c(p.java:44)
[err] 	at com.ibm.db2.jcc.t4.av.j(av.java:162)
[err] 	at com.ibm.db2.jcc.am.lc.an(lc.java:2300)
[err] 	at com.ibm.db2.jcc.am.lc.a(lc.java:3379)
[err] 	at com.ibm.db2.jcc.am.lc.a(lc.java:744)
[err] 	at com.ibm.db2.jcc.am.lc.executeQuery(lc.java:723)
[err] 	at com.ibm.ws.rsadapter.jdbc.WSJdbcStatement.executeQuery(WSJdbcStatement.java:576)
[err] 	at pdprof.db.connections.SelectEmployee.doGet(SelectEmployee.java:54)
[err] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
[err] 	at [internal classes]
[err] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[err] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[err] 	at java.base/java.lang.Thread.run(Thread.java:839)
LOCK : 115 seconds elapsed

ロックの時間が伸びたので、queryTimeout（設定値の112秒）が発生します。

syncQueryTimeoutWithTransactionTimeout : true

以下のように server.xml を変更します。

podman exec -it db2-connections bash
vi /config/server.xml

<dataSource queryTimeout="112s" syncQueryTimeoutWithTransactionTimeout="true" id="PdprofDataSource" jdbcDriverRef="Db2Driver" jndiName="jdbc/derbyEmbedded" type="javax.sql.DataSource" >

ロック 115秒とトランザクションタイムアウト（queryTimeoutは同期）120秒はエラーが起きなくなります。

http://localhost:9080/db.connections/lock?sleep=115

http://localhost:9080/db.connections/select

次に ロック115秒(上のテストをそのまま使う）、トランザクションタイムアウト30秒 をためします。

http://localhost:9080/db.connections/lock?sleep=115

http://localhost:9080/db.connections/select?timeout=30

30秒経過後にqueryTimeoutが発生します。

console.log
LOCK : 30 seconds elapsed
SELECT : Processing was cancelled due to an interrupt.. SQLCODE=-952, SQLSTATE=57014, DRIVER=4.32.28
[err] com.ibm.db2.jcc.am.SqlTimeoutException: Processing was cancelled due to an interrupt.. SQLCODE=-952, SQLSTATE=57014, DRIVER=4.32.28
[err] 	at com.ibm.db2.jcc.am.b7.a(b7.java:812)
[err] 	at com.ibm.db2.jcc.am.b7.a(b7.java:66)
[err] 	at com.ibm.db2.jcc.am.b7.a(b7.java:140)
[err] 	at com.ibm.db2.jcc.am.ResultSet.completeSqlca(ResultSet.java:4385)
[err] 	at com.ibm.db2.jcc.am.ResultSet.earlyCloseComplete(ResultSet.java:4367)
[err] 	at com.ibm.db2.jcc.t4.ab.a(ab.java:1658)
[err] 	at com.ibm.db2.jcc.t4.ab.q(ab.java:1620)
[err] 	at com.ibm.db2.jcc.t4.ab.l(ab.java:741)
[err] 	at com.ibm.db2.jcc.t4.ab.d(ab.java:110)
[err] 	at com.ibm.db2.jcc.t4.p.c(p.java:44)
[err] 	at com.ibm.db2.jcc.t4.av.j(av.java:162)
[err] 	at com.ibm.db2.jcc.am.lc.an(lc.java:2300)
[err] 	at com.ibm.db2.jcc.am.lc.a(lc.java:3379)
[err] 	at com.ibm.db2.jcc.am.lc.a(lc.java:744)
[err] 	at com.ibm.db2.jcc.am.lc.executeQuery(lc.java:723)
[err] 	at com.ibm.ws.rsadapter.jdbc.WSJdbcStatement.executeQuery(WSJdbcStatement.java:576)
[err] 	at pdprof.db.connections.SelectEmployee.doGet(SelectEmployee.java:54)
[err] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
[err] 	at [internal classes]
[err] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[err] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[err] 	at java.base/java.lang.Thread.run(Thread.java:839)
LOCK : 40 seconds elapsed

requesetTimingのinterruptHungRequests

ハング検知のタイミングで処理を中断する設定です。IBM Java8（Semeruはだめ）でしか動作しませんが、ハング時に処理が中断（試みることが）できます。

注意事項の抜粋です。

注:

  • リクエストの割り込みは、 IBM JRE 11以降のバージョンではサポートされておらず、 IBM Semeru 8以降のバージョンではサポートされていません
  • 複数のハング要求が同時に検出された場合、各要求は、最初のハング要求に対する最初のスレッド・ダンプが完了するのを待ってから、その要求の中断を試みます

ハング検知の設定

3分でハングを検知して、interruptHungRequest=true です。

server.xml
    <requestTiming hungRequestThreshold="3m" interruptHungRequests="true"
       slowRequestThreshold="5s">
    </requestTiming>
    <dataSource id="PdprofDataSource" jdbcDriverRef="Db2Driver" 
       jndiName="jdbc/derbyEmbedded" type="javax.sql.XADataSource"
       queryTimeout="112s" syncQueryTimeoutWithTransactionTimeout="true" >

以下の順でアクセスします。

  1. Employee テーブルをロック 115 秒 （Transaction 1 - 120秒以内）
  2. 1の直後 EmployeeをSELECTしたあとに TmployeeをSELECTする処理
    (Transaction 2 - timeout 200秒）
  3. 1開始の100秒後 Tmployee テーブルをロック 120 秒 （Transaction 3 - 120秒以内）

Transaction 1 完了前に Transaction 3 を開始して、Transaction 2 を長時間またせるようにします。

  • Transaction 1
http://localhost:9080/db.connections/lock?sleep=115

次に、ロック中に トランザクションタイムアウト 200 秒 で EMPLOYEE, TMPLOYEEを順にSELECTする処理にアクセスします。180秒時点でハングとなり、interrupt される想定です。

  • Transaction 2
http://localhost:9080/db.connections/selectemptmp?timeout=200

Transaction 1 開始から100秒後、Transaction 3 開始

  • Transaction 3
http://localhost:9080/db.connections/locktmp?sleep=115

以下のエラーで queryTimeoutではなく中断されることを確認しました。、

console.log
[AUDIT   ] J2CA0056I: The Connection Manager received a fatal connection error from the Resource Adapter for resource jdbc/derbyEmbedded. The exception is: state STATE_TRAN_WRAPPER_INUSE com.ibm.db2.jcc.am.DisconnectNonTransientConnectionException: [jcc][t4][2030][11211][4.32.28] A communication error occurred during operations on the connection's underlying socket, socket input stream, 
or socket output stream.  Error location: Reply.fill() - socketInputStream.read (-1).  Message: Socket closed. ERRORCODE=-4499, SQLSTATE=08001:java.net.SocketException: Socket closed
SELECT : [jcc][t4][2030][11211][4.32.28] A communication error occurred during operations on the connection's underlying socket, socket input stream, 
or socket output stream.  Error location: Reply.fill() - socketInputStream.read (-1).  Message: Socket closed. ERRORCODE=-4499, SQLSTATE=08001
[err] com.ibm.db2.jcc.am.DisconnectNonTransientConnectionException: [jcc][t4][2030][11211][4.32.28] A communication error occurred during operations on the connection's underlying socket, socket input stream, 
or socket output stream.  Error location: Reply.fill() - socketInputStream.read (-1).  Message: Socket closed. ERRORCODE=-4499, SQLSTATE=08001
[err] 	at com.ibm.db2.jcc.am.b7.a(b7.java:338)
[err] 	at com.ibm.db2.jcc.t4.a.a(a.java:577)
[err] 	at com.ibm.db2.jcc.t4.a.a(a.java:561)
[err] 	at com.ibm.db2.jcc.t4.a.a(a.java:556)
[err] 	at com.ibm.db2.jcc.t4.a.b(a.java:1727)
[err] 	at com.ibm.db2.jcc.t4.a.a(a.java:1752)
[err] 	at com.ibm.db2.jcc.t4.y.b(y.java:276)
[err] 	at com.ibm.db2.jcc.t4.y.c(y.java:342)
[err] 	at com.ibm.db2.jcc.t4.y.c(y.java:455)
[err] 	at com.ibm.db2.jcc.t4.y.v(y.java:1230)
[err] 	at com.ibm.db2.jcc.t4.ab.b(ab.java:93)
[err] 	at com.ibm.db2.jcc.t4.p.a(p.java:32)
[err] 	at com.ibm.db2.jcc.t4.av.i(av.java:150)
[err] 	at com.ibm.db2.jcc.am.lc.al(lc.java:2247)
[err] 	at com.ibm.db2.jcc.am.lc.a(lc.java:3376)
[err] 	at com.ibm.db2.jcc.am.lc.a(lc.java:744)
[err] 	at com.ibm.db2.jcc.am.lc.executeQuery(lc.java:723)
[err] 	at com.ibm.ws.rsadapter.jdbc.WSJdbcStatement.executeQuery(WSJdbcStatement.java:576)
[err] 	at pdprof.db.connections.SelectEmpTmp.doGet(SelectEmpTmp.java:58)
[err] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
[err] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
[err] 	at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1262)
[err] 	at [internal classes]
[err] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
[err] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[err] 	at java.lang.Thread.run(Thread.java:821)
[err] Caused by: 
[err] java.net.SocketException: Socket closed
[err] 	at java.net.SocketInputStream.socketRead(SocketInputStream.java:127)
[err] 	at java.net.SocketInputStream.read(SocketInputStream.java:182)
[err] 	at java.net.SocketInputStream.read(SocketInputStream.java:152)
[err] 	at com.ibm.db2.jcc.t4.y.b(y.java:230)
[err] 	... 44 more
[WARNING ] TRAS0115W: Request AALPAclZxCA_AAAAAAAAAE1 on thread 00000ae5 which was previously detected to be hung, has completed after 180115.938ms.

IBM Java8でないと動作しない点に注意しましょう。queryTimeout と interruptHungRequests では発生しているExceptionとスタックに違いがありました。発生原因を考えるための参考にできます。

トラブルシューティング

毎度のことですが、よくつかう dockerコマンドを書いておきます。この文書でもpodman, dockerとまとまりがないですが、Linux では dockerがpodmanを呼び出すようになっていました。

docker ps # 動作中のContainer確認
docker logs -f db2-connections # ログ確認
docker restart db2-connections # 再起動
docker inspect db2-connections # container 確認
docker exec -it db2-connections bash # Container内状況確認

まとめ

トランザクションのTimeout、DataSourceのqueryTimeout、requesetTimingのinterruptHungRequests をLibertyとDb2で試しました。処理が長くなったときの動作について確認しました。

参考

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?