TRUNCATEを邪魔する犯人は誰だ？(1/2)

2019年3月20日『心臓外科医の術式』

1 アプリケーション開発者からの相談
2 見慣れない待機イベント
3 次の日の朝
4 更に次の日の朝

アプリケーション開発者からの相談

システムの「心臓」こと、Oracle Databaseに日々携わるたろーちゃん。
そんなたろーちゃんのところに、アプリケーション開発者のAさんが訪ねてきました。
何かあったのでしょうか？

Aさん「たろーちゃん、ちょっと相談なんだけど…。」
たろー「うん、どうしたの？」
Aさん「ずっと前にStandard Edition の２ノードRACの Oracle Databaseのことで相談したの覚えてる？」
※Aさんのシステムについては以前の『SQL実行計画の変更その２』の回を参照して下さい。
たろー「ああ、あれね。」
Aさん「あの Oracle Database を使って夜間バッチを動かしているんだけど、稀にバッチ処理が異常終了するんだよ。」
たろー「異常終了？どんなエラーで？」
Aさん「これを見てくれ。ORA-00054っていうエラーなんだ。」

そう言うとAさんは、ノートパソコンの画面を見せました。

TRUNCATE TABLE TAB2 ;
ORA-00054: リソース・ビジー。NOWAITが指定されているか、タイムアウトしました

たろー「 TRUNCATE エラーが発生してるのか？」
Aさん「そうなんだ。この処理ではテーブルをTRUNCATEしてから、新たにデータを入れ直してるんだ。その最初のステップで異常終了している。」
たろー「ORA-00054 は対象オブジェクトのロックが取得できない時に発生するエラーだよ。何か他に処理が動いていて、そのテーブルにINSERTとかの更新処理が走っていることはないか？」
Aさん「いや、そんな筈はないんだが…。」
たろー「エラーは毎日発生してるの？」
Aさん「いや、毎日じゃない。発生したりしなかったり、マチマチだ。
エラー発生後は、単純に再実行すれば問題なく処理が終了するんだ。」
たろー「何か別な処理がロックを掛けているとしか思えないけどなぁ。」
Aさん「夜間にエラーが発生する度に監視オペレータから呼び出しの電話がかかってきて困ってるんだ。なんとかならないかなぁ？」
たろー「ふーむ…、ちょっと Statspack レポートを見てみるか。」

たろーちゃんはエラー発生の時間帯をAさんから聞き出し、その時間帯の Statspack レポートを取得しました。そのレポートには・・・。

見慣れない待機イベント

たろー「うん？………これは？」

Staspack レポートのTOP5待機イベントの上位には、見慣れない待機イベントが出力されていました。

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
Wait for shrink lock                              ####        ####   ####   52.8
Wait for shrink lock2                             ####        ####   ####   41.3
db file sequential read                            572          14     24    1.1

たろー「『Wait for shrink lock』と『Wait for shrink lock2』が上位だな。この２つで全体の待機の９０％以上を占めているぞ。」
Aさん「どういう意味の待機イベントなんだ？」
たろー「『Wait for shrink lock』はALTER INDEX … SHRINK コマンドで発生する待機イベントで、『Wait for shrink lock2』はALTER TABLE … SHRINK コマンドで発生する待機イベントだ。別な処理で TRUNCATE 対象のテーブルに対してSHRINKを実行してるんじゃないか？」
Aさん「いや、そんな処理は実行してないよ。」
たろー「 Statspack レポートを見る限り、そうとしか思えない。」
Aさん「いや、そんな筈はないんだが…。」

こんな時、Enterprise Edition なら血液検査（V$ACTIVE_SESSION_HISTORY）が使えるのになぁ・・・。

※V$ACTIVE_SESSION_HISTORYに関しては以前の記事『正体不明のパフォーマンス悪化の謎を解き明かせ！』の回をご参照下さい。

たろー「残念だけど、Standard Editionでは、ここまでが調査の限界だよ。」
Aさん「そうか……。（◞‸◟）」

Aさんはションボリして、トボトボと帰って行きました。
そんなAさんの後ろ姿を見送りながら、たろーちゃんは、何か違和感を覚えていました。

たろー（何だろう、この感覚……。俺は何か大変な見落としをしているんじゃないだろうか？）

次の日の朝

次の日の朝、たろーちゃんのところに、またAさんが訪ねてきました。

Aさん「たろーちゃん、昨日も TRUNCATE が異常終了したよ。」
たろー「また？！」
Aさん「昨日は別件で残業してて、俺が会社にいる時に発生したんだ。だから、その場ですぐに全業務アプリケーションを確認することが出来たんだが、SHRINKを実行している処理は、やっぱりなかったんだよ。」
たろー「えー、そんなバカな？！」
Aさん「誰が犯人なのか、調べる方法はないかなぁ？また呼び出しをくらうかもしれないと思うと、家に帰っても気が休まらないよ。」
たろー「えーっと、そうだなぁ……。ちょっと裏ワザを使うか。」
　

SQL> alter system set events '54 trace name errorstack level 3;name systemstate level 266';

Aさん「何をしたんだい？」
たろー「 ORA-00054 が発生した際に、詳細な情報をログに出力するように設定したんだ。」
Aさん「ほう、罠を仕掛けた感じか。」
たろー「そうだ。次にこの事象が発生したときに、犯人特定に繋がる有力な情報になるかもしれない。」

更に次の日の朝

たろー「昨晩は何も起こらなかったのかな。ちょっとアラートログを見てみるか。」
　

System State dumped to trace file /opt/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_j000_19990.trc
Errors in file /opt/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_j000_19990.trc:
ORA-00054: リソース・ビジー。NOWAITが指定されているか、タイムアウトしました

たろー「んん？！ j000バックグラウンドプロセスで ORA-00054 が発生してる？！
トレースログを見てみるか。」
たろー（カタカタカタ）
たろー「…………なんと。そういうことだったのか。」

たろーちゃんはAさんのもとに向かいました。
原因が分かったのでしょうか？

たろー「Aさん、おはよう。昨日は呼び出されなかったか？」
Aさん「ああ、昨日は大丈夫だった。呼び出されなかったのはよかったけど、現象が再現しないと調査が進まないのは困るんだよなぁ。」
たろー「そのことだけどさ。 TRUNCATE を異常終了させてる犯人が分かったぞ。」
Aさん「なに、本当か？！」
たろー「ああ、本当だ。昨日、 ORA-00054 が発生したら詳細なログを出力する設定にしただろう？」
Aさん「うむ。」
たろー「その犯人が、今度は自分より先に TRUNCATE にロックを取得されて、自分自身が ORA-00054 で異常終了してたんだ。とんだ間抜けだよな。」
Aさん「おお！犯人は一体誰だったんだ？！」

今回はここまで。
次回は犯人の真相に迫ります！

投稿者プロフィール

DBひとりでできるもん運営チーム

「DBひとりでできるもん」運営チームです。
「親しみやすさと技術力」をテーマに、技術情報・サービス・インフラ系資格取得に役立つ情報、社員等の情報をお届けします。
70名弱の事業部員で鋭意、執筆中です。
少しでも当社を知って頂けるよう、愛情込めて頑張ります！
※facebook、X(旧twitter)、インスタグラムでは「DBひとりでできるもん」の更新情報を発信しています。