Hitachi

ノンストップデータベース HiRDB Version 10 UAP開発ガイド


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トレースログを解析する例を示します。

解析例

  1. 調査対象の例外を含む通番の情報を抜き出します。

  2. 情報をThread識別情報で分類し,スレッドごとに分割します。

  3. 取得時刻によって,情報を時系列に並べます。

    次の表に示すようになります。

    表17‒128 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

  4. Exceptionのエラーの内容を確認します。

    2006/07/06 23:07:42.535のスレッド3でSQLExceptionが発生し,Statementオブジェクト又はConnectionオブジェクトが既にクローズされていることが分かります。

  5. 時系列でオブジェクトの操作を確認します。

    次のスレッドの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

  6. エラーの原因である箇所を探します。

    四つのスレッドが同一のコネクションであることは分かったので,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メソッドを実行したことであると分かります。