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 ライター バイナリがアップグレードされることを意味します。

Note

次の段落では、SQL Server 2019 (15.x) CU 4 以降の状況について説明します。 以前の SQL Server 2019 (15.x) バージョンには、既定の設定でログ ファイルに同じ量の情報は含まれません。

基本操作

手動で変更することなく、新しいログ記録を利用できます。 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 が情報を確認する重要な場所となります。

Note

この新しいログ記録インフラストラクチャは、SQL Server の既存のエラー報告インフラストラクチャを補完するものであり、代わるものではありません。 したがって、エラーが発生した場合は、Windows のアプリケーション イベント ログが、("SQLWRITER" や "VSS" などのソースでフィルター処理して) 最初に確認する場所であることは変わりありません。 SqlWriterLogger.txt により、この初期セットに追加情報が提供されます。

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

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

サービスの開始

[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 バックアップの主なフェーズを特定するその他のエントリ (OnFreezeOnThawOnPostSnapshot)
  • 最後の 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 テキスト ファイルを編集することによって構成できます。 ファイル自体には、以下で確認する、使用可能なパラメーターの簡単なインライン記述が含まれています。

Note

.ini ファイルは Windows によって保護されているフォルダー (Program Files) の下にあります。 そのため、編集するには昇格された管理者特権が必要です。 エクスプローラー内をダブルクリックすると、昇格なしでメモ帳が開きます。これにより、ユーザーは内容を読み取ることができますが、変更を保存しようとすると失敗します。 管理者としてメモ帳を起動してから、SqlWriterConfig.ini を開くか、ファイルの保存時に必要に応じて昇格のプロンプトを表示できるテキスト エディターを使用します。

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

パラメーター [オプション] 説明
EnableLogging - TRUE (既定値)
- FALSE
ユーザーは、必要である可能性が低い場合に、新しいログ記録機能全体を無効にできます。
TraceFile C:\Program Files\Microsoft SQL Server\90\Shared\SqlWriterLog.txt ユーザーはトレース ファイルのパスとファイル名を変更できます。 既定の既知の場所として変更し、任意の SQL Server 上の適切な場所に直接簡単に移動できるようにすることは推奨されません。
TraceLevel - DEFAULT (規定値)
- MINIMAL
- VERBOSE
ログの詳細度です。 詳細については、「TraceLevel の詳細」を参照してください。
TraceFileSizeMb 1 MB (既定値) ロールオーバー前の最大ファイル サイズ。 .txt ファイルでは UTF-8 エンコードが使用され、1 文字あたり 2 バイトが消費されます。 この値を増やすことは、VSS アクティビティが多いインスタンスや、ログ エントリを長時間保持する必要がある場合や、非既定の TraceLevel 値が長時間有効になっている場合に有効です。 既定値が 1 MB の場合、ほとんどの状況で十分な履歴が提供されるはずです。
ForceFlush - TRUE
- FALSE (規定値)
このオプションを TRUE に設定すると、最後のログ エントリをフラッシュする機会を得る前に SQL ライター サービスがクラッシュするまれな状況でのみ役立ちます。それ以外の場合は、既定値のままにしておいてください。

変更を適用する

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

ヒント

SQL ライターの再起動は非常に高速であり、随時行うことができます。これは、SQL ライターではステートフルな情報が保持されることも、VSS 呼び出しの間にアクティビティが存在することもないからです。 唯一の予防措置は、VSS 操作 (バックアップ、復元) の実行中に再起動を避けることです。

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

TraceLevel の詳細

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

Level Detail
DEFAULT 既定の詳細度パラメーターはほとんどのニーズに適しているはずです。既定で既に生成されている内容を観察する場合は、「一般的なログ エントリの確認」セクションを参照してください。 エラーに加え、VSS の正常な呼び出しと VSS メタデータが既定でログに記録されます。
MINIMAL このレベルでは、DEFAULT モードとそのイベントの書式設定が保持されます。 また、コードの多くの重要な場所に出力が生成されます。 中でも注目すべきは、SQLWriter ロジックで一般的なすべてのファイルとデータベース イテレーションがログに記録されることです。 特に多数のデータベースをホストしているインスタンスでは、各 VSS 操作 (日常の OnIdentify イベントを含む) についてログに記録されるエントリの数を増やすことができます。すべての単一データベースのそれぞれの物理ファイルが、VSS バックアップの過程で複数回報告される場合があります。 このレベルは、障害発生時の SQL ライター ロジックの論理的な位置をより正確に把握するためにのみ役立ちます。 また、探索目的にも便利です。 この詳細レベルでは既定の 1 MB のファイル サイズの履歴の深さが大幅に減少するため、瞬間的な調査を超えてアクティブな状態を保つことは有効ではありません。 TraceFileSizeMb 値を増やすことに関連する可能性があります。
VERBOSE 現在、このレベルでは MINIMAL と同じイベントが報告されますが、各エントリにはソース コード オブジェクトとメソッドの記述子がプレフィックスとして付けられます。 これにより、出力の幅が広くなり (サイズが最小よりも大きくなる)、読みにくくなります。 追加された情報は、Microsoft サポート サービスとのやり取り以外では役に立ちません。 MINIMAL と同じことが当てはまります。このレベルを長時間アクティブにしておくと、既定の 1 MB ファイル サイズの履歴の深さが大幅に減少し、TraceFileSizeMb 値を増やすことに関連する可能性があります。

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

次のステップ