Registro em log do Gravador VSS do SQL Server

  • Artigo

Aplica-se a: SQL Server

O SQL Server pode estar envolvido em operações de backup e restauração do VSS (Serviço de Cópias de Sombra de Volume) por meio de seu serviço dedicado do Gravador do SQL. Para obter mais informações, consulte Aplicativos de backup do SQL Server – VSS (Serviço de Cópias de Sombra de Volume) e Gravador do SQL.

O serviço relataria erros de execução para logs de eventos de aplicativos do Windows com um evento Source (ou ProviderName no contexto do PowerShell ou XML) de valor SQLWRITER, como você pode ver no exemplo mais adiante neste artigo. Antes do SQL Server 2019 (15.x), não havia nenhum log de atividades dedicado, o que tornava desafiadoras as investigações contra o SQL Server como participante de operações do VSS.

Este artigo descreve o novo log introduzido pelo SQL Server 2019 (15.x) para melhorar a visibilidade nas operações do Gravador do SQL. Essa funcionalidade também foi disponibilizada no SQL Server 2016 (13.x) Service Pack 3 e no SQL Server 2017 (14.x) Atualização Cumulativa (CU) 27.

Visão geral

As principais características do log do Gravador do SQL do SQL Server 2019 (15.x) são:

  • Ele fica ativado por padrão
  • Ele está em todo o sistema (ele rastreia a atividade do Gravador do SQL em todas as instâncias do SQL Server em execução no servidor)
  • Ele é baseado em texto
  • Seu diretório de trabalho é C:\Program Files\Microsoft SQL Server\90\Shared
  • Dentro desse diretório:
    • O registro em log ocorre no arquivo SqlWriterLogger.txt
    • Esse arquivo é renomeado para SqlWriterLogger1.txt ao atingir um tamanho máximo (por padrão, 1 MB), com o registro em log continuando no SqlWriterLogger.txt principal.
    • Há apenas um arquivo de substituição, portanto, a segunda sobreposição substitui o SqlWriterLogger1.txt existente.
    • Os parâmetros são gerenciados pelo arquivo SqlWriterConfig.ini

Como o Gravador do SQL é um componente compartilhado do SQL Server, ele tem uma instância em um sistema e sua versão principal será a mesma que a maior versão principal de qualquer instância do SQL Server instalada. Por exemplo, se instâncias do SQL Server 2016 (13.x) SP2 e do SQL Server 2019 (15.x) forem instaladas no mesmo sistema, o binário do Gravador do SQL será fornecido pelo SQL Server 2019 (15.x) e fará a manutenção de todas as instâncias em execução de todas as versões principais (embora o diretório base permaneça abaixo de \90). As instâncias e versões locais se beneficiarão do novo rastreamento do SQL Server 2019 (15.x) descrito aqui. Isso também implica que apenas atualizações cumulativas do SQL Server 2019 (15.x) atualizarão binários do Gravador do SQL nessa situação.

Observação

Os parágrafos a seguir descrevem a situação começando com o SQL Server 2019 (15.x) CU 4. As versões anteriores do SQL Server 2019 (15.x) não terão a mesma quantidade de informações no arquivo de log nas configurações padrão.

Operações básicas

Você pode se beneficiar do novo registro em log sem qualquer alteração manual. É possível abrir ou obter uma cópia do arquivo de log principal SqlWriterLogger.txt em C:\Program Files\Microsoft SQL Server\90\Shared\. O arquivo refletirá todos os eventos do VSS que atingem o Gravador do SQL, que seria principalmente:

  • Eventos OnIdentify, conforme disparado pelo comando vssadmin list writers
  • Eventos de backup
  • Eventos de restauração

Ou seja, mesmo que essas operações ocorram com êxito, o arquivo de log registrará as entradas detalhadas. Você pode confirmar se as operações VSS estão ocorrendo e interagindo com êxito com o Gravador do SQL. É uma melhoria que oferece uma maneira fácil e integrada de estabelecer esses detalhes no nível da instância do SQL Server.

Além disso, os eventos de inicialização do Serviço Gravador do SQL também serão registrados e relatarão parâmetros de log ativos.

Obviamente, se houver uma falha de operação do VSS que envolva o SQL Server, o SqlWriterLogger se tornará um lugar importante para verificar se há informações.

Observação

Essa nova infraestrutura de log complementa a existente para relatórios de erros do SQL Server, mas não a substitui. Portanto, em caso de erro, o Log de Eventos do Aplicativo do Windows serão os primeiros a verificar (filtragem em origens como "SQLWRITER" e "VSS"). SqlWriterLogger.txt fornece informações adicionais para esse conjunto inicial.

Examinar entradas de log típicas

As exportações a seguir foram feitas na configuração padrão.

Início do serviço

[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] ****************************************************************

A entrada acima será observada para cada início do serviço Gravador do SQL (pode até ser registrada duas vezes por início do serviço).

Em ordem de exibição, podemos ver as seguintes informações:

  • Um carimbo de data/hora (data + hora) na hora do servidor local e o ThreadId que origina a entrada para cada linha.
  • A ProcessId do processo SQLWriter que está sendo iniciado.
  • O fato de o serviço ter iniciado no modo 'normal' ('não executado como WIDWriter') ou no modo Banco de Banco de Dados Interno do Windows.
  • A versão dos binários do Gravador do SQL.
  • Todos os parâmetros definidos pelo arquivo SqlWriterConfig.ini:
    • O caminho de destino do arquivo de log ativo
    • O nível de detalhes do rastreamento, que neste exemplo é DEFAULT
    • O tamanho máximo do arquivo antes da substituição, que neste exemplo é 1 MB
    • A opção ForceFlush de cada atualização do arquivo de log versus uma abordagem mais relaxada/armazenada em buffer, que é False por padrão.
  • Um lembrete de que o registro em log é a hora local junto com a diferença UTC dessa hora local.

Evento 'OnIdentify' do VSS

[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 é uma operação comum do VSS. Ela é disparada pelo comando vssadmin list writers. A maioria dos solicitantes do VSS iniciaria qualquer operação de backup ou restauração do VSS com um evento OnIdentify.

Anteriormente, somente o rastreamento do criador de perfil ativo permitia que o DBA detectasse esse evento. Com o novo recurso de registro em log, cada evento levará à entrada acima.

Em ordem de exibição, veja que as seguintes informações são registradas:

  • Uma menção explícita do evento OnIdentify do VSS.
  • Uma lista de todas as instâncias ativas (em execução) do SQL Server, juntamente com o nome da instância, a versão principal e a Edição.
  • A indicação de que não tentamos listar as "Instâncias de Usuário" – um recurso específico do SQL Server também conhecido como LocalDB e normalmente não envolvido em servidores de banco de dados empresariais.

Backup bem-sucedido do VSS no modo de componente

[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.

Esse evento leva a um conjunto mais considerável de entradas. Em ordem de exibição, podemos ver as seguintes informações:

  • Uma seção OnIdentify completa, que, como já indicado, geralmente leva a um backup.
  • Menção a cada fase principal de backup do VSS, com o padrão "Entrando no Gravador do SQL xxxx".
    • O primeiro será Entering SQL Writer OnPrepareBackup.
  • Uma entrada evidente que indica o início de um backup do SQL do VSS
    • (A ID é o ThreadId que está fazendo o registro em log dessa tentativa de backup no SQLWriter)
  • A API de backup do VSS selecionada pelo solicitante do VSS, "componente" ou "não componente/volume"
  • O número de bancos de dados incluídos na lista de componentes enviada pelo solicitante do VSS, aqui, um único BD (1).
  • Uma confirmação de que cada nome de banco de dados fornecido pelo solicitante (aqui, db_on_G) foi encontrada (ou não encontrada) na instância do SQL Server à qual ela foi associada pelo solicitante do VSS (aqui, a instância padrão é GF19).
  • A variante de backup do VSS solicitada. Geralmente VSS_BT_FULL ou VSS_BT_COPY. Confira a enumeração VSS_BACKUP_TYPE.
  • Outra seção OnIdentify
  • Mais entradas identificando as fases principais do backup do VSS (OnFreeze, OnThaw, OnPostSnapshot)
  • Uma seção OnIdentify final.
  • Um relatório de fase final do VSS, cujos nome o torna um "evento de encerramento" útil: OnBackupComplete.

Essas entradas dão detalhes sobre as operações do VSS que antes eram difíceis de estabelecer rapidamente e exigiam um rastreamento avançado para serem realizadas. Um bom exemplo é o modo "Componente" ou "Não componente" de qualquer solicitação de backup do VSS. Com o Gravador do SQL do SQL Server 2019 (15.x), elas são registradas para cada solicitação do VSS por padrão e são facilmente acessíveis.

Situação de falha: banco de dados interrompido

Para ilustrar a declaração anterior de que o log do Gravador do SQL complementa a arquitetura do log de eventos, vamos examinar as entradas associadas a uma situação de falha bem conhecida: um banco de dados rasgado. Esse cenário pode ocorrer quando um backup do VSS tenta criar um conjunto de volumes de instantâneo que inclua somente um conjunto parcial de arquivos de um determinado banco de dados. O Gravador do SQL o bloqueará de acordo com as convenções do VSS.

Esta extração é o conteúdo de SqlWriterLogger.txt para a operação:

[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.

Em SqlWriterLogger.txt, vemos que ocorreu uma falha, no entanto, o único detalhe que temos sobre a falha é o 0x80780002 HResult. Esse valor é difícil de interpretar sem as referências de código de erro. Mas ele identifica a situação de banco de dados interrompido.

Exibir log de eventos

Agora, vamos verificar o conteúdo dos Logs de Eventos do Aplicativo do 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.

O evento fornece uma mensagem formatada amigável e completa explicando a situação.

A estrutura VSS do sistema operacional também relatará o problema em Logs de Eventos, usando sua nomenclatura (o VSS gerencia "componentes", que são "bancos de dados" no contexto do 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

O Log de Eventos é uma fonte melhor de informações sobre o erro. No entanto, o conteúdo do SqlWriterLogger dá detalhes sobre a solicitação de backup (um VSS_BT_FULL, solicitação de backup do VSS não componente que falhou durante a fase OnPrepareSnapshot do Gravador do SQL). Qualquer investigação de erros do VSS envolvendo o SQL Server, portanto, deve coletar e examinar ambas as fontes.

Modificar parâmetros de registro em log do Gravador do SQL

É possível configurar o registro em log do Gravador do SQL editando o arquivo de texto SqlWriterConfig.ini. O próprio arquivo contém uma descrição embutida rápida dos parâmetros disponíveis, que examinaremos abaixo.

Observação

O arquivo .ini está em uma pasta protegida pelo Windows (Arquivos de Programas). Como tal, requer privilégios elevados de administrador para edição. Clicar duas vezes no Explorer abre o Bloco de Notas sem elevação: ele permitirá que o usuário leia o conteúdo, mas as tentativas de salvar qualquer alteração falharão. Inicie o Bloco de Notas como administrador e, em seguida, abra SqlWriterConfig.ini ou use um editor de texto que seja capaz de solicitar elevação, conforme necessário, na hora de salvar o arquivo.

Ao duplicar os comentários do arquivo SqlWriterConfig.ini:

Parâmetro Opções Descrição
EnableLogging - TRUE (padrão)
- FALSE		 Permite que o usuário desabilite todo o novo recurso de registro em log, no caso improvável de ser necessário.
TraceFile C:\Program Files\Microsoft SQL Server\90\Shared\SqlWriterLog.txt Permite que o usuário altere o caminho e o nome do arquivo de rastreamento. Não é recomendável alterá-lo como o padrão e o local conhecido torna fácil ir diretamente para o lugar certo em qualquer SQL Server.
TraceLevel - DEFAULT (padrão)
- MINIMAL
- VERBOSE		 O detalhamento do registro em log. Mais informações estão em detalhes de TraceLevel.
TraceFileSizeMb 1 MB (padrão) O tamanho máximo do arquivo antes da sobreposição. O arquivo .txt usa a codificação UTF-8 e consome 2 bytes por caractere. É válido aumentar esse valor para instâncias com atividade intensa do VSS, quando é necessário reter longos períodos de entradas de log ou se valores TraceLevel não padrão estiverem habilitados por longas durações. O valor padrão de 1 MB padrão deve fornecer um amplo histórico para a maioria das situações.
ForceFlush - TRUE
- FALSE (padrão)		 Definir esta opção como TRUE só seria útil nas raras circunstâncias em que o serviço Gravador do SQL travasse antes de ter a chance de liberar suas últimas entradas de log; caso contrário, mantenha o valor padrão.

Aplique as alterações

Qualquer alteração nas configurações requer uma reinicialização do Serviço Gravador do SQL para ser ativada.

Dica

Reiniciar o Gravador do SQL é extremamente rápido e pode ser feito quando você quiser, pois o Gravador do SQL não retém nenhuma informação com estado nem tem nenhuma atividade entre as chamadas do VSS. A única precaução é evitar uma reinicialização enquanto uma operação do VSS (backup, restauração) está ocorrendo.

O Gravador do SQL relatará parâmetros ativos no arquivo de log na (re)inicialização, como pode ser visto no trecho da amostra de Inicialização do Serviço.

Detalhes de TraceLevel

O arquivo SqlWriterConfig.ini lista os seguintes níveis:

Nível Detalhe
DEFAULT Os parâmetros de verbosidade padrão devem ser adequados para a maioria das necessidades: consulte a seção Revisão de entradas de log típicas para observar o que já é gerado por padrão. Além dos erros, as chamadas do VSS bem-sucedidas, juntamente com os metadados do VSS, serão registradas por padrão.
MINIMAL Esse nível manterá a formatação do modo DEFAULT e seus eventos. Ele também vai gerar a saída em muitos locais principais do código. Mais notavelmente, ele registrará em log todos os arquivos e iterações de banco de dados que são comuns na lógica do Gravador do SQL. Ele pode aumentar o número de entradas registradas para cada operação do VSS (incluindo o evento mundano OnIdentify) por uma margem grande, especialmente em instâncias que hospedam um grande número de bancos de dados: cada arquivo físico de cada banco de dados individual pode ser relatado mais de uma vez ao longo de um backup do VSS. Esse nível só ajuda a dar uma ideia mais precisa da posição lógica da lógica do Gravador do SQL no momento de uma falha. Também é conveniente para fins de exploração. Não é útil mantê-lo ativo além das investigações momentâneas, pois o nível de detalhes reduzirá consideravelmente a profundidade do histórico do tamanho padrão do arquivo de 1 MB. Aumentar o valor TraceFileSizeMb pode ser importante.
VERBOSE Atualmente este nível relata os mesmos eventos que MINIMAL, mas prefixa cada entrada com objetos de código-fonte e descritores de métodos. Ele torna a saída mais ampla (maior em tamanho que em Mínimo) e menos acessível. As informações adicionadas não seriam úteis fora das interações com os Serviços de Suporte da Microsoft. O mesmo comentário que MINIMAL seria aplicado: manter esse nível ativo por muito tempo reduzirá consideravelmente a profundidade do histórico do tamanho padrão do arquivo de 1 MB e aumentar o valor TraceFileSizeMb poderá ser importante.

Os níveis MINIMAL e VERBOSE não fornecem detalhes adicionais de erro em caso de falha, apenas detalhes adicionais de progresso para cada operação de baixo nível relacionada às atividades do Gravador do SQL.

Próximas etapas