LoginSignup
10
5

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 5 years have passed since last update.

@abe_masanori(Masanori ABE)

OracleDBのV$SESSION.EVENTを勘違いしていた話

Last updated at Posted at 2019-08-11

プロフィールに「SQLチューニングチョットデキル」と書いておきながら、10年以上に渡りV$SESSIONのEVENT列について基本的な勘違いをしていたことに気付いたので、自分への戒めとして再現方法含め記事に残しておいうと思います。

ちなみに、V$SESSION.EVENT列は現在セッションが待機中の待機イベントを指すものではないことが分かっている方には、あまり有用な記事ではないです。

1. V$SESSIONのモニタリングとEVENT列

「門外不出のOracle現場ワザ」という書籍（Web抜粋版は[こちら](https://www.oracle.com/technetwork/jp/articles/index-082145-ja.html 門外不出のOracle現場ワザ)）に、V$SESSIONの情報を定期取得（5秒に1回など）することでOracleDBの性能問題の状況をリアルタイムに把握するという手法が載っています。ざっくり言うと、次のようなSQL文を実行すれば、ある程度状況が把握できるという方法です。

V$SESSIONからの情報取得
SELECT
    sid,
    serial#,
    program,
    status,
    sql_id,
    event
FROM
    v$session
WHERE
    username = '（アプリが利用するDBユーザ名）'

この方法はAWR/Statspackレポートを取得したり、大げさに情報収集のスクリプトを仕掛けたりせずとも手軽に現時点の以下のような状況が手軽に分かります。

  • 接続数はどれぐらいか
  • 同時実行数はどれぐらいか
  • どのSQL文がたくさん実行されているか（SQL_ID列より）
  • SQL文実行は何で待たされているか（EVENT列より）

この手軽さから、私は今までSQLチューニングの現場でこの手法を多用してきました。

しかし、先週にこの手法の中でも重要なEVENT列について大きな勘違いをしていることに気づきました。
具体的には、EVENT列にある待機イベントは該当のセッションが今現在待機しているイベントであり、メモリからのデータ読み取りや計算処理などCPUを使う処理の場合（ラッチ除く）はアイドル系の待機イベントが表示されるものと思っていました。

ちなみに、Oracle Database 18cのDatabase ReferenceではEVENT列には以下のような説明がついています。これ見たら、「上述のような勘違いも仕方なくないですか」と思わなくはないですが。

（英語）
Resource or event for which the session is waiting

（日本語）
セッションが待機しているリソースまたはイベント

以下では、EVENT列≠（現在待機中のイベント）となる再現ケースを説明していきたいと思います。

2. 再現用データ＆SQL文

2-1. データモデル

以下のようなテーブルを使います。

er.png

  • 作業者（WORKER）への仕事（TASK）のアサインを管理します。
    • 作業者と仕事の関係は1対多とします。
    • 仕事は完了したら物理削除されるものとします。
  • 削除予定作業者（DELETED_WORKER）に登録されている作業者を作業者テーブル（WORK）から定期的に削除します。

DDL文は以下になります。

DDL文
CREATE TABLE worker (
    worker_id   NUMBER(8)    NOT NULL,
    worker_name VARCHAR2(10) NOT NULL,
    CONSTRAINT pk_worker PRIMARY KEY (worker_id)
);

CREATE TABLE task (
    task_id    NUMBER(8)    NOT NULL,
    task_name  VARCHAR2(10) NOT NULL,
    worker_id NUMBER(8)    NOT NULL,
    CONSTRAINT pk_task PRIMARY KEY (task_id),
    CONSTRAINT fk_task_01 FOREIGN KEY (worker_id)
      REFERENCES worker(worker_id)
);

CREATE TABLE deleted_worker (
    worker_id NUMBER(8)    NOT NULL
);

これはOracleにおける有名なアンチパターンが含まれているのですが、ポイントになるのは以下の2点です。

  • TASKテーブルからWORKERテーブルに参照制約が作成されている。
  • TASKテーブルの参照キーには索引が作成されていない。

これで何が起こるかというと、WORKERテーブルから1行データを削除する際に、参照制約のため該当WORKERレコードに紐付くTASKレコードが存在しないかチェックする処理が裏で動きます。そのチェック（SELECT count(1) FROM TASK WHERE WORKER_ID = ?みたいな処理）のためにTASKテーブルのフルスキャンが実行されてしまいます。

（WORKERレコードの削除時にTASKテーブルにテーブルロックがかかるという問題もありますが、今回はあまり関係ありません）

2-2. データ生成

以下のスクリプトでデータ生成します。

  • WORKERテーブル10,000万件（約3MB）
  • TASKテーブル：8,000件（約3MB）
  • DELETED_WORKERテーブル：2,000万件（約200KB）
データ生成
INSERT INTO worker
SELECT
    1000000 + id,
    'W' || to_char(1000000 + id, 'FM00000000')
FROM
    (
    SELECT
        level id
    FROM
        dual
    CONNECT BY LEVEL <= 100000
    );

INSERT INTO task
SELECT
    worker_id,
    'T' || to_char(1000000 + worker_id, 'FM00000000'),
    worker_id
FROM
    worker
WHERE
    mod(worker_id, 10) != 0;

INSERT INTO deleted_worker
SELECT
    worker_id
FROM
    worker
WHERE
    mod(worker_id, 10) = 0;

COMMIT;

2-3. モニタリング対象処理

以下のDELETE文をモニタリングします。WORKERテーブルから2,000件削除する際に、8,000件のTASKテーブルフルスキャンが2,000回内部で実行されます。今回利用した環境では15秒程度掛かります。

モニタリング対象処理
DELETE FROM worker w
WHERE
	  EXISTS (
	      SELECT 1
	      FROM deleted_worker d
	      WHERE d.worker_id = w.worker_id
	  );

2-4. 測定環境

あまり重要ではないですが、今回の環境は以下です。

  • VirtualBox6.0.2上の仮想環境（CPU2コア、メモリ2GB）
  • OS：CentOS 7.6.1810 (x86_64)
  • Oracle Database 18c 18.3.0.0.0

3. モニタリング

上述のDELETE文を以下のV$SESSIONへのSQL文で1秒ごとにモニタリングしながら実行します。

V$SESSIONモニタリング
SELECT
    to_char(sysdate, 'HH24:MI:SS') tm, 
    sid,
    sql_id,
    status,
    wait_time,
    state,
    event
FROM v$session 
WHERE username = 'EV_TEST';

3-1. ケース１（バッファキャッシュ全クリア後）

一度キャッシュデータをALTER SYSTEM FLUSH BUFFER_POOL ALLで全削除した上でDELETE文を実行します。以下がその時のV$SESSIONモニタリングの結果です。

TM         SID SQL_ID        STATUS    WAIT_TIME STATE               EVENT
-------- ----- ------------- -------- ---------- ------------------- -------------------------
13:59:51   295 7hys3h7ysgf9m ACTIVE            0 WAITING             db file sequential read
13:59:52   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
13:59:53   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
13:59:54   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
13:59:55   295 czf8yap5hgng7 ACTIVE            1 WAITED KNOWN TIME   db file scattered read
13:59:56   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
13:59:57   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
13:59:58   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
13:59:59   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
14:00:00   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
14:00:01   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
14:00:02   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
14:00:03   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
14:00:04   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
14:00:05   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
14:00:06   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read
14:00:07   295 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   db file scattered read

EVENT列は最初を除いてdb file scattered readになっているので、一見テーブルフルスキャンで長い時間待機しているように見えますが、WAIT_TIME列が-1であるため、実際は待機中ではなくCPUで処理中になります。

以下、WAIT_TIME列のマニュアルによる説明。

（英語）
If the session is currently waiting, then the value is 0. If the session is not in a wait, then the value is as follows:
>0 - Value is the duration of the last wait in hundredths of a second
-1 - Duration of the last wait was less than a hundredth of a second
-2 - Parameter TIMED_STATISTICS was set to false
This column has been deprecated in favor of the columns WAIT_TIME_MICRO and STATE.

（日本語）
セッションが現在待機中の場合、値は0。セッションが待機中でない場合、値は次のとおり。
>0 - 値は、前回の待機時間(1/100秒)
-1 - 前回の待機時間は1/100秒未満だった
-2 - パラメータTIMED_STATISTICSは、falseに設定された
WAIT_TIME_MICROおよびSTATE列が設定されている場合、この列は非推奨になる。

（本当はWAIT_TIME列ではなくSTATE列を見た方が良いのかもしれませんが。）

実際、V$SESSION_EVENTでどの待機ベントでどれだけ待ったかを確認すると以下のようになり、db file scattered readでは1.2秒しか待機していないことが分かります。

14:00:07 SQL> 
14:00:07 SQL> SELECT
14:00:07   2  	  event,
14:00:07   3  	  time_waited_micro / 1000 "wait time (ms)"
14:00:07   4  FROM
14:00:07   5  	  v$session_event
14:00:07   6  WHERE
14:00:07   7  	  sid = sys_context('USERENV', 'SID');

EVENT                                    wait time (ms)
---------------------------------------- --------------
Disk file operations I/O                             22
log file sync                                        34
db file sequential read                           1,157
db file scattered read                              214
SQL*Net message to client                             0
SQL*Net message from client                          13
events in waitclass Other                             1

7行が選択されました。

3-2. ケース２（チェックポイント＆ログスイッチが起こる場合）

DELETE文実行中にチェックポイント＆ログスイッチが起きた場合のV$SESSIONのモニタリング結果は以下になります。

TM         SID SQL_ID        STATUS    WAIT_TIME STATE               EVENT
-------- ----- ------------- -------- ---------- ------------------- --------------------------------------------------
22:29:05   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   PGA memory operation
22:29:06   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:07   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:08   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:09   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:10   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:11   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:12   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:13   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:14   252 czf8yap5hgng7 ACTIVE           -1 WAITED SHORT TIME   enq: CR - block range reuse ckpt
22:29:15   252 czf8yap5hgng7 ACTIVE            7 WAITED KNOWN TIME   log file switch (private strand flush incomplete)
22:29:16   252 czf8yap5hgng7 ACTIVE            7 WAITED KNOWN TIME   log file switch (private strand flush incomplete)
22:29:17   252 czf8yap5hgng7 ACTIVE            7 WAITED KNOWN TIME   log file switch (private strand flush incomplete)
22:29:18   252 czf8yap5hgng7 ACTIVE            7 WAITED KNOWN TIME   log file switch (private strand flush incomplete)
22:29:19   252 czf8yap5hgng7 ACTIVE            7 WAITED KNOWN TIME   log file switch (private strand flush incomplete)

EVENT列にはenq: CR - block range reuse ckptやlog file switch (private strand flush incomplete)というあまり見慣れない待機イベントが多数ありますが、実際にはそれらのイベントではほとんど待機していません。（後者は74ms待機、前者はV$SESSION_EVENTに計上すらされていません）

22:29:19 SQL> SELECT
22:29:19   2      event,
22:29:19   3      time_waited_micro / 1000 "wait time (ms)"
22:29:19   4  FROM
22:29:19   5      v$session_event
22:29:19   6  WHERE
22:29:19   7      sid = sys_context('USERENV', 'SID');

EVENT                                              wait time (ms)
-------------------------------------------------- --------------
Disk file operations I/O                                        1
log file switch (private strand flush incomplete)              74
log file sync                                                   1
SQL*Net message to client                                       0
SQL*Net message from client                                    11
events in waitclass Other                                       2

3-3. その他

何回か実行すると、以下のような待機イベントがV$SESSIONのEVENT列に多数確認できますが、どれも長時間待機するものはありませんでした。

  • Disk file operations I/O
  • PGA memory operation

4. まとめ

ここまでの結果からの想像ですが、V$SESSIONのEVENT列は以下を指すのではないでしょうか。

  • 該当セッションが待機中の場合は、現在待機中のイベント
  • 該当セッションが待機中でない場合は、前回の待機イベント

つまりV$SESSIONをモニタリングする上では、以下のようにするのが好ましいということでしょうか。

SELECT
    to_char(sysdate, 'HH24:MI:SS') tm, 
    sid,
    serial#,
    program,
    status,
    sql_id,
    CASE WHEN wait_time = 0 THEN event ELSE 'CPU' END event
FROM v$session 
WHERE ...;

言い訳ですが、大体CPUネックになっている場合って、OracleのV$SESSIONを見る前にsarやtopで当たりを付けることができるので、あまり意識して見ないんですよね…

10
5
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
10
5

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?