Troubleshooting Indexing with ULS Log

I thought this addition deserved it’s own post.  Not burried in the previous which again comes from Nick Hardin and Sam Crewdson’s MS IT performance presentation AG207.  Not sure who gathered this, but this was in the appendix and not shared at the conference other than in the deck…
The following process can be used to figure out where search query time is being spent.
ULS logs should be on a separate fast drive
Set tracing level for MS Search Query Processor category to High.
01/23/2008 19:29:28.42  w3wp.exe (0x0680)   0x13C8    
Search Server Common MS Search Query Processor    0    High        
Completed query execution with timings: 437 328 297 234 172 124 – File:c:o12spdev12spsearch2ytriptripoliicommandqp.cxx Line:1750
The 5 numbers v1,v2,v3,v4,v5, v6 (in the sample above 437 328 297 234 172 124) are time measurements in milliseconds
V1 = Total time spent in QP. V2-V1 = Time spent retrieving properties and hit highlighting.
V2 = Latency of the query measured after the duplicate detection. V3-V2 = Duplicate detection time
V3 = Latency of the query measured after security trimming. It includes V4 plus retrieval of descriptors form SQL and access check. V3-V4 = Security Trimming time
V4 = Latency of the query measured after the joining of index results with the SQL part of the query. This includes V5 and the time spent in SQL for resolving the SQL part of advanced queries (e.g. queries sorted by date or queries including property based restrictions like AND size > 1000).  In short: V4-V5 = Join time
V5 = Time spent waiting for the full-text query results from the query server (time spent in index).
V6 = Cumulated time spent in various  calls to SQL except the property fetching.
Then use the logparser on it !!!!
LogParser "Select Timestamp, Extract_token(Message,6, ‘ ‘) as TotalQPTime, Extract_token(Message,10, ‘ ‘) as TimeSpentInIndex from ‘<servername>-<output-format>.log’ Where Category = ‘MS Search Query Processor’ AND Message Like ‘Completed query execution with timings:%’" -i:TSV -iCodepage:-1 -fixedSep:ON

Published by

Joel Oleson

I LOVE traveling our little planet. In my quest to visit every country in the world I've got about 35 UN countries left! I'm not just country hopping, but looking for the most immersive cultural experiences and capturing them as photos and videos. Yes, I'm also a geek. I've been recognized as a Microsoft Regional Director, a community leadership award. When not traveling, I'm in paradise in sunny southern California as I'm a Senior IT Manager at Blizzard Entertainment.

Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s