Debugger un 100% CPU du spooler


Dans ce post nous allons voir comment traiter un problème spécifique de 100% CPU causé par le spooler.


Après avoir constaté via Task Manager ou Process Explorer que le processus causant cette consommation de temps processeur était bien Spoolsv.exe (spooler d’impression), nous avons pris plusieurs dumps du processus avec l’outil Adplus.


Cette méthodologie peut être reprise pour identifier d’autres dysfonctionnements liés au spooler.


 




Collecte de dump



Pour cela, télécharger les « Debugging Tools » à cette adresse : http://www.microsoft.com/whdc/devtools/debugging/installx86.mspx et les installer sur le serveur (il est possible d’installer ces outils sur une machine moins sensible puis de copier le répertoire d’installation vers le serveur).


Après avoir installé ces outils nous avons pris des dumps du processus Spoolsv.exe via la commande suivante :



Cscript Adplus.vbs –quiet –hang –pn spoolsv.exe –r 3 60




    • -quiet => afin de ne pas avoir à répondre aux deux messages « popup » concernant les symbols

    • -hang => vous avez le choix entre hang ou crash, dans notre cas comme nous voulons prendre des dumps sans interrompre le processus nous utilisons donc –hang.

    • -pn=> cette option permet de spécifier le nom du processus, sinon vous pouvez utiliser –p en spécifiant le PID du process.

    • -r => permet d’automatiser la prise de plusieurs dumps avec un intervalle de temps entre chaque dump, ici 3 dumps avec 60s entre chaque dump.


Après avoir pris les dumps, nous les avons ouverts avec Windbg (fournis aussi avec les Debugging tools) :




  1. Menu Démarrer => Debugging tools for Windows => Windbg

  2. Depuis le menu File => Symbol file path entrez les paramètres suivants : SRV*C:\SYMBOLS*http://msdl.microsoft.com/download/symbols puis OK
    Il est important de disposer de symboles pour que Windbg puisse interpréter le contenu de la mémoire, de la pile, etc…On spécifie ici la source utilisée pour télécharger les symboles publics (en l’occurrence les serveurs publics Microsoft)

  3. File=> Open Crash Dump

 


Analyse des dumps



La première étape consiste à rechercher le thread consommant le plus de CPU :



>!runaway



User Mode Time



Thread Time



4:1144 0 days 0:00:01.312 => Le thread 4 est celui qui utilise actuellement le plus de CPU



11:135c 0 days 0:00:00.015



17:1714 0 days 0:00:00.000



16:1710 0 days 0:00:00.000



15:170c 0 days 0:00:00.000



14:1708 0 days 0:00:00.000



13:1704 0 days 0:00:00.000



12:1700 0 days 0:00:00.000



10:16fc 0 days 0:00:00.000



9:16f8 0 days 0:00:00.000



8:16f0 0 days 0:00:00.000



7:16e8 0 days 0:00:00.000



6:16ac 0 days 0:00:00.000



5:113c 0 days 0:00:00.000



3:15c8 0 days 0:00:00.000



2:ff4 0 days 0:00:00.000



1:13c 0 days 0:00:00.000



0:148 0 days 0:00:00.000



Nous devons donc nous positionner dans le contexte du thread :



>~4s



eax=0000004b ebx=00000000 ecx=00a3dea8 edx=7ffe0300 esi=00a3e008 edi=00000000



eip=7c8285ec esp=00a3df94 ebp=00a3dfd4 iopl=0 nv up ei pl nz na pe nc



cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000206



ntdll!KiFastSystemCallRet:



7c8285ec c3 ret



On affiche la pile du thread :



>kv



ChildEBP RetAddr Args to Child



00a3df90 7c82734b 77f5cd00 00a3dfe0 00010000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])



00a3df94 77f5cd00 00a3dfe0 00010000 00a3dfb4 ntdll!ZwOpenKey+0xc (FPO: [3,0,0])



00a3dfd4 77f5cc4d 0000047c 00000000 00000000 advapi32!LocalBaseRegDeleteKeyEx+0xb0 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3dfec 77f5cc0d 0000047c 00a3e008 00a3e2c4 advapi32!LocalBaseRegDeleteKey+0x14 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e038 7616687e 0000047c 00a3e2c4 00a3e288 advapi32!RegDeleteKeyW+0xd2 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e048 7613e295 0000047c 00a3e2c4 008f52a8 localspl!SplRegDeleteKey+0x3d (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e288 7613e234 0000047c 000001e0 00a3e2c4 localspl!SplRegDeleteKey+0x17b (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e4d0 7613e234 00000478 0000047c 00a3e50c localspl!SplRegDeleteKey+0x126 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e718 7613e234 00000480 00000478 00a3e754 localspl!SplRegDeleteKey+0x126 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e960 76143a57 00000174 00000480 008f9e78 localspl!SplRegDeleteKey+0x126 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e990 76143ac2 008f9e78 008f52a8 008f52a8 localspl!DeletePrinterIni+0x7a (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e9a8 7613f590 00958078 00000001 00000000 localspl!DeletePrinterForReal+0x2b (FPO: [Non-Fpo]) (CONV: stdcall)



00a3e9bc 76133674 008f52a8 008f52a8 00a3f68c localspl!CleanupDeletedPrinters+0x2b (FPO: [Non-Fpo]) (CONV: stdcall)



00a3f230 761374eb 008f52a8 00000000 008f2ab8 localspl!BuildPrinterInfo+0xee5 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3f668 761391f8 0090e8a0 00000001 00a3f68c localspl!SplCreateSpooler+0x644 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3f908 74064c44 008f2ab8 00000158 00000000 localspl!InitializePrintProvidor+0x1bc (FPO: [Non-Fpo]) (CONV: stdcall)



00a3f930 74064915 74064cd0 00000000 00000000 spoolss!InitializeProvidor+0x89 (FPO: [Non-Fpo]) (CONV: stdcall)



00a3ffb8 77e64829 008f1ea8 00000000 00000000 spoolss!InitializeRouter+0x25b (FPO: [Non-Fpo]) (CONV: stdcall)



00a3ffec 00000000 01003f90 008f1ea8 00000000 kernel32!BaseThreadStart+0x34 (FPO: [Non-Fpo]) (CONV: stdcall)



Ici on peut voir que nous essayons de faire une suppression d’une clé de registre, localspl!SplRegDeleteKey, et cela en boucle car il semble que le processus n’arrive pas à la supprimer, d’où la consommation de CPU dans le temps.



Voyons à quoi correspond cette clé (du moins trouver l’adresse du handle qui pointe vers cette clé) avec la commande suivante :



>Kp



ChildEBP RetAddr



00a3df90 7c82734b ntdll!KiFastSystemCallRet(void)



00a3df94 77f5cd00 ntdll!ZwOpenKey(void)+0xc



00a3dfd4 77f5cc4d advapi32!LocalBaseRegDeleteKeyEx(struct HKEY__ * hKey = 0x0000047c, struct _UNICODE_STRING * lpSubKey = 0x00000000, unsigned long samDesired = 0, unsigned long Reserved = 0)+0xb0



00a3dfec 77f5cc0d advapi32!LocalBaseRegDeleteKey(struct HKEY__ * hKey = 0x0000047c, struct _UNICODE_STRING * lpSubKey = 0x00a3e008 "(0x1A01)")+0x14



00a3e038 7616687e advapi32!RegDeleteKeyW(struct HKEY__ * hKey = 0x0000047c, unsigned short * lpKeyName = 0x00a3e2c4)+0xd2



00a3e048 7613e295 localspl!SplRegDeleteKey(void * hKey = 0x0000047c, unsigned short * pszSubKey = 0x00a3e2c4, struct _INISPOOLER * pIniSpooler = 0x008f52a8)+0x3d



00a3e288 7613e234 localspl!SplDeleteThisKey(void * hParentKey = 0x0000047c, void * hThisKey = 0x000001e0, unsigned short * pThisKeyName = 0x00a3e2c4, int bDeleteNullKey = 1, struct _INISPOOLER * pIniSpooler = 0x008f52a8)+0x17b



00a3e4d0 7613e234 localspl!SplDeleteThisKey(void * hParentKey = 0x00000478, void * hThisKey = 0x0000047c, unsigned short * pThisKeyName = 0x00a3e50c, int bDeleteNullKey = 1, struct _INISPOOLER * pIniSpooler = 0x008f52a8)+0x126



00a3e718 7613e234 localspl!SplDeleteThisKey(void * hParentKey = 0x00000480, void * hThisKey = 0x00000478, unsigned short * pThisKeyName = 0x00a3e754, int bDeleteNullKey = 1, struct _INISPOOLER * pIniSpooler = 0x008f52a8)+0x126



00a3e960 76143a57 localspl!SplDeleteThisKey(void * hParentKey = 0x00000174, void * hThisKey = 0x00000480, unsigned short * pThisKeyName = 0x008f9e78, int bDeleteNullKey = 1, struct _INISPOOLER * pIniSpooler = 0x008f52a8)+0x126



00a3e990 76143ac2 localspl!DeletePrinterIni(struct _INIPRINTER * pIniPrinter = 0x008f9e78)+0x7a



00a3e9a8 7613f590 localspl!DeletePrinterForReal(struct _INIPRINTER * pIniPrinter = 0x00958078, int bIsInitTime = 1)+0x2b



00a3e9bc 76133674 localspl!CleanupDeletedPrinters(struct _INISPOOLER * pIniSpooler = 0x008f52a8)+0x2b



00a3f230 761374eb localspl!BuildPrinterInfo(struct _INISPOOLER * pIniSpooler = 0x008f52a8, int UpdateChangeID = 0)+0xee5



00a3f668 761391f8 localspl!SplCreateSpooler(unsigned short * pMachineName = 0x0090e8a0, unsigned long Level = 1, unsigned char * pSpooler = 0x00a3f68c "", unsigned char * pReserved = 0x00000000 "")+0x644



00a3f908 74064c44 localspl!InitializePrintProvidor(struct _PRINTPROVIDOR * pPrintProvidor = 0x008f2ab8, unsigned long cbPrintProvidor = 0x158, unsigned short * pFullRegistryPath = 0x00000000)+0x1bc



00a3f930 74064915 spoolss!InitializeProvidor(unsigned short * pProvidorName = 0x74064cd0, unsigned short * pFullName = 0x00000000)+0x89



00a3ffb8 77e64829 spoolss!InitializeRouter(struct RouterInitializationParams * pRouterParams = 0x008f1ea8)+0x25b



00a3ffec 00000000 kernel32!BaseThreadStart(<function> * lpStartAddress = 0x01003f90, void * lpParameter = 0x008f1ea8)+0x34



La commande suivante permet d’afficher la clé de registre qui ne peut être supprimée :



>!handle 0000047c 4



Handle 0000047c



Name \REGISTRY\MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Print\Printers\bg-picklabel on bgmprint (from BG-JLP) in session 1\PrinterDriverData\Papers



Cette clé est vraisemblablement corrompue car la tentative de suppression manuelle avec Regedit s’est avérée impossible. Le nom de la clé est peu commun et peut donc contenir des caractères null.



La suppression via Regedit n'étant pas possible nous avons utilisé l'outil RegDelNull.exe (disponible depuis http://www.microsoft.com/technet/sysinternals/utilities/regdelnull.mspx ) via la commande : RegDelNull.exe hklm -s puis nous avons répondu « Yes » concernant la suppression de la clé « bg-picklabel on bgmprint (from BG-JLP) in session 1\PrinterDriverData\Papers »



Un redémarrage du spooler a permis de remettre en service le service d’impression.




 


Philippe


Windows Core Support Escalation Engineer

Comments (1)

  1. Anonymous says:

    Définition du problème Aléatoirement, lors de connexions RDP sur un serveur TS, le phénomène suivant

Skip to main content