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

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

Aさん「たろーちゃん、ちょっと相談なんだけど…。」
たろー「うん、どうしたの?」
Aさん「ずっと前にStandard Edition の 2ノードRACの Oracle Databaseのことで相談したの覚えてる?」
※Aさんのシステムについては以前の『SQL実行計画の変更 その2』の回を参照して下さい。
たろー「ああ、あれね。」
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』が上位だな。この2つで全体の待機の90%以上を占めているぞ。」
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さん「おお!犯人は一体誰だったんだ?!」

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

 

投稿者プロフィール

たろーちゃん
たろーちゃん
株式会社システムサポート インフラソリューション事業部に在籍するPlatinumホルダー。
Oracle Databaseのパフォーマンスチューニングを得意とする。
データベースは Oracle 以外興味がないという変わり者。
一番嫌いなエラーメッセージは CRS-02625。
連載「心臓外科医の術式」を執筆。