Registrazione eventi di SQL Server VSS Writer

Si applica a:SQL Server

SQL Server può essere coinvolto nelle operazioni di backup e ripristino di VSS (Volume Shadow Copy Service) tramite il suo servizio SQL Writer dedicato. Per ulteriori informazioni, vedere Applicazioni di backup di SQL Server - Servizio Copia Shadow del volume (VSS) e SQL Writer.

Il servizio segnala errori di esecuzione ai log eventi dell'applicazione Windows con un evento Source (o ProviderName nel contesto PowerShell o XML) di valore SQLWRITER, come si può vedere nell'esempio riportato più avanti in questo articolo. Prima di SQL Server 2019 (15.x), non esisteva un registro attività dedicato, il che rendeva difficili le indagini su SQL Server come partecipante alle operazioni VSS.

Questo articolo descrive il nuovo log introdotto da SQL Server 2019 (15.x) per offrire una migliore visibilità sulle operazioni SQLWriter. Questa funzionalità è stata resa disponibile anche su SQL Server 2016 (13.x) Service Pack 3 e SQL Server 2017 (14.x) Aggiornamento cumulativo (CU) 27.

Panoramica

Le caratteristiche principali del log SQLWriter di SQL Server 2019 (15.x) sono:

  • È attivo per impostazione predefinita
  • È a livello di sistema (monitorerà l'attività di SQL Writer per tutte le istanze di SQL Server in esecuzione sul server)
  • È basato su testo
  • La directory di lavoro è C:\Program Files\Microsoft SQL Server\90\Shared
  • All'interno di tale directory:
    • La creazione del log avviene nel file SqlWriterLogger.txt
    • Questo file viene rinominato in SqlWriterLogger1.txt quando si raggiunge una dimensione massima (per impostazione predefinita 1 MB), e il log continua nel SqlWriterLogger.txt principale.
    • Esiste un solo file di rollover, quindi il secondo rollover sovrascriverebbe il file esistente SqlWriterLogger1.txt.
    • I parametri vengono gestiti dal file SqlWriterConfig.ini

Poiché SQL Writer è un componente condiviso di SQL Server, dispone di una singola istanza in un sistema e la versione principale sarà la stessa della versione principale più recente di qualsiasi istanza di SQL Server installata. Ad esempio, se SQL Server 2016 (13.x) SP2 e SQL Server 2019 (15.x) sono installati nello stesso sistema, il file binario del writer SQL sarà quello fornito da SQL Server 2019 (15.x) e servirà le istanze in esecuzione di tutte le versioni principali (anche se la relativa home directory rimane in \90). Le istanze e le versioni locali trarranno vantaggio dalla nuova traccia di SQL Server 2019 (15.x) descritta qui. Ciò implica anche che in questa situazione solo gli aggiornamenti cumulativi di SQL Server 2019 (15.x) aggiorneranno i file binari del writer SQL.

Nota

I paragrafi seguenti descrivono la situazione a partire da SQL Server 2019 (15.x) CU 4. Le versioni precedenti di SQL Server 2019 (15.x) non avranno la stessa quantità di informazioni nel file di log nelle impostazioni predefinite.

Operazioni di base

È possibile usufruire del nuovo sistema di logging senza dover apportare alcuna modifica manuale. È possibile aprire o ottenere una copia del file di log principale SqlWriterLogger.txt in C:\Program Files\Microsoft SQL Server\90\Shared\. Il file riporterà tutti gli eventi VSS che raggiungono il writer SQL, che sarebbero principalmente:

  • OnIdentify eventi, come attivati dal comando vssadmin list writers
  • Eventi di backup
  • Eventi di ripristino

Ciò significa che, anche se queste operazioni vengono eseguite correttamente, il file di log registrerà comunque voci dettagliate. È possibile verificare che le operazioni VSS si verifichino e interagiscono correttamente con il writer SQL. Si tratta di un miglioramento che offre un modo predefinito semplice per stabilire questi dettagli a livello di istanza di SQL Server.

Verranno inoltre registrati gli eventi di avvio del servizio SQLWriter e verranno riportati i parametri di log attivi.

Se un errore dell'operazione VSS coinvolge SQL Server, SqlWriterLogger diventa un luogo importante per verificare la presenza di informazioni.

Nota

Questa nuova infrastruttura di log integra la segnalazione degli errori esistente per SQL Server, ma non la sostituisce. Pertanto, in caso di errore, il log eventi dell'applicazione di Windows rimane il primo luogo in cui controllare (filtrando le origini come "SQLWRITER" e "VSS"). SqlWriterLogger.txt fornirebbe informazioni aggiuntive a questo insieme iniziale.

Revisione delle voci di log tipiche

Le esportazioni seguenti sono state effettuate con l'impostazione predefinita.

Avvio del servizio

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

La voce riportata sopra sarà presente a ogni avvio del servizio SQL Writer (può persino essere registrata due volte per ogni avvio del servizio).

In ordine di apparizione, è possibile visualizzare le informazioni seguenti:

  • Una marca temporale (data + ora) nell'ora locale del server e il ThreadId da cui ha origine la voce per ogni riga.
  • Il ProcessId del processo SQLWriter in fase di avvio.
  • Il fatto che il servizio sia stato avviato in modalità "normale" (“non in esecuzione come WIDWriter”) o in modalità Database interno di Windows.
  • La versione dei binari di SQL Writer.
  • Tutti i parametri impostati dal file SqlWriterConfig.ini:
    • Il percorso di destinazione del file di log attivo
    • Livello di dettaglio della traccia, che in questo esempio è DEFAULT
    • La dimensione massima del file prima che avvenga il rollover, che in questo esempio è di 1 MB
    • L'opzione per forzare il flush a ogni singolo aggiornamento del file di log, rispetto a un approccio più permissivo/con buffer, che per impostazione predefinita è False.
  • Ti ricordiamo che la registrazione avviene in ora locale insieme al relativo offset UTC.

Evento 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 è una comune operazione VSS. Viene attivata dal comando vssadmin list writers. La maggior parte dei richiedenti VSS avvierebbe qualsiasi operazione di backup o ripristino VSS tramite un evento OnIdentify.

In precedenza, solo la traccia del profiler attivo avrebbe consentito all'amministratore del database di rilevare tale evento. Con la nuova funzionalità di log, ogni evento porterà alla voce precedente.

In ordine di apparizione, è possibile visualizzare le informazioni seguenti registrate:

  • Una menzione esplicita dell'evento VSS OnIdentify.
  • Un elenco di tutte le istanze di SQL Server attive (in esecuzione), insieme al nome dell'istanza, alla versione principale e all'edizione.
  • L'indicazione del fatto che non si è tentato di elencare "Istanze utente", una funzionalità specifica di SQL Server nota anche come Local DB, che in genere non è coinvolta nei server di database aziendali.

Backup VSS in modalità componente completato

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

Questo evento porta a un insieme di voci più ampio. In ordine di apparizione, è possibile visualizzare le informazioni seguenti:

  • Una sezione completa OnIdentify, che, come già indicato, spesso precede un backup.
  • Menzione di tutte le fasi principali VSS del backup, con il pattern "Entering SQL Writer xxxx".
    • La prima qui è Entering SQL Writer OnPrepareBackup.
  • Una voce evidente che indica l'inizio di un backup SQL di VSS
    • (ID che rappresenta il ThreadId che registra quel tentativo di backup in SQLWriter)
  • L'API di backup VSS selezionata dal richiedente VSS, "componente" o "non componente/volume"
  • Il numero di database inclusi nell'elenco dei componenti inviato dal richiedente VSS, in questo caso un singolo database (1).
  • La conferma che ogni nome di database fornito dal richiedente (qui “db_on_G”) viene trovato (o non trovato) nell'istanza di SQL Server a cui è stato associato dal richiedente VSS (qui l'istanza predefinita “GF19”).
  • Il tipo di backup VSS richiesto. In genere VSS_BT_FULL o VSS_BT_COPY. Vedere l'enumerazione VSS_BACKUP_TYPE.
  • Un'altra OnIdentify sezione
  • Altre voci che identificano le fasi principali del backup VSS (OnFreeze, OnThaw, OnPostSnapshot)
  • Una sezione finale OnIdentify.
  • Un report finale della fase VSS, che viene definito un utile "evento di chiusura": OnBackupComplete

Queste voci forniscono dettagli sulle operazioni VSS che in precedenza erano difficili da identificare rapidamente e richiedevano un tracciamento avanzato per farlo. Un esempio emblematico è la modalità "componente" o "non componente" di qualsiasi richiesta di backup VSS. Con SQL Writer di SQL Server 2019 (15.x), vengono registrati per ogni richiesta VSS per impostazione predefinita e sono facilmente accessibili.

Situazione di errore: database incompleto

Per illustrare l'istruzione precedente per la quale il log del writer SQL integra l'architettura del registro eventi, verranno esaminate le voci associate a una situazione di errore nota: un database incompleto. Questo scenario può verificarsi quando un backup VSS tenta di creare un set di snapshot di volumi che includono solo un set parziale di file di un determinato database. Il writer SQL lo bloccherà in base alle convenzioni VSS.

Questo estratto è il contenuto di SqlWriterLogger.txt per l'operazione:

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

Da SqlWriterLogger.txt si noterà che si è verificato un errore, ma gli unici dettagli presenti in caso di errore sono 0x80780002 HResult. Questo valore è difficile da interpretare senza i riferimenti al codice di errore. Identifica però la situazione di database danneggiato.

Visualizzare il registro eventi

A questo punto è possibile controllare il contenuto dei log eventi dell’applicazione di 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.

L'evento fornisce un messaggio formattato completo e semplice da interpretare che spiega la situazione.

Il framework VSS del sistema operativo segnala il problema anche nei registri eventi, usando la relativa nomenclatura (VSS gestisce i "componenti", ovvero i "database" nel contesto di 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

Il registro eventi in questo caso è una fonte migliore di informazioni sull'errore stesso. Tuttavia, il contenuto di SqlWriterLogger fornisce informazioni dettagliate sulla richiesta di backup (una richiesta VSS_BT_FULL di backup VSS non componente che ha avuto esito negativo durante la fase OnPrepareSnapshot del writer SQL). Qualsiasi indagine sugli errori VSS che coinvolgono SQL Server deve quindi raccogliere ed esaminare entrambe le fonti.

Modificare i parametri di registrazione di SQL Writer

La registrazione di SQL Writer può essere configurata modificando il file di testo SqlWriterConfig.ini. Il file stesso contiene una rapida descrizione incorporata dei parametri disponibili, che verranno esaminati di seguito.

Nota

Il file .ini si trova in una cartella protetta di Windows (Programmi). Pertanto, richiede privilegi di amministratore elevati per essere modificato. Un doppio clic in Esplora file aprirà Blocco note senza privilegi elevati: consentirà all'utente di leggere il contenuto, ma qualsiasi tentativo di salvare le modifiche non riuscirà. Avviare Blocco note come amministratore, quindi aprire SqlWriterConfig.ini o usare un editor di testo in grado di richiedere l'elevazione dei privilegi in base alle esigenze durante il salvataggio del file.

Duplicazione dei commenti del file SqlWriterConfig.ini qui:

Parametro Opzioni Descrizione
EnableLogging - TRUE (impostazione predefinita)
- FALSO		 Consente all'utente di disabilitare l'intera nuova funzionalità di log, nel caso improbabile che sia necessario.
TraceFile C:\Program Files\Microsoft SQL Server\90\Shared\SqlWriterLog.txt Consente all'utente di modificare il percorso e il nome file del file di traccia. Non è consigliabile modificarlo, poiché il percorso noto predefinito semplifica l'accesso diretto alla posizione desiderata di qualsiasi SQL Server.
TraceLevel - DEFAULT (impostazione predefinita)
-MINIMO
- VERBOSE		 La verbosità della registrazione. Ulteriori informazioni sono disponibili in i dettagli di TraceLevel.
TraceFileSizeMb 1 MB (valore predefinito) Dimensione massima del file prima del rollover. Il file .txt usa la codifica UTF-8 e utilizza 2 byte per carattere. L'aumento di questo valore è valido, ad esempio, in caso di un'intensa attività VSS, mantenendo lunghi periodi di voci di log, o se i valori non predefiniti TraceLevel sono abilitati per durate lunghe. Il valore predefinito di 1 MB deve fornire un'ampia cronologia della maggior parte delle situazioni.
ForceFlush -VERO
- FALSE (impostazione predefinita)		 L'impostazione di questa opzione su TRUE sarebbe utile solo nelle rare circostanze in cui il servizio writer SQL si arrestasse in modo anomalo prima di aver potuto scaricare le ultime voci di log; in caso contrario, mantenere il valore predefinito.

Applica modifiche

Per attivare qualsiasi modifica alle impostazioni è necessario riavviare il servizio writer SQL.

Suggerimento

Il riavvio di SQL Writer è estremamente rapido e può essere eseguito in qualsiasi momento, poiché SQL Writer non mantiene alcuna informazione sullo stato né svolge alcuna attività tra una chiamata VSS e l’altra. L'unica precauzione consiste nell'evitare un riavvio durante l'esecuzione di un'operazione VSS (backup, ripristino).

Il writer SQL segnala i parametri attivi nel file di log al momento del (ri)avvio, come si può vedere nell'estratto dell’esempio Avvio del servizio.

Dettagli di TraceLevel

Il file SqlWriterConfig.ini elenca i livelli seguenti:

Livello Dettagli
DEFAULT I parametri di dettaglio predefiniti devono essere adeguati alla maggior parte delle esigenze: fare riferimento alla sezione Verifica delle voci di log tipiche per osservare ciò che è già generato per impostazione predefinita. Oltre agli errori, le chiamate VSS riuscite, insieme ai metadati VSS, verranno registrate per impostazione predefinita.
MINIMAL Questo livello manterrà la formattazione della modalità DEFAULT e i relativi eventi. Genererà anche l'output in molte posizioni chiave del codice. In particolare, registrerà tutti i file e le iterazioni di database comuni alla logica SQLWriter. Può aumentare notevolmente il numero di voci registrate per ogni operazione VSS (incluso il banale evento OnIdentify), soprattutto sulle istanze che ospitano un numero elevato di database: ogni singolo file fisico di ogni singolo database può essere segnalato più di una volta nel corso di un backup VSS. Questo livello consente solo di dare un'idea più precisa della posizione logica della logica del writer SQL quando si verifica un errore. È utile anche per scopi di indagine. Non è utile mantenerlo attivo oltre le indagini momentanee, perché il livello dei dettagli ridurrà notevolmente la profondità della cronologia del file predefinito di 1 MB. L'aumento del valore TraceFileSizeMb può essere rilevante.
VERBOSE Attualmente questo livello riporta gli stessi eventi di MINIMAL, ma antepone a ogni voce i descrittori dei metodi e del codice sorgente. Rende l'output più ampio (dimensioni maggiori rispetto a Minimo) e meno leggibile. Le informazioni aggiunte non sarebbero utili al di fuori delle interazioni con i servizi del supporto tecnico Microsoft. Vale lo stesso commento di MINIMAL: mantenere attivo questo livello per una lunga durata ridurrà notevolmente la profondità della cronologia delle dimensioni predefinite del file di 1 MB, e l'aumento del valore TraceFileSizeMb potrebbe essere rilevante.

I livelli MINIMAL e VERBOSE non forniscono dettagli aggiuntivi sull’errore in caso di esito negativo, ma solo dettagli aggiuntivi sullo stato di avanzamento di ogni operazione di basso livello correlata alle attività del writer SQL.

Passaggi successivi

  • Last updated on