年が明けたばかりのある日、「特定のパーティションに対する更新処理が遅いが原因がわからないので調査して欲しい」と依頼を受けました。
リリースしたばかりの本番環境で、構成は以下の通りです。
パーティションの種別はリスト・パーティションで数は約80、バインド変数を使用していて_optim_peek_user_binds=falseの設定なので実行計画は変わらないのですが、問題のないパーティションに対する処理は0.001秒／件、遅い時は0.02秒／件で、20倍程度の差が出ているとか。
OEMで取得した実行計画が送られてきましたが、二次インデックスのレンジ・スキャンになっています。
![【オラクル認定資格試験対策書】ORACLE MASTER Bronze［12c SQL基礎］（試験番号：1Z0-061）完全詳解＋精選問題集【電子書籍】[ 西 昭彦 ]](https://thumbnail.image.rakuten.co.jp/@0_mall/rakutenkobo-ebooks/cabinet/1289/2000002631289.jpg?_ex=128x128 "【オラクル認定資格試験対策書】ORACLE MASTER Bronze［12c SQL基礎］（試験番号：1Z0-061）完全詳解＋精選問題集【電子書籍】[ 西 昭彦 ]")
update文は以下のような単純なもので、ビューや副問い合わせ等は使用していません。
update TABLE_A set col0=TO_DATE(DECODE(trim(:b0),'',null ,:b0),'YYYYMMDDHH24MISS'),（中略）,col14=:b14
where col15=TO_NUMBER(:b15) and col16=:b16 and col17=:b17 and col18=:b18 and col19=TO_NUMBER(:b19) and col20=TO_NUMBER(:b20) and col21=:b21 and col22=TO_DATE(:b22,'YYYYMMDDHH24MISS')
断片化によりレコード数がほぼ同じでもセグメントサイズが増加している可能性をまず疑い、セグメント情報を取得してもらいましたが、セグメント数もほぼ同じです。
SQL_ID、ハッシュ値ともに変わらず複数のパーティションに対する処理が同時実行されるので調査し辛いケースなのですが、数時間にわたってAWRレポートとSQLレポートを取得してもらったところ、はっきり違いが見られました。
正常な時間帯（SQLレポート抜粋）
| Stat Name | Statement Total | Per Execution | % Snap Total |
|---|---|---|---|
| Elapsed Time (ms) | 604,576 | 1.24 | 1.26 |
| CPU Time (ms) | 417,554 | 0.86 | 1.02 |
| Executions | 488,278 | ||
| Buffer Gets | 147,657,733 | 302.41 | 15.28 |
| Disk Reads | 118,520 | 0.24 | 0.27 |
| Parse Calls | 27 | 0.00 | 0.00 |
| Rows | 488,278 | 1.00 | |
| User I/O Wait Time (ms) | 38,476 | ||
| Cluster Wait Time (ms) | 116,133 | ||
| Application Wait Time (ms) | 7 | ||
| Concurrency Wait Time (ms) | 422 | ||
| Invalidations | 0 | ||
| Version Count | 1 | ||
| Sharable Mem(KB) | 72 |
遅い処理を含む時間帯（SQLレポート抜粋）
| Stat Name | Statement Total | Per Execution | % Snap Total |
|---|---|---|---|
| Elapsed Time (ms) | 21,936,975 | 22.36 | 30.81 |
| CPU Time (ms) | 21,408,346 | 21.82 | 33.03 |
| Executions | 981,188 | ||
| Buffer Gets | 4,025,589,463 | 4,102.77 | 68.15 |
| Disk Reads | 275,092 | 0.28 | 0.59 |
| Parse Calls | 23 | 0.00 | 0.00 |
| Rows | 981,188 | 1.00 | |
| User I/O Wait Time (ms) | 87,974 | ||
| Cluster Wait Time (ms) | 180,419 | ||
| Application Wait Time (ms) | 9 | ||
| Concurrency Wait Time (ms) | 500 | ||
| Invalidations | 0 | ||
| Version Count | 6 | ||
| Sharable Mem(KB) | 430 |
遅い時には論理読み込みが正常時の10倍以上で、かつ処理時間の殆どがCPU時間なので、論理読み込み数が多いのが遅延の原因と考えられます。
AWRレポートのSegments by Logical Readsでも、遅いパーティションに対しては、正常なパーティションの10倍程度の読み込みがある事が確認できました。
レンジ・スキャンなのでデータ件数・量が同程度でも、データの格納順が異なる事によって読み込む必要のあるブロック数は変わりうるのですが、ではどうやって解消するかです。
さしあたって検証環境で実行計画を確認してみたところ・・・
-----------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | E-Rows |E-Bytes| Cost (%CPU)| E-Time | Pstart| Pstop |
-----------------------------------------------------------------------------------------------------------------------
| 0 | UPDATE STATEMENT | | | | 1 (100)| | | |
| 1 | UPDATE | TABLE_A | | | | | | |
| 2 | PARTITION LIST SINGLE| | 1 | 198 | 2 (0)| 00:00:01 | 15 | 15 |
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
|* 3 | INDEX RANGE SCAN | PK_TABLE_A | 1 | 198 | 2 (0)| 00:00:01 | 15 | 15 |
-----------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("col15"=15 AND "col19"=19 AND "col20"=20 AND "col22"=TO_DATE(' 2020-01-01 00:00:00',
'syyyy-mm-dd hh24:mi:ss'))
filter("col19"=19 AND "col20"=20 AND "col22"=TO_DATE(' 2020-01-01 00:00:00', 'syyyy-mm-dd
hh24:mi:ss') AND TO_NUMBER("col16")=16 AND TO_NUMBER("col17")=17 AND TO_NUMBER("col18")=18 AND
TO_NUMBER("col21")=21)
主キーのレンジスキャンになっていたのですが、理由はデータ型の合わないリテラルを使用していた為で、暗黙の型変換によりカラムに対して関数が使用されたせいでした。
それを見て改めて主キーの定義を確認したのですが、where句で主キーの全てのカラムがイコールで指定されANDで結合されています。
つまり、二次インデックスのレンジスキャンではなく、主キーのユニークスキャンが選ばれるべきケースです。
検証環境で正しい型のバインド変数を設定したところ、主キーのユニークスキャンが選択されました。
データ型不一致に関して調べたところ、以下のドキュメントを見つけました。
カスタマ推奨SYS_OP_C2C Causing Full Table/Index Scans (ドキュメントID 732666.1)
Javaなどのアプリでバインド変数を生成した場合、stringで指定したバインド変数がNVARCHAR2になってしまうので、実際のデータ型と一致しない場合に暗黙の型変換が発生してしまう、という事象で、実行計画を確認すると以下のようになります。
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(SYS_OP_C2C("COL1")=:B1)
AWRのSQLレポートでは確認できない部分なので、本番環境で実際にSQLを実行したタイミングで以下を取得してもらいましたが、結果として、暗黙の型変換には該当していませんでした。
SQL> select * from table(dbms_xplan.display_cursor(sql_id=>'xxxxxxx',format=>'typical iostats last'));
もう一つ、気になったのが以下のドキュメントです。
Unique Index Is Going Unusable State After Data Loading Using SQL*Loader (ドキュメントID 2184469.1)
SQL*Loaderのダイレクト・ロードでデータ投入後、主キーが使用不可状態になるという事象ですが、これには該当していない事が判明しました。
と言うのも、12cの新機能で、使用不可のインデックスはセグメントが無くなるのですが、セグメントサイズが0で無い事は確認済です。
11.2 New Feature: Unusable Indexes and Index Partitions Do Not Consume Space (ドキュメントID 1266458.1)
後はもう、統計情報が古いくらいしか原因がなさそうなのでテーブルおよびインデックスについて情報を取得してもらったのですが、テーブル、インデックスともに、見事に統計が失効していました。
※前回統計情報取得時以降に10％を超える更新、またはtruncateを行った場合、統計は失効します。
costベースオプティマイザは統計情報が最新である前提で設計されている為、統計が失効していたら適切な実行計画が選択される事は期待できません。
最初から確認しておけば良かったのですが、自動化メンテナンスJOBで統計情報を取っているという思い込みがあったのです。が、このシステムでは無効にしてありました・・・
先入観に囚われてはいけない、というのが今回の教訓でした。
