Comments
Description
Transcript
簡単シリーズ トレース編 目次 2002/03
簡単シリーズ トレース編 2002/03 SS&WSCC#1 目次 １ DB2 UDBのトレース機能と用途 ２ DB2 イベントモニター ２−１ イベントモニター概要 ２−２ SQLステートメントイベント ２−３ デッドロックイベント ２−４ イベントモニター補足事項 ３． db2diag.log ４． CLIトレース ４−１ CLIトレースの収集方法 ４−２ CLIトレースの調査例 ５． db2trc 終わりに 付録 CLIトレースの追及例 Systems Solution & Web Server Competence Center No.1 DM Group 1-2 １ DB2 UDBのトレース機能と用途 トレース機能が欲しくなるのはどんな時でしょう？ 問題の原因究明 なりゆきの把握 悪い原因の発見 証拠の収集 DB2 UDBのアプリケーションやサーバーが期待通りの動きをしない 時、何がどこまでうまく行って最後はどうなったか？成り行きを 見て原因究明を行いたいことがあります。当資料ではこういっ た目的に使えるDB2の機能の使い方と見方をご紹介します。 当資料では、各DB2の機能の正式名称にはこだわらず、この目的に合う 機能をひろくトレース機能と呼んでいます Systems Solution & Web Server Competence Center No.1 DM Group １ DB2 UDBのトレース機能と用途 よくある関心事と解決策 アプリケーションの実行時間が長い、どこに時間がかかっているのだろう？ 実行時間の長いSQLがあるのか？それはどれか？ SQLの発行と発行の間に時間がかかっているのか？ SQLが非常に多く発行されているのか？ イベントモニター for STATEMENTS を利用してみましょう デッドロックが起こってしまった。どこに原因があるのだろう？ どのアプリケーションと、どのアプリケーションで起こったのか？ どんなSQLとどんなSQLで起こったのか？ どのクライアントとどのクライアントで起こったのか？ イベントモニター for DEADLOCKS を利用してみましょう DB2でこんな現象が起きてしまった、その状況はどこに残っていないか？ db2diag.log ファイルを調べてみましょう Java や VB で不思議なエラーが返ってくる、これはなぜ？ CLIトレースを収集してみましょう DB2内部エンジンの動きはわからないの？ db2trc で資料収集してみましょう 今までの資料でらちがあかない、そんな時どうする？ 状況によってはOSやPDツールによるiptraceも併用してみましょう Systems Solution & Web Server Competence Center No.1 DM Group 3-4 ２−１ イベントモニター概要 イベントモニターの種類 イベントモニターには次の８種類の事象を収集できます、この資料ではよく使われる２つを取り上げます DATABASE データベースイベント 全アプリケーションがデータベースから切断した時に記録 TABLES 各表のイベント 全アプリケーションがデータベースから切断した時に記録 DEADLOCKS デッドロックイベント デッドロックの発生時に記録 TABLESPACE 表スペースイベント 全アプリケーションがデータベースから切断した時に記録 BUFFERPOOL バッファープールイベント 全アプリケーションがデータベースから切断した時に記録 CONNECTIONS 各アプリケーションの接続イベント 各アプリケーションがデータベースから切断した時に記録 STATEMENTS SQLステートメントイベント 各SQLステートメントの完了時に記録 TRANSACTION COMMIT/ROLLBACKイベント 各トランザクションの終了時に記録 デッドロックイベント ステートメントイベント Systems Solution & Web Server Competence Center No.1 DM Group ２−１ イベントモニター概要 イベントモニターの操作に必要な権限 作成、削除、活動、非活動 イベントモニターの操作はSYSADM または DBADM 権限に限られています イベントモニター使用の流れ CREATE EVENT MONITOR sql によるイベントモニターの登録 モニター名 モニタータイプ 書き出し先(ファイル、名前つきパイプ) オプション SET EVENT MONITOR STATE sql による イベントモニターの活動化 発生したイベントをDB2が収集、書き出し 登録 活動化 ｱﾌﾟﾘｹｰｼｮﾝ SET EVENT MONITOR STATE sql によるイベントモニターの非活動化 db2 catalog 0000000.evt SQL db2 出力先 ファイル 非活動化 db2evmon プログラムによる編集出力 db2evmon イベントモニターの操作はCREATE EVENT MONITOR ＳＱＬ文であらかじめ登録され た収集対象のイベントを活動化させてファイルまたは名前つきパイプにイベント を収集します ファイル出力すると、非活動化後に編集プログラムdb2evmonで編集出力できます 名前つきパイプへ出力するとすぐに編集・処理プログラムへ渡すことができます イベントモニターのレコード形式は公開されていて編集プログラムをユーザーが作成す ることもできます。編集用サンプルプログラムも提供されています。 Systems Solution & Web Server Competence Center No.1 DM Group 5-6 イベントモニター 出力リスト ２−２ SQL ステートメントイベント：収集手順 収集手順 使用環境:DB2 for Windows/NT V7.1 FP3 Unix/Linux環境では書き出し先ディレクトリー名の変更と、そのディレクトリーへのdb2インスタンスのパーミッション付与が必要です イベントモニターの登録 create event monitor ev1 for statements write to file 'c:¥common¥kantan¥trace1' replace DB20000I SQL コマンドが正常に終了しました。 解説: DB2コマンドラインプロセッサーから、EV1 という名前のイベントモニターをSTATEMENTSイベントとして登録します 出力はファイル書き出しとし、書き出し先ディレクトリー名を ' ' で囲んで指定します replace オプションをつけると、活動化-非活動化、のあと再度活動化した際に、前回のファイルを上書きします 一般にトレースファイルは大きくなりがちですから、replaceオプションを使って前回分を含まない方が読みやすくなります イベントモニターの活動化 set event monitor ev1 state 1 DB20000I SQL コマンドが正常に終了しました。 登録したイベントを活動化するとイベントの収集が始まります トレースしたいアプリケーションの実行 イベントモニターの非活動化 set event monitor ev1 state 0 DB20000I SQL コマンドが正常に終了しました。 登録したイベントを非活動化するとイベントの収集が終わり、ファイル書き出しが終了します イベントの編集出力 db2evmon -db データベース別名 -evm ev1 > event1.txt イベントの出力を編集出力します。該当のデータベース別名とイベント名を指定します Systems Solution & Web Server Competence Center No.1 DM Group ブランクページ 7-8 ２−２ SQL ステートメントイベント：出力の見方 実行時間の長いSQLはどれか？ 8) Statement Event ... Appl Handle: 3 Appl Id: *LOCAL.DB2.010830105525 Appl Seq number: 0001 ハンドル3:アプリケーションの コネクション情報 ハンドル３の コネクションヘッダー イベントを参照 Record is the result of a flush: FALSE ------------------------------------------Select文はCloseイベン Type : Dynamic トに注目すれば十分 Operation: Close カーソルのClose Section : 201 Creator : NULLID Select文を発行したパッ パッケージ名 Package : SQLC2D01 ケージ名(参考) ③ Cursor : SQLCUR201 問 Cursor was blocking: FALSE 題 Text : select count(*) from syscat.columns x, syscat.columns y 発行された動的SQL文 の ------------------------------------------SQL Start Time: 08/30/2001 19:59:09.057957 Stop Time: 08/30/2001 19:59:33.369759 実行時間 24.3秒 Exec Time: 24.311802 seconds Number of Agents created: 1 ①時間が長い User CPU: 23.573897 seconds CPU時間 23.5秒 System CPU: 0.040058 seconds Fetch Count: 1 Select結果 1行 Sorts: 0 ②行読み取り、 Total sort time: 0 行取り出しが多い Sort overflows: 0 DB2が読み取ったのは 13,158,756行 Rows read: 13158756 Rows written: 0 Internal rows deleted: 0 Internal rows updated: 0 Internal rows inserted: 0 参考 SQLCA: 正常終了 SQLCODE 0 sqlcode: 0 sqlstate: 00000 Systems Solution & Web Server Competence Center No.1 DM Group ２−２ SQL ステートメントイベント：出力の見方：解説 実行時間の長いSQLはどれか？ ①：まず、実行時間とCPU時間の多いイベントに着目しましょう Exec Time: に実行経過時間が秒単位で User CPU Time: にDB2が使用したCPU時間が秒単位で表示されます これらが長いものを選びましょう、 カーソルを使ったSelectの操作はPrepare Open Describe Close の４つのイベントとして載ります。このうちCloseの操作に着目すれ ば十分です ②：時間が長いのは取り扱った行数が多いためか、参考に見てみましょう Fetch Count: にアプリケーションに返された、アプリケーションが受け取った行数が Rows Read: には、その準備のためにDB2が内部的に読み取った行数が載ります ③：この処理に使われた動的SQLのSQL文を見てみましょう Text: に載ります、SQL文の最大長は64KB です 次でこのSQLを発行したアプリケーション名を見るために、Appl Handle: と Appl Id: の値を確認しておきましょう Systems Solution & Web Server Competence Center No.1 DM Group 9-10 ２−２ SQL ステートメントイベント：出力の見方 実行時間の長いSQLを発行したアプリケーションは何か？ 3) Connection Header Event ... ハンドル３の ハンドル3:アプリケーションの Appl Handle: 3 ステートメントイベントを コネクション情報 Appl Id: *LOCAL.DB2.010830105525 参照 Appl Seq number: 0001 DRDA AS Correlation Token: *LOCAL.DB2.010830105525 プログラム名 db2bp.exe (コマンドラインプロセッサー) Program Name : db2bp.exe Authorization Id: DB2ADMIN Execution Id : DB2ADMIN 接続したAUTHORIZATION IDはDB2ADMIN Codepage Id: 943 Country code: 81 Client Process Id: 832 SAMPLEデータベース Client Database Alias: sample Client Product Id: SQL07020 Client Platform: Unknown Client Communication Protocol: Local Client Network Name: Connect timestamp: 08/30/2001 19:55:25.815032 アプリケーションの情報をあらわす"コネクションヘッダーイベント"も出力に含まれています SQLの発行のステートメントイベントに載っていたAppl Handle: と Appl Id: の値を持つコネクションヘッダーイベントを探してみましょう Program Name: に 実行プログラム名が載ります。 db2bp.exe は DB2コマンドラインプロセッサーです Java ならば Java.exe 、MicroSoft Visual StudioのVisual Basic V6でADOを使っていてデバック中なら VB6.exe などと表示さ れます ほかに、データベースへ接続時に指定したユーザーＩＤ(authorization ID) や接続のデータベース別名なども載ります この実行プログラム名は db2 list applications コマンドでも表示されます Systems Solution & Web Server Competence Center No.1 DM Group ２−２ SQL ステートメントイベント：静的SQLの出力の見方 実行時間の長いSQLを発行したアプリケーションは何か？ 7) Statement Event ... Appl Handle: 10 Appl Id: *LOCAL.DB2.010830152055 Appl Seq number: 0001 セク ショ ン１ ハンドル１０:アプリケーションの コネクション情報 ハンドル１０の コネクションヘッダー 6) Connection Header Event ... Appl Handle: 10 Record is the result of a flush: FALSE Appl Id: *LOCAL.DB2.010830152055 ------------------------------------------Appl Seq number: 0001 Type : Static DRDA AS Correlation Token: *LOCAL.DB2.010830152055 Operation: Execute Exucutes操作 Program Name : STATIC2.exe Section : 1 Authorization Id: DB2ADMIN プログラム名 Creator : DB2ADMIN Execution Id : DB2ADMIN STATIC2.exe パッケージ名STATIC2 Package : STATIC2 Codepage Id: 943 Cursor : Country code: 81 Cursor was blocking: FALSE Client Process Id: 2068 ------------------------------------------Client Database Alias: sample Start Time: 08/30/2001 14:22:46.566173 Client Product Id: SQL07020 Stop Time: 08/30/2001 14:23:20.986290 Client Platform: Unknown Exec Time: 34.420117 seconds 実行時間 34.4秒 Client Communication Protocol: Local Number of Agents created: 1 Client Network Name: User CPU: 33.868701 seconds CPU時間 33.8秒 Connect timestamp: 08/30/2001 14:22:46.556588 System CPU: 0.080115 seconds Fetch Count: 0 Sorts: 0 次に静的SQLについて見てみましょう Total sort time: 0 静的SQLとは埋め込みSQLプログラムをプリコンパイルしバインドし実行するプロ Sort overflows: 0 グラミング方式です。 Rows read: 2 実行時間やプログラム名は編集出力にあらわれますが、SQL文は直接現れませ Rows written: 0 ん。これはすでにプリコンパイラーがSQL文を翻訳を事前に終えているためです。 Internal rows deleted: 0 次に見るように、パッケージ名とセクション番号から、別のユーティリティを使って Internal rows updated: 0 SQL文を知ることができます Internal rows inserted: 0 SQLCA: sqlcode: 0 sqlstate: 00000 Systems Solution & Web Server Competence Center No.1 DM Group 11-12 ２−２ SQL ステートメントイベント：静的SQLの出力の見方 実行時間の長いSQLを発行したアプリケーションは何か？ 静的SQLプログラムの問題のSQL文はどんなものか？ db2bfd -s static2.bnd static2.bnd: SQL Statements = 4 セク ショ ン１ Line Sec Typ Var Len SQL statement text ---- --- --- --- --- --------------------------------------------------------41 0 10 0 13 INCLUDE SQLCA 51 0 5 0 21 BEGIN DECLARE SECTION 53 0 2 0 19 END DECLARE SECTION 65 1 0 1 135 SELECT CHAR(COUNT(*)) INTO :H00001 FROM SYSCAT.TABLES X, SYSCAT.TABLES Y, SYSCAT. TABLES Z static2.bndの セクション１のSQL文 ステートメントイベントでパッケージ中でSQL文が発行されたセクション番号がわかります。 パッケージをバインドした元のバインドファイルがあれば、それに対してdb2bfdユーティリティを実行してセクション番号に対応 するSQL文を表示することができます static2.bnd は静的SQLのソースをDB2プリコンパイラーでプリコンパイルして生成されたバインドファイルです Systems Solution & Web Server Competence Center No.1 DM Group ブランクページ 13-14 ２−３ デッドロック イベント：収集手順 収集手順説明 使用環境:DB2 for Windows/NT V7.1 FP3 Unix/Linux環境では書き出し先ディレクトリー名の変更と、そのディレクトリーへのdb2インスタンスのパーミッション付与が必要です イベントモニターの登録 create event monitor ev2 for deadlocks write to file 'c:¥common¥kantan¥trace2' replace DB20000I SQL コマンドが正常に終了しました。 解説: DB2コマンドラインプロセッサーから、EV2 という名前のイベントモニターをDEADLOCKSイベントとして登録します 出力はファイル書き出しとし、書き出し先ディレクトリー名を ' ' で囲んで指定します replace オプションをつけると、活動化-非活動化、のあと再度活動化した際に、前回のファイルを上書きします 一般にトレースファイルは大きくなりがちですから、replaceオプションで前回分を含まない方が読みやすくなります イベントモニターの活動化 set event monitor ev2 state 1 DB20000I SQL コマンドが正常に終了しました。 登録したイベントを活動化するとイベントの収集が始まります デッドロックの発生 イベントモニターの非活動化 set event monitor ev2 state 0 DB20000I SQL コマンドが正常に終了しました。 登録したイベントを非活動化するとイベントの収集が終わり、ファイル書き出しが終了します イベントの編集出力 db2evmon -db データベース別名 -evm ev2 > event2.txt イベントの出力を編集出力します。該当のデータベース別名とイベント名を指定します Systems Solution & Web Server Competence Center No.1 DM Group ブランクページ 15-16 ２−３ デッドロックイベント：出力の見方 いつデッドロックが起こったのか？ deadlock Event ﾚｺｰﾄﾞの確認 7) Deadlocked Connection ...(デッドロック対象アプリケーション) Appl Id: *LOCAL.DB2.010830152045 (自分) Appl Seq number: 0001 (相手) Appl Id of connection holding the lock: *LOCAL.DB2.010830152046 Seq. no. of connection holding the lock: 0001 Lock wait start time: 08/30/2001 12:39:42.599334 Requesting lock as part of escalation: FALSE Deadlock detection time: 08/30/2001 12:41:29.707303 Table of lock waited on : EMPLOYEE Schema of lock waited on : ADMINISTRATOR Tablespace of lock waited on : USERSPACE1 Type of lock: Row Mode of lock: X Mode application requested on lock: NS Node lock occured on: 0 Lock object name: 257 Application Handle: 0 (自分) 6) Deadlocked Connection ...(デッドロック対象アプリケーション) Appl Id: *LOCAL.DB2.010830152046 (自分） Appl Seq number: 0001 (相手) Appl Id of connection holding the lock: *LOCAL.DB2.010830152045 Seq. no. of connection holding the lock: 0001 Lock wait start time: 08/30/2001 12:41:21.623688 Requesting lock as part of escalation: FALSE Deadlock detection time: 08/30/2001 12:41:29.707303 Table of lock waited on : EMPLOYEE Schema of lock waited on : ADMINISTRATOR Tablespace of lock waited on : USERSPACE1 Type of lock: Row Mode of lock: X Mode application requested on lock: NS Node lock occured on: 0 Lock object name: 4 Application Handle: 1 (自分) 2つのアプリケーションで発生 この時刻にDEADLOCKが発生した RollBackしたのは6)の方 5) Deadlock Event ...(デッドロックの発生) Number of applications deadlocked: 2 Deadlock detection time: 08/30/2001 12:41:29.707303 Rolled back Appl Id: : *LOCAL.DB2.010830152046 Rolled back Appl seq number: : 0001 コネクションヘッ ダー３）に対応 コネクションヘッ ダー４）に対応 Systems Solution & Web Server Competence Center No.1 DM Group ２−３ デッドロックイベント：出力の見方：解説 いつデッドロックが起こったのか？ デッドロックイベントの出力にはDeadlock Event のレコードに続き、デッドロック対象のアプリケーションのレコードが載ります Deadlock Eventレコード はデッドロックの事象そのものです Deadlocked Connectionレコード がデッドロック対象アプリケーションです デッドロックイベントに発生時刻やRollbackされた側のアプリケーションID、関連したアプリケーション数が載ります デッドロック コネクションレコードには相手のアプリケーションのＩＤも載ります Appl Id of connection holding the lock: が相手のアプリケーションＩＤです デッドロック コネクションレコードには自分のAppl Id が載り、コネクションヘッダーイベントのレコードと対応付けられます。 Appl Id とAppl Handle がコネクションヘッダーイベントにもあります Systems Solution & Web Server Competence Center No.1 DM Group 17-18 ２−３ デッドロックイベント：出力の見方 どのアプリケーションとどのアプリケーションでデッドロックが起こったのか？ コネクションヘッダーイベントの確認 3) Connection Header Event ...(コネクションヘッダー) Appl Handle: 0 7) Appl Id: *LOCAL.DB2.010830152045 Appl Seq number: 0001 DRDA AS Correlation Token: *LOCAL.DB2.010830105525 (DB2コマンドプロセッサー) Program Name : db2bp.exe Authorization Id: DB2ADMIN Execution Id : DB2ADMIN Codepage Id: 943 Country code: 81 Client Process Id: 832 Client Database Alias: sample （SAMPLEデータベース) Client Product Id: SQL07020 Client Platform: Unknown Client Communication Protocol: Local Client Network Name: Connect timestamp: 08/30/2001 12:38:19.416275 4) Connection Header Event ...(コネクションヘッダー) Appl Handle: 1 6) Appl Id: *LOCAL.DB2.010830152046 Appl Seq number: 0001 DRDA AS Correlation Token: *LOCAL.DB2.010830135535 (DB2コマンドプロセッサー） Program Name : db2bp.exe Authorization Id: DB2ADMIN Execution Id : DB2ADMIN Codepage Id: 943 Country code: 81 Client Process Id: 1980 (SAMPLEデータベース) Client Database Alias: sample Client Product Id: SQL07020 Client Platform: Unknown Client Communication Protocol: Local Client Network Name: Connect timestamp: 08/30/2001 12:38:27.186339 前々ページのデッ ドロックコネクショ ンレコード７） に対応 前々ページの デッドロックコネ クションレコード ６）に対応 デッドロックコネクションレコードのAppl Id: か Appl Handle:の値を使ってコネクションヘッダーイベントを見つけることができます コネクションヘッダーイベントにはプログラム名があります Program Name: db2bp.exe は DB2コマンドプロセッサーがアプリケーションプログラムであることを示します Systems Solution & Web Server Competence Center No.1 DM Group ２−３ デッドロックイベント：出力の見方 どんなSQLと、どんなＳＱＬで起こったのか？ Deadlocked Connectionﾚｺｰﾄﾞの確認 対象表名はTable of lock waited on とSchema of lock waited on でわかります、この場合Administrator.Employee表です SQL文そのものは、この資料だけではわかりません しかしながら、取得されたLockのModeから発行されたSQLのタイプの候補を推測できます このケースでは、INSERT/UPDATE/DELETE (Xロック)後SELECT(NSロック)された可能性があります ただしNSロックはSELECTだけとは限りませんのでこれ以外の可能性もあります、SQL文を特定するには別の情報が要ります 6) Deadlocked Connection ...(デッドロック対象アプリケーション) Appl Id: *LOCAL.DB2.010830152046 (自分） Appl Seq number: 0001 (相手) Appl Id of connection holding the lock: *LOCAL.DB2.010830152045 Seq. no. of connection holding the lock: 0001 Lock wait start time: 08/30/2001 12:41:21.623688 Requesting lock as part of escalation: FALSE Deadlock detection time: 08/30/2001 12:41:29.707303 Table of lock waited on : EMPLOYEE 対象表 Schema of lock waited on : ADMINISTRATOR Tablespace of lock waited on : USERSPACE1 Type of lock: Row 行のX (相手の保持していたロック) Mode of lock: X ロック Mode application requested on lock: NS (自分の要求したロック) Node lock occured on: 0 行のNextKey Lock object name: 4 Shareロック Application Handle: 1 (自分） 相手がEMPLOYEE表の行のExclusive Lock持っ ている時に、 自分はその行にNext Key Share Lockを取ろうと した 7) Deadlocked Connection ...(デッドロック対象アプリケーション) Appl Id: *LOCAL.DB2.010830152045 (自分) Appl Seq number: 0001 (相手) Appl Id of connection holding the lock: *LOCAL.DB2.010830152046 Seq. no. of connection holding the lock: 0001 Lock wait start time: 08/30/2001 12:39:42.599334 Requesting lock as part of escalation: FALSE Deadlock detection time: 08/30/2001 12:41:29.707303 Table of lock waited on : EMPLOYEE 対象表 Schema of lock waited on : ADMINISTRATOR Tablespace of lock waited on : USERSPACE1 Type of lock: Row 行のX (相手の保持していたロック) Mode of lock: X ロック Mode application requested on lock: NS (自分の要求したロック) Node lock occured on: 0 行のNextKey Lock object name: 257 Shareロック Application Handle: 0 （自分） 相手がEMPLOYEE表の行のExclusive Lock持っ ている時に、 自分はその行にNext Key Share Lockを取ろうと した Systems Solution & Web Server Competence Center No.1 DM Group 19-20 ２−３ デッドロックトイベント：出力の見方 どのクライアントと、どのクライアントで起こったのか？ コネクションヘッダーイベントの確認 3) Connection Header Event ...(コネクションヘッダー) Appl Handle: 0 Appl Id: *LOCAL.DB2.010830152045 Appl Seq number: 0001 DRDA AS Correlation Token: *LOCAL.DB2.010830105525 Program Name : db2bp.exe (DB2コマンドプロセッサー) Authorization Id: DB2ADMIN Execution Id : DB2ADMIN Codepage Id: 943 Country code: 81 Client Process Id: 832 Client Database Alias: sample （SAMPLEデータベース) Client Product Id: SQL07020 Client Platform: Unknown Client Communication Protocol: Local （ローカルクライアント） Client Network Name: Connect timestamp: 08/30/2001 12:38:19.416275 4) Connection Header Event ...(コネクションヘッダー) Appl Handle: 1 Appl Id: *LOCAL.DB2.010830152046 Appl Seq number: 0001 DRDA AS Correlation Token: *LOCAL.DB2.010830135535 Program Name : db2bp.exe (DB2コマンドプロセッサー） Authorization Id: DB2ADMIN Execution Id : DB2ADMIN Codepage Id: 943 Country code: 81 Client Process Id: 1980 Client Database Alias: sample (SAMPLEデータベース) Client Product Id: SQL07020 Client Platform: Unknown Client Communication Protocol: Local （ローカルクライアント） Client Network Name: Connect timestamp: 08/30/2001 12:38:27.186339 このケースは Client Communication Protocol: Local となっていますので、サーバー内のアプリケーションでデッドロックが発生してい ます Client Communication Protocolが TCP/IPの場合、IPアドレスは application snapshot で知ることができます db2 get snapshot for all applications on データベース別名 でその時点のapplication snapshot をあらかじめ取得しておきます applicaiton snapshotには各アプリケーションのあるクライアントのIPアドレスが出力されます、これとAppl Id でつき合わせことでIP アドレスがわかります、今回の例にはのっていません Systems Solution & Web Server Competence Center No.1 DM Group ２−３ デッドロックイベント：再現させたSQLの流れ このケースでの発生原因（分離レベルCS) Appl Id: FROM *LOCAL.DB2.010830152046 1)DELETE EMPLOYEE WHERE EMPNO='000010' 削除行にXロック EMPNOに索引あり 3)SELECT COUNT(*) FROM EMPLOYEE WHERE SALARY = 1000.00 索引の無い列Salaryの検索のために全件読み、 ２)のXロックへを待つ Appl Id: *LOCAL.DB2.010830152045 2)DELETE FROM EMPLOYEE WHERE EMPNO='000340' 削除行にＸロック EMPNOに索引あり 4)SELECT COUNT(*) FROM EMPLOYEE WHERE SALARY = 2000.00 索引の無い列Salaryの検索のために全件読み、 １）のXロックを待つ デッドロックを発生させる流れは次の通り １）左のアプリケーションでEMPLYEE表のキー000010をautocommit off でDELETEする ２）右のアプリケーションでEMPLYEE表のキー000340をautocommit off でDELETEする ３）左のアプリケーションでEMPLYEE表のSALARY = 1000.00 の条件を満たす行数をautocommit off で SELECTする SALARYには索引が無いので全行読んで調べるしかなく、1)で右が更新した行を読むためにNSロックを獲得しようとする、この時、 右側のアプリケーションのDELETEによるXロック(Exclusive Lock)は保持されたままなのでロック待ちとなる NSロックは分離レベルCSでCommitずみの値を読むために要求される ４)右のアプリケーションでEMPLYEE表のSALARY = 2000.00 の条件を満たす行数をautocommit off で SELECTする SALARYには索引が無いので全行読んで調べるしかなく、2)で左が更新した行を読むためにNSロックを獲得しようとする、この時、 左側のアプリケーションのDELETEによるXロック(Exclusive Lock)は保持されたままなのでロック待ちとなる NSロックは分離レベルCSでCommitずみの値を読むために要求される ５）左右ともロック待ちが解けないため、デッドロックが成立する Systems Solution & Web Server Competence Center No.1 DM Group 21-22 ２−４ イベントモニター補足事項 イベントモニターの消去 db2 drop event monitor for ev1 DB20000I SQL コマンドが正常に終了しました。 登録したイベントモニターを削除します イベントモニターの再収集 drop event monitor していなければ 何度でも "活動化、再現テスト、非活動化 、編集出力" を繰り返すことができます。 参照情報記載場所 CREATE EVENT MONITOR 他 db2evmon イベントモニター出力の解説 出力編集サンプルプログラム SQL 解説書 コマンド解説書 システムモニター手引きおよび解説書 sqllib¥samples¥c¥ evm.c evmread.c evmprint.c Systems Solution & Web Server Competence Center No.1 DM Group ブランクページ 23-24 3 db2diag.log ファイルの利用：概要 db2diag.log ファイルの概要 db2diag.logはDB2が情報を記録するASCIIファイル 記録内容 BACKUP / RESTORE などデータベース管理事象のログ エラー情報 エラーの理由を示すDIAメッセージ エラーSQLCODE データベースのクラッシュ時の情報、ダンプファイル、トラップファイル ファイルの場所 データベースマネジャー構成パラメーターDB2DIAGPATHディレクトリー 省略時:Windows SQLLIB¥DB2 ディレクトリー Unix インスタンスオーナーのホームディレクトリーの sqllib/db2dump 記録方法 常に最後に追加される タイムスタンプ付き 単調増大するため定期的に保存・削除が必要 DIAGLEVELパラメータによる記録レベル指定（０−４、省略時３） DB2 EE/WE/PEでは３を推薦 ４はinformationalメッセージが必要な場合に使用 DB2 EEE本番システムでは３を推薦 4ではNFS共有ファイルへの書き込みのためパフォーマンスダウンの影響 DIAGPATHをNFSからローカルdiskに代えれば４も現実的 Systems Solution & Web Server Competence Center No.1 DM Group 解説:3 db2diag.log ファイルの利用：概要 db2diag.logファイルはdb2が情報を記録するasciiファイルです。記録内容には２種類ありま す。ひとつはデータベースのバックアップ・リストアなのデータベース管理の事象の記録で す。もうひとつは発生したエラーに関する情報です。DIAではじまるメッセージコードでエ ラーの理由を説明する診断メッセージが書かれ、あわせてSQLCODEや発生したダンプ ファイルやトラップファイルを示します。 db2diag.logファイルはDB2DIAGPATHデータベースマネジャー構成パラメータの示すディレ クトリーに書かれます。省略時ではWindowsでsqllib¥db2 ディレクトリーにUnix/Linuxでは インスタンスオーナーのホームディレクトリーのsqllib/db2dumpディレクトリーです。 ファイルは常に最後に追加して書かれます。ファイルは単調増大するため、定期的に保 存し削除する運用が必要です。メッセージにはタイムスタンプが付加されていて事象の発 生時刻がわかります。 データベース構成パラメータのDIAGLEVELパラメータ（０から４まで）により記録される情 報のレベルが変わります。省略時は３でwarningまで記録されますが、４にするとより多く、 informationalメッセージまで記録されます。DB2 EEではレベル４ではかなり情報量が多い ためレベル３を推薦します。DB2 WE/PEも同様です。 DB2 EEEでは省略時ではdb2diag.logファイルはNFS共有ファイルであるため書き出し量の 多いレベル４ではパフォーマンスダウンを起こしえます。このため本番システムではレベ ル３を推薦します。レベル４を使いたい場合はDIAGPATHディレクトリーをNFSでなくローカ ルディスクへ変更することを推薦します Systems Solution & Web Server Competence Center No.1 DM Group 25-26 3 db2diag.log ファイルの利用：ロックエスカレーション ロックエスカレーション事象の確認 ロックエスカレーションが発生した時刻や表名、ロックタイプ等を知ることができます ロックエスカレーションの発生はSNAPSHOTモニターのデータベース スナップショットのLock escalations(ロックエスカレーショ ン発生回数)やExclusive lock escalations(Xロックのロックエスカレーション回数)を見てわかります。 db2diag.logを参照すれば時刻、表、該当Applid 等、より詳しい情報が把握できます DIAGLEVELは３で記録されます,DIAGLEVEL４ではさらにロックエスカレーションを起こした動的SQL文も表示されます 2001-09-05-08.48.38.752000 Instance:DB2 Node:000 PID:852(db2syscs.exe) TID:1164 Appid:*LOCAL.DB2.010904234838 data_management sqldEscalateLocks Probe:2 Database:TEST1 ----- Lock Count, Target : 1253, 626 Table (ID) Name : (2;6) DB2ADMIN.T1 Locks, Request Type : 1251, X Result (0 = success): 0 タイムスタンプ ロックエスカレーション事象 表名:DB2ADMIN.T1 Xロック（Exclusive ロック) Systems Solution & Web Server Competence Center No.1 DM Group 3 db2diag.log ファイルの利用：ロックタイムアウト ロックタイムアウト事象の確認 ロックタイムアウトの発生はSNAPSHOTモニターのデータベース スナップショットでのLock Timeouts(ロックタイムアウト発生回 数)を見てわかります db2diag.logを参照すれば時刻、該当Applid 等、より詳しい情報が把握できます 前提DIAGLEVELは４で記録されます 行のXロック要求がロックタイムアウト発生した例 表のIXロック要求がロックタイムアウト発生した例 2001-09-05-09.09.36.370000 Instance:DB2 Node:000 PID:848(db2syscs.exe) TID:1848 Appid:*LOCAL.DB2.010905000925 lock_manager sqlplnfd Probe:80 Database:TEST1 2001-09-05-09.08.40.931000 Instance:DB2 Node:000 PID:848(db2syscs.exe) TID:1848 Appid:*LOCAL.DB2.010905000830 lock_manager sqlplnfd Probe:80 Database:TEST1 Request for lock "REC: (2, 6) RID 00000939" in mode "..X" timed out Application caused the lock wait is "*LOCAL.DB2.010905000654" Package name: CURSOR2 パッケージ名 セクション番号 Section: 2 Request for lock "TAB: (2, 6)" in mode ".IX" timed out Application caused the lock wait is "*LOCAL.DB2.010905000654" Package name: CURSOR2 パッケージ名 セクション番号 Section: 1 Systems Solution & Web Server Competence Center No.1 DM Group 27-28 3 db2diag.log ファイルの利用：ロックタイムアウト db2diag.logに載っているロックタイムアウトを起こしたパッケージ名とセクション名から、該当する静的SQLプログラムのSQL文を調査 してみましょう。今回はDB2のカタログ視点からSQL文を調べてみます。 前ページ左の行のXロック要求がロックタイムアウトした例はパッケージCURSOR2のセクション2でしたが、これはUPDATE文で あることがSYSCAT.STATEMNTSをSELECTすることによりわかります このケースではロックタイムアウトの再現操作としてコマンドラインプロセッサーから次のSQLを発行しました db2 +c DELETE FROM T1 WHERE C1=1000 前ページ右の表のIXロック要求がロックタイムアウトした例はパッケージCURSOR2のセクション1でしたが、これはSELECT文で あることがSYSCAT.STATEMNTSをSELECTすることによりわかります。実際のコーディング上のステートメントはこの SELECT文に対するOpen cursor 文でロックタイムアウトが発生します。 このケースではロックタイムアウトの再現操作としてコマンドラインプロセッサーから次のSQLを発行しました db2 +c LOCK TABLE T1 IN EXCLUSIVE MODE カタログ視点を使うとBINDされたパッケージのSQL文を実際に見ることができて確実です。一方、db2bfdユーティリティは使わ れたバインドファイルが確実にわかっているなら、データベースに全く影響を与えずにSQL文を調査できる利点があり ます select pkgname, sectno, substr(text,1,128) as sql from syscat.statements where pkgname='CURSOR2' PKGNAME SECTNO SQL -------- ------ ---------------------------------------------------------CURSOR2 1 SELECT c1, c2 FROM t1 FOR UPDATE OF c2 CURSOR2 2 UPDATE T1 SET C2=C2+1 WHERE CURRENT OF C1 セクション１のSQL セクション2のSQL 2 レコードが選択されました。 Systems Solution & Web Server Competence Center No.1 DM Group 3 db2diag.log ファイルの利用：デッドロック デッドロック事象の確認 デッドロックの発生はSNAPSHOTモニターのデータベース スナップショットのDeadlock Detected(デッドロック検知した回数)を 見てわかります db2diag.logを参照すれば時刻、Rollbackした動的SQL、要求されていたロックタイプ等、詳しい情報が把握できます DIAGLEVELは４で記録されます 2001-09-05-09.23.21.457000 Instance:DB2 Node:000 PID:1856(db2syscs.exe) TID:1196 Appid:*LOCAL.DB2.010904121913 lock_manager sqlplnfd Probe:80 Database:SAMPLE Rollbackした側 NSロック要求待ちで デッドロックになった Request for lock "REC: (2, 6) RID 0000001B" in mode ".NS" failed due to deadlock 相手のAppli Id Application caused the lock wait is "*LOCAL.DB2.010905002035" Statement: 7365 6c65 6374 2063 6f75 6e74 282a 2920 select count(*) 6672 6f6d 2065 6d70 6c6f 7965 6520 7768 from employee wh ロールバックしたSQL 6572 6520 7361 6c61 7279 3d30 ere salary=0 Systems Solution & Web Server Competence Center No.1 DM Group 29-30 4 CLIトレース：概要 CLI(コールレベルインターフェース)の概要 CLIとDB2 Jdbc, ODBC, VB ADO, IBM native OLEDBプロバイダーなどはDB2へSQLを発行す るインターフェースとしてCLI(コールレベルインターフェース）を使っていま す。それぞれのプログラミングの結果がCLIのインターフェース変換されて DB2へ要求されます CLIはマイクロソフト社が提唱したODBCをもとに国際標準となったSQL/CLIプログラ ミングインターフェースです。 DB2は国際標準SQL/CLIとODBC両方をサポートしています。DB2アプリケーション プログラミングはCLIプログラミングと埋め込みSQLプログラミングの２つに 大別されます CLIの特徴 CLIにはODBCの特徴でもあるデータベースの一覧を得るAPIや表の一覧を得るAPI が備わっています。CLIプログラミングでは表の一覧を得るために、データ ベースのカタログ表の名前や列名を知る必要がありません。 埋め込みSQLプログラミングのようなアプリケーションプログラムのプリコンパイルは 必要ありません。その代わりに、実行時に動的に必要な処理を行います。 例えばアプリケーションプログラムがSELECT文を発行したら、結果を受け 取る前にアプリケーションプログラムは、DB2に、”わたしが出したSELECT 文の結果は何列ありましたっけ？”とか”１番目の列は列タイプは何で、長さ はいくらでしたっけ？”、”二番目の列は......"のように動的に列属性に応じた 処理をアプリケーションプログラムで行います。このためCLIのAPIは５０個程 度もあり、トレースも各列ごとにエントリーがあるためかなり長いものとなりま す。 CLIトレースの用途 JdbcやVB ADOからのプログラミングで予定外の事象が発生した場合はDB２へと CLIアプリケーションプログラムの接点でのなりゆきを示すCLIトレースの解 析が役立ちます 以下で資料の取り方と着眼点を紹介しましょう Systems Solution & Web Server Competence Center No.1 DM Group ブランクページ 31-32 4-1 CLIトレースの収集方法 CLIトレース収集の指定 CLIはアプリケーションプログラムとDB2クライアントの接点となるインターフェースです。トレース収集 の指定はDB2クライアント機に行います。 以下はWindows 2000での指定です。Unix/Linux の場合は環境にあわせたディレクトリー名を指 定し、DB2のインスタンスから書き出せるようにパーミッションを指定してください CLIアプリケーションの動くクライアントPCやクライアントインスタンスのdb2cli.iniファイルを編集します sqllib¥db2cli.ini (Windowsの場合) sqllib/cfg/db2cli.ini (Unix/Linuxの場合) [COMMON] TRACEPATHNAME=C:¥CLITRACE TRACE=1 TRACEFLUSH=1 説明 TRACEPATHNAME CLIトレースを書き出すディレクトリーを指定します マルチスレッドアプリケーションではスレッドごとにファイルができます TRACE=1 CLIトレースを掛けることを指定します TRACEFLUSH=1 トレースを同期的にディスクへ書き出す指定です、同期的書き出しの方がトレース収集のも れがないので安心です コメント化の方法 ;TRACE=1 のように先頭に; を付加すればコメントになります 指定のタイミング db2cli.ini ファイルを変更した後に、アプリケーションをデータベースへの接続から始めてください Systems Solution & Web Server Competence Center No.1 DM Group 4-2 CLIトレース調査例 例題：ストアードプロシージャビルダーで"ソース取得"がエラー ストアードプロシージャビルダーで開発したストアードプロシージャのソースはDB2カタログに格納され ます。ストアードプロシージャビルダーを終了して次に開発の続きを行う場合はソースの取得という操 作でソースプログラムを呼び出します この問題をCLIトレースで判別します、CLIトレースをエラーの起こるPCと正常のPCの両方で取得しま す ストアードプロシージャビルダーはJava jdbcアプリケーションです、jdbcドライバーはdb2へCLIの インターフェースでSQL発行します Systems Solution & Web Server Competence Center No.1 DM Group 33-34 4-2 CLIトレース調査例 トレース取得操作 db2cli.ini にトレース取得のパラメータをセットします ストアードプロシージャビルダーを起動し、再現する直前まで操作します 再現直前時点のトレースファイルコピー(参考) CLIトレースは多量に出力されるのでエラー個所を特定するためには"エラー発生前"のトレース範囲を知っておくと絞り込みが容 易です 参考のため、再現直前の段階でトレースディレクトリーに書かれたトレースファイルを別のディレクトリーにコピーしておきましょ う。 再現操作 エラーが起きる操作を行って、エラーを再現させます 再現直後のトレースファイルコピー エラー発生以降のエントリーができるだけ含まれないようにすみやかにコピーしましょう db2cli.ini修正 db2アプリケーション開始 再現直前まで操作 トレースコピー 再現前 トレース 注目 個所 再現 トレースコピー 再現後 トレース Systems Solution & Web Server Competence Center No.1 DM Group 4-2 CLIトレース調査例 トレースファイルの確認 再現直前にコピーしておいたトレースファイルと再現直後にコピーしたトレースファイルを比べると次のことがわかります ファイル数が、３個から４個に増えている 1564.2のファイルの大きさが増えて最終更新時刻が１分あとに変わっている 1564.3のファイルが再現後、新規に増えている このことから、問題のエラーの個所は1564.2のファイルの437バイト目より後、か1564.3ファイルに載っていると絞込むことができます 注目個所 C:¥CLITRACE¥0906-1 のディレクトリ 2001/09/06 2001/09/06 2001/09/06 2001/09/06 2001/09/06 06:23 <DIR> . 06:23 <DIR> .. 06:22 39,181 1564.0 06:23 140,560 1564.1 06:23 437 1564.2 3 個のファイル 180,178 バイト 再現直後 トレース C:¥CLITRACE¥0906-2 のディレクトリ 2001/09/06 2001/09/06 2001/09/06 2001/09/06 2001/09/06 2001/09/06 06:24 <DIR> 06:24 <DIR> 06:22 06:23 06:24 06:24 4 個のファイル 188,334 バイト Systems Solution & Web Server Competence Center No.1 DM Group 35-36 39,181 140,560 611 7,982 . .. 1564.0 1564.1 1564.2 1564.3 注 目 個 所 再現直前 トレース 4-2 CLIトレース調査例 エラーメッセージ発生個所の確認 1564.3ファイルで SQL_ERROR を検索してみましょう、CLIプログラムでエラーメッセージが返される場合には必ずSQL_ERROR戻りコー ドが返ります ここではSQLGetDataInternal（列からのデータの取り出し）要求に対してSQL_ERRORが返っています、次にこのSQL_ERRORが問 題のCLI0150Eメッセージ、SQLSTATE=HYC00になったのかどうか確認しましょう 再現直後 トレース 2001/09/06 2001/09/06 2001/09/06 2001/09/06 2001/09/06 2001/09/06 06:24 <DIR> 06:24 <DIR> 06:22 06:23 06:24 06:24 4 個のファイル 188,334 バイト 39,181 140,560 611 7,982 . .. 1564.0 1564.1 1564.2 1564.3 注 目 個 所 C:¥CLITRACE¥0906-2 のディレクトリ SQL_ERROR という文字を検索 CLI関数名 SQLDescribeColW( hStmt=1:2, iCol=1, pszColName=NULL, cbColNameMax=0, pcbColName=NULL, pfSQLType=&0ab2fb08, pcbColDef=&0ab2fb0c, pibScale=NULL, pfNullable=NULL ) ---> Time elapsed - +6.798000E-003 seconds 要求 SQLDescribeColW( pfSQLType=SQL_LONGVARCHAR, pcbColDef=10485760 ) <--- SQL_SUCCESS Time elapsed - +8.699900E-002 seconds 応答 SQLGetDataInternal( hStmt=1:2, iCol=1, fCType=SQL_C_WCHAR, prgbValue=&0ab2fb48, cbValueMax=20971522, pcbValue=&0ab2fb54 ) ---> Time elapsed - +6.043000E-003 seconds 要求 SQLGetDataInternal( ) <--- SQL_ERROR Time elapsed - +5.761200E-002 seconds 応答 Systems Solution & Web Server Competence Center No.1 DM Group 4-2 CLIトレース調査例 エラーメッセージ発生個所の確認 エラーメッセージはSQL_ERROR戻りコードが返った後にアプリケーションプログラムからのエラーメッセージ取り出し要求に返されます。 下の例ではSQL_ERRORの発生後、２組の診断データ構造フィールドの要求・応答の後、アプリケーションがDB2へエラー情報を要 求し、DB2からエラーメッセージコード、SQLSTATE、SQLCODEが返されています CLI関数名 前ページより SQLGetDataInternal( ) <--- SQL_ERROR Time elapsed - +5.761200E-002 seconds SQLGetDiagFieldW( fHandleType=SQL_HANDLE_STMT, hHandle=1:2, iRecNumber=1, fDiagIdentifier=Unknown value 2467, pDiagInfo=&0ab2f9e4, cbDiagInfoMax=140, pcbDiagInfo=&0ab2fa92 ) ---> Time elapsed - +6.737000E-003 seconds SQLGetDiagFieldW( pDiagInfo=1650747904, pcbDiagInfo=0 ) <--- SQL_SUCCESS Time elapsed - +7.845800E-002 seconds SQLGetDiagFieldW( fHandleType=SQL_HANDLE_STMT, hHandle=1:2, iRecNumber=1, fDiagIdentifier=Unknown value 2461, pDiagInfo=&0ab2fa80, cbDiagInfoMax=4, pcbDiagInfo=&0ab2fa92 ) ---> Time elapsed - +6.226000E-003 seconds SQLGetDiagFieldW( pDiagInfo=0, pcbDiagInfo=0 ) <--- SQL_SUCCESS Time elapsed - +7.465700E-002 seconds SQLErrorW( hEnv=0:0, hDbc=0:0, hStmt=1:2, pszSqlState=&0ab2fa70, pfNativeError=&0ab2fa7c, pszErrorMsg=&0ab2f1e0, cbErrorMsgMax=1024, pcbErrorMsg=&0ab2fa86 ) DB2へエラー情報の取り出し要求 ---> Time elapsed - +6.685000E-003 seconds SQLErrorW( pszSqlState="HYC00 at " - X"4800590043003000300000006179FEFF00000000", pfNativeError=-99999, pszErrorMsg="[IBM][CLI Driver] CLI0150E EeDuL(gM [･ SQLSTATE=HYC00" - X"5B00490042004D005D005B0043004C0049002000440072006900760 0650072005D00200043004C0049003000310035003000450020002000C930E930A430D030FC 304C307F4F287567304D307E305B30933002302000530051004C00530054004100540045003D0048005900430030003000", pcbErrorMsg=57 ) <--- SQL_SUCCESS Time elapsed - +9.428800E-002 seconds DB2からのエラー情報応答 Systems Solution & Web Server Competence Center No.1 DM Group 37-38 4-2 CLIトレース調査例 エラー発生個所のまとめ "どんな要求に対してどんなエラーメッセージが返されたのか？" トレースの第一次分析はここまでで十分です。前の２ページでわかったことをまとめてみましょう SQLGetDataInternal(列の値の取り出し）要求に対して、戻りコードSQL_ERROR が返された、 エラーメッセージはCLI0150E SQLSTATEは HYC00, SQLCODE は -99999 次に何をするか？ エラーメッセージだけでは、"何をやったら"がわからなくて"どうなったか"だけしかわかりません。 CLIトレースによって"何をやったら"の流れが始めからわかります。 エラー発生より上を見て行く。 このトレースの上を見ていけば原因は究明できるはずです。それには流れを追うためにCLIのプログラミングの知識が必要です。 幸いCLIはODBCとISO のSQL/CLI の標準に準拠していますから、それらのプログラミングの経験者の方にも追いやすい ものです。 正常に動くトレースと比較する 正常ケースのトレースと比較して違いを見つければ、あまりプログラミング知識がなくても原因がわかるでしょう。 正常ケースとの環境の違いを見つける db2cli.iniの指定の違いなど、プログラムの外にある環境の違いでプログラムの動き方は変わります。db2cli.iniの指定はデータベー スのコネクションの際にトレースに載りますから、トレースを見ても違いがわかります。 サポート部門への問い合わせ、事例照会 ここまで資料がとれればIBMアンサーラインセンターなど専門の部門で追求ができるでしょう、また同様の事例検索のためのキー ワードもメッセージより多く得られたので問題事例照会も精度が上がるでしょう。これ以降の追及手順は付録に載せます。 Systems Solution & Web Server Competence Center No.1 DM Group ブランクページ 39-40 5 db2trc db2trcの概要 概要 db2エンジンの動作の流れをトレース イベントモニターfor STATESMENTS や CLIトレースはアプリケーションプログラムから見たDB2への要求と応答の流れが載るもの でした。これに対しdb2trcはdb2のエンジン内部の動きをトレースするツールです。 出力情報は非公開 db2trcの出力ファイルは読み方が公開されていません。アンサーラインセンターから要求されたら取得し、出力ファイルを送付しま す。 注意点 トレースは多量に出力されます、トレース収集は再現用のシステムを占有使用して、必要最小限の操作だけ行うのが現実的です トレース収集は負荷のかかるため一般に、本番システムはサービス停止中に行うか別のシステムで再現させて収集します 必要な権限はSYSADM SYSCTRL SYSMAINT です DB2 EEE ではそれぞれのノードでトレース収集を実行する必要があります 取得手順 トレース取得手順はアンサーラインセンターから毎回具体的に指示されます。ここでは一例を紹介します。 コマンドの仕様はコマンド解説書に記述されています db2trc on -e -1 -l 16000000 トレースを開始します -e -1 はエラーが何個発生してもトレースを停止しない -l はトレースバッファーサイズです 問題を再現する db2trc dump trace.dat メモリー上のトレースをファイルに書き出します db2trc off トレースを止めます db2trc fmt trace.dat trace.fmt トレースのバイナリーファイルをフォーマットします、トレースがwrapしていないことをメッセージで確かめます wrapしていたら、始めの部分が上書きされて残っていません、トレースバッファーサイズを大きくするか、または 手際よく、早く操作してとりなおしましょう db2trc flw trace.dat trace.flw フォーマットされたトレースがうまくとれていたら、トレースの流れのサマリーをあらわすflow トレースファイルを出力 しましょう Systems Solution & Web Server Competence Center No.1 DM Group 5 db2trc db2trcの利用例 db2問題判別の手引きより 問題：DB2を起動してアプリケーションからデータベースへCONNECTするとSQL1042C "予期しないシステムエラーが発生しました"の メッセージで全くCONNECTできない db2diag.log に情報があるが詳細が不明 SQL1042Cの"メッセージのユーザーの応答":"データベースの接続中にエラーが起きた場合はトレースを取得(以下に指示があり ます）して、IBMサポートに連絡してください " db2diag.logメッセージ 1997-03-16-08:54:38.001160 Instance:payroll Node:000 PID:74467(db2syscs (SAMPLE)) Appid:*LOCAL.payroll.970317140834 data_management (5) sqldmund Probe:375 Database:SAMPLE Error during undo. (3) 0ae6 ffff 0ae6 ffff 0000 005e efa2 6363 (4) db2trcのfmt出力 3478 DB2 non-fatal_err oper_system_services sqloopenp (1.4.15.140) pid 55; tid 38; cpid 112; time 365535; trace_point 6 433a 5c44 4232 5c53 514c 3030 3030 315c /DB2/SQL00001/ 5351 4c54 3030 3032 2e30 5c53 514c 3030 SQLT0002.0/SQL00 3031 302e 4441 54 010.DAT (2) 3479 DB2 cei_data oper_system_services sqloopenp (1.25.15.140) pid 55; tid 38; cpid 112; time 365535; trace_point 7 ffff ffff 3480 DB2 cei_errcode oper_system_services sqloopenp (1.6.15.140) pid 55; tid 38; cpid 112; time 365535; trace_point 254 return_code = 0xffffe60a (1) = -6646 = SQLO_FNEX Systems Solution & Web Server Competence Center No.1 DM Group 41-42 db2diag.log のメッセージ 0ae6 ffff はWindowsではバイト反転しているため 実際は FFFF E60A です E60A は 問題判別の手引き:付録A DB2 Internral Reuturn Codesの表ではFile does not exist です どんなファイルが存在しなかったのか？ファイル名 まではdb2diag.logには載っていません db2trcのトレース出力 trace.fmt から e60a または E60A を検索すると トレースの3480番に0xffffe60a が見つかります これはOSのサービスsqloopenp の戻りコードです が、上へたどると/DB2/SQL00001/SQLT0002.0 /SQL00010.DAT ファイルを処理していることがわ かります。この処理の結果ファイルが見つからない メッセージが返されました ファイルの存在やUnix/Linuxならファイルのパー ミッションを確認し、もし本当になければ、データ ベースのバックアップをrestoreしてend of log まで rollforwardすればこのファイルも回復できるでしょう 終わりに その他のツール 参照情報 DB2問題判別の手引き 第１６章トレース Administration Tools Trace コントロールセンター、アラートセンター、コマンドセンターなど管理ツールのトレースを収集します ddcsトレース DB2 Connectのトレースです。ホストDB2への接続時の問題判別に有効です。DB2 Connect使用者の手引きに使い方があります db2drdat DRDA 接続時に交換されるデータストリーム上の問題判別やパフォーマンスチューニングに有効です SNAトレース SNA接続のホストDB2との通信に関してDB2がSNAアラートを生成する機能です 同様にDB2はSNMPアラートも生成します CLIトレースのその他のトレース用キーワード TRACECOMM=0|1 1でCLI要求・応答がネットワークを通った情報が載ります TRACETIMESTAMP= 3 タイムスタンプ(秒)がトレースに載ります 2 年月日秒マイクロ秒がトレースに載ります 1 タイムスタンプ(秒)と年月日秒マイクロ秒の両方がトレースに載ります TRACEPIDTID=0|1 1 プロセスIDとスレッドIDがトレースに載ります JDBCトレース JDBCメソッドについてのトレースを収集します、db2cli.iniに以下のパラメータを指定します JDBCTRACE=1 JDBCTRACEPATHNAME=C:¥CLITRACE JDBCFLUSH=1 ODBCドライバーマネジャートレース ODBCドライバーマネジャートレースはアプリケーションがODBCドライバーマネジャーを呼び出す部分のトレースです (ODBCの場合CLIトレースはその後に、ODBCドライバーマネジャーからDB2クライアントが呼び出された部分のトレースです） これについてははMicrosoft ODBC3.0 SDKプログラマーズレファレンスを参照してください OSその他のトレース アプリケーションサーバーとデータベースサーバー間の問題判別の際にOSの持つIPトレースの機能やスニファーなどネットワーク上 のトレースツールが有効な場合もあります。 Systems Solution & Web Server Competence Center No.1 DM Group 付録 CLIトレースの追求例 着眼点:列値を取り出そうとしてエラーとなった元のSELECT文はどんなものか？ この操作はステートメントハンドル1:2を使ってSQLを発行して結果を操作しています、トレースを上にたどり、ステートメントハンドル1:2が (フリーされ再割り振りされたりせずに)有効な範囲でステートメントハンドル1:2のSQL文を探すとSELECT文のPrepareが見つかります SQLPrepareW( ) <--- SQL_SUCCESS 応答 上へたどる CLI関数名 SQLPrepareW( hStmt=1:2, pszSqlStr="select class_source from sysibm.sysjarcontents where jarschema = ? and jar_id = ? and class = ?" X"730065006C00650063007400200063006C006100730073005F0073006F0075007200630065002000660072006F006D0020007300 79007300690062006D002E007300790073006A006100720063006F006E00740065006E007400730020007700680065007200650020 006A006100720073006300680065006D00610020003D0020003F00200061006E00640020006A00610072005F006900640020003D0 20003F00200061006E006400200063006C0061007300730020003D0020003F00", cbSqlStr=95 ) ---> Time elapsed - +3.798000E-003 seconds 要求 ( StmtOut="select class_source from sysibm.sysjarcontents where jarschema = ? and jar_id = ? and class = ?" ) Time elapsed - +3.589300E-002 seconds 中略 CLI関数名 SQLDescribeColW( hStmt=1:2, iCol=1, pszColName=NULL, cbColNameMax=0, pcbColName=NULL, pfSQLType=&0ab2fb08, pcbColDef=&0ab2fb0c, pibScale=NULL, pfNullable=NULL ) ---> Time elapsed - +6.798000E-003 seconds 要求 SQLDescribeColW( pfSQLType=SQL_LONGVARCHAR, pcbColDef=10485760 ) <--- SQL_SUCCESS Time elapsed - +8.699900E-002 seconds 応答 SQLGetDataInternal( hStmt=1:2, iCol=1, fCType=SQL_C_WCHAR, prgbValue=&0ab2fb48, cbValueMax=20971522, pcbValue=&0ab2fb54 ) ---> Time elapsed - +6.043000E-003 seconds 要求 SQLGetDataInternal( ) <--- SQL_ERROR Time elapsed - +5.761200E-002 seconds 応答 Systems Solution & Web Server Competence Center No.1 DM Group 43-44 問題の SELECT文 付録 CLIトレースの追求例 着眼点:問題のSELECTの列１はどんなものか？ 表名がsysibm.sysjarcontents で問題の列名がclass_sourceであることがわかりましたからDESCRIBE TABLEコマンドで CLASS_SOURCE列の列属性がわかります 一方、問題発生直前のSQLDescribeCol関数は(第一列の)列属性をDB2に聞くためのものですが、ここではlong型10485760バイ トとDB2から返されていますこの不一致はなぜでしょう？ SQLPrepareW( hStmt=1:2, pszSqlStr="select class_source from sysibm.sysjarcontents where jarschema = ? and jar_id = ? and class = ?" （途中省略) ---> Time elapsed - +3.798000E-003 seconds 要求 問題の SELECT文 ( StmtOut="select class_source from sysibm.sysjarcontents where jarschema = ? and jar_id = ? and class = ?" ) CLASS_SOURCE列 SQLPrepareW( ) CLOB(10485760) <--- SQL_SUCCESS Time elapsed - +3.589300E-002 seconds 応答 中略 不一致？ SQLDescribeColW( hStmt=1:2, iCol=1, pszColName=NULL, cbColNameMax=0, pcbColName=NULL, pfSQLType=&0ab2fb08, pcbColDef=&0ab2fb0c, pibScale=NULL, pfNullable=NULL ) ---> Time elapsed - +6.798000E-003 seconds 要求 SELECTの第一列(CLASS_SOURCE列) LONG VARCHAR型 10485760バイト SQLDescribeColW( pfSQLType=SQL_LONGVARCHAR, pcbColDef=10485760 ) <--- SQL_SUCCESS Time elapsed - +8.699900E-002 seconds 応答 SQLGetDataInternal( hStmt=1:2, iCol=1, fCType=SQL_C_WCHAR, prgbValue=&0ab2fb48, cbValueMax=20971522, pcbValue=&0ab2fb54 ) ---> Time elapsed - +6.043000E-003 seconds 要求 SQLGetDataInternal( ) <--- SQL_ERROR Time elapsed - +5.761200E-002 seconds 応答 Systems Solution & Web Server Competence Center No.1 DM Group 付録 CLIトレースの追求例 注意点:真の原因は問題発生点よりずっと前に存在しうる このケースの原因はdb2cli.iniにLONGDATACOMPAT=1 という指定があったためでした。正常ケースと異常ケースを比較すると４つに分かれたトレースファイル の最初のファイル1564.0 にあるデータベースへの接続のパラメータにLOGNDATACOMPAT=1が追加されていることがわかります。この指定によりCLOBなど ラージオブジェクトをサポートしないアプリケーションのためにCLOBをLONG VARCHARとして見せる変換が働き、アプリケーションには列１の属性がLONG VARCHAR型として返されました。しかしLONG VARCHARはもともと32700バイトまでしか許されないため、今回のような10485760バイトでは"CLI0150Eドライ バーが使用できません"エラーとなりました。パラメータをはずせば解決です。 最初のトレースファイルのデータベース接続部分 connect 要求 connect 応答 SQLDriverConnectW( hDbc=0:1, hwnd=0:0, szConnStrIn="DSN=TEST1;UID=db2admin;PWD=********", cbConnStrIn=35, szConnStrOut=NULL, cbConnStrOutMax=0, pcbConnStrOut=NULL, fDriverCompletion=SQL_DRIVER_NOPROMPT ) ---> Time elapsed - +9.634000E-003 seconds ( DBMS NAME="DB2/NT", Version="07.02.0000", Fixpack="0x23010105" ) ( Application Codepage=943, Database Codepage=943, Char Send/Recv Codepage=943, Graphic Send/Recv Codepage=941, iGraphic Codepage=941 ) SQLDriverConnectW( ) <--- SQL_SUCCESS Time elapsed - +2.496622E+000 seconds ( DSN="TEST1" ) ( UID="db2admin" ) ( PWD="********" ) ( DBALIAS="test1" ) db2cli.iniから追加さ ( LONGDATACOMPAT="1" ) れたパラメータ db2カタログ 情報の属性 SQLDescribeCol関数でアプリケー ションに返された属性 CLASS_SOURCE列 CLOB(10485760) SELECTの第一列(CLASS_SOURCE列) LONG VARCHAR型 10485760バイト db2が列型を置き 換えて見せる 矛盾 DB2制限 LONG VARCHAR型 32700バイトま で Systems Solution & Web Server Competence Center No.1 DM Group 45-46 CLI0150Eドライバー が使用できません