Comment résoudre un 100% cpu kernel?

Voici un exemple de troubleshooting d’un problème de 100% cpu en mode kernel en utilisant le « Microsoft Windows Performance Toolkit » + un kernel dump.

Scenario

Une application réalisant des accès aux données (ODBC) part en 100% cpu après quelques milliers d’accès au SGBD. i.e. tout marche correctement pendant quelques minutes puis nous partons en 100% cpu en mode kernel ce qui a pour résultat d’avoir un système inutilisable.

Outils

Nous allons utiliser le « Microsoft Windows Performance Toolkit » que l’on peut télécharger ici https://msdn.microsoft.com/en-us/library/cc305187.aspx , ainsi qu’un kernel dump au moment où le problème est visible. Pour analyser le kernel dump nous allons utiliser windbg.exe qui est distribué avec les « Debugging Tools for Windows » téléchargeable ici https://www.microsoft.com/whdc/devtools/debugging/default.mspx .

Collecte des données

Xperf: nous avons démarré une trace xperf alors que l’application marchait bien puis, nous avons laissé celle-ci continuer alors que le problème était visible. Les commandes étant les suivantes :

xperf –on Base+Diag (pour démarrer le tracing)

xperf –d c:\cpu.etl (pour arrêter le tracing)

Kernel Dump: https://msdn.microsoft.com/en-us/library/cc266492.aspx

Troubleshooting

La première étape va consister à constater le problème de 100% cpu à partir du dump. Pour cela j’ouvre le dump dans windbg (menu File+ Open Crash Dump…). Puis, je cherche mon processus (apisend.exe) responsable du 100% cpu en utilisant la commande «!process»:

Nous obtenons donc l’adresse de notre processus cible. Nous pouvons utiliser la commande !process avec cette nouvelle information afin d’obtenir des informations détaillées :

Nous constatons donc que le thread 81fc8290 a passé 7 minutes et 33 secondes en mode kernel. Sachant que l’application venait d’être lancée quelques minutes avant la génération du dump, cela semble effectivement important.

Maintenant, concentrons-nous sur la trace xperf. Je lance donc xperfview.exe, ouvre le fichier cpu.etl et me concentre sur la vue « CPU Sampling by Thread » :

Nous constatons bien que l’utilisation cpu est correcte pendant un moment puis passe en 100% cpu. Si je sélectionne une plage pendant cette période de 100% et fais un clique droit + « Summary Table ». J’obtiens les informations suivantes :

Il est maintenant clair que 99.06% du temps cpu est utilisé par apisend.exe. Nous pouvons récupérer plus d’informations en cliquant sur la croix devant notre nom de processus :

Nous obtenons ainsi la distribution du temps cpu par composant. Cette vue nous indique que 98.37% du temps cpu s’est effectué dans win32k.sys. Nous sommes donc bien en mode kernel et notre problème a un rapport avec le GDI.

Nous pouvons continuer la même démarche et descendre dans le détail des fonctions utilisées par win32k.sys en cliquant sur la croix dans la colonne « Function ». Nous obtenons ainsi :

Le/les appels à la fonction à l’adresse 0xbf876531 consomme(nt) 79.97% de notre temps cpu. Nous pouvons maintenant utiliser cette adresse à partir du kernel dump pour trouver notre coupable (ou victime).

Le débogueur nous indique que nous sommes dans du code ayant un rapport avec les Timers Windows. Les Timers sont bien gérés par la partie GDI (win32k.sys).

La situation est donc la suivante : cette application utilise des timers pour effectuer certaines tâches et, après quelques minutes, l’utilisation de ces Timers entraine un 100% cpu.

Pour aller plus loin, il nous faut donc comprendre ce que fait cette application et obtenir les morceaux de code concernant la manipulation des Timers.

Conclusion

Après analyse du code, nous avons apporté 2 modifications :

1- Le code était implémenté de telle manière qu’en cas d’erreur d’accès aux données, le Timer crée (pour effectuer une annulation de la requête de manière asynchrone) n’était jamais détruit. Nous avons donc ajouté un KillTimer() en cas d’erreur.

2- Lors de l’appel du handler de Timer, celui-ci n’était détruit que juste avant de quitter ce handler. Nous avons modifié cette implémentation afin de détruire le handler le plus tôt possible pour éviter des problèmes de réentrance si jamais le code (ODBC) devait prendre plus de temps que la durée du Timer lui-même.

Une fois ces 2 modifications apportées, l’application et le serveur se sont mis à fonctionner parfaitement bien.

Epilogue

Xperf est vraiment un outil extrêmement puissant. Il me parait indispensable de savoir l’utiliser. Xperf EST l’outil standard de tracing pour Windows Vista, Windows 2008 et les prochaines versions d’OS. Xperf peut être utilisé (pour la partie Kernel) sous Windows 2003 et Windows XP mais ne s’installera pas sur ces plateformes. Il faudra donc l’installer sur un Vista ou un 2008 puis copier l’intégralité du répertoire sur 2003 ou XP.

Merci de m’avoir lu jusqu’ici :-)

Hervé Chapalain

Windows Core Escalation Engineer