SQL Server VSS 编写器日志记录

适用于:SQL Server

SQL Server可以参与 VSS (卷影复制服务,) 通过其专用 SQL 编写器服务执行备份和还原操作。 有关详细信息,请参阅SQL Server备份应用程序 - 卷影复制服务 (VSS) 和 SQL 编写器

该服务会向 Windows 应用程序事件日志报告执行错误,其中事件 Source (,或者在 ProviderName PowerShell 或 XML 上下文) 值 SQLWRITER,如本文后面的 示例 所示。 在 2019 SQL Server (15.x) 之前,没有专用活动日志,因此对作为 VSS 操作参与者的SQL Server进行调查具有挑战性。

本文介绍了 SQL Server 2019 (15.x) 引入的新日志,使读者可以更好地了解其 SQLWriter 操作。 此功能在 SQL Server 2016 (13.x) Service Pack 3 和 201 (7 SQL Server 14.x) 累积更新 (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 中进行。
    • 只有一个滚动更新文件,因此第二个滚动更新将覆盖现有的 SqlWriterLogger1.txt
    • 参数是由 SqlWriterConfig.ini 文件管理的

由于 SQL 编写器是SQL Server共享组件,因此它在系统上具有单个实例,并且其主版本将与安装的任何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 编写器二进制文件。

注意

以下段落介绍了从 SQL Server 2019 (15.x) CU 4 开始的情况。 早SQL Server 2019 (15.x) 版本在默认设置下日志文件中的信息量不会相同。

基本操作

无需任何手动更改,即可从新日志记录中获益。 可以在 C:\Program Files\Microsoft SQL Server\90\Shared\ 中打开或获取主 SqlWriterLogger.txt 日志文件的副本。 该文件将反映所有到达 SQL 编写器的 VSS 事件,其中主要是:

  • OnIdentify 事件,这些事件由 vssadmin list writers 命令触发
  • 备份事件
  • 还原事件

也就是说,即使这些操作成功发生,日志文件仍会记录详细条目。 可以确认 VSS 操作正在进行并与 SQL 编写器成功交互。 这是一项改进,提供了一种在SQL Server实例级别建立这些详细信息的简单内置方式。

此外,还将记录 SQLWriter 服务启动事件,并报告活动日志记录参数。

如果 VSS 操作失败涉及SQL Server,SqlWriterLogger 将成为检查任何信息的重要位置。

注意

这个新的日志记录基础结构补充了现有错误报告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 编写器服务 (都会观察到上述条目,它甚至可以在每次服务启动) 记录两次。

按外观顺序,可以看到以下信息:

  • 时间戳 (本地服务器时间) 日期 + 时间,以及每行的条目发起的 ThreadId。
  • 正在启动的 SQLWriter 进程的 ProcessId。
  • 服务在“正常”模式下启动的事实 (未以 WIDWriter ) 或Windows 内部数据库模式运行。
  • 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 实例的列表,以及它们的实例名称、主版本和版本类别。
  • 指示我们未尝试列出“用户实例”-一种特定的SQL Server功能,也称为 LocalDB,通常不涉及企业数据库服务器。

成功的组件模式 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 部分(如上文所述),它通常会导致一次备份。
  • 提及备份的每个主 VSS 阶段,其模式为“进入 SQL 编写器 xxxx”。
    • 这里,第一个为 Entering SQL Writer OnPrepareBackup
  • 一个指示 VSS SQL 备份启动的明显条目
    • (ID 是正在 SQLWriter) 中为该备份尝试执行日志记录的 ThreadId
  • VSS 请求程序选择的 VSS 备份 API,“组件”或“非组件/卷”
  • VSS 请求者发送的组件列表中包含的数据库计数,此处单个 DB (1) 。
  • 确认此处 (“db_on_G”) 的每个请求者提供的数据库名称 () SQL Server) (此处的默认实例“GF19”) 。
  • 请求的 VSS 备份类型。 通常为 VSS_BT_FULLVSS_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 内容提供了有关备份请求(在 SQL 编写器的 OnPrepareSnapshot 阶段失败的非组件 VSS 备份请求 VSS_BT_FULL)的详细信息。 因此,对涉及 SQL Server 的 VSS 错误的任何调查都应收集和查看这两个源。

修改 SQL 编写器日志记录参数

通过编辑 SqlWriterConfig.ini 文本文件,可以配置 SQL 编写器日志记录。 文件本身包含可用参数的快速内联说明,我们将在下文中查看。

注意

该 .ini 文件位于受 Windows 保护的文件夹 (Program Files) 下。 因此,它需要提升的管理员权限才能进行编辑。 双击资源管理器可以打开记事本(无需提升的权限):它将允许用户读取内容,但保存任何更改的尝试将会失败。 以管理员身份启动记事本,然后打开 SqlWriterConfig.ini,或使用能够在保存文件时根据需要提示提升的文本编辑器。

在此处复制 SqlWriterConfig.ini 文件注释:

参数 选项 说明
EnableLogging - true (默认)
-假
允许用户在不太可能需要的情况下禁用全新的日志记录功能。
TraceFile C:\Program Files\Microsoft SQL Server\90\Shared\SqlWriterLog.txt 允许用户更改跟踪文件的路径和文件名。 不建议更改它,因为一个默认的众所周知的位置会很容易直接转到任何 SQL Server 上的正确位置。
TraceLevel - DEFAULT (default)
-最小
-详细
日志记录的详细程度。 有关详细信息,请参阅 TraceLevel 详细信息
TraceFileSizeMb 1 MB (默认) 滚动更新前的最大文件大小。 .txt 文件使用 UTF-8 编码,每个字符占用 2 个字节。 增加此值是有效的,例如,对于密集的 VSS 活动、长时间保留日志条目,或者如果长时间启用非默认值 TraceLevel , 对于大多数情况,默认的 1-MB 值应提供充足的历史记录。
ForceFlush -真
- FALSE (默认)
将此选项设置为 TRUE 仅在 SQL 编写器服务在有机会刷新其最后一个日志条目之前崩溃的极少数情况下有用;否则保留默认值。

应用更改

对设置的任何更改都需要重启 SQL 编写器服务才能生效。

提示

重启 SQL 编写器非常快,可以任意完成,因为 SQL 编写器不会保留任何有状态信息,也不会在 VSS 调用之间有任何活动。 唯一需要的预防措施是避免在进行 VSS 操作(备份、还原)时重启。

SQL 编写器将在(重新)启动时在其日志文件中报告活动参数,如服务启动示例摘录中所示。

TraceLevel 详细信息

该文件 SqlWriterConfig.ini 列出了以下级别:

级别 详细信息
DEFAULT 默认详细参数应足以满足大多数需求:请参阅 查看典型日志记录条目 部分,观察默认情况下已生成的内容。 除了记录错误之外,默认情况下还会记录成功的 VSS 调用以及 VSS 元数据。
MINIMAL 此级别将保留模式及其事件的格式 DEFAULT 设置。 它还将在代码的许多关键位置生成输出。 最值得注意的是,它会记录 SQLWriter 逻辑中常见的所有文件和数据库迭代。 它可以使针对每个 VSS 操作(包括常见的 OnIdentify 事件)记录的条目数量大大增加,尤其是在托管大量数据库的实例上:每个数据库的每个物理文件可能会在 VSS 备份过程中被报告多次。 这个级别只有助于在失败情况发生时更准确地提供 SQL 编写器逻辑的逻辑位置。 它也便于浏览。 在进行暂时性调查后,将其保持活动状态没有用,因为详细信息级别将大大减少默认 1-MB 文件大小的历史记录深度。 增大 TraceFileSizeMb 值可能会有用。
VERBOSE 目前,此级别报告的事件与 MINIMAL相同,但为每个条目添加源代码对象和方法描述符的前缀。 这会使输出更宽(大小比 MINIMAL 大),可读性更差。 除了与 Microsoft 支持服务进行交互之外,添加的信息将不会有用。 它适用与 MINIMAL 相同的注释:长时间保持此级别的活动状态将大大降低默认 1MB 文件大小的历史记录深度,增大 TraceFileSizeMb 值可能会有用。

MINIMALVERBOSE 级别在失败时不提供其他 错误 详细信息,仅针对与 SQL 编写器活动相关的每个低级别操作提供其他 进度 详细信息。

后续步骤