Oracle Standard EditionでActive Session History (ASH)っぽく監視、分析する
Oracle Database Standard EditionではASHはもちろんできない。
なので、それっぽい監視の仕組みを導入している。
仕組みとしては、
１、３０秒毎にV$SESSIONの情報を取得しMySQLに突っ込む
２、MySQLのデータをMuninでグラフ化
１、３０秒毎にV$SESSIONの情報を取得しMySQLに突っ込む
↑のスクリプトでv$sessionからデータ取得してMySQLに投入する。
MySQL側にV$SESSIONとほぼ同等のテーブルを用意して、そこにデータを投入している。
取得したデータで分析する
例えば、直近１週間で１０分間に最もセッションが詰ってた時間を調べるときは
$mysql -e"use ora_session;select substr(snapshot_date,1,15),count(*) from TABLE where snapshot_date > DATE_SUB( now(), interval 7 day ) group by 1 order by 2 desc limit 30;" +----------------------------+----------+ | substr(snapshot_date,1,15) | count(*) | +----------------------------+----------+ | 2015-10-11 17:3 | 2271 | | 2015-10-09 23:5 | 339 | | 2015-10-11 11:3 | 147 | | 2015-10-09 02:0 | 105 | | 2015-10-12 00:1 | 102 | +----------------------------+----------+
2015-10-11 17:30～2015-10-11 17:40の間にアクティブなセッションが2271件も存在している。
続いて、2015-10-11 17:30～2015-10-11 17:40の間の最も多い待機イベントを調べる
$mysql -e"use ora_session;select snapshot_date,wait_class,event ,count(*) from TABLE where snapshot_date between '2015-10-11 17:30:00' and '2015-10-11 17:40:00' group by 1,2,3;" +---------------------+-------------+-------------------------------+----------+ | snapshot_date | wait_class | event | count(*) | +---------------------+-------------+-------------------------------+----------+ | 2015-10-11 17:30:07 | Application | enq: TX - row lock contention | 77 | | 2015-10-11 17:30:07 | Commit | log file sync | 1 | ・ ・ ・ | 2015-10-11 17:31:38 | Application | enq: TX - row lock contention | 409 | | 2015-10-11 17:31:38 | Idle | SQL*Net message from client | 2 | | 2015-10-11 17:31:38 | Network | SQL*Net message to client | 1 | | 2015-10-11 17:32:09 | Application | enq: TX - row lock contention | 637 | | 2015-10-11 17:32:39 | Application | enq: TX - row lock contention | 715 | ・ ・
毎度お馴染みのenq: TX - row lock contentionが大量に発生していることがわかる。
この待機が発生しだした2015-10-11 17:30:07を調べてみる。
$mysql -e"use ora_session;
select SNAPSHOT_DATE,MACHINE,SID,SQL_ID,EVENT as 'ロック情報',SECONDS_IN_WAIT as '待ち時間(秒)'
,UNIX_TIMESTAMP(SNAPSHOT_DATE) - UNIX_TIMESTAMP(SQL_EXEC_START) as '実行時間(秒)'
,ROW_WAIT_OBJ_NO,ROW_WAIT_FILE_NO,ROW_WAIT_BLOCK_NO,ROW_WAIT_ROW_NO,BLOCKING_SESSION
from TABLE where SNAPSHOT_DATE = '2015-10-11 17:30:07';"
+---------------------+------------+------+---------------+-------------------------------+-------------------+-------------------+-----------------+------------------+-------------------+-----------------+------------------+
| SNAPSHOT_DATE | MACHINE | SID | SQL_ID | ロック情報 | 待ち時間(秒) | 実行時間(秒) | ROW_WAIT_OBJ_NO | ROW_WAIT_FILE_NO | ROW_WAIT_BLOCK_NO | ROW_WAIT_ROW_NO | BLOCKING_SESSION |
+---------------------+------------+------+---------------+-------------------------------+-------------------+-------------------+-----------------+------------------+-------------------+-----------------+------------------+
| 2015-10-11 17:30:07 | app-server | 6 | 6r448m5sbza05 | enq: TX - row lock contention | 34 | 34 | 104277 | 10 | 538428 | 0 | 551 |
| 2015-10-11 17:30:07 | app-server | 17 | 3mjcg94m0qq4m | enq: TX - row lock contention | 19 | 19 | 104277 | 10 | 544996 | 17 | 551 |
| 2015-10-11 17:30:07 | app-server | 86 | 3mjcg94m0qq4m | enq: TX - row lock contention | 15 | 15 | 104277 | 9 | 540636 | 2 | 551 |
| 2015-10-11 17:30:07 | app-server | 95 | 3mjcg94m0qq4m | enq: TX - row lock contention | 31 | 31 | 104277 | 7 | 548980 | 18 | 551 |
| 2015-10-11 17:30:07 | app-server | 156 | 3mjcg94m0qq4m | enq: TX - row lock contention | 29 | 29 | 104277 | 8 | 538586 | 8 | 551 |
| 2015-10-11 17:30:07 | app-server | 161 | 3mjcg94m0qq4m | enq: TX - row lock contention | 25 | 24 | 104277 | 10 | 544996 | 17 | 551 |
| 2015-10-11 17:30:07 | app-server | 231 | 3mjcg94m0qq4m | enq: TX - row lock contention | 13 | 13 | 104277 | 10 | 539284 | 12 | 551 |
| 2015-10-11 17:30:07 | app-server | 234 | 6r448m5sbza05 | enq: TX - row lock contention | 26 | 26 | 104277 | 9 | 539441 | 10 | 551 |
・
| 2015-10-11 17:30:07 | bat-server | 551 | 6qbcxf4jzst0c | SQL*Net message from client | 0 | 1444552207 | -1 | 0 | 0 | 0 | 0 |
・
と大量に出力される。
ここからわかる情報としては、
１、各セッションがどれくらい待機しているか。
２、各セッションが実行しているSQL
３、各セッションが待機している行はどこか。
４、どのセッションが原因で待機しているか。
１、各セッションがどれくらい待機しているか。
待ち時間(秒)列または実行時間(秒)列を見ると、そのセッションが待機している時間が表示される。
２、各セッションが実行しているSQL
SQL_ID列を見ると実行中のSQL_IDが表示されているので、ORACLEで問い合わせと実行されているSQLが確認できる。
SID：6の場合、SQL_ID:6r448m5sbza05なのでOracle側で以下を実施。
SQL>SELECT sql_text FROM v$sqltext WHERE SQL_ID ='6r448m5sbza05'; SQL_TEXT ---------------------------------------------------------------- UPDATE master SET datetime = SYSDATE WHERE master_id = :1
３、各セッションが待機している行はどこか。
ROW_WAIT_OBJ_NOとROW_WAIT_FILE_NOとROW_WAIT_BLOCK_NOとROW_WAIT_ROW_NOを元にDBMS_ROWIDパッケージを使用して、rowidから行を特定できる。
SID：6の場合、
ROW_WAIT_OBJ_NO:104277 ROW_WAIT_FILE_NO:10 ROW_WAIT_BLOCK_NO:538428 ROW_WAIT_ROW_NO: 0なので、
SQL>select object_name,dbms_ROWID.ROWID_create (1,data_object_id,10,538428,0)
from dba_objects where data_object_id=104277;
OBJECT_NAME DBMS_ROWID.ROWID_C
------------------ ------------------
MASTER AAAZdVAAKAACDc8AAA
SQL>select * from master where rowid='AAAZdVAAKAACDc8AAA';
USER_ID MASTER_ID DATETIME
--------- ---------- ----------
1 23 2015/10/11
４、どのセッションが原因で待機しているか。
BLOCKING_SESSION列を確認すると、待機している原因のSIDが表示されている。
すべてが551となってるため、SID：551を確認するとbat-serverが実行しているセッションが原因だとわかる。
注意：bat-serverが実行したどのSQLが原因で詰まっているかはわからない。
SQL_ID:6qbcxf4jzst0cが表示されているが、それは2015-10-11 17:30:07にv$sessionを取得したタイミングでbat-serverが実行しているものなので原因はその前に実行したSQLかもしれない。
こんな感じで調査することが可能である。
うちではこれらのSQLはすべてスクリプト化して実行している。
次回はグラフ化について書きたい。
