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