処理時間が長いSQL文に対して、原因を調査するため、SQL文のアクセスプランと実行状態の内訳を表示します。“2.2.1 処理時間が長いSQL文を特定する”で表示されたコネクションIDおよびSQLの開始時刻をrdbpmsqllistコマンドのcオプションおよびtオプションに指定して実行します。
アクセスプラン
アクセスプランは、SQL文を実行するときのデータベースへのアクセス手順を表現したものです。データベースの同じ資源に対してアクセスを行うときでも、アクセス手順には複数の方法があり、それが適切に選択されていない場合には、処理時間が大幅に長くなることがあります。
参照
アクセス手順にどのようなものがあり、それらがアクセスプランでどのように表現されるかの詳細については、“アプリケーション開発ガイド（共通編）”の“アプリケーションの性能”を参照してください。
実行状態の内訳
サンプリングした実行状態の内訳は、SQL文が実際に動作した状況をサンプリングしたものです。
一定時間間隔で処理状態を確認し、集計した結果です。どのような処理に時間がとられていたのかということを判断するためのヒントになります。
SQL文のアクセスプランと実行状態の内訳の表示例を説明します。
$ rdbpmsqllist -c 2008102015375000000315 -t 2008/10/15-09:18:19.598
Symfoware Server Performance Monitor / SQL detailed information
Start time: 2008/10/15 09:18:19.598 (1)
End time: 2008/10/15 09:18:33.454 (2)
Running time: 13.856 (3)
Connection ID: 2008101015375000000315 (4)
Connection information:
Uid: I4874 (5)
Pid: 23045 (6)
Sid: ----- (7)
Type: SQL (8)
Name: APL001/CONNECT1 (9)
Client information:
Client: u=UserID,i=RequestID,h=HostName (10)
Module: IJServer01 (11)
Action: ----- (12)
Termination status:
Status: normal (13)
Message Number: 2001 (14)
SQL statement: (15)
SELECT COUNT(*)FROM USR1.TBL1
Access plan: (16)
Convert SQL statement:
SELECT COUNT(*) FROM USR1.TBL1
Advice to an SQL statement:
JYP2401I 表の全件検索を行います．
===============================================================================
Main query
=sno===sectname=====input1==============input2==============output/update======
1 : SCAN [TBL1DSO ][ ][ ]
GROUP [ ][ ][APPL ]
-------------------------------------------------------------------
[ 1] SCAN ELEMENT
table name USR1.TBL1
scan type TABLE ALL SCAN
dso name TBL1DSO [NONE/NONE]
condition evaluation No
scan record number 10
[ 2] GROUPING ELEMENT
condition evaluation No
[ 3] OUTPUT ELEMENT
record length 8
Execution environment
-------------------------------------------------------------------------------
transaction access mode : READ WRITE
transaction isolation level : READ UNCOMMITTED
R_LOCK : YES
JOIN_RULE : AUTO
JOIN_ORDER : INSIDE
SCAN_KEY_ARITHMETIC_RANGE : YES
SCAN_KEY_CAST : YES
TID_SORT : YES
TID_UNION : YES
USQL_LOCK : SH
IGNORE_INDEX : NO
INACTIVE_INDEX_SCAN : YES
SS_RATE : 0.200000 0.250000 0.500000 0.400000 0.000100
Sampling status: (17)
ACTIVE: 2
WAITING: 11
LOCK_TEMPORARY: 1
DB_READ: 10
(1) SQL文の開始時刻
(SQL文の実行を開始した時刻です。表示形式は、“西暦/月/日 時:分:秒.ミリ秒”です。)(2) SQL文の終了時刻
(SQL文の実行が終了した時刻です。表示形式は、“西暦/月/日 時:分:秒.ミリ秒”です。)(3) SQL文の処理時間
(Symfoware/RDBがSQL文を処理していた時間です。単位は秒.ミリ秒です。
途中で処理を中断し、別のSQL文の処理を行ったあとで、再開することもあるため、
処理時間はSQL文の終了時刻とSQL文の開始時刻の差よりも小さくなることがあります。)(4) SQL文を実行したコネクションのコネクションID
(コネクションIDはSymfoware/RDBが自動的に採番して割り当てます。)(5) ログイン名
(6) プロセスID
(コネクションの接続を行っているアプリケーションプロセスのプロセスIDです。
トランザクションモニタ配下のアプリケーションの場合は、このSQL文の実行を依頼した
クライアントプロセスのプロセスIDになります。)(7) セションID
(マルチスレッド環境で動作しているアプリケーションのセションIDです。
マルチスレッド環境で動作していない場合には、“-----”となります。)
Solaris/Windowsの場合
(8) クライアントプロセス種別
SQL : システム内通信のアプリケーション
SQL-XA : トランザクションモニタ配下のアプリケーション
TCP/IP : RDB2_TCP接続のアプリケーション
RDA-SV : RDA-SV接続のアプリケーション
ODOS : ODOS連携のODBCアプリケーション(9) モジュール名
システム内通信のアプリケーション :
アプリケーションロードモジュール名/コネクション名
(アプリケーションロードモジュール名が15バイトを超える場合は、
先頭の15バイトのみが出力されます。)
トランザクションモニタ配下のアプリケーション :
データベース名/コネクション名
(トランザクションモニタ配下のアプリケーションのデータベース名/
コネクション名は、OPEN-INFO文字列に指定された値が表示されます。)
RDB2_TCP接続のアプリケーション :
接続端末のIPアドレス/コネクション名
RDA-SV接続のアプリケーション :
接続端末のIPアドレス/コネクション名
ODOS連携のODBCアプリケーション :
接続端末のIPアドレス/データソース名または
アプリケーションのロードモジュール名/データソース名
Linuxの場合
(8) クライアントプロセス種別
SQL : システム内通信のアプリケーション
SQL-XA : トランザクションモニタ配下のアプリケーション
TCP/IP : RDB2_TCP接続のアプリケーション
ODOS : ODOS連携のODBCアプリケーション(9) モジュール名
システム内通信のアプリケーション :
アプリケーションロードモジュール名/コネクション名
(アプリケーションロードモジュール名が15バイトを超える場合は、
先頭の15バイトのみが出力されます。)
トランザクションモニタ配下のアプリケーション :
データベース名/コネクション名
(トランザクションモニタ配下のアプリケーションのデータベース名/
コネクション名は、OPEN-INFO文字列に指定された値が表示されます。)
RDB2_TCP接続のアプリケーション :
接続端末のIPアドレス/コネクション名
ODOS連携のODBCアプリケーション :
接続端末のIPアドレス/データソース名または
アプリケーションのロードモジュール名/データソース名(10) クライアント情報
(Interstage Application Serverと連携している場合、Webサーバ接続情報が設定されます。
(設定される情報の形式は、Interstage Application Serverのマニュアルを参照してください。))
(Interstage Application Serverと連携していない場合、“-----”が表示されます。)
(11) モジュール情報
(Interstage Application Serverと連携している場合、IJServer名が設定されます。
(設定される情報の形式は、Interstage Application Serverのマニュアルを参照してください。))
(Interstage Application Serverと連携していない場合、“-----”が表示されます。)(12) アクション情報
(常に“-----”が表示されます。) (13) SQL文の終了ステータス
normal: 正常に終了した
error: エラーで終了した
canceled: タイムアウトやrdbtermコマンドにより処理が中断した(14) メッセージ変数に設定されるメッセージの番号
(表示されるのは数字部分の4桁になります。)
(rdbprtmsgコマンドのjypオプションにより、メッセージに関する情報を表示できます。)
SQL文の終了ステータスが“canceled”の場合には、“---”となります。(15) SQL文
(実行したSQL文です。
先頭から50文字以内を表示します。
英小文字は英大文字で表示します。
SQL文の前後の空白は削除して表示します。
SQL文中の冗長な空白は削除して表示します。)(16) アクセスプラン
SQLのアクセスプランです。
表示項目の詳細に関しては、“SQLTOOLユーザーズガイド”を参照してください。(17) サンプリングした実行状態の内訳
SQL文が動作中のときにサンプリングした、処理状態の内訳です。
一定時間間隔で処理状態を確認し集計した結果です。
ACTIVE: 動作中の状態を検出した回数
WAITING: 入出力処理待ち、資源の占有待ちなどにより処理が一時的に中断中の状態を検出した回数 処理状態にWAITINGがある場合には、さらに待ち状態となった原因に関する内訳が
その後に続きます。
LOCK : トランザクション占有待ちを検出した回数
LOCK_TEMPORARY : トランザクション一時占有待ちを検出した回数
DB_BUFFER : 共用バッファの空き待ちを検出した回数
DB_READ : ページ読込み待ちを検出した回数
DB_WRITE : ページ書込み待ちを検出した回数
DB_WRITE_TRNEND : トランザクション終了時のページ書込み待ちを検出した回数
DB_SEND : メモリ常駐ページの待機系システムへの送信待ちを検出した回数
LOG_BI_BUFFER : BIログバッファの空き待ちを検出した回数
LOG_AI_BUFFER : AIログバッファの空き待ちを検出した回数
LOG_RCP : リカバリログ量の減少待ちを検出した回数
LOG_BI_READ : BIログ読込み待ちを検出した回数
LOG_BI_WRITE : BIログ書込み待ちを検出した回数
LOG_AI_WRITE : AIログ書込み待ちを検出した回数
LOG_ARC_FULL：アーカイブログファイルの満杯状態の解消待ちを検出した回数
COM_BUFFER : RDBシステム間通信の通信バッファの空き待ちを検出した回数
COM_SEND : RDBシステム間通信の送信待ちを検出した回数
COM_RECV : RDBシステム間通信の受信待ちを検出した回数
OTHER : 上記以外の待ちを検出した回数アクセスプランの内容を参照することで、どのデータベース資源に対して、どのようなアクセスを行っているかを見ることができます。
この例では、表の全件検索が行われていることがわかります。
表の全件検索では、表に格納されているすべてのデータを参照するため、表に格納されているデータ量に応じて処理時間がかかります。また、表に格納されているすべてのデータがメモリ上に読み込まれていることも少ないため、データの読込み処理が多く発生し、さらに時間がかかることになります。このことは、サンプリングした実行状態の内訳に記載されている、13回中10回がデータベースからのデータ読込み待ちで止まっているという状況からも見てとれます。
このように、アクセスプランの情報や、サンプリングした実行状態の内訳を見ることで、どのような点に問題があるのかを判断することができます。
注意
以下のSQL文ではアクセスプランは表示されません。
CALL文
COMMIT文
ROLLBACK文