17.18.3 出力例と解析方法
(1) 出力例
Exceptionトレースログの出力例を次に示します。
[1] HiRDB_Type4_JDBC40_Driver 09-50 2006/07/06 23:07:09.129 Thread[main,5,main]@1259414@1:[E][PrdbConnection@82c01f.createStatement(1)] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:09.160 Thread[main,5,main]@1259414@1:[R][PrdbConnection@82c01f.createStatement(1)] ConnectionID(sds:23:20484) : SID(0) Return=JP.co.Hitachi.soft.HiRDB.JDBC.PrdbStatement@1e4cbc4 2006/07/06 23:07:09.160 Thread[main,5,main]@1259414@1:[E][PrdbStatement@1e4cbc4.execute] ConnectionID(sds:23:20484) : SID(0) sql=DELETE FROM SEINO_TABLE 2006/07/06 23:07:14.285 Thread[main,5,main]@1259414@1:[E][PrdbConnection@82c01f.commit] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:14.301 Thread[main,5,main]@1259414@1:[R][PrdbConnection@82c01f.commit] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:14.301 Thread[main,5,main]@1259414@1:[R][PrdbStatement@1e4cbc4.execute] ConnectionID(sds:23:20484) : SID(1) Return=false 2006/07/06 23:07:14.301 Thread[main,5,main]@1259414@1:[E][PrdbConnection@82c01f.prepareStatement(1)] ConnectionID(sds:23:20484) : SID(0) sql=INSERT INTO SEINO_TABLE VALUES(?, ?) 2006/07/06 23:07:14.348 Thread[main,5,main]@1259414@1:[R][PrdbConnection@82c01f.prepareStatement(1)] ConnectionID(sds:23:20484) : SID(0) Return=JP.co.Hitachi.soft.HiRDB.JDBC.PrdbPreparedStatement@15d56d5 2006/07/06 23:07:26.567 Thread[main,5,main]@1259414@1:[E][PrdbConnection@82c01f.commit] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:26.567 Thread[main,5,main]@1259414@1:[R][PrdbConnection@82c01f.commit] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:26.567 Thread[main,5,main]@1259414@1:[E][PrdbStatement@1e4cbc4.executeQuery] ConnectionID(sds:23:20484) : SID(0) sql=SELECT * FROM SEINO_TABLE 2006/07/06 23:07:26.676 Thread[main,5,main]@1259414@1:[R][PrdbStatement@1e4cbc4.executeQuery] ConnectionID(sds:23:20484) : SID(1) Return=JP.co.Hitachi.soft.HiRDB.JDBC.PrdbResultSet@3eca90 2006/07/06 23:07:28.332 Thread[main,5,main]@1259414@1:[E][PrdbResultSet@3eca90.close] ConnectionID(sds:23:20484) : SID(1) 2006/07/06 23:07:28.332 Thread[main,5,main]@1259414@1:[E][PrdbConnection@82c01f.commit] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:28.332 Thread[main,5,main]@1259414@1:[R][PrdbConnection@82c01f.commit] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:28.332 Thread[main,5,main]@1259414@1:[R][PrdbResultSet@3eca90.close] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:28.332 Thread[Thread-0,5,main]@30090737@2:[E][PrdbConnection@82c01f.prepareStatement(1)] ConnectionID(sds:23:20484) : SID(0) sql=SELECT * FROM SEINO_TABLE 2006/07/06 23:07:28.332 Thread[Thread-0,5,main]@30090737@2:[R][PrdbConnection@82c01f.prepareStatement(1)] ConnectionID(sds:23:20484) : SID(0) Return=JP.co.Hitachi.soft.HiRDB.JDBC.PrdbPreparedStatement@2808b3 2006/07/06 23:07:28.348 Thread[Thread-1,5,main]@5462872@3:[E][PrdbConnection@82c01f.prepareStatement(1)] ConnectionID(sds:23:20484) : SID(0) sql=DELETE FROM SEINO_TABLE WHERE I1=? 2006/07/06 23:07:28.358 Thread[Thread-1,5,main]@5462872@3:[E][PrdbConnection@82c01f.commit] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:29.672 Thread[Thread-1,5,main]@5462872@3:[R][PrdbConnection@82c01f.commit] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:30.098 Thread[Thread-1,5,main]@5462872@3:[R][PrdbConnection@82c01f.prepareStatement(1)] ConnectionID(sds:23:20484) : SID(0) Return=JP.co.Hitachi.soft.HiRDB.JDBC.PrdbPreparedStatement@922804 2006/07/06 23:07:30.332 Thread[Thread-2,5,main]@25253977@4:[E][PrdbConnection@82c01f.rollback(1)] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:42.098 Thread[Thread-2,5,main]@25253977@4:[R][PrdbConnection@82c01f.rollback(1)] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:42.098 Thread[Thread-2,5,main]@25253977@4:[E][PrdbConnection@82c01f.close] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:42.098 Thread[Thread-2,5,main]@25253977@4:[R][PrdbConnection@82c01f.close] ConnectionID(sds:23:20484) : SID(0) 2006/07/06 23:07:42.535 Thread[Thread-1,5,main]@5462872:Exception: ExceptionClass: SQLException UapEnvironment: * Message: KFPJ20006-E Connection closed[PrdbPreparedStatement.setInt] ErrorCode: -1020006 SQLState: R2400 Etc.: *,*,**** URLInfo: jdbc:hitachi:hirdb://DBHOST=localhost,DBID=22200, ENCODELANG=UTF-8 RootAP:127.0.0.1/1234/0x0000000000000001 PropertyInfo: [URL]ENCODELANG=UTF-8 java.sql.SQLException: KFPJ20006-E Connection closed[PrdbPreparedStatement.setInt] at JP.co.Hitachi.soft.HiRDB.JDBC.JdbMakeException.generateSQLException(JdbMakeException.java:31) at JP.co.Hitachi.soft.HiRDB.JDBC.PrdbStatement.generateClosedSQLException(PrdbStatement.java:3005) at JP.co.Hitachi.soft.HiRDB.JDBC.PrdbPreparedStatement.setInt(PrdbPreparedStatement.java:1170) at Exception1.run(ExceptionTraceSample.java:57) [2] HiRDB_Type4_JDBC_Driver 09-50 2006/07/06 23:07:25.863 Thread[Thread-5,5,main]@24431647@5:Warning: UapEnvironment: USER(USER1), NAMEPORT(22200), CWAITTIME(0), SWAITTIME(600), HOST(localhost), FESHOST( ), SERVICEGRP(sds), SWATCHTIME( ), SERVICEPORT( ), SRVTYPE(WS), CLTRCVPORT( ), CLTRCVADDR( ), FESGRP( ) Message: KFPZ02445-I Client information, Type=Reconnect,inf=AUTO_RECONNECT,number=5,interval=5 [PrdbStatement.prepare] Etc.: 4,sqapyac1.c(651),SET URLInfo: jdbc:hitachi:hirdb://DBHOST=localhost,DBID=22200, ENCODELANG=UTF-8 RootAP:127.0.0.1/1234/0x0000000000000001 PropertyInfo: [URL]ENCODELANG=UTF-8
(2) 解析方法
Exceptionトレースログの解析方法について説明します。Exceptionトレースログはテキストエディタなどで参照できます。
ここでは,「出力例」のExceptionトレースログを解析する例を示します。
解析例
-
調査対象の例外を含む通番の情報を抜き出します。
-
情報をThread識別情報で分類し,スレッドごとに分割します。
-
取得時刻によって,情報を時系列に並べます。
次の表に示すようになります。
表17‒129 Exceptionトレースログを時系列に並べた例 日時
スレッド1
スレッド2
スレッド3
スレッド4
Thread[main,5,main]
@1259414@1
Thread[Thread-0,5,main]
@30090737@2
Thread[Thread-1,5,main]
@5462872@3
Thread[Thread-2,5,main]
@25253977@4
2006/07/06
23:07:09.129
PrdbConnection
@82c01f.createStatement(1)
2006/07/06
23:07:09.160
PrdbStatement
@1e4cbc4.execute
2006/07/06
23:07:14.285
PrdbConnection
@82c01f.commit
2006/07/06
23:07:14.301
PrdbConnection
@82c01f.prepareStatement(1)
2006/07/06
23:07:26.567
PrdbConnection
@82c01f.commit
2006/07/06
23:07:26.567
PrdbStatement
@1e4cbc4.executeQuery
2006/07/06
23:07:26.567
PrdbStatement
@1e4cbc4.execute
2006/07/06
23:07:28.332
PrdbResultSet
@3eca90.close
PrdbConnection
@82c01f.prepareStatement(1)
2006/07/06
23:07:28.332
PrdbConnection
@82c01f.commit
2006/07/06
23:07:28.348
PrdbConnection
@82c01f.prepareStatement(1)
2006/07/06
23:07:28.358
PrdbConnection
@82c01f.commit
2006/07/06
23:07:30.332
PrdbConnection
@82c01f.rollback
2006/07/06
23:07:42.098
PrdbConnection
@82c01f.close
2006/07/06
23:07:42.535
SQLException発生
KFPJ20006-E Connection closed
-
Exceptionのエラーの内容を確認します。
2006/07/06 23:07:42.535のスレッド3でSQLExceptionが発生し,Statementオブジェクト又はConnectionオブジェクトが既にクローズされていることが分かります。
-
時系列でオブジェクトの操作を確認します。
次のスレッドのConnectionオブジェクトのオブジェクトIDが同じであることから,四つのスレッドが同一のコネクションで処理されていることが分かります。
-
2006/07/06 23:07:09.129のスレッド1
-
2006/07/06 23:07:28.332のスレッド2
-
2006/07/06 23:07:28.348のスレッド3
-
2006/07/06 23:07:30.332のスレッド4
-
-
エラーの原因である箇所を探します。
四つのスレッドが同一のコネクションであることは分かったので,Statement.closeメソッド又はConnection.closeメソッドを実行している箇所を探すと,スレッド4が2006/07/06 23:07:42.098でConnection.closeメソッドを実行していることが分かります。このことから,2006/07/06 23:07:42.535のスレッド3で発生したSQLExceptionの原因は,スレッド4が2006/07/06 23:07:42.098でConnection.closeメソッドを実行したことであると分かります。