19c新機能検証の第8回になります。
今回も引き続き、自動索引について検証します。
検証に使用した環境は以下の通りです。
自動索引の検証(1)でインデックスのリビルドに長時間かかる謎？がありました。
ジャーナル・テーブルが作成されたという事はインデックスのオンライン・リビルドが行われたという事なのでAWRで確認してみました。
確かにREBUILDが実行されています。まだ不可視索引の状態で実体が無いのに、なぜリビルドが行われたのでしょう…？
しかも21時間もかかっています。
今回はその謎に迫ってみます。
まず自動索引関連で自動的に実行されたコマンドを確認します。
SQL> select TABLE_NAME,INDEX_NAME,COMMAND,START_TIME,ERROR# from DBA_AUTO_INDEX_IND_ACTIONS order by START_TIME;
TABLE_NAME INDEX_NAME COMMAND START_TIME ERROR#
---------- --------------------------- --------------------------- ------------------- -------
T13 SYS_AI_1uwmhyznsw0bh CREATE INDEX 2019/12/16 11:29:17 0
T13 SYS_AI_1uwmhyznsw0bh REBUILD INDEX 2019/12/16 11:29:31 0
T13 SYS_AI_1uwmhyznsw0bh ALTER INDEX VISIBLE 2019/12/16 11:32:49 0
T13 SYS_AI_cpk05daxpfy3x CREATE INDEX 2019/12/16 13:33:29 0
T13 SYS_AI_9aquyb4jhjmu8 CREATE INDEX 2019/12/16 13:33:29 0
T13 SYS_AI_9aquyb4jhjmu8 REBUILD INDEX 2019/12/16 13:33:39 0
T13 SYS_AI_9aquyb4jhjmu8 ALTER INDEX VISIBLE 2019/12/16 13:36:13 0
TEST1 SYS_AI_86t24jx7jj2fx CREATE INDEX 2019/12/16 14:34:00 0
TEST1 SYS_AI_7xjh7m3qwx0hy CREATE INDEX 2019/12/16 14:34:00 0
TEST1 SYS_AI_7xjh7m3qwx0hy REBUILD INDEX 2019/12/16 14:34:21 0
（略）
インデックスの作成、リビルド、可視化が行われていますね。
この時間帯のAWRを確認すると、rebuildに長時間（SYS_AI_6dv62bpn4hsjtのrebuildに385.72秒、SYS_AI_7cpt1r4zs0cs3のreuildに130.07秒）かかっていました。
更にSYS_AUTO_INDEX_TASKの状態を確認します。
SQL> SELECT task_id, task_name, status, execution_start, execution_end,ERROR_MESSAGE FROM sys.dba_advisor_tasks where task_
name like '%AUTO_INDEX%';
TASK_ID TASK_NAME
---------- --------------------------------------------------------------------------------------------------------
STATUS EXECUTION_START EXECUTION_END
----------- ------------------- -------------------
ERROR_MESSAGE
-------------------------------------------------------------------------------------------------------------------
5 SYS_AUTO_INDEX_TASK
EXECUTING 2019/12/25 14:04:12
SQL> select sysdate from dual;
SYSDATE
-------------------
2019/12/25 15:55:05
14：04に開始したのに15:55になっても実行中(EXECUTING)のままです。
自動実行コマンドの方も確認します。
SQL> select TABLE_NAME,INDEX_NAME,COMMAND,START_TIME,ERROR# from DBA_AUTO_INDEX_IND_ACTIONS where error# <> 0 order by START
_TIME;
TABLE_NAME INDEX_NAME COMMAND START_TIME ERROR#
--------- ------------------------------ -------------------- ------------------- ----------
TEST1 SYS_AI_7xjh7m3qwx0hy REBUILD INDEX 2019/12/16 14:34:21 -12751
TEST4 SYS_AI_163qvs4b2s3s9 REBUILD INDEX 2019/12/17 13:43:19 -12751
T2 SYS_AI_fjjrg7da66v50 REBUILD INDEX 2019/12/25 14:43:44 -12751
SQL> !oerr ora 12751
12751, 00000, "cpu time or run time policy violation"
Rebuildはエラーで異常終了していますが、タスクは実行中のままです。
タスクを終了する方法をサポートに確認し、実行してみました。
SQL> exec dbms_advisor.interrupt_task('SYS_AUTO_INDEX_TASK');
BEGIN dbms_advisor.interrupt_task('SYS_AUTO_INDEX_TASK'); END;
*
ERROR at line 1:
ORA-13643: The task can not be interrupted or cancelled.
ORA-06512: at "SYS.PRVT_ADVISOR", line 4412
ORA-06512: at "SYS.PRVT_ADVISOR", line 6476
ORA-06512: at "SYS.PRVT_ADVISOR", line 4404
ORA-06512: at "SYS.DBMS_ADVISOR", line 299
ORA-06512: at line 1
SQL> exec dbms_advisor.cancel_task('SYS_AUTO_INDEX_TASK');
BEGIN dbms_advisor.cancel_task('SYS_AUTO_INDEX_TASK'); END;
*
ERROR at line 1:
ORA-13643: The task can not be interrupted or cancelled.
ORA-06512: at "SYS.PRVT_ADVISOR", line 2963
ORA-06512: at "SYS.PRVT_ADVISOR", line 6476
ORA-06512: at "SYS.PRVT_ADVISOR", line 2954
ORA-06512: at "SYS.DBMS_ADVISOR", line 20
ORA-06512: at line 1
残念ながらエラーになってしまい、タスクの強制終了は出来ませんでした。
翌日、状況を再度確認しました。
SQL> select TABLE_NAME,INDEX_NAME,COMMAND,START_TIME,ERROR# from DBA_AUTO_INDEX_IND_ACTIONS order by START_TIME;
TABLE_NAME INDEX_NAME COMMAND START_TIME ERROR#
------------- ------------------------------ -------------------- ------------------- ----------
（略）
T4 SYS_AI_6dv62bpn4hsjt REBUILD INDEX 2019/12/25 14:04:35 0
T13 SYS_AI_cpk05daxpfy3x REBUILD INDEX 2019/12/25 14:41:17 0
T2 SYS_AI_fjjrg7da66v50 REBUILD INDEX 2019/12/25 14:43:44 -12751
S1 SYS_AI_01xa95srm0sgc CREATE INDEX 2019/12/25 22:20:03 0
S3 SYS_AI_cx4kzpgrwzy8y CREATE INDEX 2019/12/25 22:20:03 0
S2 SYS_AI_2sh5sm7h5wh07 CREATE INDEX 2019/12/25 22:20:03 0
T3 SYS_AI_8x10xb5syn3u0 ALTER INDEX VISIBLE 2019/12/25 22:20:23 0
T4 SYS_AI_6dv62bpn4hsjt ALTER INDEX VISIBLE 2019/12/25 22:20:23 0
S1 SYS_AI_01xa95srm0sgc REBUILD INDEX 2019/12/25 22:35:30 0
S2 SYS_AI_2sh5sm7h5wh07 REBUILD INDEX 2019/12/25 22:35:51 0
（略）
55 rows selected.
夜になって自動的に回復していたようです。
ここまでのリビルドの動きについて、サポートに確認してみました。
Q．自動索引のrebuildは、どのようなタイミングで行われるのですか？
A．オラクル内部で自動索引は使用可能かを検証する前に「rebuild」を行います。
流れとしては下記のような感じです。
・ 自動索引のcreate(索引候補をUnusable 尚且つInvisible状態で作成(メタデータの変更のみ))
・ 自動索引のrebuild(実体を作成)
・ 自動索引をVISIBLEにして検証を行う
・ 有効ではないと判断されたら自動索引をDROP
※削除されるのは一定時間経過後なので、有効でないと判断されたインデックスはinvisibleの状態に戻る。
Q．対象の自動索引はINVISIBLEなので実体(セグメント)が無いのですが、reuildに長時間かかっています。
A．REBUILDより索引の実体を作りますので、データの量に依存します。
普通の「index online rebuild」と同じ程度の時間が要ると認識して頂ければと存じます。
なお、今回リビルドを行う時に「blocking txn id for DDL」のような待機が発生してたため、より時間が掛かったように見られます。
マニュアルにはthis is a data dictionary metadata change onlyと書かれていたので、メタデータだけの状態で検証を行い、有効と判断されたら実体化する…というイメージだったのですが、実体化してから検証するのですね。
「サイズの大きなテーブルだと自動索引が作成されにくい？」という疑問がありましたが、リビルドを行って実体化しないと検証できないならば、サイズの大きなテーブルで自動索引が作成されるまでに時間がかかるのも頷けます。
今回、検証していた中で同程度のサイズのテーブルでもインデックスのリビルドにかなりの長時間を要したものとそうでない物があったのは、「blocking txn id for DDL」の待機が発生したのが原因でした。
自動索引の検証で行われるリビルドはrebuild onlineなので、リビルド実行中にDMLは同時実行されますが、逆にDMLが先に実行されているとリビルド側はロックを獲得できずに待機してしまいます。
自動索引が作られるようにDMLを発行していたので、それでリビルドが長時間化してしまった、という事になります。
つまり、実際の運用でもDMLを実行しているとなかなかリビルドが実行されず、自動索引も作成されない…となるのですね。
リビルドにもそれなりの負荷がかかりますし、運用中に自動索引機能をONにするのはパフォーマンス影響が心配されます。
次回は引き続き自動索引、ファンクションインデックスについて検証します。
