SQLDIAG (épisode 2)

Lundi, mai 10, 2010
By David Baffaleuf in SQL Server (dbaffaleuf@capdata-osmozium.com) [71 article(s)]

Deuxième épisode de la trilogie sur SQLDIAG et les outils avancés de diagnostic autour de SQL Server. Nous parlerons aujourd’hui du résultat de la trace lancée lors du rapport précédent et de son contenu. Nous verrons comment charger le contenu de la trace SQL et du fichier BLG dans SQL Profiler pour interprétation. Puis nous verrons comment mettre en place RML Utilities pour agréger et afficher le résultat d’une trace SQLDIAG.

Contenu d’une trace SQLDIAG:

Une fois la trace terminée, Ctrl-C stoppe le collecteur et commence à écrire les fichiers résultats sous l’arborescence. On retrouve une arborescence telle que:

<NOM TRACE>
|___ log_*.trc
|___ MS2K8-WIN2008-1__sp_sqldiag_Shutdown.OUT
|___ MS2K8-WIN2008-1_MSINFO32.txt
|___ MS2K8-WIN2008-1_SQLDIAG__sp_trace_*.trc
|___ SQLDIAG.lbg
|___ internal
     |___ *.txt
     |___ *.OUT
  • log*.trc: ces fichiers contiennent la trace par défaut de l’instance. Ils ont été copiés de leur répertoire origine (le plus souvent ~MSSQL\LOG). Cf note bas de page dans le premier article.
  • MS2K8-WIN29008-1__sp_sqldiag_Shutdown.OUT: ce fichier est divisé en plusieurs parties. Il n’est généré qu’au moment du Crtrl-C pour ne pas rater d’évènements survenus pendant la trace. Il commence par contenir le contenu de chaque fichier ERRORLOG*, puis la configuration de l’instance, la liste des processus (sp_who), la liste des verrous (sp_lock), la liste des bases (sp_helpdb), des informations sur le binaire (xp_msver), donne la liste de toutes les procédures stockées étendues déclarées (sp_helpextendedproc) , et le contenu de sysprocesses, sys.dm_exec_sessions, ::fn_virtualservernodes() si sur cluster, sysdevices, sysdatabases, sys.master_files. Enfin, la liste des requêtes en cours d’exécution. Le reste , où chaque vue sys.dm_os* est récupérée, est plus à destination du support pour diagnostic. Celà leur donne une image précise de l’activité au niveau des schedulers (SQLOS), de la mémoire, des latches, des modules chargés dans l’espace d’adressage de sqlservr.exe, etc… C’est beaucoup plus pratique que de faire générer un dump ou un mini-dump au client qui rencontre un problème. D’ailleurs, il y aura certainement un article prochainement sur les vues sys.dm_os* principales, je ne m’étends donc pas dessus, car pour l’instant ce n’est pas ce qui nous intéresse.
  • MS2K8-WIN29008-1_MSINFO32.txt: Contient le contenu au format texte de msinfo32. Toutes les informations systèmes sont contenues dans ce fichier, classées par section entre crochets ([]). Nombre d’entre elles sont sans intérêt (IRQ/DMA, périphériques, clavier, pilotes, etc…), il y cependant certaines sections qui valent le coup d’oeil: [System Summary] pour les informations systèmes courantes (OS, CPU, mémoire, etc…), [Drives] et [Disks] pour les disques, [Running Tasks] pour les processus en cours d’exécution, [Windows Error Reporting] pour les messages d’erreurs de l’eventvwr.
  • MS2K8-WIN29008-1_SQLDIAG__sp_trace_*.trc: ces fichiers contiennent la trace SQL Trace que l’on a paramétrée dans le fichier XML.
  • SQLDIAG.blg: ce fichier contient la trace système paramétrée dans le fichier XML.
  • ~internal\: ce sous répertoire contient les logs de l’exécution de SQLDIAG. En fonction de la version utilisée, les fichiers OUT et txt peuvent se trouver au même niveau que les fichiers résultats.

Les deux axes qui vont nous intéresser sont principalement les fichiers de trace SQL et le fichier BLG. Les autres fichiers seront plus à utiliser à des fins de diagnostic.

Charger une trace SQL et un fichier BLG dans SQL Profiler:

Il est possible de charger un fichier de compteurs perfmon et une trace SQL dans SQL Profiler pour corrélation. Ce n’est possible toutefois que si les deux traces ont été générées ensembles, le plus souvent à l’aide d’un outil comme SQLDIAG ou PSSDIAG. Tout d’abord, ouvrir la trace SQL dans Profiler, puis File->Import Performance Data… Sélectionner le fichier BLG généré dans la même trace, puis les compteurs à charger (pour plus de lisibilité, on ne prendra que les compteurs disque dans notre cas), et importer la trace:

L’écran se divise en quatre parties. Les zones extrêmes représentent l’affichage classique de SQL Profiler: texte et statistiques des requêtes. La partie centrale présente les graphes associés aux compteurs du fichier BLG, et la partie inférieure la liste des compteurs avec les valeurs Min, Max, Average:

Il est possible de zoomer et de déplacer le curseur temporel dans la partie centrale, et Profiler va pointer sur les requêtes exécutées à l’instant sélectionné, et la valeur de ‘Selected‘ dans la partie inférieure est également mise à jour pour chaque compteur.

Maintenant il faut bien faire attention à ce que l’on lit ou ce que l’on interprète. Il faut bien se rendre compte que SQL Trace collecte les statistiques pour un évènement une fois qu’il s’est terminé, donc ce n’est pas parce qu’on va pointer sur un pic CPU ou un de temps de service disque  qu’on va tomber pile sur le problème. On va dire que ça facilite la tâche, ça permet de corréler des informations, mais ça ne fait pas le travail à votre place. Une requête peut commencer à faire des lectures physiques depuis le disque pendant une minute, puis faire d’autres opérations en mémoire (des tris, des agrégations) et se terminer un certain temps  après le pic. Un petit exemple d’une requête qui fait des accès physiques pendant 1 minute et qui se termine à la fin du pic. Si on ne regarde pas bien, on rate l’information:

RML Utilities:

RML Utilities est une petite application due, comme pas mal d’outils et d’avancées sur le moteur, à l’initiative de l’équipe Customer Support Services. La première version de RML s’appuyait sur deux binaires Ostress et ReadTrace principalement, elle a été refondue en 2007 pour incorporer une petite application d’affichage des traces, basée sur des reports RDL. Les versions x86 et x64 sont téléchargeables depuis la page d’accueil de RML. L’installation n’a rien de compliqué, donc on va passer directement à la phase d’intégration des traces.

Cette intégration se fait avec ReadTrace. Tout d’abord, on va créer une base pour stocker les données des traces:

create database RMLDB

Puis ReadTrace avec les options -I<chemin vers fichier trc initial> -S<instance> -d<Baserepository> (important de ne pas laisser d’espace entre le commutateur et le paramètre)

$ ./ReadTrace -IE:/SQLDIAG/TRACE3/SQL2008__sp_trace.trc -SMS2K8-Win2008-1 -E -dRMLDB

05/10/10 17:13:20.920 [0X000013B4] Output path was not specified; defaulting to C:\Users\capdata\AppData\Local\Temp\2\\output
05/10/10 17:13:21.000 [0X000013B4] Readtrace a SQL Server trace processing utility.
Version 9.01.0109 built for x86.
Copyright (c) Microsoft Corporation 1997-2008. All rights reserved.
05/10/10 17:13:21.002 [0X000013B4] Number of processors: 1
05/10/10 17:13:21.002 [0X000013B4]     Active proc mask: 0x00000001
05/10/10 17:13:21.008 [0X000013B4]         Architecture: 0
05/10/10 17:13:21.009 [0X000013B4]            Page size: 4096
05/10/10 17:13:21.009 [0X000013B4]         Highest node: 0
05/10/10 17:13:21.010 [0X000013B4]         Package mask: 0x00000001
05/10/10 17:13:21.011 [0X000013B4]         Processor(s): 0x00000001 Function units: Separated
05/10/10 17:13:21.011 [0X000013B4]           Processors: 0x00000001 assigned to Numa node: 0
05/10/10 17:13:21.012 [0X000013B4] -IE:/SQLDIAG/TRACE3/SQL2008__sp_trace.trc
05/10/10 17:13:21.012 [0X000013B4] -SMS2K8-Win2008-1
05/10/10 17:13:21.013 [0X000013B4] -E
05/10/10 17:13:21.013 [0X000013B4] -dRMLDB
05/10/10 17:13:21.014 [0X000013B4] Using language id (LCID): 1024 [French_France.1252] for character formatting with NLS: 0x00500100 and Defined: 0x00050100
05/10/10 17:13:21.015 [0X000013B4] Attempting to cleanup existing RML files from previous execution
05/10/10 17:13:21.016 [0X000013B4] Using extended RowsetFastload synchronization
05/10/10 17:13:21.017 [0X000013B4] Establishing initial database connection:
05/10/10 17:13:21.017 [0X000013B4] Server: MS2K8-Win2008-1
05/10/10 17:13:21.018 [0X000013B4] Database: RMLDB
05/10/10 17:13:21.018 [0X000013B4] Authentication: Windows
05/10/10 17:13:21.470 [0X000013B4] Using SQL Client version 10
05/10/10 17:13:21.471 [0X000013B4] Creating or clearing the performance database
05/10/10 17:13:22.916 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace.trc (SQL 2005)
05/10/10 17:13:22.918 [0X000013B4] Validating core events exist
05/10/10 17:13:22.919 [0X000013B4] Validating necessary events exist for analysis
05/10/10 17:13:22.921 [0X000013B4] Validating necessary events exist for RML breakout
05/10/10 17:13:22.922 [0X000013B4] WARNING: Event [Server: Server Memory Change] missing from trace
05/10/10 17:13:22.923 [0X000013B4] WARNING REPLAY: The following trace events were not captured: [Sessions:ExistingConnection, Security Audit: Audit Login, Se
rity Audit: Audit Logout, Stored Procedures: RPC Output Parameter, Cursors:Unprepare, Cursors:CursorClose, Cursors:CursorPrepare, Cursors:CursorCreated, Curso
:CursorExecute, TSQL: Prepare SQL, TSQL: Unprepare SQL, Errors and Warnings:Attention, Transactions:SQLTransaction, Transactions:DTCTransaction, Transactions:
:Begin Tran starting and completed, Transactions:TM:Commit Tran starting and completed, Transactions:TM:Rollback Tran starting and completed, Transactions:TM:
ve Tran starting and completed, Transactions:TM:Promote Tran starting and completed, SQL:BatchStarting and SQL:BatchCompleted, RPC:Starting and RPC:Completed]
Review the help file to ensure that you have collected the appropriate set of events and columns for RML replay needs.  Lack of these events can lead to sever
replay problems.

Trace flag -T28 disables the check allowing RML output processing. *** Use with caution as the output and behavior could be unpredictable.
05/10/10 17:13:22.993 [0X000013B4] Events Read: 1000 Queued: 1000 Processed/sec: 0
05/10/10 17:13:23.026 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_1.trc (SQL 2005)
05/10/10 17:13:23.038 [0X000013B4] Events Read: 2000 Queued: 2000 Processed/sec: 0
05/10/10 17:13:23.070 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_2.trc (SQL 2005)
05/10/10 17:13:23.082 [0X000013B4] Events Read: 3000 Queued: 3000 Processed/sec: 0
05/10/10 17:13:23.261 [0X000013B4] Events Read: 4000 Queued: 4000 Processed/sec: 0
05/10/10 17:13:23.271 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_3.trc (SQL 2005)
05/10/10 17:13:23.284 [0X000013B4] Events Read: 5000 Queued: 5000 Processed/sec: 0
05/10/10 17:13:23.328 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_4.trc (SQL 2005)
05/10/10 17:13:23.342 [0X000013B4] Events Read: 6000 Queued: 6000 Processed/sec: 0
05/10/10 17:13:23.361 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_5.trc (SQL 2005)
05/10/10 17:13:23.366 [0X000013B4] Events Read: 7000 Queued: 7000 Processed/sec: 0
05/10/10 17:13:23.396 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_6.trc (SQL 2005)
05/10/10 17:13:23.406 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_7.trc (SQL 2005)
05/10/10 17:13:23.475 [0X000013B4] Events Read: 8000 Queued: 8000 Processed/sec: 0
05/10/10 17:13:23.574 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_8.trc (SQL 2005)
05/10/10 17:13:24.175 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_9.trc (SQL 2005)
05/10/10 17:13:24.313 [0X000013B4] Events Read: 9000 Queued: 8998 Processed/sec: 2
05/10/10 17:13:24.854 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_10.trc (SQL 2005)
05/10/10 17:13:24.905 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_11.trc (SQL 2005)
05/10/10 17:13:24.939 [0X000013B4] Processing file: E:\SQLDIAG\TRACE3\SQL2008__sp_trace_12.trc (SQL 2005)
05/10/10 17:13:24.959 [0X000013B4] Found TRACE_STOP with 0 bytes of data
05/10/10 17:13:24.961 [0X000013B4] Found [TRACE_STOP] event indicating the end of the trace files.
05/10/10 17:13:24.962 [0X000013B4] Reads completed
05/10/10 17:13:24.965 [0X000013B4] Shutting down the worker thread message queues.
05/10/10 17:13:24.996 [0X000013B4] Waiting for the worker threads to complete final actions.
05/10/10 17:13:26.074 [0X000013B4] Performing general cleanup actions.
05/10/10 17:13:26.076 [0X000013B4] Reducing cached memory.
05/10/10 17:13:26.096 [0X000013B4] Total Events Processed: 11117
05/10/10 17:13:26.101 [0X000013B4]  Total Events Filtered: 0
05/10/10 17:13:26.102 [0X000013B4] Parse errors: 0
05/10/10 17:13:26.224 [0X000013B4] Table ReadTrace.tblUniqueBatches: loaded ~445 rows
05/10/10 17:13:26.225 [0X000013B4] Table ReadTrace.tblUniqueStatements: loaded ~0 rows
05/10/10 17:13:26.225 [0X000013B4] Table ReadTrace.tblUniquePlans: loaded ~0 rows
05/10/10 17:13:26.226 [0X000013B4] Table ReadTrace.tblUniquePlanRows: loaded ~0 rows
05/10/10 17:13:26.241 [0X000013B4] Table ReadTrace.tblBatches: loaded ~4355 rows
05/10/10 17:13:26.242 [0X000013B4] Table ReadTrace.tblStatements: loaded ~0 rows
05/10/10 17:13:26.243 [0X000013B4] Table ReadTrace.tblPlans: loaded ~0 rows
05/10/10 17:13:26.244 [0X000013B4] Table ReadTrace.tblPlanRows: loaded ~0 rows
05/10/10 17:13:26.257 [0X000013B4] Table ReadTrace.tblInterestingEvents: loaded ~3 rows
05/10/10 17:13:26.258 [0X000013B4] Table ReadTrace.tblConnections: loaded ~0 rows
05/10/10 17:13:26.262 [0X000013B4] WARNING: One or more warning conditions exist that may affect the quality of the analysis data.  See RMLDB.ReadTrace.tblWar
ngs table and the ReadTrace log for complete details.
05/10/10 17:13:26.269 [0X000013B4] Indexing tables...
05/10/10 17:13:27.413 [0X000013B4] Doing post-load data cleanup...
05/10/10 17:13:27.863 [0X000013B4] Computing partial aggregates...
05/10/10 17:13:28.977 [0X000013B4] Data load completed.
05/10/10 17:13:28.979 [0X000013B4] Using execution path: c:\Program Files\Microsoft Corporation\RMLUtils
05/10/10 17:13:28.980 [0X000013B4] Launching [c:\Program Files\Microsoft Corporation\RMLUtils\Reporter.exe]
05/10/10 17:13:29.253 [0X000013B4] *******************************************************************************
* ReadTrace encountered one or more WARNINGS. A warning condition typically   *
* continues processing with reduced functionality, but the ReadTrace output   *
* may be adversely affected. Review the log file for details.                 *
*******************************************************************************
05/10/10 17:13:29.324 [0X000013B4]
 

Les deux warnings indiquent juste qu’il va manquer certains évènements, notamment les évènements pour pouvoir faire un replay dans Profiler.  A la fin du chargement, l’application ‘Reporter‘ est lancée et permet de visualiser les informations de la trace:

Ensuite, il est assez simple de naviguer dans l’interface et de visualiser l’information agrégée, par exemple en cliquant sur ‘Unique Batches’:

… et de repérer les requêtes consommatrices par critère (coût CPU, I/Os, durée), et visualiser le plan (si pris dans la trace):

Dernier épisode, on verra OSTRESS et ORCA, et les alternatives à SQLDIAG+RML Utilites: PSSDIAG, SQL Nexus, SQLH2, Data Collector, les reports SSMS.

A+ David B. (avec la collaboration de Martial LUCAS. )

lrwxrwxrwx 1 root root 4 2008-07-09 12:41 /bin/sh -> bash


Continuez votre lecture sur le blog :




Cliquer pour partager cet article sur Viadeo
Cliquer sur "CAPTURER" pour sauvegarder cet article dans Evernote Clip to Evernote

Tags: , , ,

Leave a Reply