読者です 読者をやめる 読者になる 読者になる

kenken0807_DBメモ

つば九郎が好きなDBAです。Oracle Standard Editionでの運用やツールとかとかの備忘録。特に記載がない場合はoracle11gR2です。時々MySQL

Oracle Standard EditionでActive Session History (ASH)っぽく監視、分析する

Oracle Database Standard EditionではASHはもちろんできない。
なので、それっぽい監視の仕組みを導入している。

仕組みとしては、
1、30秒毎にV$SESSIONの情報を取得しMySQLに突っ込む
2、MySQLのデータをMuninでグラフ化

1、30秒毎にV$SESSIONの情報を取得しMySQLに突っ込む

github.com

↑のスクリプトでv$sessionからデータ取得してMySQLに投入する。
MySQL側にV$SESSIONとほぼ同等のテーブルを用意して、そこにデータを投入している。

取得したデータで分析する

例えば、直近1週間で10分間に最もセッションが詰ってた時間を調べるときは

$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 |
・

と大量に出力される。

ここからわかる情報としては、
1、各セッションがどれくらい待機しているか。
2、各セッションが実行しているSQL
3、各セッションが待機している行はどこか。
4、どのセッションが原因で待機しているか。

1、各セッションがどれくらい待機しているか。

待ち時間(秒)列または実行時間(秒)列を見ると、そのセッションが待機している時間が表示される。

2、各セッションが実行しているSQL

SQL_ID列を見ると実行中のSQL_IDが表示されているので、ORACLEで問い合わせと実行されているSQLが確認できる。
SID6の場合、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

3、各セッションが待機している行はどこか。

ROW_WAIT_OBJ_NOROW_WAIT_FILE_NOROW_WAIT_BLOCK_NOROW_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

4、どのセッションが原因で待機しているか。

BLOCKING_SESSION列を確認すると、待機している原因のSIDが表示されている。
すべてが551となってるため、SID551を確認するとbat-serverが実行しているセッションが原因だとわかる。

注意:bat-serverが実行したどのSQLが原因で詰まっているかはわからない。 SQL_ID:6qbcxf4jzst0cが表示されているが、それは2015-10-11 17:30:07にv$sessionを取得したタイミングでbat-serverが実行しているものなので原因はその前に実行したSQLかもしれない。

こんな感じで調査することが可能である。
うちではこれらのSQLはすべてスクリプト化して実行している。
次回はグラフ化について書きたい。