Partager via

SQL Server - Journalisation de l’enregistreur VSS Writer

  • Article

S’applique à : SQL Server

SQL Server peut être impliqué dans les opérations de sauvegarde et de restauration VSS (Service VSS) via son service SQL Writer dédié. Pour plus d’informations, consultez Applications de sauvegarde SQL Server - Service de cliché instantané des volumes (VSS) et enregistreur SQL Writer.

Le service signale des erreurs d’exécution aux journaux des événements de l’application Windows avec un événement Source (ou ProviderName dans le contexte PowerShell ou XML) de valeur SQLWRITER, comme vous pouvez le voir dans l’exemple plus loin dans cet article. Avant SQL Server 2019 (15.x), il n’y avait aucun journal d’activité dédié, ce qui rendait difficiles les investigations sur SQL Server en tant que participant dans les opérations VSS.

Cet article décrit le nouveau journal introduit par SQL Server 2019 (15.x) pour fournir une meilleure visibilité sur ses opérations sqlwriter. Cette fonctionnalité a également été mise à disposition dans SQL Server 2016 (13.x) Service Pack 3 et SQL Server 2017 (14.x) Mise à jour cumulative (CU) 27.

Vue d’ensemble

Les principales caractéristiques de la journalisation SQL Server 2019 (15.x) SQLWriter sont les suivantes :

  • L’option est activée par défaut
  • Elle est active à l’échelle du système (elle trace l’activité de l’enregistreur SQL Writer sur toutes les instances SQL Server s’exécutant sur le serveur)
  • Elle est basée sur du texte
  • Son répertoire de travail est C:\Program Files\Microsoft SQL Server\90\Shared
  • Dans ce répertoire :
    • La journalisation a lieu dans le fichier SqlWriterLogger.txt
    • Ce fichier est renommé SqlWriterLogger1.txt lorsqu’il atteint une taille maximale (par défaut, 1 Mo), et la journalisation continue dans le fichier SqlWriterLogger.txt principal.
    • Comme il n’y a qu’un seul fichier de substitution, la deuxième substitution remplace l’élément SqlWriterLogger1.txt existant.
    • Les paramètres sont gérés par fichier SqlWriterConfig.ini

L’enregistreur SQL Writer étant un composant partagé SQL Server, il dispose d’une instance unique sur un système et sa version principale est la même que la version principale la plus élevée d’une instance SQL Server installée. Par exemple, si des instances d SQL Server 2016 (13.x) SP2 et SQL Server 2019 (15.x) sont installées sur le même système, le fichier binaire de l’enregistreur SQL Writer sera celui fourni par SQL Server 2019 (15.x) et traitera toutes les instances en cours d’exécution de toutes les versions principales (même si son répertoire racine reste sous \90). Les versions et instances locales tirent parti du nouveau suivi SQL Server 2019 (15.x) décrit ici. Cela implique également que seules les mises à jour cumulatives de SQL Server 2019 (15.x) vont mettre à niveau les fichiers binaires de l’enregistreur SQL Writer dans cette situation.

Remarque

Les paragraphes suivants décrivent la situation commençant par SQL Server 2019 (15.x) CU 4. Les versions SQL Server 2019 (15.x) antérieures n’auront pas la même quantité d’informations dans le fichier journal sous les paramètres par défaut.

Opérations de base

Vous pouvez tirer parti de la nouvelle journalisation sans modification manuelle. Vous pouvez ouvrir ou obtenir une copie du fichier journal principal SqlWriterLogger.txt dans C:\Program Files\Microsoft SQL Server\90\Shared\. Le fichier reflète tous les événements VSS qui atteignent l’enregistreur SQL Writer, qui sont principalement :

  • Des événements OnIdentify, tels qu’ils sont déclenchés par la commande vssadmin list writers
  • Des événements de sauvegarde
  • Des événements de restauration

Autrement dit, même si ces opérations ont lieu, le fichier journal enregistre toujours les entrées détaillées. Vous pouvez confirmer que les opérations VSS sont en cours et que l’interaction avec l’enregistreur SQL Writer est réussie. Il s’agit d’une amélioration qui offre un moyen simple d’établir ces détails au niveau d’une instance SQL Server.

En outre, les événements de démarrage du service SQLWriter sont également enregistrés et signalent les paramètres de journalisation actifs.

En cas d’échec de l’opération VSS impliquant SQL Server, SqlWriterLogger devient un emplacement important pour vérifier toutes les informations.

Remarque

Cette nouvelle infrastructure de journalisation complète le rapport d’erreurs existant pour SQL Server, elle ne le remplace pas. Par conséquent, en cas d’erreur, le journal des événements de l’application de Windows reste le premier emplacement à vérifier (en filtrant sur des sources telles que « SQLWRITER » et « VSS »). SqlWriterLogger.txt fournit des informations supplémentaires à ce jeu initial.

Examen des entrées de journalisation typiques

Les exportations suivantes ont été apportées sous le paramètre par défaut.

Début du service

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

L’entrée ci-dessus est observée pour chaque démarrage du service de l’enregistreur SQL Writer (elle peut même être consignée deux fois par démarrage du service).

Dans l’ordre d’apparition, nous pouvons voir que les informations suivantes :

  • Un horodatage (date + heure) dans l’heure du serveur local, et le threadID à l’origine de l’entrée pour chaque ligne.
  • Le ProcessId du processus SQLWriter en cours de démarrage.
  • Le fait que le service a démarré en mode « normal » (« ne s’exécute pas en tant que WIDWriter ») ou en mode de base de données interne Windows
  • La version des fichiers binaires de l’enregistreur SQL Writer.
  • Tous les paramètres définis par le fichier SqlWriterConfig.ini :
    • Le chemin cible du fichier journal actif
    • Le niveau de détail du suivi, DEFAULT dans cet exemple
    • La taille maximale du fichier avant la substitution, 1 Mo dans cet exemple
    • L’option ForceFlush permettant de vider de force chaque mise à jour unique du fichier journal par rapport à une approche plus souple/mise en mémoire tampon, False par défaut.
  • Un rappel indiquant que la journalisation a l’heure locale et le décalage UTC de cette heure locale.

Événement « OnIdentify » 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 est une opération VSS courante. Elle est déclenchée par la commande vssadmin list writers. La plupart des demandeurs VSS démarrent toutes les opérations de sauvegarde ou de restauration VSS par un événement OnIdentify.

Auparavant, seul le suivi du profileur actif permettait à DBA de détecter de ce type d’événement. Avec la nouvelle fonctionnalité de journalisation, chaque événement entraîne l’entrée ci-dessus.

Dans l’ordre d’apparition, nous pouvons voir que les informations suivantes sont journalisées :

  • Une mention explicite de l’événement VSS OnIdentify.
  • La liste de toutes les instances SQL Server actives (en cours d’exécution), ainsi que leur nom d’instance, version principale et édition.
  • Indication que nous n’avons pas essayé de répertorier : « Instances utilisateur », une fonctionnalité SQL Server spécifique également connue sous le nom de LocalDB, qui n’est généralement pas impliquée sur les serveurs de base de données d’entreprise.

Sauvegarde VSS en mode composant réussie

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

Cet événement génère un ensemble d’entrées plus important. Dans l’ordre d’apparition, nous pouvons voir que les informations suivantes :

  • Une section OnIdentify complète, qui, comme indiqué, est souvent le fait d’une sauvegarde.
  • La mention de chaque phase VSS principale de la sauvegarde, avec le modèle « Entering SQL Writer xxxx ».
    • La première ici étant Entering SQL Writer OnPrepareBackup.
  • Une entrée visible indiquant le début d’une sauvegarde SQL VSS
    • (l’ID est le ThreadId qui procède à la journalisation de cette tentative de sauvegarde dans SQLWriter)
  • L’API de sauvegarde VSS sélectionnée par le demandeur VSS, « component » ou « non-component/volume »
  • Le nombre de bases de données incluses dans la liste de composants envoyée par le demandeur VSS, ici une seule base de données (1).
  • Une confirmation que chaque nom de base de données fourni par le demandeur (ici « db_on_G ») est trouvé (ou introuvable) sur l’instance SQL Server à laquelle il est associé par le demandeur VSS (ici l’instance par défaut « GF19 »).
  • La version de la sauvegarde VSS demandée. Généralement VSS_BT_FULL ou VSS_BT_COPY. Consultez l’énumération VSS_BACKUP_TYPE.
  • Une autre section OnIdentify
  • Plus d’entrées identifiant les principales phases de la sauvegarde VSS (OnFreeze, OnThaw, OnPostSnapshot)
  • Une section OnIdentify finale.
  • Un rapport final de la phase VSS, qui en fait un « événement de fermeture » utile : OnBackupComplete.

Ces entrées fournissent des détails sur les opérations VSS précédemment difficiles à répertorier rapidement et qui nécessitaient un suivi avancé pour ce faire. Un exemple est le mode « Component » ou « non-Component » d’une demande de sauvegarde VSS. Avec l’enregistreur SQL Writer SQL Server 2019 (15.x), ils sont enregistrés pour chaque requête VSS par défaut et sont facilement accessibles.

Situation d’échec : base de données endommagée

Pour illustrer l’instruction précédente dans laquelle la journalisation de l’enregistreur SQL Writer complète l’architecture du journal des événements, observons les entrées associées à une situation de défaillance bien connue : une base de données endommagée. Ce scénario peut se produire lorsqu’une sauvegarde VSS tente de créer un ensemble d’instantanés de volumes qui inclut uniquement un ensemble partiel de fichiers d’une base de données donnée. L’enregistreur SQL Writer le bloque conformément aux conventions VSS.

Cet extrait est le contenu de SqlWriterLogger.txt pour l’opération :

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

À partir de SqlWriterLogger.txt, nous voyons qu’une défaillance s’est produite, mais les seuls détails que nous avons en cas d’échec sont . Cette valeur est difficile à interpréter sans les références du code d’erreur. Toutefois, elle identifie la situation de la base de données endommagée.

Afficher le journal d’événements

Consultons maintenant le contenu des journaux des événements d’application 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’événement fournit un message mis en forme complet et convivial expliquant la situation.

Le cadre VSS du SE signale également le problème dans les journaux des événements, à l’aide de sa nomenclature (VSS gère les « composants », qui sont des « bases de données » dans le contexte 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

Le journal d’événements est une meilleure source d’informations sur l’erreur elle-même. Toutefois, le contenu de SqlWriterLogger fournit des détails sur la demande de sauvegarde (VSS_BT_FULL, demande de sauvegarde VSS non-composant qui a échoué pendant la phase OnPrepareSnapshot de l’enregistreur SQL Writer). Toute investigation des erreurs VSS impliquant SQL Server doit donc collecter et examiner les deux sources.

Modifier des paramètres de journalisation de l’enregistreur SQL Writer

La journalisation de l’enregistreur SQL Writer peut être configurée en modifiant le fichier texte SqlWriterConfig.ini. Le fichier lui-même contient une description en ligne rapide des paramètres disponibles, que nous allons examiner ci-dessous.

Remarque

Le fichier .ini se trouve dans un dossier protégé par Windows (Fichiers de programme). En tant que tel, sa modification requiert des privilèges d’administrateur élevés. Un double-clic dans l’Explorateur ouvre le Bloc-notes sans élévation des privilèges : cela permet à l’utilisateur de lire le contenu, mais les tentatives d’enregistrement des modifications échouent. Démarrez le Bloc-notes en tant qu’administrateur, puis ouvrez SqlWriterConfig.ini ou utilisez un éditeur de texte qui peut demander si nécessaire une élévation des privilèges au moment de l’enregistrement du fichier.

Commentaires sur la duplication du fichier SqlWriterConfig.ini :

Paramètre Options Description
EnableLogging - TRUE (valeur par défaut)
- FALSE		 Permet à l’utilisateur de désactiver l’intégralité de la nouvelle fonctionnalité de journalisation, dans le cas improbable où cela est nécessaire.
TraceFile C:\Program Files\Microsoft SQL Server\90\Shared\SqlWriterLog.txt Permet à l’utilisateur de modifier le chemin d’accès et le nom de fichier du fichier de suivi. Il n’est pas recommandé de le changer, car l’emplacement par défaut, bien connu facilite l’accès au bon endroit sur tout SQL Server.
TraceLevel - DEFAULT (valeur par défaut)
- MINIMAL
- VERBOSE		 Niveau de détail de la journalisation. Pour plus d’informations, consultez Détails de TraceLevel.
TraceFileSizeMb 1 Mo (par défaut) Taille maximale du fichier avant la substitution. Le fichier .txt utilise l’encodage UTF-8 et utilise 2 octets par caractère. L’augmentation de cette valeur est valide pour une instance avec une activité VSS intense, en conservant de longues périodes d’entrées de journal, ou si les valeurs TraceLevel non par défaut sont activées pour des durées longues. La valeur par défaut de 1 Mo doit fournir un historique suffisamment large pour la plupart des situations.
ForceFlush - TRUE
- FALSE (valeur par défaut)		 La définition de cette option sur TRUE n’est utile que dans les rares cas où le service de l’enregistreur SQL Writer se bloque avant de pouvoir vider ses dernières entrées de journal ; sinon, conservez la valeur par défaut.

Appliquer les changements

Toute modification apportée aux paramètres nécessite un redémarrage du service de l’enregistreur SQL Writer à des fins d’activation.

Conseil

Le redémarrage de l’enregistreur SQL Writer est extrêmement rapide et peut être effectué à partir du moment où l’enregistreur SQL Writer ne conserve aucune information avec état et n’a aucune activité entre les appels VSS. La seule précaution consiste à éviter un redémarrage lors d’une opération VSS (sauvegarde, restauration).

L’enregistreur SQL Writer signale les paramètres actifs dans son fichier journal lors du (re)démarrage, comme vous pouvez le voir dans l’exemple d’extraction Service Start.

Détails de TraceLevel

Le fichier SqlWriterConfig.ini répertorie les niveaux suivants :

Niveau Détail
DEFAULT Les paramètres de verbosité par défaut doivent être adaptés à la plupart des besoins : reportez-vous à la section Consultation des entrées de journalisation typiques pour observer ce qui est déjà généré par défaut. En plus des erreurs, les appels VSS réussis, ainsi que les métadonnées VSS, sont enregistrés par défaut.
MINIMAL Ce niveau conserve la mise en forme du mode et de ses événements. Il génère également une sortie dans de nombreux emplacements clés du code. Plus particulièrement, il journalise tous les fichiers et toutes les itérations de base de données qui sont courants dans la logique SQLWriter. Cela peut augmenter le nombre d’entrées journalisées pour chaque opération VSS (y compris les événements OnIdentify courants) par une marge importante, en particulier sur les instances hébergeant un grand nombre de bases de données : chaque fichier physique unique de chaque base de données peut être signalé plusieurs fois au cours d’une sauvegarde VSS. Ce niveau permet de donner une idée plus précise de la position logique de la logique de l’enregistreur SQL Writer au moment de la défaillance. Il est également pratique à des fins d’exploration. Il n’est pas utile de le garder actif au-delà des investigations momentanées, car le niveau de détail réduit beaucoup la profondeur de l’historique de la taille de fichier par défaut de 1 Mo. L’augmentation de la valeur TraceFileSizeMb peut être pertinente.
VERBOSE Actuellement, ce niveau signale les mêmes événements que , mais préfixe chaque entrée avec les descripteurs de l’objet de code source et des méthodes. Cela rend la sortie plus large (taille supérieure à la valeur Minimal) et moins lisible. Les informations ajoutées ne sont pas utiles en dehors des interactions avec les services de support Microsoft. Le même commentaire que MINIMAL s’applique : conserver ce niveau pendant une longue durée réduit la profondeur de l’historique de la taille de fichier par défaut de 1 Mo, et l’augmentation de la valeur TraceFileSizeMb peut s’avérer utile.

Les niveaux MINIMAL et VERBOSE ne fournissent pas d’autres détails d’erreur en cas d’échec, mais uniquement des détails de progression supplémentaires pour chaque opération de bas niveau liée aux activités de l’enregistreur SQL Writer.

Étapes suivantes