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 !!!!

http://www.microsoft.com/technet/scriptcenter/tools/logparser/default.mspx

 

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

This site uses Akismet to reduce spam. Learn how your comment data is processed.