目次
相関図おさらい
「心臓外科医の術式」、いろんなキャラクターが登場しますが、
今回もたろーちゃんの同期のAさんが再登場します
アプリケーション開発者からの相談
システムの「心臓」こと、Oracle Database に日々携わるたろーちゃん。
そんなたろーちゃんのところに、アプリケーション開発者のAさんが訪ねてきました。
今回は何があったのでしょうか？
Aさん「たろーちゃん、ちょっと時間ある？」
たろー「うん、どうしたの？」
Aさん「今、新しいシステムを開発中なんだけど、データベースはなんと Exadata を使うことになったんだよ。」
たろー「へぇー、凄いな。」
Aさん「でもね。今、性能テスト中なんだけど、SELECT 文のパフォーマンスが出てなくて困ってるんだよ。」
たろー「Exadata なのに？」
Aさん「そう。ちょっと見てくれないかな。」
たろー「えー。Exadata って苦手なんだよなぁ・・・。」
Aさん「まぁまぁ、そう言わずに。ちょっとだけでいいから見てくれよ。」
嫌々ながらも、たろーちゃんはAさんの話を聞くことにしました。
Aさん「問題となっているのは、この SELECT 文なんだ。」
SQL> set linesize 32767
SQL> set timing on
SQL> set autotrace traceonly
SQL> SELECT * FROM MST_TBL WHERE DELFLG <> '1' OR DELFLG IS NULL ;
5353657行が選択されました。
経過: 00:00:28.49
実行計画
----------------------------------------------------------
Plan hash value: 2335235626
-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 5353K| 255M| 1593 (8)| 00:00:01 |
|* 1 | TABLE ACCESS STORAGE FULL| MST_TBL | 5353K| 255M| 1593 (8)| 00:00:01 |
-------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - storage("DELFLG" IS NULL OR "DELFLG"<>'1')
filter("DELFLG" IS NULL OR "DELFLG"<>'1')
統計
----------------------------------------------------------
0 recursive calls
0 db block gets
128945 consistent gets
128938 physical reads
0 redo size
171161667 bytes sent via SQL*Net to client
3926778 bytes received via SQL*Net from client
356912 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
5353657 rows processed
たろー「シンプルな SELECT 文だな。535万行のフルスキャンで約30秒か。そんなもんじゃないかな。」
Aさん「そう。日中帯に実行すると、この速度なんだ。でも夜間バッチ時間帯に実行すると、約１時間かかるんだよ。」
たろー「１時間？！ 何だろう、リソースの食い合いが起きてるのかな？
とりあえず、この SELECT 文が実行されている夜間バッチ時間帯の AWR レポートを見てみようか。」
たろーちゃんは問題のSELECT文が実行されている時間帯の AWR レポートを取得して、調査することにしました。
たろー「該当 SQL の Elapsed Time は 3,003.21秒でトップだな。この時の実行計画を見てみよう。」
続けてたろーちゃんは、問題の SELECT 文の SQL レポートを取得して、調査することにしました。
たろー「実行計画は、遅かった夜間帯も早かった日中帯も同じだな。」
Aさん「実行計画は同じなのに、どうしてこんなに実行時間に差があるんだろう？」
たろー「・・・血液検査をしてみよう。」
たろーちゃんは該当時間帯の V$ACTIVE_SESSION_HISTORY の情報を調べることにしました。
※ V$ACTIVE_SESSION_HISTORY に関しては以前の記事『正体不明のパフォーマンス悪化の謎を解き明かせ！』の回をご参照下さい。
血液検査の結果は？
たろー「うわぁ、これは酷い・・・。
待機イベント『cell single block physical read』で、ずっと待たされているぞ。」
Aさん「どういう意味の待機イベントなんだ？」
たろー「Aさんは、非 Exadata環境の『db file sequential read』っていう待機イベントを知ってるかな？」
Aさん「ああ、その待機イベントなら知ってる。確かバッファキャッシュ経由で、インデックススキャンを実行している場合に発生する待機イベントだよな？」
たろー「その通り。Exadata環境の『cell single block physical read』は非 Exadata環境の『db file sequential read』と同じ意味だ。」
Aさん「ほう・・・・・・・・・。」
たろー「・・・。」
Aさん「・・・・・・あれ？」
たろー「気づいたか？」
Aさん「確か実行計画では、テーブルフルスキャンだったよな？」
＜＜再掲＞＞
たろー「その通りだ。フルスキャンの場合、Exadata環境なら『cell single block physical read』ではなく、『cell multiblock physical read』が発生する筈なんだ。これは非 Exadata環境でいう『db file scattered read』と同じ意味の待機イベントだ。」
Aさん「どういうことだ？インデックスなんて使っていないのに・・・。」
たろー「本来ならマルチブロックリードを行う筈が、何らかの問題でシングルブロックリードを行ってしまっているのだろう。」
Aさん「でも、たろーちゃん。日中帯に実行したら全然早いんだよ？」
たろー「うーむ・・・。夜間帯は行連鎖でも発生していたのかなぁ？
Aさん。MST_TBL っていう表は、夜間帯も日中帯も同じ状態なのか？」
Aさん「ああ、同じ筈だ。」
たろー「じゃあ、行連鎖の線も可能性が低いけど・・・一応、見てみるか。」
たろーちゃんは MST_TBL の行連鎖状態を調べることにしました。
SQL> @?/rdbms/admin/utlchain 表が作成されました。 SQL> analyze table MST_TBL list chained rows; 表が分析されました。 SQL> select * from chained_rows; レコードが選択されませんでした。
たろー「うーむ、やっぱり行連鎖は発生していないなぁ。」
調査は振り出しに戻ってしまいました。
SQLトレースの取得
たろー「夜間帯に実行された時の SQL トレースを取得したいな。」
Aさん「SQL トレース？ということは、処理実行時に会社にいないとダメだよな。」
たろー「いや、実はいい方法があるんだ。対象の SQL_ID さえ分かっていれば、event を仕掛けることが出来るんだ。」
Aさん「おお！具体的にはどうするんだ？」
たろー「こうだ。」
SQL> ALTER SYSTEM SET EVENTS 'sql_trace [sql:4wsc8zg59zz74] wait=true,bind=true,plan_stat=adaptive';
たろー「これで SQL_ID: 4wsc8zg59zz74 が実行された時に、自動で SQL トレースが取得されるんだ。」
Aさん「へぇー、便利だな。これなら夜中に出社してずっと張り付いてなくてもいいのか。」
たろー「そういうこと。注意点としては、CDB ではなく、PDB で仕掛けなければならない点だ。それさえ間違えなければ、わざわざ夜間帯に出社する必要はないよ。」
Aさんとたろーちゃんは、この状態で翌朝調査することにしました。
SQL トレースの結果は？
Aさん「おはよう、たろーちゃん。SQL トレースの結果はどうだった？」
たろー「今ちょうど見てる所だ。SQL トレースから、どんな動作をしているのかが分かったよ。」
たろーちゃんは、SQL トレースから分かった状況をAさんに説明しました。
① ハードパースを実施
② 実行フェーズに入り、必要なデータが格納されているディスクファイルへの操作要求を実行
③ SmartScan を活用してデータを取得（数ミリ秒）
④ 結果を PGA に展開後、クライアントに応答開始
⑤ 1～2 秒に一度フェッチを行う処理を 1000 回程度繰り返した後、ストレージからのシングルブロックリードを 200 万回以上繰り返し（約1 時間）
⑥ 結果をクライアントに応答し、処理を完了
Aさん「⑤がネックなのか？」
たろー「そうだ。何を読み込んでいるのかまでは SQL トレースでは分からないけど、⑤で『cell single block physical read』が発生しているのは、間違いない。」
Aさん「ふーむ・・・。」
たろー「とりあえず、忘れないうちに event を解除しておこう。」
SQL> ALTER SYSTEM SET EVENTS 'sql_trace [sql:4wsc8zg59zz74] off';
一体、何を読み込んでいるのか？
Aさん「一体、何をシングルブロックリードしてるんだろう？？」
たろー「うーむ・・・。ASH レポートも見てみるか。」
たろーちゃんは、ASH レポートも取得しました。
たろー「ん？これは・・・？？」
たろー「この『Top DB Files』セクションの内容から察するに、読み込んでいるのは UNDO データだな。」
Aさん「UNDO データ？」
たろー「Aさん。この SELECT 文が実行されている時に、UPDATE や DELETE 等の DML 文が同時に実行されてたんじゃないか？」
Aさん「いや、そんな筈はないよ。」
たろー「本当に？」
Aさん「嘘なんかつかないよ。」
たろー「ふーむ・・・。」
たろーちゃんは ASH を調べ、同時間帯に MST_TBL にアクセスしている SQL 文を探しましたが、発見することは出来ませんでした。Aさんの言うことは嘘ではなさそうです。
だとしたら、この大量のUNDOデータの読み込みは・・・。
たろーちゃんは何かピンッときたようです。ASH を使って、更に何かを調べ始めました。
Aさん「たろーちゃん。何を調べてるんだい？」
たろー「ASH の範囲を広げて調査してるんだよ。UNDO を読み取るには、必ず何か理由がある筈だから。
・・・お、これは・・・。」
たろー「SELECT が実行されるよりも前に、MST_TBL に対して大量の INSERT が実行されているんだな。」
Aさん「そうだ。すまん。そういえば、バッチ処理の概要を説明していなかったな。
このバッチ処理では、」
① MST_TBL 表を TRUNCATE
② 別テーブルからアプリケーションを経由して MST_TBL 表に大量 INSERT
③ MST_TBL 表を SELECT
Aさん「と、いうことをやっているんだ。たろーちゃんが今見てるのは、②の部分だ。」
たろー「なるほど。で、パフォーマンス問題が発生しているのは③の SELECT なんだな？」
Aさん「そうだ。」
たろー「今、Excel 上では SQL_ID でフィルタリングしているけど、全部表示させると、INSERT以外にもたくさんのSQLが流れているのが分かるな。」
Aさん「うむ。他のバッチ処理もいくつか並走しているからな。」
たろー「これだと、かなりバッファキャッシュに負担が掛かってそうだな・・・。
②の大量 INSERT 時の COMMIT 頻度はどうなんだ？」
Aさん「一番最後に１回だけだ。」
たろー「ふむ・・・。」
Aさん「１件毎 COMMIT するより、最後に１回だけ COMMIT した方が早いだろ？」
たろー「うむ、確かにそうだ。」
たろーちゃんは目をつむり、考えを巡らせます。
・・・しばらくして、口を開きました。
たろー「Aさん。試しにこういう風にアプリケーションを変更できないかな？」
Aさん「なになに？・・・」
Aさん「まぁ、出来ないことはないけど・・・。」
たろー「原因は、『とある１つのこと』しか考えられないんだ。」
Aさん「分かった、やってみる。結果はまた明日の朝だな。」
Aさんは、たろーちゃんに言われた通りにアプリケーションを変更し、次の日を迎えました。
アプリケーションを変更した結果は？
Aさん「たろーちゃん！」
たろー「おお、どうだった？」
Aさん「SELECT が早くなったぞ！」
よぉし、予想通りだ。
Aさん「一体どういうことなんだ？メカニズムを説明してくれ！」
たろーちゃんは一体、何をしたのでしょうか？
それは・・・。
（・・・続く）
投稿者プロフィール
