パフォーマンスモニタの使用方法を説明します。
以下の手順で使用します。
処理時間が長いSQL文を特定する
SQL文のアクセスプランと実行状態の内訳を表示する
rdbpmsqllistコマンドを使用し、処理時間が長いSQL文から順番に一覧を表示します。
コマンドの実行例と表示内容を以下に示します。
$ rdbpmsqllist Symfoware Server Performance Monitor / SQL list information Period of analysis: 2008/10/15 08:00:00 - 2008/10/15 11:48:33 (1) (2) (3) (4) (5) (6) time connection-id running-time status SQL 2008/10/15-09:18:19.598 2008101015375000000315 13.856 normal SELECT COUNT(*)FROM USR1.TBL1 2008/10/15-11:33:18.311 2008101015375000000118 1.438 normal UPDATE USR1.TBL8 SET COL1=COL1+1 2008/10/15-10:08:02.819 2008101015375000000290 1.192 normal COMMIT
(1) SQL文の処理時間の解析を行った対象の期間
(処理時間が長いSQL文の調査を行う対象とした期間です。
遅い処理が発生した時間帯が判っている場合には、対象となる期間を指定することで、
情報を絞り込むことができます。
対象となる期間を指定するには、rdbpmsqllistコマンドのpオプションを使用します。)(2) SQL文の開始時刻
(SQL文の実行を開始した時刻です。表示形式は、“西暦/月/日-時:分:秒.ミリ秒”です。)(3) SQL文を実行したコネクションのコネクションID
(コネクションIDはPRIMEFLEX for HA Databaseが自動的に採番して割り当てます。
コネクションIDおよびSQL文の開始時刻をrdbpmsqllistコマンドのcオプションおよびtオプションに
指定して実行すると、コネクションおよびSQL文に関する詳細な情報を表示することができます。)(4) SQL文の処理時間
(PRIMEFLEX for HA DatabaseがSQL文を処理していた時間です。単位は秒.ミリ秒です。
一覧はこの時間が長い順番にソートされて表示されています。)(5) SQL文の終了ステータス
normal : 正常に終了した
error : エラーで終了した
canceled : タイムアウトやrdbtermコマンドにより処理が中断した(6) SQL文
(実行したSQL文です。
先頭から50文字以内を表示します。
英小文字は英大文字で表示します。
SQL文の前後の空白は削除して表示します。
SQL文中の冗長な空白は削除して表示します。)この例では、2008年10月15日の9時18分19秒に実行した単一行SELECT文で約14秒の時間がかかっていることがわかります。
このSQL文の処理が長かった原因を調査するための詳細な情報を取得する方法については、“5.2.2.2 SQL文のアクセスプランと実行状態の内訳を表示する”を参照してください。
注意
処理が完了していないSQL文に関する情報は表示されません。動作中のSQL文に関する情報を参照するには、そのSQL文の処理の完了を待ってから、情報の表示を行ってください。
採取対象となるSQL文は、以下のとおりです。
CALL文
COMMIT文
DELETE文:位置づけ
DELETE文:探索
INSERT文
OPEN文
ROLLBACK文
単一行SELECT文
UPDATE文:位置づけ
UPDATE文:探索
問合せ式(Java連携またはODBC連携のアプリケーションの場合)
採取対象のSQL文がOPEN文の場合、カーソルが閉じられるまでにPRIMEFLEX for HA Databaseがそのカーソルを処理するのにかかった時間が、処理時間となります。
処理時間が長いSQL文に対して、原因を調査するため、SQL文のアクセスプランと実行状態の内訳を表示します。“5.2.2.1 処理時間が長いSQL文を特定する”で表示されたコネクションIDおよびSQLの開始時刻をrdbpmsqllistコマンドのcオプションおよびtオプションに指定して実行します。
アクセスプラン
アクセスプランは、SQL文を実行するときのデータベースへのアクセス手順を表現したものです。データベースの同じ資源に対してアクセスを行うときでも、アクセス手順には複数の方法があり、それが適切に選択されていない場合には、処理時間が大幅に長くなることがあります。
参照
アクセス手順にどのようなものがあり、それらがアクセスプランでどのように表現されるかの詳細については、“Symfoware Server アプリケーション開発ガイド（共通編）”の“アプリケーションの性能”を参照してください。
実行状態の内訳
サンプリングした実行状態の内訳は、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: TCP/IP (8)
Name: 10.124.4.123/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
SAME_COST_JOIN_ORDER : ORDER
GROUP_COL_COND_MOVE : YES
CHOOSE_TID_UNION : NO
MAX_SCAN_RANGE : 1000
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文の処理時間
(PRIMEFLEX for HA DatabaseがSQL文を処理していた時間です。単位は秒.ミリ秒です。
途中で処理を中断し、別のSQL文の処理を行ったあとで、再開することもあるため、
処理時間はSQL文の終了時刻とSQL文の開始時刻の差よりも小さくなることがあります。)(4) SQL文を実行したコネクションのコネクションID
(コネクションIDはPRIMEFLEX for HA Databaseが自動的に採番して割り当てます。)(5) ログイン名
(6) プロセスID
(コネクションの接続を行っているアプリケーションプロセスのプロセスIDです。）(7) セションID
(マルチスレッド環境で動作しているアプリケーションのセションIDです。
マルチスレッド環境で動作していない場合には、“-----”となります。) (8) クライアントプロセス種別
SQL : システム内通信のアプリケーション
TCP/IP : リモートアクセスのアプリケーション
ODOS : ODOS連携のODBCアプリケーション(9) モジュール名
システム内通信のアプリケーション :
アプリケーションロードモジュール名/コネクション名
(アプリケーションロードモジュール名が15バイトを超える場合は、
先頭の15バイトのみが出力されます。)
リモートアクセスのアプリケーション :
接続端末の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のアクセスプランです。
表示項目の詳細に関しては、“Symfoware Server 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文