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:\o12sp\dev12sp\search2\ytrip\tripoli\icommand\qp.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