Registro em log do Gravador VSS do SQL Server

  • Artigo

Aplica-se a:SQL Server

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 de Gravador de SQL dedicado. Para obter mais informações, consulte SQL Server Fazer backup de aplicativos – VSS (Serviço de Cópias de Sombra de Volume) e Gravador de SQL.

O serviço relataria erros de execução aos Logs de Eventos de Aplicativo 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 SQL Server 2019 (15.x), não havia nenhum log de atividades dedicado, o que tornava as investigações contra SQL Server como participante em operações vss desafiadoras.

Este artigo descreve o novo log introduzido por 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 SQL Server 2017 (14.x) CU (Atualização Cumulativa) 27.

Visão geral

As principais características do log do SQLWriter 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 SQL Server, ele tem uma única instância em um sistema e sua versão principal será a mesma que a versão principal mais alta de qualquer instância SQL Server instalada. Por exemplo, se SQL Server 2016 (13.x) SP2 e SQL Server 2019 (15.x) estiverem instalados no mesmo sistema, o binário gravador do SQL será aquele fornecido pelo SQL Server 2019 (15.x) e atenderá a todas as instâncias em execução de todas as versões principais (mesmo que seu diretório base permaneça em \90). As instâncias e versões locais se beneficiarão do novo rastreamento SQL Server 2019 (15.x) descrito aqui. Isso também implica que apenas atualizações cumulativas 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 SQL Server 2019 (15.x) CU 4. Versões anteriores 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 ainda registrará entradas detalhadas. Você pode confirmar se as operações do VSS estão ocorrendo e interagindo com êxito com o Gravador do SQL. É uma melhoria que oferece uma maneira fácil interna de estabelecer esses detalhes em SQL Server nível de instância.

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

Se uma falha de operação do VSS envolver SQL Server, o SqlWriterLogger se tornará um local importante para verificar se há informações.

Observação

Essa nova infraestrutura de registro em log complementa o relatório de erros existente para SQL Server, ela não a substitui. Portanto, em caso de erro, o Log de Eventos de Aplicativo do Windows continua sendo o primeiro lugar a ser verificado (filtragem em Fontes como "SQLWRITER" e "VSS"). SqlWriterLogger.txt forneceria 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 de Serviço Gravador do SQL (pode até ser registrada duas vezes por início de serviço).

Em ordem de aparência, podemos ver as seguintes informações:

  • Um carimbo de data/hora (data + hora) na hora do servidor local e o ThreadId originando a entrada para cada linha.
  • A ProcessId do processo SQLWriter que está sendo iniciado.
  • O fato de o serviço ter começado no modo 'normal' (não está em execução como WIDWriter') ou no modo Banco de Dados Interno do Windows.
  • A versão dos binários do Gravador do SQL.
  • Todos os parâmetros definidos pelo SqlWriterConfig.ini arquivo:
    • 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 acontecer, que neste exemplo é de 1 MB
    • A opção de forçar o ForceFlush a cada atualização para o arquivo de log versus uma abordagem mais descontraída/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 SQL Server (em execução), juntamente com o nome da instância, a versão principal e a Edição.
  • A indicação de que não tentamos listar "Instâncias de Usuário" – um recurso de SQL Server específico também conhecido como LocalDB e normalmente não envolvido em servidores de banco de dados corporativos.

Backup do VSS no modo de componente bem-sucedido

[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 aparência, podemos ver as seguintes informações:

  • Uma seção OnIdentify completa, que, como já indicado, geralmente leva a um backup.
  • Menção de todas as fases principais do backup do VSS, com o padrão "Inserindo o 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
    • (ID sendo o ThreadId que está fazendo o log para essa tentativa de backup no SQLWriter)
  • A API de backup do VSS selecionada pelo solicitante do VSS, "componente" ou "não componente/volume"
  • A contagem 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 encontrado (ou não encontrado) na instância do SQL Server à qual foi associado 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, que nomeia, torna-o um "evento de fechamento" útil: OnBackupComplete.

Essas entradas fornecem detalhes sobre as operações do VSS que antes eram difíceis de estabelecer rapidamente e exigiam rastreamento avançado para fazer isso. Um bom exemplo é o modo "Componente" ou "Não componente" de qualquer solicitação de backup do VSS. Com o SQL Server 2019 (15.x) do Gravador do SQL, 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 rasgado

Para ilustrar a instrução anterior de que o registro em log do Gravador do SQL complementa a arquitetura do Log de Eventos, vamos examinar as entradas associadas a uma situação de falha conhecida: um banco de dados rasgado. Esse cenário pode ocorrer quando um backup do VSS tenta criar um conjunto de instantâneos de volumes que incluem apenas 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.

De SqlWriterLogger.txt vemos que ocorreu uma falha, no entanto, os únicos detalhes que temos sobre a falha é o 0x80780002 HResult. Esse valor é difícil de interpretar sem as referências de código de erro. No entanto , ele identifica a situação do banco de dados interrompida.

Exibir log de eventos

Agora, vamos verificar o conteúdo dos Logs de Eventos de 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 nos Logs de Eventos, usando sua nomenclatura (o VSS gerencia 'componentes', que são 'bancos de dados' no contexto de 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 em si aqui. 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 log do Gravador do SQL

É possível configurar o registro em log do Gravador do SQL editando o arquivo de texto SqlWriterConfig.ini. O arquivo em si 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.iniou use um editor de texto que pode solicitar elevação conforme necessário ao salvar o arquivo.

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

Parâmetro Opções Descrição
Habilitar Log – TRUE (padrão)
-FALSE		 Permite que o usuário desabilite todo o novo recurso de registro em log, no caso improvável de que seja 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)
-MÍNIMO
-VERBOSE		 O detalhamento do registro em log. Mais informações estão em Detalhes do TraceLevel.
TraceFileSizeMb 1 MB (padrão) O tamanho máximo do arquivo antes da substituição. O arquivo .txt usa a codificação UTF-8 e consome 2 bytes por caractere. Aumentar esse valor é válido, por exemplo, com atividade intensa do VSS, retenção de longos períodos de entradas de log ou se valores não padrão TraceLevel estiverem habilitados por longas durações. O valor padrão de 1 MB deve fornecer um amplo histórico para a maioria das situações.
ForceFlush -VERDADE
- FALSE (padrão)		 Definir essa opção TRUE como só seria útil nas raras circunstâncias em que o serviço Gravador do SQL falharia 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

A reinicialização do Gravador do SQL é extremamente rápida e pode ser feita à vontade, pois o Gravador do SQL não retém nenhuma informação com estado nem tem nenhuma atividade entre chamadas 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 SqlWriterConfig.ini arquivo lista os seguintes níveis:

Nível Detalhe
DEFAULT Os parâmetros de detalhamento 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 DEFAULT modo 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 de 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, esse nível relata os mesmos eventos que MINIMAL, mas prefixa cada entrada com descritores de métodos e objeto de código-fonte. 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.

MINIMAL os níveis 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