トランザクションログのデータフォーマットを徹底調査
これまでトランザクションログのデータフォーマットをきちんと調査したことがなかったので、改めて構造をきちんと調べようと思いました。お客様からは、デタッチした時にコピーしたトランザクションログが送られてきていたので、ついでにトランザクションログの内容を確認できるツールを作ることにしました。構造がわかってもバイナリエディタで見るのはさすがにつらいからです。また、障害が発生した時の内容を確認したかったというのも理由のひとつです。というのも、データベースにアタッチすれば、DBCC LOGコマンド等で内容は確認できるのですが、送られてきたファイルをアタッチすると、ファイルのサイズが微妙に変わっていて気持ち悪かったのです。
ソースコードやらなんやらを調べて理由がわかりました。トランザクションログの先頭8KBは、ファイルヘッダーページと呼ばれるページの構造をした部分だったのです。この部分には、ファイルのサイズやバックアップやリストアに必要な情報が記録されます。BACKUP LOGを行う時に、この部分を読み取ろうとしてstale read detectionに引っかかっていたのです。
BACKUP LOGが失敗した理由は、これでわかりました。しかし、トランザクションログが拡張できなかった理由については不明のままです。エラーログからはこれ以上のことがわかりそうになかったので、メモリダンプを調査してみることにしました。予期しないBACKUP LOGエラーの延長でassertエラーに引っかかりメモリダンプが出力されていたのです。
ところが、ざっと調べてみる限り拡張できない理由はわかりませんでした。何か手がかりがないかなぁと考えていた時に、思いつきました。SQL Serverは、飛行機の blackbox recorder のような機能を持っています。Ring bufferと呼ばれる循環型のインメモリ ログバッファーです。ここに何かヒントが記録されていのじゃないかと思って、メモリダンプからリングバッファーの内容を抜き出してみました。
すると見つかりました。9002 エラー (トランザクションフル) 時のスレッドスタックが大量に記録されているのですが、同様に824エラーも大量に記録されているのです。しかも、それは必ず交互に記録されています。824エラー, 9002エラー,824エラー, 9002エラー,824エラー, 9002エラー…の繰り返しです。
スレッドスタックをヒントにソースコードを追ってはっきりしました。起きていたのは次のような現象です。
トランザクションログがフルになったのでログファイルを拡張します。拡張によってファイルサイズが変更になったので、ヘッダーページに保存されている情報、ファイルサイズなどを書き換えようとします。しかし、ヘッダーページの読み込みは、stale read エラーで失敗します。ログファイルを拡張する部分のコードでは、処理途中で何らかのエラーが発生しても特定のエラー以外は捕捉するようになっており、ユーザーにはトランザクションがフルで書き込めませんとしかエラーを返さないのです。つまり、すべてのエラーは stale read の824エラーがきっかけだったのです。
824エラーが発生した理由については不明です。SQL ServerがI/Oを発行した後は、処理を下位のレイヤー(OSやストレージなど)にゆだねるしかないので、できるのはエラーを検知することだけです(*)。もちろん、不具合でエラーを誤検知する可能性もあるのですが、もしそうであれば、もっと頻繁に発生していてもおかしくない気がします。
(*)ハミングコードのようなエラーコレクションは考えられるのですが、SQL Serverはリトライというアプローチをとります。
824エラーなどの破損系エラーは厄介なエラーです。完全にハードウェアが壊れているような場合はよいのですが、1ビット反転しただけとか、何か電気系統が一時的におかしかっただけじゃないの？みたいなことがあります。SQL Serverは、824エラーなどのハードウェアエラーを検知すると、何度か読み込みをリトライしたりデータベースを再起動したりしますが、その結果、処理が正常に終了したということもあります。
とはいえ、破損系エラーに備えて、きちんとバックアップを取っておきましょう！ちなみに、可用性グループを構成していれば、ファイル破損が発生しても自動修復してくれるかもしれませんよ！
