プチIT化

【IMP-00058】エラーが出た時にどうしたか?という話

こんにちは、わたあめです。Oracleのエラー対処をしていると、1日あっという間に過ぎませんか?!まさに先日の私はそうでした。

今日は、トラブル発生時のエラー解決に1秒でも近づけるように、どうエラー対処したかを書こうと思います。今回ぶち当たったエラーはこちら!!Oracleのデータベースをインポートしていたら、いきなりシャットダウンされてました。

IMP-00058: Oracleエラー1089が発生しました。
ORA-01089: 即時シャットダウン処理中 - 操作はできません

わたあめ
わたあめ
お、おおう…突然シャットダウンされたことに動揺しちゃう。初めて見るエラーだ(げんなり)

そして、もう一つ。シャットダウンの前にこのようなOracleアラートが出ていました。

Thread 1 cannot allocate new log, sequence XXXXX
Checkpoint not complete

これらについて調べました。その過程を綴っています。それでは、いきましょう!

結論から:原因と対処

まずは結論から。

原因

不明。この記事開いた甲斐なしと思われた方、本当にごめんなさい。ただ、絶対コレが原因と自信はないけど、ある程度のこれかな?があります。そして、エラーが発生した時、どう確認したかを後述していますので、良かったら、見て行ってください。

何となくあたりをつけた原因ですが、データベースのREDOログファイル周辺と予想しています。(詳しくは後述)

対処

今回は、インポート処理を再度行ったら時間は通常の倍かかってしまったものの、インポート処理が正常に終了しました。根本的な解決をするには、データベースのチューニング、になると思います。(未実施)

わたあめ
わたあめ
同じ事象が再現するか?を確認しようとしたところ、うまくいった!

だけど、根本解決にはなっていないので、最終的には抜本的解決を目指します。(なう)

確認手順

では、エラーが発生したら何をしたか?です。

ログ確認

まずはこれに尽きます。ログの確認がエラー解決の手掛かりになります。実行中に出てきたエラーはこちらです。

IMP-00058: Oracleエラー1089が発生しました。
ORA-01089: 即時シャットダウン処理中 - 操作はできません
IMP-00058: Oracleエラー3114が発生しました。
ORA-03114: Oracleに接続されていません。
IMP-00000: エラーが発生したためインポートを終了します。

Oracleのアラートログも確認しています。実行ログに時間も併せてあるかと思いますので、その周辺のログを確認すると良いです。今回シャットダウン時にこのようなログが出ていました。(※pidの値などは変えています。)

Tue May 5 04:20:10 2020
Starting background process PPPP
EMN0 started with pid=XX, OS id=YYYY
Tue May 5 04:20:10 2020
Shutting down instance: further logons disabled
Tue May 5 04:20:13 2020
Stopping background process PPPP
Tue May 5 04:20:14 2020
Shutting down instance (immediate)
License high water mark = 10
Tue May 5 04:20:14 2020
Stopping Job queue slave processes
Tue May 5 04:20:14 2020
Job queue slave processes stopped

アラートログは、それぞれ違うと思います。わたあめが探すときは大体C:\とかD:\とかの中に[oracle]という名前のフォルダがあるのでそこに入っていって[admin]フォルダの中の周辺[bdump]フォルダの"alert_XXX.log"みたいなファイルを見つけてます。

シャットダウンが実行される前、このようなログもアラートログに頻発してました。このアラートの原因になっている処理で逼迫されてDBが落ちてしまったのでは?と仮定します。

Thread 1 cannot allocate new log, sequence XXXXX
Checkpoint not complete

エラー番号で調べる

ログを確認した後は、とにかく検索です。検索の仕方はエラー番号、エラーメッセージをそのまま検索しています。運が良ければ、どなた様かのブログに辿り着き、原因が書いてある。もちろん環境が異なれば当てはまらないこともありズバッと解決には至らないかもしれませんが、ヒントになる事が多いです。

ただ、なかなか起きない珍しいエラーだと、情報が出てこない!!(汗)また、海外サイトの掲示板の情報ばかり、ということも多々です。見つかったらラッキーくらいの気持ちです。

今回の場合、以下のキーワードで検索かけました。とにかくネットサーフィンの波に乗りまくります。

  • "IMP-00058"
  • "Oracleエラー1089"
  • "cannot allocate new log"
  • "Checkpoint not complete"

調べていくと、どうもREDOファイルが怪しい!という事が分かってきました。

原因?詳細:REDOログ・ファイルのサイズ

わたあめ
わたあめ
いやいや、REDOログ・ファイルってなんやねん!(突然の関西弁)

ここでは、技術的な解説というより、技術情報を読み漁ったわたあめが自身の理解の範囲で、簡単な言葉で雑に説明していきます。間違って解釈してるかもしれませんので、そこはご了承くださいね。

REDOログファイル(多分、きちんと言うとオンラインREDO・ログファイルになりそう)は、大量の更新内容を一気に処理するときに一時的にその更新情報を格納するファイルです。今回の場合だと、大量のデータをインポートしていて、そのインポートする情報をREDOファイルに一時的に格納していました。

で、このREDOログファイル、どうもファイルサイズが指定されているっぽい。(このファイルサイズでどれだけ情報を格納できるか決まるっぽい。)そして、REDOログファイルは複数あるよう。ひとつのファイルが満杯になると、次のファイルにスイッチされます。で、移った先のファイルにまた情報を貯める。

Thread 1 cannot allocate new log, sequence XXXXX
Checkpoint not complete

上記エラーが発生するのは、データ量?処理?が多すぎてこれ以上REDOログ・ファイルに割り当てられないよ、情報保持できないよ、という事っぽいです。また、チェックポイントとはディスクに情報を書き込むことなので、これが完了しなかったということは、REDOログファイルの内容がキチンと反映できなかった!ということかと。

つまり、1度目のインポートでDBが落ちてしまったのは「処理多すぎ!記憶できない・書き込めない、できませーん!」「もう無理シャットダウンしちゃう!!」みたいな事が起こったのではないかと思います。2度目のインポートは正常に終了しましたが、通常の倍の時間がかかりました。これは、REDOログファイルの処理が滞っていて、待ち時間とか結構発生しちゃったんじゃないかなー?と思います。(予想)

時間かかったのは、とあるテーブルのみで発生。そのテーブル、1行の情報量が多いんですよね。だからかなぁ?

根本的対処:チューニング

インポート処理、運が良ければ時間はかかるが正常終了する、という状況で、一時的に問題は回避できました。が、根本的解決にはチューニングが必要なようです。REDOログ・ファイルのサイズを大きくする、個数自体を増やす必要がありそうです。

チューニングはまだ行っていませんが、この対処によってこのアラートを抑えることができれば、と考えています。

さいごに

長い文章を最後までお読みいただき、ありがとうございました!エラー原因は環境によっても違うし、ズバッと解決できることは少ないと思いますが、わたあめのトラブル奮闘記でした。

それでは、また!

flier(フライヤー)