Sybase et exploitation pratique de dbcc procbuf

Introduction

Le contexte est parfois particulier au sujet des procédures stockées dans Sybase Adaptive Server Enterprise : un utilisateur note une dérive sur le plan d’exécution d’une procédure stockée au cours d’une semaine d’activité. Malheureusement cette procédure stockée n’est pas en cours d’utilisation au moment de l’analyse et on peut logiquement supposer une recompilation régulière de cette procédure stockée pour expliquer la dérive, recompilation qui modifie le plan d’exécution de la procédure stockée (dans notre contexte, une colonne date d’index n’est plus utilisée dans le plan).

L’analyse du cache de procédure avec sp_monitorconfig 'procedure cache size' ne révèle pas de saturation au niveau de ce cache, l’hypothèse de la recompilation est fortement confirmée et liée à l’exécution de commandes sp_recompile sur les objets sollicités dans la procédure stockée qui est recompilée.

Deux informations sont nécessaires pour mener l’analyse même si la procédure stockée en question n’est pas en cours d’exécution :

la dernière date de recompilation de la procédure stockée.
le plan d’exécution de la procédure stockée.

La commande dbcc non supportée dbcc procbuf donne ces deux informations (date de recompilation et plan d’exécution). La sortie de dbcc procbuf est très verbeuse et il ne faut pas en être effrayé, elle fournit quand même des informations précieuses sur le plan d’exécution dans le cache de procédures et la date de dernière compilation.

Syntaxe et mise en œuvre de dbcc procbuf

La syntaxe pour l’utilisation de dbcc procbuf est la suivante (la trace 3604 est nécessaire) :

dbcc procbuf (dbid, objid, nbufs, printopt = { 0 | 1 } )

La commande dbcc help permet de retrouver la syntaxe de dbcc procbuf.

dbcc traceon(3604)
go
dbcc help ( procbuf )
go

          procbuf( dbid, objid, nbufs, printopt = { 0 | 1 } )
DBCC execution completed. If DBCC printed error messages,
contact a user with System Administrator (SA) role.

Paramètre	Description
`dbid`	identifiant de la base de données
`objid`	identifiant de la procédure stockée
`nbufs`	nombre de buffers ou de procédures stockées
`printopt`	options d’affichage , 0 pour le résumé, 1 pour le détail. Avec 1, les plans d’exécution sont notamment affichés.

Quelques exemples d’utilisation :

dbcc procbuf (0,0,0,0) donnera le résumé de toutes les procédures stockées en cache de la base de données courante.

dbcc traceon(3604)
go
dbcc procbuf (0,0,2,0)
go

dbcc procbuf (0,0,2,0) donnera le résumé des 2 premières stockées en cache de la base de données courante.

Voici ci-dessous un exemple allégé de résultat pour la base master avec la commande dbcc procbuf (0,0,0,0) : les procédures stockées en cache de la base master sont triées par ordre MRU => LRU (Most Recent Used vers Least Recent Used en cache), elles sont séparées par le mot clé PROCBUF:

PROCEDURES (in MRU to LRU order):

PROCBUF:
address=0x204F6F24 id=336001197 pbdbid=1
pbplannum=13
pbuid=1 pbihash=0x00000000 pbnhash=0x00000000 pbprev=0x204F700C
pbtimestamp: Feb 23 2007 2:39PM
pbnext=0x204F73AC pbprochdr=0x20EE0000 pbparam=0x00000000pbtype=4
pbstate=1 pbstat=0x0 pbusecnt=0 pbspid=0 pbdes=0x203E96F4
pbxdes=0x00000000
pbname='sp_getmessage' pbprocnum=1
..........
Summary of memory usage:
 Total # of PROCHDRs used : 1
 Total # of pages used : 24
 Total # of bytes used : 48080
 Total # of lost bytes for alignment : 77
 Total # of pages lost for alignment : 0
 Total percentage of memory lost : 0
..........

PROCBUF:
address=0x204F70F4 id=368001311 pbdbid=1
pbplannum=17
pbuid=1 pbihash=0x00000000 pbnhash=0x00000000 pbprev=0x204F72C4
pbtimestamp: Feb 23 2007 2:41PM
pbnext=0x204F6C6C pbprochdr=0x20E91000 pbparam=0x00000000pbtype=4
pbstate=1 pbstat=0x0 pbusecnt=0 pbspid=0 pbdes=0x203EA378
pbxdes=0x00000000
pbname='sp_configure' pbprocnum=1
........
Summary of memory usage:
 Total # of PROCHDRs used : 3
 Total # of pages used : 195
 Total # of bytes used : 398586
 Total # of lost bytes for alignment : 830
 Total # of pages lost for alignment : 0
 Total percentage of memory lost : 0
...........
				
PROCBUF:
address=0x204F6A9C id=352001254 pbdbid=1
pbplannum=3
pbuid=1 pbihash=0x00000000 pbnhash=0x00000000 pbprev=0x204F69B4
pbtimestamp: Feb 23 2007 2:39PM
pbnext=0x204F71DC pbprochdr=0x20E88000 pbparam=0x00000000pbtype=4
pbstate=1 pbstat=0x0 pbusecnt=0 pbspid=0 pbdes=0x203CF9F0
pbxdes=0x00000000
pbname='sp_aux_getsize' pbprocnum=1
........
Summary of memory usage:
 Total # of PROCHDRs used : 1
 Total # of pages used : 23
 Total # of bytes used : 46733
 Total # of lost bytes for alignment : 109
 Total # of pages lost for alignment : 0
 Total percentage of memory lost : 0
........

La sortie de dbcc procbuf (0,0,0,0) pour la base master montre que les procédures stockées sp_getmessage, sp_configure et sp_aux_getsize sont en cache.

Pour chaque procédure stockée, on retrouve l’identifiant de la procédure stockée (id), l’id de la base de données (pbdbid), le nom de la procédure stockée (pbname) et également l’identifiant du plan d’exécution de la procédure stockée (pbplannum).

La date de compilation de la procédure stockée est donnée dans la sortie avec pbtimestamp :

pbtimestamp: Feb 23 2007 2:39PM

La consommation mémoire d’une procédure stockée dans le cache de procédure est également indiquée à la fin du paragraphe. La procédure stockée sp_aux_getsize consomme 46733 bytes dans le cache de procédure :

Total # of bytes used : 46733

Cette consommation mémoire est également donnée en pages utilisées (Total # of pages used).

La somme de toutes les pages utilisées par toutes les procédures stockées en cache (Total # of pages used) s’approche de la valeur Num_active donnée par sp_monitorconfig 'procedure cache size'

execute sp_monitorconfig 'procedure cache size'
go

Usage information at date and time: Feb 23 2007 3:35PM.
Name                   Num_free      Num_active      Pct_act     Max_Used     Num_Reuse
---------------------- ---------    -------------    ---------   ----------   ---------
procedure cache size      1894        1377             42.10        1662              0

Exemple pratique

Dans le cas pratique de l’article, la commande dbcc procbuf est lancée sur la procédure stockée en question qui dérive avec l’option printopt à 1 pour avoir également les éléments sur son plan d’exécution :

dbcc traceon(3604)
go
dbcc procbuf (6,1386715304,0,1)
go

Comme la sortie de dbcc procbuf est très verbeuse, il est même préfèrable de tout déporter dans un fichier avec l’option -o du binaire isql :

isql -Usa -odbcc_procbuf.log

dbcc traceon(3604)
go
dbcc procbuf (6,1386715304,0,1)
go
exit
          PROCEDURES (in MRU to LRU order):
PROCBUF:
address=0x47c12b78 id=1386715304 pbdbid=6
pbplannum=48100
pbuid=1 pbihash=0x0 pbnhash=0x0 pbprev=0x47c0d718
pbtimestamp: Feb 9 2007 10:12AM
pbnext=0x47d259c0 pbprochdr=0x536a4800 pbparam=0x0 pbtype=4
pbstate=1 pbstat=0x0 pbusecnt=0 pbspid=0 pbdes=0x478c21c8pbxdes=0x0
pbname='p_slat_get_assets' pbprocnum=1

La partie pbtimestamp montre bien que la procédure stockée p_slat_get_assets a été recompilée à 10h12 du matin le jour même de l’analyse du problème.

La sortie est très verbeuse avec l’option printopt à 1, toutefois c’est la seule sortie qui permet de retrouver les mots clés du plan d’exécution de la procédure stockée (scan, positioning by key, positioning at table start pour les table scans…) ainsi que les noms des indexes et objets :

MAIN EOP (0x54de15b0):
e_opnext=0x0 e_opsubor=0x0 e_opstatus=(0x00000000)
e_optype= 4 (E_SUBSTITUTE) e_opvar=1 (MATURITY_CLASS_HISTORY) e_opindid=1
(PK_MATURITY_CLASS_HISTORY) e_opscantype=1 e_opscnt=3 e_oporsargcnt=0
e_oprowbuf=0x0, e_opindbuf=0x0
e_opminlen=22 e_oprowfmt=1 (DEF_ROWFORMAT)
(scan type: 1 (SCAN_NORMAL) )
Ascending scan, positioning by key
Keys are:
       INSTRUMENT_ID

Dans le cas pratique de cet article, la procédure stockée a un plan d’exécution qui a dérivé car la colonne MATURITY_CLASS_DATE n’est plus pris en compte sur l’index PK_MATURITY_CLASS_HISTORY de la table MATURITY_CLASS_HISTORY, le bon plan étant le suivant :

MAIN EOP (0x54de15b0):
e_opnext=0x0 e_opsubor=0x0 e_opstatus=(0x00000000)
e_optype= 4 (E_SUBSTITUTE) e_opvar=1 (MATURITY_CLASS_HISTORY) e_opindid=1
(PK_MATURITY_CLASS_HISTORY) e_opscantype=1 e_opscnt=3 e_oporsargcnt=0
e_oprowbuf=0x0, e_opindbuf=0x0
e_opminlen=22 e_oprowfmt=1 (DEF_ROWFORMAT)
(scan type: 1 (SCAN_NORMAL) )
Ascending scan, positioning by key
Keys are:
       INSTRUMENT_ID
       MATURITY_CLASS_DATE

Les statistiques sur la colonne MATURITY_CLASS_DATE étaient en cause dans ce problème et elles ont été recalculées pour retrouver le bon plan d’exécution.