簡単シリーズ トレース編 2004/03

簡単シリーズ
トレース編
2004/03
目次
１ DB2 UDBのトレース機能と用途
２ DB2 イベント・モニター
２−１
２−２
２−３
２−４
イベント・モニター概要
SQLステートメント・イベント
デッドロック・イベント
イベント・モニター補足事項
３． db2diag.log
３−１ db2diag.logファイルの概要
３−２ db2diag.logファイルの利用
４． CLIトレース
４−１ CLIトレースの収集方法
４−２ CLIトレースの調査例
５． db2trc
終わりに
付録 CLIトレースの追究例
１ DB2 UDBのトレース機能と用途
■
トレース機能が欲しくなるのはどんな時でしょう？
問題の原因究明
●
成り行きの把握
●
悪い原因の発見
●
証拠の収集
●
–
–
DB2 UDBのアプリケーションやサーバーが期待通りの動きをしな
い時、何がどこまでうまく行って最後はどうなったか？成り行きを
見て原因究明を行いたいことがあります。当資料ではこういった
目的に使えるDB2の機能の使い方と見方をご紹介します。
当資料では、各DB2の機能の正式名称にはこだわらず、この目的に合
う機能をひろくトレース機能と呼んでいます
１ DB2 UDBのトレース機能と用途
■
よくある関心事と解決策
アプリケーションの実行時間が長い、どこに時間がかかっているのだろう？
●
–
–
–
実行時間の長いSQLがあるのか？それはどれか？
SQLの発行と発行の間に時間がかかっているのか？
SQLが非常に多く発行されているのか？
➨
イベント・モニター for STATEMENTS を利用してみましょう
デッドロックが起こってしまった。どこに原因があるのだろう？
●
–
–
–
どのアプリケーションと、どのアプリケーションで起こったのか？
どんなSQLとどんなSQLで起こったのか？
どのクライアントとどのクライアントで起こったのか？
➨
イベント・モニター for DEADLOCKS を利用してみましょう
DB2でこんな現象が起きてしまった、その状況はどこかに残っていないか？
●
➨
db2diag.log ファイルを調べてみましょう
Java や VB で不思議なエラーが返ってくる、これはなぜ？
●
➨
CLIトレースを収集してみましょう
DB2内部エンジンの動きはわからないの？
●
➨
db2trc を資料収集してみましょう
今までの資料でらちがあかない、そんな時どうする？
●
➨
状況によってはOSやPDツールによるiptraceも併用してみましょう
２−１ イベント・モニター概要
■
イベント・モニターの種類
イベント・モニターでは以下の事象を収集できます。この資料では以下の矢印で示したよく使われるイベン
ト・タイプを取り上げます
DATABASE
●
➨
データベースイベント
全アプリケーションがデータベースから切断した時に記録
➨
各表のイベント
全アプリケーションがデータベースから切断した時に記録
–
TABLES
●
–
DEADLOCKS
DEADLOCKS WITH DETAILS
●
●
–
デッドロック・イベント
➨
デッドロックの発生時に記録
デッドロック・イベント
TABLESPACES
●
–
➨
表スペース・イベント
全アプリケーションがデータベースから切断した時に記録
BUFFERPOOLS
●
–
バッファー・プール・イベント
➨
全アプリケーションがデータベースから切断した時に記録
CONNECTIONS
●
–
➨
各アプリケーションの接続イベント
各アプリケーションがデータベースから切断した時に記録
STATEMENTS
●
–
➨
SQLステートメント・イベント
各SQLステートメントの完了時に記録
TRANSACTIONS
●
–
➨
COMMIT/ROLLBACKイベント
各トランザクションの終了時に記録
ステートメント・イベント
２−１ イベント・モニター概要
■
イベント・モニターの操作に必要な権限
作成、削除、活動、非活動
●
–
■
イベント・モニターの操作はSYSADM または DBADM 権限に限られています
イベント・モニター使用の流れ
1. CREATE EVENT MONITOR SQLステートメントによるイベント・モニターの登録
–
–
–
–
モニター名
モニター・タイプ
書き出し先(ファイル、名前つきパイプ、表)
オプション
登録
DB2カタログ
2. SET EVENT MONITOR STATE SQLステートメントによる イベント・モニターの活動化
活動化
0000000.evt
SQL
3. 発生したイベントをDB2が収集、書き出し
ｱﾌﾟﾘｹｰｼｮﾝ
DB2
出力先
ファイル
4. SET EVENT MONITOR STATE SQLステートメントによるイベント・モニターの非活動化
5. db2evmon ツールによる編集出力
■
非活動化
イベント・モニターの操作
CREATE EVENT MONITOR SQLステートメントで収集対象のイベント情報を登録し、活
動化させ、ファイル、名前つきパイプ、または表にイベントを収集します
db2evmon
●
–
–
–
–
ファイル出力すると、非活動化後に編集プログラムdb2evmonで編集出力できます
名前つきパイプへ出力するとすぐに編集・処理プログラムへ渡すことができます
V8からは表に出力することも可能です。イベント・アナライザーというGUIツールで
結果をトレースすることも可能です
イベント・モニターのレコード形式は公開されており、編集プログラムをユーザー
が作成することもできます。編集用サンプル・プログラムも提供されています
イベント・モニター
出力リスト
２−２ SQL ステートメント・イベント：収集手順
■
収集手順例
実行環境:DB2 V8.1 FixPak 4 (Windows 2000)
●
Unix/Linux環境では、書き出し先ディレクトリー名の変更と、そのディレクトリーのDB2インスタンス・オーナーへのパー
ミッション付与が必要です
–
1. イベント・モニターの登録
–
create event monitor ev1 for statements write to file 'c:¥common¥kantan¥trace1' replace
DB2コマンド行プロセッサーから、EV1 という名前のイベント・モニターを、STATEMENTSイベントとして登録します
➨
出力はファイル書き出しとし、書き出し先ディレクトリー名を ‘ ’ で囲んで指定します
➨
ディレクトリーは、CREATE EVENT MONITOR の時に存在している必要はありません。ただし、イベント・モニターが活
動化される時点で、ターゲット・パスの存否の検査が行われます
➨
replace オプションをつけると、活動化-非活動化の後、再度活動化した際に、前回のファイルを上書きします。一般に
トレース・ファイルは大きくなりがちですので、replaceオプションを使って前回分を含まない方が読みやすくなります
➨
一般にトレースファイルは
2. イベント・モニターの活動化
–
➨
set event monitor ev1 state 1
登録したイベントを活動化するとイベントの収集が始まります
3. トレースしたいアプリケーションの実行
4. イベント・モニターの非活動化
–
➨
set event monitor ev1 state 0
登録したイベントを非活動化するとイベントの収集が終わり、ファイル書き出しが終了します
5. イベントの編集出力
–
➨
db2evmon -db データベース別名 -evm ev1 > event1.txt
イベント・モニターの出力をテキスト・ファイルに編集出力します。該当のデータベース別名とイベント名を指定します
■
このページはブランクです。
２−２ SQL ステートメント・イベント：出力の見方
■
実行時間の長いSQLはどれか？
8) Statement Event ...
Appl Handle: 7
Appl Id: *LOCAL.DB2.00C307053257
Appl Seq number: 0007
ハンドル7:アプリケーションの
コネクション情報
ハンドル7の
コネクション・ヘッダー・
イベントを参照
Record is the result of a flush: FALSE
------------------------------------------Type
: Dynamic
Select文はCloseイベント
Operation: Close
に注目すれば十分
カーソルのClose
Section : 201
Creator : NULLID
Select文を発行したパッ
Package : SQLC2E03
パッケージ名
ケージ名(参考)
Consistency Token : AAAAAJHR
Package Version ID :
Cursor : SQLCUR201
Cursor was blocking: TRUE
③問題
Text
: select count(*) from syscat.columns x, syscat.columns y
発行された動的SQL文
のSQL
------------------------------------------Start Time: 01/27/2004 14:44:46.700560
Stop Time: 01/27/2004 14:44:58.729690
実行時間 12.0秒
Exec Time: 12.029130 seconds
①時間が長い
Number of Agents created: 1
User CPU: 11.476503 seconds
CPU時間 11.4秒
System CPU: 0.000000 seconds
Fetch Count: 1
Select結果 1行
Sorts: 0
②行読み取り、
Total sort time: 0
行取り出しが多い
Sort overflows: 0
DB2が読み取ったのは 11,878,362行
Rows read: 11878362
Rows written: 0
２−２ SQL ステートメント・イベント：出力の見方
Internal rows deleted: 0
Internal rows updated: 0
Internal rows inserted: 0
Bufferpool data logical reads: 610144
Bufferpool data physical reads: 67
Bufferpool temporary data logical reads: 0
Bufferpool temporary data physical reads: 0
Bufferpool index logical reads: 5
Bufferpool index physical reads: 3
Bufferpool temporary index logical reads: 0
Bufferpool temporary index physical reads: 0
SQLCA:
sqlcode: 0
sqlstate: 00000
■
正常終了 SQLCODE 0
参考
実行時間の長いSQLはどれか？
①：まず、実行時間とCPU時間の多いイベントに着目しましょう
●
–
–
–
Exec Time: に実行経過時間が秒単位で表示
User CPU: にDB2が使用したCPU時間が秒単位で表示されます
これらが長いものを選びましょう、
カーソルを使ったSelectの操作はPrepare、Open、Describe、Close の４つのイベントとして載ります。このうちCloseの操作
に着目すれば十分です
②：時間が長いのは取り扱った行数が多いためか、参考に見てみましょう
●
–
–
Fetch Count: にアプリケーションに返された、アプリケーションが受け取った行数が
Rows Read: には、その準備のためにDB2が内部的に読み取った行数が載ります
③：この処理に使われた動的SQLのSQL文を見てみましょう
●
–
Text: に載ります、SQL文の最大長は64KB です
次に、このSQLを発行したアプリケーション名を見るために、Appl Handle: と Appl Id: の値を確認しておきましょう
●
２−２ SQL ステートメント・イベント：出力の見方
■
実行時間の長いSQLを発行したアプリケーションは何か？
3) Connection Header Event ...
Appl Handle: 7
Appl Id: *LOCAL.DB2.00C307053257
Appl Seq number: 0006
DRDA AS Correlation Token: *LOCAL.DB2.00C307053257
Program Name : db2bp.exe
Authorization Id: DB2ADMIN
Execution Id : DB2ADMIN
Codepage Id: 943
Territory code: 81
Client Process Id: 756
Client Database Alias: SAMPLE
Client Product Id: SQL08014
Client Platform: Unknown
Client Communication Protocol: Local
Client Network Name:
Connect timestamp: 01/27/2004 14:32:58.996794
ハンドル7:アプリケーションの
コネクション情報
ハンドル7の
ステートメント・イベントを
参照
プログラム名 db2bp.exe (コマンド行プロセッサー)
接続したAUTHORIZATION IDはDB2ADMIN
SAMPLEデータベース
アプリケーションの情報をあらわす“コネクション・ヘッダー・イベント"も出力に含まれています
●
ステートメント・イベントに載っていたAppl Handle: と Appl Id: の値を持つコネクション・ヘッダー・イベントを探してみましょう
●
–
Program Name: に 実行プログラム名が載ります。 db2bp.exe は DB2コマンド行プロセッサーです
Java ならば Java.exe 、MicroSoft Visual StudioのVisual Basic V6でADOを使っていてデバック中なら VB6.exe などと表
示されます
➨
この実行プログラム名は db2 list applications コマンドでも表示されます
その他に、データベース接続時に指定したユーザーＩＤ(authorization ID) や接続中のデータベース別名なども表示されま
す
➨
–
■
このページはブランクです。
２−２ 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
Appl Id: *LOCAL.DB2.010830152055
Appl Seq number: 0001
DRDA AS Correlation Token: *LOCAL.DB2.010830152055
Program Name : STATIC2.exe
プログラム名
Authorization Id: DB2ADMIN
Execution Id : DB2ADMIN
STATIC2.exe
Codepage Id: 943
Country code: 81
Client Process Id: 2068
Client Database Alias: sample
Client Product Id: SQL07020
Client Platform: Unknown
Client Communication Protocol: Local
Client Network Name:
Connect timestamp: 08/30/2001 14:22:46.556588
Record is the result of a flush: FALSE
------------------------------------------Type
: Static
Exucutes操作
Operation: Execute
Section : 1
Creator : DB2ADMIN
パッケージ名STATIC2
Package : STATIC2
Cursor :
Cursor was blocking: FALSE
------------------------------------------Start Time: 08/30/2001 14:22:46.566173
Stop Time: 08/30/2001 14:23:20.986290
実行時間 34.4秒
Exec Time: 34.420117 seconds
Number of Agents created: 1
CPU時間 33.8秒
User CPU: 33.868701 seconds
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
●次に見るように、パッケージ名とセクション番号から、別のユーティリティーを使って
Internal rows inserted: 0
SQL文を知ることができます
SQLCA:
sqlcode: 0
sqlstate: 00000
２−２ 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プリコンパイラーでプリコンパイルして生成されたバインド・ファイルです
２−３ デッドロック・イベント：収集手順
■
収集手順例
実行環境:DB2 V8.1 FixPak 4 (Windows 2000)
●
Unix/Linux環境では書き出し先ディレクトリー名の変更と、そのディレクトリーのDB2インスタンス・オーナーへのパー
ミッション付与が必要です
–
1. イベント・モニターの登録
–
create event monitor ev2 for deadlocks with details write to file 'c:¥common¥kantan¥trace2' replace
DB2コマンド行プロセッサーから、EV2 という名前のイベントモニターを、DEADLOCKS WITH DETAILSイベントとして
登録します
➨
出力はファイル書き出しとし、書き出し先ディレクトリー名を ‘ ’ で囲んで指定します
➨
ディレクトリーは、CREATE EVENT MONITOR の時に存在している必要はありません。ただし、イベント・モニターが活
動化される時点で、ターゲット・パスの存否の検査が行われます
➨
replace オプションをつけると、活動化-非活動化の後、再度活動化した際に、前回のファイルを上書きします。一般に
トレース・ファイルは大きくなりがちですので、replaceオプションを使って前回分を含まない方が読みやすくなります
➨
一般にトレースファイルは大きく
2. イベント・モニターの活動化
–
➨
set event monitor ev2 state 1
登録したイベントを活動化するとイベントの収集が始まります
3. トレースしたいアプリケーションの実行（デッドロックの発生）
4. イベント・モニターの非活動化
–
➨
set event monitor ev2 state 0
登録したイベントを非活動化するとイベントの収集が終わり、ファイル書き出しが終了します
5. イベントの編集出力
–
➨
db2evmon -db データベース別名 -evm ev2 > event2.txt
イベント・モニターの出力をテキスト・ファイルに編集出力します。該当のデータベース別名とイベント名を指定します
■
このページはブランクです。