This project is read-only.

DESCRIPTION

Extracts the B4LY tags matching the specified correlation ID mask from the specified ULS file.

It is also possible to specify a Threshold, so only the slowest Executions are displayed.

Totalisation is the sum of all Execution time matching the correlationID.

IMPORTANT: As some scopes are included in other, the TotalExecTime do not represent the Time for the beginning.

Example using CorrelationId mask

.\DUMP-ExecutionTime.1.ps1 -file Vince88050ULS.log -CorrelationId *913f689c-a6dc-d0a4-8cee-724e694865a6* -showTotalColumn

Extracts all Execution time for correlation ID 913f689c-a6dc-d0a4-8cee-724e694865a6

The output will be like

ExecTime TotalExecTime Monitored Scope
------ ------------- ------------------------------
40.603 40.603 Leaving Monitored Scope (PostResolveRequestCacheHandler).
27.523 68.126 Leaving Monitored Scope (GetFileAndMetaInfo).
28.289 96.415 Leaving Monitored Scope (GetWebPartPageContent).
47.070 143.485 Leaving Monitored Scope (PublishingMobile: Resolve the default or non-default
...CUT...
16,747.120 43,092.380 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/sites/<PII:H

88 monitored scopes matched, for a total of 43092.38 ms


Example Using Threshold


.\DUMP-ExecutionTime.ps1 -Threshold 2000 -file vrunge88050ULS.log

Extracts all Execution times above 2000 ms, regardless of their correlation ID. This allows for easy identification of the slowest executions.

Extracting Execution Times above 2000 ms from file c:\vincent\tests\psdump-executiontime\vrunge88050_ULS.log

The Output will be:

Extracting Execution Times above 2000 ms from file c:\vincent\tests\psdump-executiontime\vrunge88050_ULS.log
with correlation id matching *

ExecTime Monitored Scope
------ ------------------------------
2,282.073 Leaving Monitored Scope (DataBinding DataFormWebPart (Cust-K<PII:H101(uyeoIB3fqKZMcSfzsPRP5Vo...
2,620.962 Leaving Monitored Scope (DataBinding DataFormWebPart (Cust-Ohjeet)).
16,747.120 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/sites/<PII:H101(...

3 monitored scopes matched, for a total of 21650.16 ms

Example with multiple files

dir *log | .\Dump-ExecutionTime.ps1 -Threshold 2000

Extract all scopes above 2 seconds from all files with LOG extension.
Example Output:

Extracting Execution Times above 2000 ms from file C:\vincent\tests\PS_Dump-ExecutionTime\anotherlog.log with correlation id matching *

ExecTime Monitored Scope
------ ------------------------------
2,282.073 Leaving Monitored Scope (DataBinding DataFormWebPart (Cust-K<PII
2,620.962 Leaving Monitored Scope (DataBinding DataFormWebPart (Cust-Ohjeet)).
16,747.120 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/sites/blah/<Default.aspx)).

3 monitored scopes matched, for a total of 21650.16 ms

-----------------------------------------------------------------------------------------


Extracting Execution Times above 2000 ms from file C:\vincent\tests\PS_Dump-ExecutionTime\Ignacio Verbose-c526639c.log with correlation id matching *

ExecTime Monitored Scope
------ ------------------------------
8,580.957 Leaving Monitored Scope (Scope Name 1).
8,581.096 Leaving Monitored Scope (This is another scope).
8,641.322 Leaving Monitored Scope (SharePointForm Control Render).
14,294.430 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/Forms/AllItems.aspx)).

4 monitored scopes matched, for a total of 40097.8 ms

-----------------------------------------------------------------------------------------


Extracting Execution Times above 2000 ms from file C:\vincent\tests\PSDump-ExecutionTime\vrunge88050_ULS.log with correlation id matching *

ExecTime Monitored Scope
------ ------------------------------
2,282.073 Leaving Monitored Scope (DataBinding DataFormWebPart (blah.
2,620.962 Leaving Monitored Scope (DataBinding DataFormWebPart (list2).
16,747.120 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/sites/>/Default.aspx)).

3 monitored scopes matched, for a total of 21650.16 ms

-----------------------------------------------------------------------------------------


Processed 3 files

PARAMETERS

file

The ULS file to scan. This parameter is here for simple command line writing.

files

a collection of ULS files to scan.
This is mapped to the pipeline input. So the line below would dump the exec times for all *.log files
dir {*.log} | Dump-ExecutionTime.ps1 -Threshold 300

CorrelationId

MASK for matching correlation ID, eg *913f689c-a6dc-d0a4-8cee-724e694865a6*
If not specified, all correlation ID will match the default value "*".

Threshold

Only Execution time above this value will be considered.
Threshold is in milliseconds.

ShowTotalColumn

Whether to show the TotalExecTime column.

NOTES

Event B4LY are logged when the logging for the product "SharePoint Foundation", category "Monitoring"
is set to "High" or more.

Last edited Jan 19, 2014 at 9:07 PM by VRunge, version 7