SQL Server VSS Writer のログ記録

適用対象: SQL Server

SQL Server は、専用 SQL ライター サービスを使用して VSS (ボリューム シャドウ コピー サービス) のバックアップ操作と復元操作に関与できます。 詳細については、「SQL Server バックアップ アプリケーション - ボリューム シャドウ コピー サービス (VSS) と SQL ライター」を参照してください。

このサービスは、この記事の後半の例でわかるように、イベント Source (または PowerShell または XML コンテキストの ProviderName) の値 SQLWRITER を使用して Windows アプリケーション イベント ログに実行エラーを報告します。 SQL Server 2019 (15.x) より前は、専用のアクティビティ ログは存在せず、VSS 操作の参加者として SQL Server に対する調査は困難でした。

この記事では、SQLWriter 操作の可視性を高めるために SQL Server 2019 (15.x) で導入された新しいログについて説明します。 この機能は、SQL Server 2016 (13.x) Service Pack 3 と SQL Server 2017 (14.x) Cumulative Update (CU) 27 でも使用できるようになりました。

概要

SQL Server 2019 (15.x) SQLWriter ログの主な特性は次のとおりです。

• 既定でオンになる
• システム全体である (サーバー上で実行されているすべての SQL Server インスタンスに対する SQL ライター アクティビティをトレースする)
• テキストベースである
• 作業ディレクトリは C:\Program Files\Microsoft SQL Server\90\Shared である
• そのディレクトリ内:
  • ログ記録は SqlWriterLogger.txt ファイルで行われる
  • このファイルの名前は、最大サイズ (既定では 1 MB) に達したときに SqlWriterLogger1.txt に変更され、メインの SqlWriterLogger.txt でログ記録が続行されます。
  • ロールオーバー ファイルは 1 つだけなので、2 回目のロールオーバーによって既存の SqlWriterLogger1.txt が上書きされます。
  • パラメーターは SqlWriterConfig.ini ファイルによって管理される

SQL ライターは SQL Server 共有コンポーネントであるため、システム上に 1 つのインスタンスがあり、そのメジャー バージョンは、インストールされているすべての SQL Server インスタンスの最上位メジャー バージョンと同じになります。 たとえば、SQL Server 2016 (13.x) SP2、SQL Server 2019 (15.x)が同じシステム上にインストールされている場合、SQL ライターのバイナリは SQL Server 2019 (15.x) によって提供されるものになり、すべてのメジャー バージョンから実行されているすべてのインスタンスが処理されます (そのホーム ディレクトリが \90 のままであっても)。 ローカル インスタンスおよびバージョンでは、ここで説明する新しい SQL Server 2019 (15.x) トレースを利用できます。 また、この状況では SQL Server 2019 (15.x) の累積的な更新プログラムによってのみ SQL ライター バイナリがアップグレードされることを意味します。

基本操作

手動で変更することなく、新しいログ記録を利用できます。 C:\Program Files\Microsoft SQL Server\90\Shared\ のメイン SqlWriterLogger.txt ログ ファイルを開くことも、そのコピーを取得することもできます。 ファイルには、主に次のような、SQL ライターに到達するすべての VSS イベントが反映されます。

• コマンド vssadmin list writers によってトリガーされる OnIdentify イベント
• バックアップ イベント
• 復元イベント

つまり、これらの操作が正常に行われた場合でも、ログ ファイルには詳細なエントリが記録されます。 VSS 操作が発生しており、SQL ライターと正常にやり取りしていることを確認できます。 これは、SQL Server インスタンス レベルでこれらの詳細を確立するための簡単なビルトイン方法を提供する強化機能です。

さらに、SQLWriter サービスの開始イベントも記録され、アクティブなログ記録パラメーターが報告されます。

言うまでもなく、SQL Server に関する VSS 操作障害が発生した場合は、SqlWriterLogger が情報を確認する重要な場所となります。

一般的なログ エントリの確認

既定の設定で次のエクスポートが行われています。

サービスの開始

[01/11/2021 02:54:59, TID 61f8] ****************************************************************
[01/11/2021 02:54:59, TID 61f8] **  SQLWRITER TRACING STARTED - ProcessId: 0x4124
[01/11/2021 02:54:59, TID 61f8] **  Service is not running as WIDWriter.
[01/11/2021 02:54:59, TID 61f8] **  SQL Writer version is 15.0.4073.23
[01/11/2021 02:54:59, TID 61f8] **  MODERN LOGGER V2 ENABLED ON C:\Program Files\Microsoft SQL Server\90\Shared\SqlWriterLogger.txt
[01/11/2021 02:54:59, TID 61f8] **  With TraceLevel = DEFAULT, TraceFileSizeMb = 1, ForceFlush = False
[01/11/2021 02:54:59, TID 61f8] **  Recording events in Server Local Time. UTC OFFSET: -8:00
[01/11/2021 02:54:59, TID 61f8] ****************************************************************

上記のエントリは、SQL ライター サービスの開始ごとに観察されます (サービスの開始ごとに 2 回ログに記録される場合があります)。

表示順に、次の情報がわかります。

• ローカル サーバー時刻のタイムスタンプ (日付と時刻)、および各行のエントリの発生元の ThreadId。
• 開始されている SQLWriter プロセスの ProcessId。
• サービスが '通常' モード ('WIDWriter として実行されていない') と Windows Internal Database モードのどちらで開始されたかという事実
• SQL ライター バイナリのバージョン。
• SqlWriterConfig.ini ファイルによって設定されたすべてのパラメーター:
  • アクティブ ログ ファイルのターゲット パス
  • トレースの詳細レベル (この例では DEFAULT)
  • ロールオーバー発生前のファイルの最大サイズ (この例では 1 MB)
  • ログ ファイルのそれぞれの更新を ForceFlush するオプションと、より緩やかなまたはバッファーされた方法 (既定では False)。
• ローカル時刻の UTC オフセットと共に、ローカル時刻をログに記録することの通知。

VSS の 'OnIdentify' イベント

[01/12/2021 08:23:40, TID 464c] Entering SQL Writer OnIdentify.
[01/12/2021 08:23:40, TID 464c] Service: MSSQLSERVER Server: GF19. Version=15
[01/12/2021 08:23:40, TID 464c] Instance MSSQL15.MSSQLSERVER Edition: Developer Edition
[01/12/2021 08:23:40, TID 464c] Instance MSSQL15.NAMED1 Edition: Enterprise Edition: Core-based Licensing
[01/12/2021 08:23:40, TID 464c] Skip User Instances Enumeration

OnIdentify は一般的な VSS 操作です。 これは vssadmin list writers コマンドによってトリガーされます。 ほとんどの VSS 要求元は、OnIdentify イベントを使用して VSS のバックアップまたは復元操作を開始します。

これまで、DBA はアクティブなプロファイラー トレースのみでこのようなイベントを検出できました。 新しいログ記録機能を使用すると、各イベントにより上記のエントリが発生するようになります。

表示順に、次の情報がログに記録されているのがわかります。

• OnIdentify VSS イベントの明示的な言及。
• アクティブな (実行中の) すべての SQL Server インスタンスと、それらのインスタンスの名前、メジャー バージョン、およびエディションの一覧。
• "ユーザー インスタンス" (LocalDB とも呼ばれる特定の SQL Server 機能で、通常はエンタープライズ データベース サーバーには関係しない) を一覧表示しようとしていたのではないという表示。

成功したコンポーネント モードの VSS バックアップ

[01/11/2021 02:30:19, TID 32c8] Entering SQL Writer Initialize.
[01/11/2021 02:33:33, TID 232c] Entering SQL Writer OnIdentify.
[01/11/2021 02:33:33, TID 232c] Service: MSSQLSERVER Server: GF19. Version=15
[01/11/2021 02:33:33, TID 232c] Instance MSSQL15.MSSQLSERVER Edition: Developer Edition
[01/11/2021 02:33:33, TID 232c] Instance MSSQL15.NAMED1 Edition: Enterprise Edition: Core-based Licensing
[01/11/2021 02:33:33, TID 232c] Skip User Instances Enumeration
[01/11/2021 02:33:37, TID 232c] Entering SQL Writer OnPrepareBackup.
[01/11/2021 02:33:37, TID 232c] ****************************************************************
[01/11/2021 02:33:37, TID 232c] **  VSS SQL BACKUP BEGIN - ID: 232c
[01/11/2021 02:33:37, TID 232c] ****************************************************************
[01/11/2021 02:33:37, TID 232c] Component based backup selected.
[01/11/2021 02:33:37, TID 232c] Database count from metadata is 1
[01/11/2021 02:33:37, TID 232c] Database db_on_G on instance GF19 found in metadata
[01/11/2021 02:33:37, TID 232c] Backup type is VSS_BT_COPY
[01/11/2021 02:33:38, TID 232c] Entering SQL Writer OnPrepareSnapshot.
[01/11/2021 02:33:38, TID 232c] Service: MSSQLSERVER Server: GF19. Version=15
[01/11/2021 02:33:38, TID 232c] Instance MSSQL15.MSSQLSERVER Edition: Developer Edition
[01/11/2021 02:33:38, TID 232c] Instance MSSQL15.NAMED1 Edition: Enterprise Edition: Core-based Licensing
[01/11/2021 02:33:38, TID 232c] Skip User Instances Enumeration
[01/11/2021 02:33:38, TID 232c] Entering SQL Writer OnFreeze.
[01/11/2021 02:33:38, TID 232c] Entering SQL Writer OnThaw.
[01/11/2021 02:33:38, TID 232c] Entering SQL Writer OnPostSnapshot.
[01/11/2021 02:33:38, TID 232c] Entering SQL Writer OnIdentify.
[01/11/2021 02:33:38, TID 232c] Service: MSSQLSERVER Server: GF19. Version=15
[01/11/2021 02:33:38, TID 232c] Instance MSSQL15.MSSQLSERVER Edition: Developer Edition
[01/11/2021 02:33:38, TID 232c] Instance MSSQL15.NAMED1 Edition: Enterprise Edition: Core-based Licensing
[01/11/2021 02:33:38, TID 232c] Skip User Instances Enumeration
[01/11/2021 02:33:40, TID 232c] Entering SQL Writer OnBackupComplete.

このイベントによって、さらにかなり多くのエントリのセットが発生します。 表示順に、次の情報がわかります。

• 既述のとおり、完全な OnIdentify セクションにより、多くの場合、バックアップが発生します。
• "Entering SQL Writer xxxx" パターンの、バックアップのすべての主な VSS フェーズの言及。
  • ここでは、Entering SQL Writer OnPrepareBackup が最初のものです。
• VSS SQL バックアップの開始を示す明確なエントリ
  • (SQLWriter でのそのバックアップ試行のログ記録を実行している ThreadId である ID)
• VSS 要求元、"コンポーネント" あるいは "非コンポーネントまたはボリューム" によって選択された VSS バックアップ API
• VSS 要求元によって送信されるコンポーネント リストに含まれるデータベースの数 (ここでは単一 DB (1))。
• VSS 要求元 (ここでは既定のインスタンス 'GF19') によって関連付けられている SQL Server インスタンスで、要求元が指定した各データベース名 (ここでは 'db_on_G') が見つかった (または見つからない) という確認。
• 要求された VSS バックアップのフレーバー。 通常は VSS_BT_FULL または VSS_BT_COPY です。 VSS_BACKUP_TYPE 列挙を参照してください。
• 別の OnIdentify セクション
• VSS バックアップの主なフェーズを特定するその他のエントリ (OnFreeze、OnThaw、OnPostSnapshot)
• 最後の OnIdentify セクション。
• 最後の VSS フェーズ レポート。OnBackupComplete という名前を付ければ、便利な "終了イベント" となります。

これらのエントリにより、以前は迅速に作成するのが難しく、これを行うには詳細トレースが必要だった VSS 操作の詳細が提供されます。 主な例は、VSS バックアップ要求の "コンポーネント" または "非コンポーネント" モードです。 SQL Server 2019 (15.x) SQL ライターを使用すると、既定でそれぞれの VSS 要求についてログに記録され、簡単にアクセスできます。

障害の状況: 破損したデータベース

SQL ライターのログ記録で イベント ログ アーキテクチャが補完されるという前の記述を説明するために、破損したデータベースなど、よく知られているエラー状況に関するエントリを見てみましょう。 VSS バックアップでボリュームのスナップショット セットが作成されようとしたときに発生することがあります。これには、特定のデータベースの一部のファイル セットのみが含まれます。 SQL ライターにより、VSS 規則に従ってブロックされます。

これは、操作の SqlWriterLogger.txt の内容を抜粋したものです。

[01/11/2021 02:57:00, TID 5a88] Entering SQL Writer OnIdentify.
[01/11/2021 02:57:00, TID 5a88] Service: MSSQLSERVER Server: GF19. Version=15
[01/11/2021 02:57:00, TID 5a88] Instance MSSQL15.MSSQLSERVER Edition: Developer Edition
[01/11/2021 02:57:00, TID 5a88] Instance MSSQL15.NAMED1 Edition: Enterprise Edition: Core-based Licensing
[01/11/2021 02:57:00, TID 5a88] Skip User Instances Enumeration
[01/11/2021 02:57:02, TID 5a88] Entering SQL Writer OnPrepareBackup.
[01/11/2021 02:57:02, TID 5a88] ****************************************************************
[01/11/2021 02:57:02, TID 5a88] **  VSS SQL BACKUP BEGIN - ID: 5a88
[01/11/2021 02:57:02, TID 5a88] ****************************************************************
[01/11/2021 02:57:02, TID 5a88] Volume based (= NonComponent) backup selected.
[01/11/2021 02:57:02, TID 5a88] Backup type is VSS_BT_FULL
[01/11/2021 02:57:03, TID 5a88] Entering SQL Writer OnPrepareSnapshot.
[01/11/2021 02:57:03, TID 5a88] Service: MSSQLSERVER Server: GF19. Version=15
[01/11/2021 02:57:03, TID 5a88] Instance MSSQL15.MSSQLSERVER Edition: Developer Edition
[01/11/2021 02:57:03, TID 5a88] Instance MSSQL15.NAMED1 Edition: Enterprise Edition: Core-based Licensing
[01/11/2021 02:57:03, TID 5a88] Skip User Instances Enumeration
[01/11/2021 02:57:03, TID 5a88] HRESULT EXCEPTION CAUGHT: hr: 0x80780002
[01/11/2021 02:57:03, TID 5a88] Entering SQL Writer OnAbort.

SqlWriterLogger.txt を見ると、障害が発生したことがわかります。しかし、障害に関する唯一の詳細は 0x80780002 HResult です。 この値は、エラー コードを参照しないと解釈するのが困難です。 しかし、破損したデータベースの状況は特定できます。

イベント ログの表示

次は、Windows アプリケーション イベント ログの内容を確認してみましょう。

Log Name:      Application
Source:        SQLWRITER
Date:          1/11/2021 02:57:03 AM
Event ID:      24579
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      GF19
Description:
Sqllib error: Database db_on_G_and_H of SQL Server instance GF19  is stored on multiple volumes, only some of which are being shadowed.

イベントにより、状況を説明する完全なユーザーフレンドリな形式のメッセージが提供されます。

また、OS VSS フレームワークでは、その用語体系を使用して、イベント ログで問題が報告されます (VSS により 'コンポーネント' が管理されます。これらは、SQL Server のコンテキストでは 'データベース' です)。

Log Name:      Application
Source:        VSS
Date:          1/11/2021 02:57:03 AM
Event ID:      8229
Task Category: None
Level:         Warning
Keywords:      Classic
User:          N/A
Computer:      GF19
Description:
A VSS writer has rejected an event with error 0x800423f0, The shadow-copy set only
 contains only a subset of the volumes needed to correctly backup the selected
components of the writer.
Changes that the writer made to the writer components while handling the event will
 not be available to the requester.
Check the event log for related events from the application hosting the VSS writer.

Operation:
   PrepareForSnapshot Event

Context:
   Execution Context: Writer
   Writer Class Id: {a65faa63-5ea8-4ebc-9dbd-a0c4db26912a}
   Writer Name: SqlServerWriter
   Writer Instance Name: Microsoft SQL Server 2019:SQLWriter
   Writer Instance ID: {a16fed29-e555-4cc5-8938-c89201f31f7e}
   Command Line: "C:\Program Files\Microsoft SQL Server\90\Shared\sqlwriter.exe"
   Process ID: 22628

イベント ログは、ここではエラー自体の情報源として適しています。 しかし、SqlWriterLogger の内容には、バックアップ要求 (VSS_BT_FULL。SQL ライターの OnPrepareSnapshot フェーズ中に失敗した非コンポーネント VSS バックアップ要求) の詳細が示されます。 そのため、SQL Server に関連する VSS エラーの調査では、''両方'' のソースを収集して確認する必要があります。

SQL ライターのログ記録パラメーターの変更

SQL ライターのログ記録は、SqlWriterConfig.ini テキスト ファイルを編集することによって構成できます。 ファイル自体には、以下で確認する、使用可能なパラメーターの簡単なインライン記述が含まれています。

ここで SqlWriterConfig.ini ファイルのコメントを複製します。

変更を適用する

設定を変更する場合は、アクティブ化するために SQL ライター サービスを再起動する必要があります。

SQL ライターにより、「サービスの開始」サンプルの抜粋に示されているように、(再) 起動時にそのログ ファイルでアクティブなパラメーターが報告されます。

TraceLevel の詳細

SqlWriterConfig.ini ファイルには、次のレベルが一覧表示されます。

MINIMAL および VERBOSE レベルでは、障害が発生した場合に追加のエラーの詳細は提供されません。SQL ライターのアクティビティに関する各詳細レベルの操作について、追加の 進行状況詳細のみが示されます。

次のステップ

• SQL Server バックアップ アプリケーション - ボリューム シャドウ コピー サービス (VSS) と SQL ライター
• BACKUP (Transact-SQL)
• RESTORE (Transact-SQL)
• SQL Server データベースのバックアップと復元
• SQL Server トランザクション ログのアーキテクチャと管理ガイド