案件の概要
トランザクションログは、INSERTやUPDATEなどトランザクションが実行される度に記録されます。ログファイルに書き込めるスペースがなくなると、SQL Serverは自動でファイルを拡張して空きスペースを作り、その空きスペースにトランザクションを書き込んでいきます。この拡張処理は通常ディスクスペースがある限り失敗しません。
お客様のトランザクションは、ログに書き込めるスペースがなくなったというエラーで失敗していました。
エラー: 9002、重大度: 17、状態: 2。 The transaction log for database 'TEST' is full. To find out why space in the log cannot be reused, see the log_reuse_wait_desc column in sys.databases
「これはいったい何だったんだ？」
ディスクには空き容量が十分にあったので、自動拡張が行われてトランザクションがエラーになることはないはずです。しかし、自動拡張が失敗したというエラーは出力されておらず、トランザクションログがいっぱいで書き込めないというエラーだけが発生していました。
トランザクションログは、バックアップするとトランケーションポイントより古い領域については再利用可能な領域になります。再利用可能な領域があれば、ファイルを拡張しなくて済みます。お客様はこの状況を復旧しようとして、何度かBACKUP LOGを試みたようでした。しかし、それも意味不明なエラーで失敗。仕方がないので、データベースをデタッチ・アタッチし、何とか復旧したそうです。
「これはいったい何だったんだ？」ということで調査依頼が来ました。送られてきたSQL Serverエラーログを見ると、確かに「トランザクションログがフル」のエラーがたくさん出力されていました。BACKUP LOGが実行された形跡もあり、その時には以下のエラーで失敗していることがわかりました。
エラー: 824、重大度: 24、状態: 2。 SQL Server detected a logical consistency-based I/O error: 古いページ (読み取ったページが返したログ シーケンス番号 (LSN) (0:142:0) は、最後に書き込まれた LSN (0:596:0) より古い番号です). It occurred during a 読み取り of page (2:0) in database ID 7 at offset 0000000000000000 in file 'L:\Program Files\Microsoft SQL Server\MSSQL10.TESTINST\MSSQL\DATA\TEST_log.ldf'. Additional messages in the SQL Server error log or system event log may provide more detail. This is a severe error condition that threatens database integrity and must be corrected immediately. Complete a full database consistency check (DBCC CHECKDB). This error can be caused by many factors; for more information, see SQL Server Books Online. バックアップ エラー: 3041、重大度: 16、状態: 1。 バックアップ BACKUP failed to complete the command BACKUP LOG TEST. Check the backup application log for detailed messages.
824エラーは、ファイルの破損を示すエラーです。これを見た瞬間、「あ、ファイル破損か。だからBACKUP LOGがうまくいかなかったのね。」と一瞬納得したのですが、続くエラーメッセージを読んでムムっと思いました。
SQL Server detected a logical consistency-based I/O error: 古いページ (読み取ったページが返したログ シーケンス番号 (LSN) (0:142:0) は、最後に書き込まれた LSN (0:596:0) より古い番号です).
824エラーにはいくつか種類があるのですが、このメッセージは、ページに対するI/OでLost Write, Stale Readを検出した時のエラーのメッセージです。トレースフラグ818を設定することで有効になるI/Oエラー検出機能によるものです。
SQL Serverは、1ページを8KBで扱います。ページのヘッダー部分には4バイトのチェックサムがあります。ディスクに書き込む際には、8KBのデータをもとにチェックサムが算出されここに保存されます。読み込まれた時には、同じように8KBのデータからチェックサムを算出して、自身が持っている (書き込む前に算出された) チェックサムと一致するかを検証します。一致しない場合、8KBのうち、どこかのデータが変わっていると判断し破損を検知します。
しかし、1ページ書き込んだ値が丸ごと喪失した場合どうなるでしょうか？読み込み時には、1書き込み分古いデータが返ってきます。この古いデータは、書き込まれた時と読み込まれた時で8KBのデータが異なっているわけではないのでチェックサムが一致してしまいます。読み込みの時に、OSやストレージが誤って1書き込み分古いデータを返した場合も同じです。
トレースフラグ818を有効にすると、このようなチェックサムでは検知できないような問題を検出する機能、stale read detection を有効にすることができます。お客様は、トレースフラグ818を有効にしていたのです。
Additional SQL Server diagnostics added to detect unreported I/O problems http://support.microsoft.com/kb/826433/
「へー、stale read errorなんて初めて見たなぁ」と驚いていた時、アレッと思いました。Stale read detectionは、ページに対して行われる検証です。よく考えたら、トランザクションログに記録されるレコードのフォーマットは8KBのページフォーマットではありません。I/Oの単位がページフォーマットではないので、検証は行われないはずなのです。しかし、エラーメッセージには、はっきりとファイル名が出力されています。トランザクションログファイルで stale read が検知されたことは間違いなさそうです。
