2−3 デッドロック・イベント:出力の見方 いつデッドロックが起こったのか? Deadlock Event レコードの確認 ・2つのアプリケーションで発生
by user
Comments
Transcript
2−3 デッドロック・イベント:出力の見方 いつデッドロックが起こったのか? Deadlock Event レコードの確認 ・2つのアプリケーションで発生
2−3 デッドロック・イベント:出力の見方 ■ いつデッドロックが起こったのか? Deadlock Event レコードの確認 ● 3) Deadlock Event ... (デッドロックの発生) Deadlock ID: 2 Number of applications deadlocked: 2 Deadlock detection time: 01/29/2004 10:35:48.767928 Rolled back Appl participant no: 2 Rolled back Appl Id: *LOCAL.DB2.00BB89012635 Rolled back Appl seq number: : 0002 ■ ・2つのアプリケーションで発生 ・この時刻にDEADLOCKが発生した ・Appl Idより、ロールバックしたのは4)の方 どのアプリケーションでデッドロックが起き、どちらがロールバックされたのか? Connection Header Event レコードの確認 ● 4) Connection Header Event ... (コネクション・ヘッダー) Appl Handle: 12 Appl Id: *LOCAL.DB2.00BB89012635 Appl Seq number: 0002 DRDA AS Correlation Token: *LOCAL.DB2.00BB89012635 Program Name : db2bp.exe (DB2コマンド行プロセッサー) Authorization Id: DB2ADMIN Execution Id : DB2ADMIN Codepage Id: 943 Territory code: 81 Client Process Id: 412 Client Database Alias: SAMPLE (SAMPLEデータベース) Client Product Id: SQL08014 Client Platform: Unknown Client Communication Protocol: Local (ローカル・クライアント) Client Network Name: Connect timestamp: 01/29/2004 10:26:34.724490 6) Connection Header Event ... (コネクション・ヘッダー) Appl Handle: 11 Appl Id: *LOCAL.DB2.008689012622 Appl Seq number: 0002 DRDA AS Correlation Token: *LOCAL.DB2.008689012622 Program Name : db2bp.exe (DB2コマンド行プロセッサー) Authorization Id: DB2ADMIN Execution Id : DB2ADMIN Codepage Id: 943 Territory code: 81 Client Process Id: 784 Client Database Alias: SAMPLE (SAMPLEデータベース) Client Product Id: SQL08014 Client Platform: Unknown Client Communication Protocol: Local (ローカル・クライアント) Client Network Name: Connect timestamp: 01/29/2004 10:26:22.118095 2−3 デッドロック・イベント:出力の見方:解説 デッドロック・イベントモニターでは、以下の3種類のレコードが取得できます。 Deadlock Event ● – – デッドロック情報のサマリー 発生時刻、関わったアプリケーションの数、ロールバックされたアプリケーションIDなどがわかります 以下は、関わったアプリケーションごとに作成されます。 ●Connection Header Event – デッドロックに関わったアプリケーションの接続情報 Deadlocked Connection ● – デッドロックに関連する詳細情報 − どのアプリケーションのどのオブジェクトをどのようにロック待ちしていたか、すでに取得していたロック、などの情報 ■ いつデッドロックが起こったのか? Deadlock Event レコードを確認します。 ● – ■ Appl Id: などの値を使って、関連するConnection Header Eventレコード等を見つけることができます どのアプリケーションでデッドロックが起き、どちらがロールバックされたのか? Connection Header Eventレコードには、デッドロックに関係したプログラム名等が出力されます。 ● – ■ Program Name: db2bp.exe は、DB2コマンド行プロセッサーがアプリケーション・プログラムであることを示します どのクライアントと、どのクライアントで起こったのか? Connection Header EventレコードのClient Communication Protocolに着目します ● – この例ではLocal となっていますので、サーバー内のアプリケーションでデッドロックが発生しています Client Communication ProtocolがTCP/IPの場合、IPアドレスは application snapshot で知ることができます ● – – db2 get snapshot for all applications on データベース別名 でその時点のsnapshot をあらかじめ取得しておきます applicaiton snapshotには各アプリケーションが稼動するクライアントのIPアドレスが出力されます、これとAppl Id でつき合 わせことでIPアドレスがわかります 2−3 デッドロック・イベント:出力の見方 ■ どのアプリケーションとどのアプリケーションでデッドロックが起こったのか? Deadlocked Connection レコードの確認(1/3) ● 5) Deadlocked Connection ... (デッドロック対象アプリケーション) Deadlock ID: 2 Participant no.: 2 Participant no. holding the lock: 1 Appl Id: *LOCAL.DB2.00BB89012635 (自分) Appl Seq number: 0002 Appl Id of connection holding the lock: *LOCAL.DB2.00BB89012635 Seq. no. of connection holding the lock: 0002 Lock wait start time: Lock Name : 0x02000600040000000000000052 Lock Attributes : 0x00000000 このロックを待っていた Release Flags : 0x00000001 Lock Count :1 Hold Count :0 Current Mode : none Deadlock detection time: 01/29/2004 10:35:48.768075 Table of lock waited on : EMPLOYEE 対象表 Schema of lock waited on : DB2ADMIN Tablespace of lock waited on : USERSPACE1 Type of lock: Row Mode of lock: X - Exclusive (相手の保持していたロック) Mode application requested on lock: NS - Share (and Next Key Share) (自分の要求したロック) 相手がロック・オブジェク Node lock occured on: 0 ト名 4 のXロックを保持 Lock object name: 4 しているところに、下記 Application Handle: 12(自分) select文でNSロックを取 りにいき、ロック待ちと コネクション・ヘッ なった ダー4)に対応 7) Deadlocked Connection ... (デッドロック対象アプリケーション) Deadlock ID: 2 Participant no.: 1 Participant no. holding the lock: 2 Appl Id: *LOCAL.DB2.008689012622 (自分) Appl Seq number: 0002 Appl Id of connection holding the lock: *LOCAL.DB2.008689012622 Seq. no. of connection holding the lock: 0002 Lock wait start time: Lock Name : 0x02000600000100000000000052 Lock Attributes : 0x00000000 このロックを待っていた Release Flags : 0x00000001 Lock Count :1 Hold Count :0 Current Mode : none Deadlock detection time: 01/29/2004 10:35:48.768530 Table of lock waited on : EMPLOYEE 対象表 Schema of lock waited on : DB2ADMIN Tablespace of lock waited on : USERSPACE1 Type of lock: Row Mode of lock: X - Exclusive (相手の保持していたロック) Mode application requested on lock: NS - Share (and Next Key Share) (自分の要求したロック) 相手がロック・オブジェク Node lock occured on: 0 ト名 256 のXロックを保 Lock object name: 256 持しているところに、下 Application Handle: 11 (自分) 記select文でNSロックを 取りにいき、ロック待ちと コネクション・ヘッ なった ダー6)に対応 2−3 デッドロック・イベント:出力の見方 ■ ■ どのアプリケーションとどのアプリケーションでデッドロックが起こったのか? どんなSQLと、どんなSQLで起こったのか? Deadlocked Connection レコードの確認(2/3) ● 5) Deadlocked Connection ... 7) Deadlocked Connection ... (中略) Deadlocked Statement: Type : Dynamic Operation: Fetch Section : 201 Creator : NULLID Package : SQLC2E03 発行したSQL文が Cursor : SQLCUR201 わかる Cursor was blocking: FALSE Text : SELECT COUNT(*) FROM EMPLOYEE WHERE SALARY=2000.00 List of Locks: Lock Name : 0x02000000010000000100AE0056 Lock Attributes : 0x00000000 Release Flags : 0x40000000 Lock Count :1 Hold Count :0 Lock Object Name :0 Object Type : Internal - Variation Mode : S - Share (中略) Deadlocked Statement: Type : Dynamic Operation: Fetch Section : 201 Creator : NULLID Package : SQLC2E03 発行したSQL文が Cursor : SQLCUR201 わかる Cursor was blocking: FALSE Text : SELECT COUNT(*) FROM EMPLOYEE WHERE SALARY=1000.00 List of Locks: Lock Name : 0x02000600000100000000000052 Lock Attributes : 0x00000000 Release Flags : 0x00000001 Lock Count :1 Hold Count :0 Lock Object Name : 256 Object Type : Row Tablespace Name : USERSPACE1 Table Schema : DB2ADMIN Table Name : EMPLOYEE Mode : NS - Share (and Next Key Share) デッドロック解消後、ロック・オブ ジェクト名256を取得できた 2−3 デッドロック・イベント:出力の見方 ■ どのアプリケーションとどのアプリケーションでデッドロックが起こったのか? Deadlocked Connection レコードの確認(3/3) ● 5) Deadlocked Connection ... 7) Deadlocked Connection ... (中略) Lock Name Lock Attributes Release Flags Lock Count Hold Count Lock Object Name Object Type Tablespace Name Table Schema Table Name Mode Lock Name Lock Attributes Release Flags Lock Count Hold Count Lock Object Name Object Type Tablespace Name Table Schema Table Name Mode Locks Held: 4 Locks in List: 4 : 0x02000600000100000000000052 : 0x00000020 ロック・オブジェ : 0x40000000 クト名256にX :1 ロックを保持し :0 ており、それを : 256 相手のアプリ : Row ケーションが : USERSPACE1 ロック待ち。 : DB2ADMIN デッドロック解消 : EMPLOYEE 後、相手にロッ : X - Exclusive クを取られた (中略) : 0x02000600000000000000000054 : 0x00000000 : 0x40000001 :2 :0 :6 : Table : USERSPACE1 : DB2ADMIN : EMPLOYEE : IX - Intent Exclusive (中略) Lock Name Lock Attributes Release Flags Lock Count Hold Count Lock Object Name Object Type Tablespace Name Table Schema Table Name Mode : 0x02000600040000000000000052 : 0x00000020 : 0x40000000 ロック・オブジェ :1 クト名4にXロッ :0 クを保持してお :4 り、それを相手 : Row のアプリケー : USERSPACE1 ションがロック : DB2ADMIN 待ちしていた : EMPLOYEE : X - Exclusive Lock Name Lock Attributes Release Flags Lock Count Hold Count Lock Object Name Object Type Tablespace Name Table Schema Table Name Mode : 0x02000600000000000000000054 : 0x00000000 : 0x40000001 :2 :0 :6 : Table : USERSPACE1 : DB2ADMIN : EMPLOYEE : IX - Intent Exclusive Locks Held: 5 Locks in List: 5 2−3 デッドロック・イベント:出力の見方:解説 ■ どのアプリケーションとどのアプリケーションでデッドロックが起こったのか? デッドロックを引き起こしたロック・オブジェクト名等より、相手のアプリケーションを特定することが可能です。 Deadlocked Connection レコードのAppl Id: か Appl Handle:の値を使って、 Connection Header Eventと関連づけることができ ます ● ● ■ どんなSQLと、どんなSQLで起こったのか? Deadlocked Connection レコードには、デッドロックの対象となった表や、SQL文も出力されます。 ● – – DEADLOCKS WITH DETAILSイベント・タイプではSQL文が出力されますが、DEADLOCKSイベント・タイプでは出力されま せん 対象表名はTable of lock waited on とSchema of lock waited on でわかります。この例ではDB2ADMIN.Employee表です 2−3 デッドロック・イベント:再現させたSQLの流れ ■ このケースでの発生原因(分離レベルCS) Appl Id: LOCAL.DB2.00BB89012635 1)DELETE FROM EMPLOYEE WHERE EMPNO='000010' Appl Id: *LOCAL.DB2.008689012622 ● 削除行にXロック EMPNOに索引あり – – 2)DELETE FROM EMPLOYEE WHERE EMPNO='000340' ● – – 3)SELECT COUNT(*) FROM EMPLOYEE WHERE SALARY = 1000.00 削除行にXロック EMPNOに索引あり ● 索引の無い列Salaryの検索のために全 件読み、2)のXロックの解放を待つ – ■ 4)SELECT COUNT(*) FROM EMPLOYEE WHERE SALARY = 2000.00 ● 索引の無い列Salaryの検索のために全 件読み、1)のXロックの解放を待つ – デッドロックを発生させる流れは次の通り(autocommit は off に設定) 1)左のアプリケーションでEMPLYEE表のキー000010をDELETEする 2)右のアプリケーションでEMPLYEE表のキー000340をDELETEする ●3)左のアプリケーションでEMPLYEE表のSALARY = 1000.00 の条件を満たす行数をSELECTする ● ● – SALARYには索引が無いので、全行読む必要があり、2)で右が更新した行を読むためにNSロックを獲得しようとする。こ の時、右側のアプリケーションのDELETEによるXロック(Exclusive Lock)は保持されたままなのでロック待ちとなる ➨ NSロックは、分離レベルCSでCommit済みの値を読むために要求される 4)右のアプリケーションでEMPLYEE表のSALARY = 2000.00 の条件を満たす行数をSELECTする ● – SALARYには索引が無いので、全行読む必要があり、1)で左が更新した行を読むためにNSロックを獲得しようとする、こ の時、左側のアプリケーションのDELETEによるXロック(Exclusive Lock)は保持されたままなのでロック待ちとなる 5)左右ともロック待ちが解けないため、デッドロックが成立する ● 2−4 イベント・モニター補足事項 ■ デッドロック・イベント・モニター DB2 V8より、デフォルトのデッドロック・イベント・モニターが開始されています ● DB2DETAILDEADLOCK という名前のイベント・モニターが、新規に作成されるデータベースごとに作成されます データベースが活動化されると開始され、データベース・ディレクトリー内のファイルに書き込みます このイベント・モニターによるオーバーヘッドは、 これをドロップすることによって回避することができます – – – DEADLOCKSイベント・タイプでは、関係するSQL文は出力されませんが、DEADLOCKS WITH DETAILS イベント・タイプを使 用すると可能です。ただし、追加の情報が収集されるため、デッドロックが発生したときにパフォーマンス・コストの負担になる ことに注意が必要です。 ● ■ イベント・モニター全般について イベント・モニターの再活動化 ● drop event monitor していなければ 何度でも "活動化、再現テスト、非活動化 、編集出力" を繰り返すことができま す。 – イベント・モニターの削除 ● – ➨ db2 drop event monitor ev1 登録したイベント・モニターを削除します 参照情報 ● – – – – – DB2インフォメーション・センター CREATE EVENT MONITOR 他 db2evmon イベントモニター出力の解説 出力編集サンプルプログラム sqllib¥samples¥c¥evm.c evmread.c evmprint.c 『SQL リファレンス』 『コマンド・リファレンス』 『システム・モニター ガイドおよびリファレンス』 3−1 db2diag.log ファイルの概要 ■ db2diag.log ファイルの概要 db2diag.logはDB2が情報を記録するASCIIファイル ● – 記録内容 BACKUP / RESTORE などデータベース管理事象のログ ➨ エラー情報 エラーの理由を示すDIAメッセージ エラーSQLCODE データベースのクラッシュ時の情報、ダンプ・ファイル、トラップ・ファイル ➨ – ファイルの場所 データベース・マネジャー構成パラメーターDB2DIAGPATHディレクトリーで指定 ➨ 省略時 Windows: SQLLIB¥DB2 ディレクトリー Unix: インスタンス・オーナーのホーム・ディレクトリーの下の sqllib/db2dump ➨ – 記録方法 常に最後に追加される ➨ タイムスタンプ付き ➨ 単調増大するため定期的に保存・削除が必要 ➨ DIAGLEVELデータベース・マネジャー構成パラメーターによる記録レベル指定(0−4、省略時3) 単一パーティション・データベースでは3を推奨 4はinformationalメッセージが必要な場合にのみ使用 パーティション・データベース(Data Partitioning Feature使用)でも3を推奨 省略時ではNFS共有ファイルへ書き込む DIAGLEVELを4にする場合は、特にDIAGPATHをNFSからローカル・ディスクに代え、 パフォーマンスへの影響を回避することを推奨 ➨ 3−1 db2diag.log ファイルの概要 db2diag.logファイルはDB2が情報を記録するasciiファイルです。 記録内容には2種類あります。 ● ● – – ひとつはデータベースのバックアップ、リストアなのデータベース管理の事象の記録です もうひとつは発生したエラーに関する情報です。DIAではじまるメッセージ・コードでエラーの理由を説明する診断メッセージ が書かれ、あわせてSQLCODEや発生したダンプ・ファイルやトラップ・ファイルを示します。 db2diag.logファイルはDB2DIAGPATHデータベース・マネジャー構成パラメーターの示すディレクトリーに書かれます。 ● – – 省略時ではWindowsではsqllib¥db2 ディレクトリー Unix/Linuxではインスタンス・オーナーのホーム・ディレクトリーの下のsqllib/db2dumpディレクトリーです。 ファイルは常に最後に追加して書かれます。 ファイルは単調増大するため、定期的に保存し削除するという運用が必要です。 ●メッセージにはタイムスタンプが付加されていて事象の発生時刻がわかります。 ● ● データベース・マネージャー構成パラメータのDIAGLEVELパラメーターにより、記録される情報のレベルが変わります。 ● – – – 指定可能な値は0から4までで、省略時は3です。Warningレベルまで記録されます 4にするとより多く、informationalメッセージまで記録されます 通常はレベル3の設定を推奨します Database Partitioning Featureを使ったパーティション・データベース環境では、省略時のままではdb2diag.logファイル はNFS共有ファイルに出力するため、書き出し情報量の多いレベル4では特にパフォーマンスの影響が懸念されます。 ● – – 通常はレベル3の使用を推奨します レベル4を使う場合などでは特に、DIAGPATHディレクトリーをNFSでなくローカル・ディスクへ変更することを推奨します 3−2 db2diag.log ファイルの利用:ロック・エスカレーション ■ ロック・エスカレーション事象の確認 ロック・エスカレーションが発生した時刻や表名、ロック・タイプ等を知ることができます ● – ロック・エスカレーションの発生は、SNAPSHOTモニターのデータベース・スナップショットのLock escalations(ロック・エスカ レーション発生回数)や、Exclusive lock escalations(Xロックのロック・エスカレーション回数)でも確認できます – db2diag.logを参照すれば時刻、表、該当Applid 等、より詳しい情報が把握できます – DIAGLEVELは3で記録されます 2004-01-29-17.29.49.645000 Instance:DB2 Node:000 PID:2576(db2syscs.exe) TID:1664 Appid:*LOCAL.DB2.00DB09082949 data management sqldEscalateLocks Probe:3 Database:SAMPLE タイムスタンプ ロック・エスカレーション事象 ADM5502W The escalation of "44" locks on table "DB2ADMIN.T1" to lock intent "X" was successful. Xロック(Exclusive ロック) 表名:DB2ADMIN.T1 3−2 db2diag.log ファイルの利用:ロック・タイムアウト ■ ロック・タイムアウト事象の確認 – ロック・タイムアウトの発生は、SNAPSHOTモニターのデータベース・スナップショットのLock Timeouts(ロック・タイムアウト発 生回数)でも確認できます – db2diag.logを参照すれば時刻、該当Applid 等、より詳しい情報が把握できます – DIAGLEVELは4で記録されます 2004-01-30-09.45.50.698000 Instance:DB2 Node:000 PID:2396(db2syscs.exe) TID:2496 Appid:*LOCAL.DB2.012DC0004535 lock manager sqlplnfd Probe:80 Database:SAMPLE Request for lock "TAB: (3, 263)" in mode ".IS" timed out Could be waiting for lock held by indoubt transaction Statement: 0x04FCA3B0 : 5345 4C45 4354 2043 4F55 4E54 282A 2920 0x04FCA3C0 : 4652 4F4D 2054 31 行のXロック要求にてロック・タイムアウトが発生し た静的SQLの例 SELECT COUNT(*) FROM T1 ロック・タイムアウ トになった動的 SQL文 表のIXロック要求にてロック・タイムアウトが発生し た静的SQLの例 2004-01-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 2004-01-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 セクション番号 3−2 db2diag.log ファイルの利用:ロック・タイムアウト db2diag.logに載っているロック・タイムアウトを起こしたパッケージ名とセクション名から、該当する静的SQLプログラムの SQL文を調査してみましょう。今回はDB2のカタログ視点からSQL文を調べてみます。 ● 前ページ左下の行のXロック要求にてロック・タイムアウトが発生した例では、パッケージCURSOR2のセクション2が原因でし たが、これはUPDATE文であることが、以下のようにSYSCAT.STATEMNTSをSELECTすることによりわかります – ➨ 前ページ右下の表のIXロック要求にてロック・タイムアウトが発生した例では、パッケージCURSOR2のセクション1が原因でし たが、これはSELECT文であることがSYSCAT.STATEMNTSをSELECTすることによりわかります。実際のコーディング上のス テートメントでは、このSELECT文に対するOpen cursor 文にてロック・タイムアウトが発生します – ➨ – このケースではロック・タイムアウトの再現操作として、コマンド行プロセッサーから次のSQLを発行しました db2 +c DELETE FROM T1 WHERE C1=1000 このケースではロック・タイムアウトの再現操作として、コマンド行プロセッサーから次の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 2 レコードが選択されました。 セクション1のSQL セクション2のSQL 3−2 db2diag.log ファイルの利用:デッドロック ■ デッドロック事象の確認 – デッドロックの発生は、SNAPSHOTモニターのデータベース・スナップショットのDeadlock Detected(デッドロック検知した回数) でも確認できます – db2diag.logを参照すれば時刻、ロールバックした動的SQL文、要求されていたロック・タイプ等、詳しい情報が把握できます – DIAGLEVELは4で記録されます 2004-01-30-10.30.30.742000 Instance:DB2 Node:000 PID:2356(db2syscs.exe) TID:2568 Appid:*LOCAL.DB2.012DC0012637 lock manager sqlplnfd Probe:80 Database:SAMPLE ロールバックした側 Request for lock "REC: (2, 6) RID 00000004" in mode ".NS" failed due to deadlock Could be waiting for lock held by indoubt transaction Statement: 0x04FCC950 : 7365 6C65 6374 2063 6F75 6E74 282A 2920 select count(*) 0x04FCC960 : 6672 6F6D 2065 6D70 6C6F 7965 6520 7768 from employee wh 0x04FCC970 : 6572 6520 7361 6C61 7279 3D30 ere salary=0 NSロック要求待ちで デッドロックになった ロールバックしたSQL 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プログラミン グの2つに大別されます。 CLIの特徴 ● – – CLIにはODBCの特徴でもあるデータベースの一覧を得るAPIや表の一覧を得るAPIが備 わっています。CLIプログラミングでは表の一覧を得るために、データベースのカタログ表 の名前や列名を知る必要がありません。 埋め込みSQLプログラミングのようなアプリケーション・プログラムのプリコンパイルは必 要ありません。その代わりに、実行時に動的に必要な処理を行います。例えばアプリケー ション・プログラムがSELECT文を発行したら、結果を受け取る前にアプリケーション・プロ グラムは、DB2に、”私が出したSELECT文の結果は何列ありましたっけ?”とか”1番目の 列は列タイプは何で、長さはいくらでしたっけ?”、”二番目の列は......“のように動的に列 属性に応じた処理をアプリケーション・プログラムで行います。このためCLIのAPIは50個 程度もあり、トレースも各列ごとにエントリーがあるためかなり長いものとなります。 CLIトレースの用途 ● – JDBCやVB ADOからのプログラミングで予定外の事象が発生した場合は、DB2とCLIアプ リケーション・プログラムの接点でのなりゆきを示すCLIトレースの解析が役立ちます。 以下で資料の取り方と着眼点を紹介しましょう ● 4-1 CLIトレースの収集方法 ■ ● CLIトレース収集の指定 CLIはアプリケーション・プログラムとDB2クライアントの接点となるインターフェースです。トレース収集の指定はDB2クラ イアント機にて行います。 – – – ● アプリケーションを実行するユーザーに対して、指定したパスにトレース・ファイルを書き込む権限付与を忘れないでください 権限がない場合、ファイルは生成されませんが、警告にもエラーにもなりません 指定されたトレース・パスが存在しない場合、そのパスは作成されません CLIアプリケーションの動くクライアントPCやクライアント・インスタンスのdb2cli.iniファイルを編集します – – sqllib¥db2cli.ini (Windowsの場合) sqllib/cfg/db2cli.ini (Unix/Linuxの場合) [COMMON] ● – TRACEPATHNAME=C:¥CLITRACE TRACE=1 TRACEFLUSH=1 テキスト・ファイルを直接編集する他に、DB2構成アシスタントの利用、UPDATE CLI CFGコマンドの利用も可能です – TRACEPATHNAME 説明 ¾ ¾ – TRACE=1 ¾ – トレースを同期的にディスクへ書き出す指定です、同期的書き出しの方がトレース収集のもれがないので安心です コメント化の方法 ¾ ● CLIトレースを掛けることを指定します TRACEFLUSH=1 ¾ – CLIトレースを書き出すディレクトリーを指定します マルチスレッド・アプリケーションでは、スレッドごとにファイルが生成されます ;TRACE=1 のように先頭に; を付加すればコメントになります 指定のタイミング – db2cli.ini ファイルを変更した後に、アプリケーションをデータベースへ再接続してから始めてください 4-2 CLIトレースの調査例 ■ トレース取得操作 db2cli.ini にトレース取得のパラメータをセットします ● トレースを取得したいアプリケーション・プログラムを起動し、エラーが再現する直前まで操作します ● – 再現直前時点のトレース・ファイルのコピー(参考) CLIトレースは多量に出力されるので、エラー個所を特定するためには"エラー発生前"のトレース範囲を知っておくと絞り込み が容易です ➨ 参考のため、再現直前の段階でトレース・ディレクトリーに書かれたトレース・ファイルを、別のディレクトリーにコピーしておき ましょう ➨ エラーの再現操作 ● エラーが起きる操作を行って、エラーを再現させます – – ➨ 再現直後のトレース・ファイルのコピー エラー発生以降のエントリーができるだけ含まれないようにすみやかにコピーしましょう db2cli.ini修正 DB2アプリケーション開始 再現直前まで操作 トレース・ファイルのコピー 再現前 トレース 注目 個所 エラーの再現 トレース・ファイルのコピー 再現後 トレース 4-2 CLIトレースの調査例 ■ トレース・ファイルの確認 再現直前にコピーしておいたトレース・ファイルと、再現直後にコピーしたトレース・ファイルを比べると、以下の例では次 のことがわかります ● ファイル数が、3個から4個に増えている 1564.2のファイルの大きさが増えて最終更新時刻が1分あとに変わっている 1564.3のファイルが再現後、新規に増えている – – – このことから、問題のエラーの個所は1564.2のファイルの437バイト目より後か、1564.3ファイルに載っていると絞込むこ とができます ●db2cli.iniにTRACEPATHNAME キーワードが設定されているときには、自動的にアプリケーションのプロセス ID とスレッ ド・シーケンス番号を使用してトレース・ログ・ファイルに名前が付けられます ● スレッドが 3 つあるアプリケーションの DB2 CLI トレースは次のような DB2 CLI トレース・ログ・ファイルを生成します ➨ – 100390.0、 100390.1、 100390.2 DB2 V8のWindows版では、p640t740.cli のようなファイル名になります 再現直前 トレース 再現直後 トレース 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 06:23 06:23 3 個のファイル 180,178 バイト . .. 39,181 1564.0 140,560 1564.1 437 1564.2 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 バイト 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 という文字を検索 CLI関数名 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 個のファイル 39,181 140,560 611 7,982 . .. 1564.0 1564.1 1564.2 1564.3 188,334 注 目 個 所 – バイト 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 応答 4-2 CLIトレースの調査例 ■ エラー・メッセージ発生個所の確認 エラー・メッセージは、SQL_ERROR戻りコードが返った後に、アプリケーション・プログラムからのエラー・メッセージ取り出 し要求に返されます。 ● – CLI関数名 下の例ではSQL_ERRORの発生後、2組の診断データ構造フィールドの要求・応答の後、アプリケーションがDB2へエラー情報 を要求し、DB2からはエラー・メッセージ・コード、SQLSTATE、SQLCODEが返されています 前ページより 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 ) ---> Time elapsed - +6.685000E-003 seconds DB2へエラー情報の取り出し要求 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からのエラー情報応答 4-2 CLIトレースの調査例 ■ エラー発生個所のまとめ “どんな要求に対してどんなエラー・メッセージが返されたのか?" トレースの第一次分析はここまでで十分です。前の2ページでわかったことをまとめてみましょう ● – – – – ■ SQLGetDataInternal(列の値の取り出し)要求に対して、戻りコードSQL_ERROR が返された エラーメッセージはCLI0150E SQLSTATEは HYC00 SQLCODE は -99999 次に何をするか? エラー・メッセージだけでは、"何をやったら"がわからなくて"どうなったか"だけしかわかりません ● – CLIトレースによって“何をやったら”の流れが始めからわかります エラー発生より上を見て行く ● – このトレースの上を見ていけば原因は究明できるはずです。それには流れを追うためにCLIのプログラミングの知識が必要で す。幸いCLIはODBCとISO のSQL/CLI の標準に準拠していますから、それらのプログラミングの経験者の方にも追いやす いものです 正常に動くトレースと比較する ● – 正常ケースのトレースと比較して違いを見つければ、あまりプログラミング知識がなくても原因がわかるでしょう 正常ケースとの環境の違いを見つける ● – db2cli.iniの指定の違いなど、プログラムの外にある環境の違いでプログラムの動き方は変わります。db2cli.iniの指定はデー タベースのコネクションの際にトレースに載りますから、トレースを見ても違いがわかります サポート部門への問い合わせ、事例照会 ● – ここまで資料がとれればIBMのサポート部門など専門の部門で追求ができるでしょう、また同様の事例検索のためのキー ワードも、メッセージより多く得られたので、問題事例照会も精度が上がるでしょう。これ以降の追究手順は付録に掲載しま す ■ このページはブランクです。 5 db2trc ■ db2trcの概要 概要 ● ➨ db2エンジンの動作の流れをトレース イベント・モニターfor STATESMENTS や CLIトレースはアプリケーション・プログラムから見たDB2への要求と応答の流れが 載るものでした。これに対し、db2trcはdb2のエンジン内部の動きをトレースするツールです。 ➨ 出力情報は非公開 db2trcの出力ファイルは読み方が公開されていません。IBMのサポート部門から要求された場合に取得し、出力ファイルを送 付します。 – – 注意点 ● ➨ ➨ ➨ ➨ トレースは多量に出力されるため、トレース収集時はエラー再現用にシステムを占有使用し、必要最小限の操作だけ行うの が望ましいです トレース収集は負荷がかかるため、一般には本番システムのサービス停止中に行うか別のシステムで再現させて収集します Unix/Linuxでは、SYSADM、SYSCTRL、またはSYSMAINT権限が必要なことに注意してください 複数データベース・パーティション・システムでは、それぞれのデータベース・パーティションに対して、トレースを実行する必要 があります 取得手順 ● – トレース取得手順はIBMのサポート部門から毎回具体的に指示されます。ここでは一例を紹介します。コドの仕様はコマンす db2trc on -l 16000000 トレースを開始します。-l はトレース・バッファー・サイズです ➨ 問題を再現する ➨ db2trc dump trace.dat メモリー上のトレースをバイナリー・ファイルに書き出します ➨ db2trc off トレースを止めます ➨ db2trc fmt trace.dat trace.fmt トレースのバイナリー・ファイルをテキスト・フィアルにフォーマットします トレースがwrapしていないことをメッセージで確かめます wrapしていたら、始めの部分が上書きされて残っていませんので、トレース・バッファー・サイズを大きくするか、または 手際よく、早く操作して取り直しましょう ➨ db2trc flw trace.dat trace.flw フォーマットされたトレースがうまくとれていたら、トレースの流れのサマリーをあらわすflow トレース・ファイルを出力 しましょう ➨ 5 db2trc ■ db2trcの利用例(DB2 V7 『問題判別の手引き』より) 問題: DB2を起動してアプリケーションからデータベースへCONNECTすると、SQL1042C “予期しないシステム・エラーが 発生しました"のメッセージで全くCONNECTできない ● – – db2diag.log に情報はあるが詳細は不明 SQL1042Cメッセージ: ユーザーの応答: データベースの接続中にエラーが起きた場合はトレースを取得して、IBMサポートに連絡 してください DB2 V8からは、db2diag.logの16進コードの解釈は変わりました。以下のWebサイトをご参照ください ● – http://www-1.ibm.com/support/docview.wss?rs=71&context=SSEPGG&q=0x0258000C&uid=swg21066178&loc=en_US&cs=utf8&lang=en+en 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 ■ 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 インフォメーション・センター 管理ツール・ログ コントロール・センターなどDB2 のグラフィカル管理ツールのトレースを収集します ➨ ddcsトレース ➨ db2drdat ➨ SNAトレース DB2 Connectのトレースです。ホストDB2への接続時の問題判別に有効です DRDA 接続時に交換されるデータ・ストリーム上の問題判別やパフォーマンス・チューニングに有効です SNA接続のホストDB2との通信に関してDB2がSNAアラートを生成する機能です 同様にDB2はSNMPアラートも生成します ➨ CLIトレースのその他のトレース用キーワード TRACECOMM=0|1 TRACETIMESTAMP= 3 2 1 TRACEPIDTID=0|1 ➨ 1にすると、CLI要求・応答に関する通信関連情報が出力されます タイムスタンプ(年月日時分秒ミリ秒)がトレースに載ります 絶対実行時(秒およびミリ秒)がトレースに載ります 絶対実行時(秒およびミリ秒)の後にタイムスタンプ(年月日時分秒ミリ秒)がトレースに載ります 1にすると、プロセスIDとスレッドIDがトレースに載ります JDBCトレース JDBCメソッドについてのトレースを収集します、db2cli.iniに以下のパラメータを指定します JDBCTRACE=1 JDBCTRACEPATHNAME=C:¥CLITRACE JDBCFLUSH=1 ➨ ODBCドライバーマネジャートレース ODBCドライバーマネジャートレースは、アプリケーションがODBCドライバーマネジャーを呼び出す部分のトレースです (ODBCの場合のCLIトレースは、その後に、ODBCドライバーマネジャーからDB2クライアントが呼び出された部分のトレースになります) 詳細は、Windowsの[コントロールパネル]-[管理ツール]-[データソース(ODBC)]のオンライン・ヘルプ等をご参照ください – ➨ OSその他のトレース アプリケーション・サーバーとデータベース・サーバー間の問題判別の際に、OSの持つIPトレースの機能や、スニファーなど ネットワーク上のトレース・ツールが有効な場合もあります。 付録 CLIトレースの追究例 ■ 着眼点: 列値を取り出そうとしてエラーとなった元のSELECT文はどんなものか? この操作はステートメント・ハンドル1:2を使ってSQLを発行して結果を操作しています、トレースを上にたどり、ステートメン ト・ハンドル1:2が(フリーされ再割り振りされたりせずに)有効な範囲でステートメントハンドル1:2のSQL文を探すとSELECT 文のPrepareが見つかります ● 要求 応答 要求 応答 要求 応答 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 = ?" ) SQLPrepareW( ) <--- SQL_SUCCESS 上へたどる CLI関数名 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 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 問題の SELECT文 付録 CLIトレースの追究例 ■ 着眼点: 問題のSELECTの列1はどんなものか? SELECT文より、表名がsysibm.sysjarcontents、検索する列名はclass_sourceであることがわかります DB2のDESCRIBE TABLEコマンド等でCLASS_SOURCE列の列属性はCLOBであることがわかります ●一方、問題発生直前のSQLDescribeCol関数は(第1列の)列属性を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 ( StmtOut="select class_source from sysibm.sysjarcontents where jarschema = ? and jar_id = ? and class = ?" ) SQLPrepareW( ) <--- SQL_SUCCESS 応答 中略 要求 応答 要求 応答 CLASS_SOURCE列 Time elapsed - +3.589300E-002 seconds CLOB(10485760) 不一致? 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 SELECTの第一列(CLASS_SOURCE列) LONG VARCHAR型 10485760バイト 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 問題の SELECT文 付録 CLIトレースの追究例 ■ 注意点: 真の原因は問題発生点よりずっと前に存在し得る このケースの原因はdb2cli.iniにLONGDATACOMPAT=1 という指定があったためでした 正常ケースと異常ケースを比較すると4つに分かれたトレース・ファイルの最初のファイル1564.0 にあるデータベースへの 接続のパラメーターにLOGNDATACOMPAT=1が追加されていることがわかります ● ● – この指定によりCLOBなどラージ・オブジェクトをサポートしないアプリケーションのために、CLOBをLONG VARCHARとして見 せる変換が働き、アプリケーションには列1の属性がLONG VARCHAR型として返されました。しかしLONG VARCHARはもとも と32700バイトまでしか許されないため、今回のような10485760バイトでは“CLI0150Eドライバーが使用できません”エラーとなり ました。LONGDATACOMPAT=1のパラメーターをはずせば解決です。 最初のトレース・ファイルのデータベース接続部分 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="********" ) db2cli.iniから取得さ ( DBALIAS="test1" ) ( LONGDATACOMPAT="1" ) れたパラメーター SELECTの第一列(CLASS_SOURCE列) LONG VARCHAR型 10485760バイト DB2カタログ 情報の属性 CLASS_SOURCE列 CLOB(10485760) SQLDescribeCol関数でアプ リケーションに返された属性 DB2が列型を置き 換えて見せる 矛盾 DB2の制限: LONG VARCHAR型 32700バイト まで CLI0150Eドライバー が使用できません