Connaître les temps d’exécution … sans Développeur Dashboard!

  • Article

En analysant des problèmes de performance, je me suis confronté à un environnement où le developer dashboard n'est pas disponible.

Les logs ULS contiennent les temps d'exécution dans les évènements B4LY. Les évènements B4LY ne sont logués que lorsque pour le produit SharePoint Foundation, la catégorie Monitoring est à High ou plus verbeuse.

J'ai écrit un script PowerShell pour extraire les temps d'exécution des logs ULS, pour un correlation ID donné. L'objectif est de comprendre rapidement ce qui a consommé le temps de réponse. J'ai publié le script à https://dumpexecutiontime.codeplex.com/  

La documentation complète (syntaxe, exemples, paramètres) est disponible sur codeplex.

Pour extraire les temps d'exécution:

  1. Mettre le niveau de diagnostic pour le produit SharePoint Foundation, catégorie Monitoring à High ou supérieur.
  2. Reproduire le problème
  3. Enregistrer localement le script Dump-ExecutionTime.ps1 depuis https://dumpexecutiontime.codeplex.com/.
  4. Dans une session PowerShell, exécuter Dump-ExecutionTime.ps1 :

dir v:*log | C:\Tests\Dump-ExecutionTime.ps1 -Threshold 500

La sortie sera par exemple:

Extracting Execution Times above 500 ms from file V:\srs\Ignacio Verbose-c52663.log with correlation

id matching *

ExecTime         Monitored Scope
----------       ------------------------------
   729.130       Leaving Monitored Scope (Directory Search).
   792.014       Leaving Monitored Scope (Directory Search).
   666.610       Leaving Monitored Scope (PortalSiteMapNode: Populating navigation children for web:

/<PII:..>).
   722.340       Leaving Monitored Scope (Directory Search).
   659.460       Leaving Monitored Scope (Directory Search).
   675.208       Leaving Monitored Scope (Directory Search).
   510.887       Leaving Monitored Scope (Directory Search).
   616.288       Leaving Monitored Scope (Directory Search).
   603.682       Leaving Monitored Scope (Directory Search).
   523.035       Leaving Monitored Scope (Directory Search).
   592.420       Leaving Monitored Scope (Directory Search).
   507.795       Leaving Monitored Scope (Directory Search).
   620.947       Leaving Monitored Scope (Directory Search).
 8,580.957       Leaving Monitored Scope (Render the Web part of the PII own documents).
 8,581.096       Leaving Monitored Scope (Redner the Web part- Main).
 8,641.322       Leaving Monitored Scope (SharePointForm Control Render).
14,294.430       Leaving Monitored Scope (Request GET:https://server.domain.com/Forms/AllItems.aspx)).

17 monitored scopes matched, for a total of 48317.62 ms

Dans cet exemple, les appels à Directory Search (surlignés en jaune) sont responsables de la plus grande partie du temps de réponse.

Je remercie Dominique Vives pour la relecture de ce billet.

Vincent Runge