Execution times without Developer Dashboard?

  • Article

While analyzing performance issues, I came across a situation where the developer dashboard is not available.

ULS logs actually contain the execution times, in events with tags b4ly. The b4ly events are only logged when the logging for the product SharePoint Foundation, category Monitoring is set to High or more.

I wrote a powershell script to extract execution times from ULS logs, for a given correlation ID. The goal is to understand quickly what took time when processing the request.I've published the script as on https://dumpexecutiontime.codeplex.com/  . Examples and parameter details are described at https://dumpexecutiontime.codeplex.com/documentation

To extract the execution times:

  1. Set the logging level for the product SharePoint Foundation, category Monitoring to High or more.
  2. Reproduce the issue
  3. Retrieve the Dump-ExecutionTime.ps1 script from https://dumpexecutiontime.codeplex.com/ and save it locally
  4. Start powershell & run Dump-ExecutionTime.ps1 , e.g.

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

The output is like below:

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 (Render 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

In this example, the Directory Searches are responsible for most of the response time.

Enjoy!

Vincent Runge