Using ULSViewer and Regex to narrow down SharePoint performance problems

Just wanted to share a trick I use often to gain better understanding of a SharePoint performance issue.

I'm sure we've all seen ULS log entries that say something like this:

Leaving Monitored Scope (SomeOperationName). Execution Time = 2.344050348

If not, look at your SP2010 or higher ULS logs and you'll definitely see a bunch of them.

 

On to the point of this post. If you wanted to quickly identify long running operations directly in ULSViewer, you can use RegEx to quickly filter the timing data.

The steps to do this is as follows:

1. Connect ULSViewer to live server data OR to a set of log files (CTRL+U OR CTRL+O)

2. Select Modify Filter from the Edit menu (CTRL+M)

3. In the Field column, select Message

4. In the Operation column, select Regex Match

5. In the Value column, type or paste in the beginning portion of the text you want to match on, eg if you wanted all slow operations, type in Execution Time=

6. Next plug-in the regex you wish to apply right after the = sign. The entire string in the value column would look something like: Execution Time=[1-9]{1}[0-9]{3}

 

Super duper quick primer on how to apply regex:

1. First, understand that the timing data is in milliseconds and there are 1000 ms in 1 second. (so a 5 second operation will have timing that is >= 5000)

2. Next, understand what you're interested in chasing after. Are you wanting to see all timings that took longer than 5 seconds/30 seconds etc.

3. Next craft your regex. Let's use an example for illustration.

For requests that took longer than a second, the regex would be: [1-9]{1}[0-9]{3}

Explanation:

The first half of the regex [1-9]{1}, looks for the occurence of the numbers 1 through 9 in the first digit following the = sign

The second half of the regex [0-9]{3}, looks for  the occurence of the numbers 0 through 9 in the next 3 digits

So to identify requests that took longer than 10 seconds, your regex would be: [1-9]{1}[0-9]{4}

The regex for requests that took longer than 30 seconds would be [3-9]{1}[0-9]{4}

 

At any rate, this little trick lets me identify performance issues such as these: