I know troubleshooting Search Query issues in SharePoint 2010 can be a difficult tasks.  Usually, the problem I’m asked to tackle is why are my queries slow?   I wanted to provide some additional detail and a behind the scenes look at what a Search Query looks like.    I recommend reviewing my original Search Query blog if you need to brush up on the related components and how they work together.

http://blogs.msdn.com/b/russmax/archive/2010/04/23/search-2010-architecture-and-scale-part-2-query.aspx 

Note:  This scenario is strictly SharePoint 2010 without Fast

I figured the best way to diagram what happens behind the scenes is to use the Query Flow steps from my original blog and break them apart with a series of logging techniques.   For Example (Network traces and ULS Logs)

When troubleshooting issues with Search Queries, It’s extremely important to identify how these moving parts operate together within the ULS logs and Network traces.   Also, within the ULS logs we do a very good job of logging the execution times of each particular function “monitored scope”.   The intent of this email is to provide you with a road map of how to walk a query behind the scenes with ULS logs and Network traces..

 

The main steps during Query Flow are the following:

1. A search is performed by a user

2. The WFE serving the call uses the associated search service application proxy to connect to a server running the Query and Site Settings Service also known as the Query Processor. It uses WCF for this communication.

3. The QP will connect to the following components to gather results merges\security trims and return results back to WFE:

  • Query Component - holds entire index or partition of an index
  • Property Store DB – holds metadata\properties of indexed content
  • Search Admin DB – holds Security Descriptors\Configuration data
  • 4. WFE displays search results to the user

     

    Below is a walkthrough of what a Query transaction looks like behind the scenes broken apart by the main steps above.

    My current environment is setup like the following:

    • WFE – Hosting the public facing sites for end users
    • APP - Hosts both the Query Component and the Query Processor

     

    Step 1 – A search is performed by a user

    The following query was for “Dirk”

    The following Request is submitted to the Web Front End the user is currently connected to:

    Http: Request, GET /_layouts/OSSSearchResults.aspx, Query:k=Dirk&cs=This%20Site&u=http%3A%2F%2Fwfe, Using NTLM Authorization  

    Capturing this request with a network trace looks like:

    clientinitialquery

     

     

    Step 2 - The WFE serving the call uses the associated search service application proxy to connect to a server running the Query and Site Settings Service also known as the Query Processor. It uses WCF for this communication.

    Behind the scenes, a query is submitted against the designated server running the Query Processor via a web service call to that servers SearchService.svc web service.   Where is that located within IIS? 

    QP-webservice

     

    ULS Logs set to Verbose on the WFE

    01/27/2012 11:30:45.18    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Logging Correlation Data    xmnv    Medium    Name=Request (GET:http://wfe:80/_layouts/OSSSearchResults.aspx?k=Dirk&cs=This%20Site&u=http%3A%2F%2Fwfe)    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

     

    Call to the Query Processor via the SearchService.svc web service to execute the request:

    01/27/2012 11:31:17.12    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Monitoring    nasq    Verbose    Entering monitored scope (SharePointSearchRuntime::GetQueryResult)    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 11:31:17.15    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Monitoring    nasq    Verbose    Entering monitored scope (Execute)    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 11:31:17.15    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Topology    e5mc    Medium    WcfSendRequest: RemoteAddress: 'http://app:32843/6c270a2117544235b521a8e5a864c5f6/SearchService.svc' Channel: 'Microsoft.Office.Server.Search.Administration.ISearchServiceApplication' Action: 'http://tempuri.org/ISearchQueryServiceApplication/Execute' MessageId: 'urn:uuid:5c0fbea8-1ca8-4146-8150-c6d8b735adae'    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 11:31:17.15    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Monitoring    nasq    Verbose    Entering monitored scope (ExecuteWcfOperation:http://tempuri.org/ISearchQueryServiceApplication/Execute)    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

     

     

    Network Monitor

    WFE-PostToQP

    We send multiple Post request to the QP along with HTTP Payload.   The Post request with HTTP Payload that matters is the last one sent in the network conversation.  For example, the HTTP Payload contains the following:

    117    12:31:05 PM 1/27/2012    4.0724607    w3wp.exe    10.1.0.12    10.1.0.11    HTTP    HTTP:Request, POST /6c270a2117544235b521a8e5a864c5f6/SearchService.svc     {HTTP:11, TCP:10, IPv4:9}

    119    12:31:05 PM 1/27/2012    4.0746818    w3wp.exe    10.1.0.12    10.1.0.11    HTTP    HTTP:HTTP Payload, URL: /6c270a2117544235b521a8e5a864c5f6/SearchService.svc     {HTTP:11, TCP:10, IPv4:9}

    Frame 119 is important as the payload information contains the method “Execute”  and the QueryText “dirk”:

    http://tempuri.org/ISearchQueryServiceApplication/ExecuteD.­º?$íe¡ïH¡´?¸Ìúb?D,D*«..@.ServiceContext.6http://schemas.microsoft.com/sharepoint/servicecontext..i)

    http://schemas.datacontract.org/2004/07/Microsoft.Office.Server.Search.Query._.PartitionId?$00000000-0000-0000-0000-000000000000_.PersonalizationData..nil?._.QueryText?.dirk_.RankingModelId._.ResultTypes?.RelevantResults_.ResultsProvider?.SharepointSearch_.RowLimit?2_.RowsPerPage?._.Sid._.SiteId?$195a8767-f198-4491-a994-353973710934_

     

     

    Step 3 - The QP will connect to the following components to gather results merges\security trims and return results back to WFE

  • Query Component - holds entire index or partition of an index
  • Property Store DB – holds metadata\properties of indexed content
  • Search Admin DB – holds Security Descriptors\Configuration data
  •  

    ULS Logs set to Verbose on the Server hosting the Query Processor

    Here is the inbound request from the WFE.

    01/27/2012 09:31:16.93    w3wp.exe (0x1544)    0x1644    SharePoint Foundation    Topology    e5mb    Medium    WcfReceiveRequest: LocalAddress: 'http://app.contoso.local:32843/6c270a2117544235b521a8e5a864c5f6/SearchService.svc' Channel: 'System.ServiceModel.Channels.ServiceChannel' Action: 'http://tempuri.org/ISearchQueryServiceApplication/Execute' MessageId: 'urn:uuid:5c0fbea8-1ca8-4146-8150-c6d8b735adae'    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 09:31:16.93    w3wp.exe (0x1544)    0x1644    SharePoint Foundation    Monitoring    nasq    Medium    Entering monitored scope (ExecuteWcfServerOperation)    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

     

    When the Query Processor starts on the request, it will get a new correlation ID:

    01/27/2012 09:31:17.13    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2ni    Verbose    Calling CQPCache::GetQPCache.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    Here is where Query Processor will start fetching results from the Query Component\s holding the index to retrieve results as well as the Search Property Store Database on the SQL server:

    01/27/2012 09:31:18.02    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2pp    Verbose    Entering Split Command Tree parser.                                             [splitter.cxx:184]  d:\office\source\search\native\ytrip\tripoli\icommand\splitter.cxx    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.43    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2ps    Verbose    Tree only had both FT and SQL constraints... split apart.                       [splitter.cxx:230]  d:\office\source\search\native\ytrip\tripoli\icommand\splitter.cxx    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    QP Fetching results from the Index:

    01/27/2012 09:31:18.43    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2jx    Verbose    Executing SubQuery FT Part:   op: (116) DBOP_and   wKind: (3) DBVALUEKIND_I4: 0   first child:     op: (145) DBOP_content_freetext     wKind: (259) DBVALUEKIND_CONTENT: 'Dirk ', method 0, weight 100000000, lcid 0x409     first child:       op: (5) DBOP_column_name       wKind: (258) DBVALUEKIND_ID: 012357bd-1113-171d-1f25-292bb0b0b0b0 2147450879   next sibling:     op: (68) DBOP_equal     wKind: (3) DBVALUEKIND_I4: 0     first child:       op: (5) DBOP_column_name       wKind: (258) DBVALUEKIND_ID: 012357bd-1113-171d-1f25-292bb0b0b0b0 2147418095     next sibling:       op: (0) DBOP_scalar_constant       wKind: (12) DBVALUEKIND_VARIANT VT_LPWSTR 'http://wfe'    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.66    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2kp    Verbose    Got 14 candidates from FT.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.66    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2ks    Verbose    Got some.. Now joining with SQL.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.66    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2et    Verbose    Candidates Query to SQL: /* {599CD6CE-7C0C-44E8-8983-0BE66F7176AD} */  SET NOCOUNT ON;DECLARE @joinData VARBINARY(MAX) ; SET @joinData = ? ; DECLARE @joinRows INT ; SET @joinRows = DATALENGTH(@joinData) / 8 ;;WITH DocIds(DocId, Value) AS ( SELECT TOP(@joinRows) CAST(SUBSTRING(@joinData, ((ord.n-1)*8) + 1, 4) AS INT), CAST(SUBSTRING(@joinData, ((ord.n-1)*8) + 5, 4) AS INT) FROM dbo.MSSOrdinal AS ord WITH(NOLOCK) WHERE ord.n <= @joinRows )  SELECT A.DuplicateHashes, A.HasPluggableSecurityTrimming, A.DocId, A.Sdid FROM DocIds AS T INNER LOOP JOIN MssDocSdids AS A ON T.DocId = A.DocId ORDER BY T.Value DESC OPTION (MAXDOP 1)    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.68    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2l2    Verbose    Got 14 candidates after join.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    Now Security Trimming and Dup removal of the results:

    01/27/2012 09:31:18.68    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2p4    Verbose    In CSecurityTrimmer::AccessCheck there were 1 unique sdids among the candidates.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.69    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2ke    Verbose    Had 14 candidates before sec-trimming, have 14 candidates after.  'fMoreCandidates' = 0.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.69    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2la    Verbose    Had 14 candidates before near dup removal, have 5 candidates after.  'fMoreCandidates' = 0.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    QP Fetching results from SQL Server:

    01/27/2012 09:31:18.69    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2jx    Verbose    Executing SubQuery SQL Part:   op: (68) DBOP_equal   wKind: (3) DBVALUEKIND_I4: 0   first child:     op: (5) DBOP_column_name     wKind: (258) DBVALUEKIND_ID: 012357bd-1113-171d-1f25-292bb0b0b0b0 7   next sibling:     op: (0) DBOP_scalar_constant     wKind: (12) DBVALUEKIND_VARIANT VT_LPWSTR 'http://Dirk'  FT Part:   op: (68) DBOP_equal   wKind: (3) DBVALUEKIND_I4: 0   first child:     op: (5) DBOP_column_name     wKind: (258) DBVALUEKIND_ID: 012357bd-1113-171d-1f25-292bb0b0b0b0 2147418095   next sibling:     op: (0) DBOP_scalar_constant     wKind: (12) DBVALUEKIND_VARIANT VT_LPWSTR 'http://wfe'    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.69    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2et    Verbose    Candidates Query to SQL: /* {599CD6CE-7C0C-44E8-8983-0BE66F7176AD} */  SET NOCOUNT ON; SELECT TOP 2797 A.DuplicateHashes, A.HasPluggableSecurityTrimming, A.DocId, A.Sdid FROM MssDocSdids AS A WITH (NOLOCK) LEFT OUTER JOIN dbo.MSSDocProps AS P7 WITH (NOLOCK) ON ( P7.DocId = A.DocId AND P7.Pid = 7 ) WHERE P7.llVal = ?    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.71    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2jd    Verbose    Got 0 candidates from this sub-query.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    Sort and Rank the Search Results:

    01/27/2012 09:31:18.71    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2jk    Verbose    Performing 'Multi Sub-Query sort-by-rank' final candidates code-path.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.71    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2jw    Verbose    Fetching Search-Results from property store.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    Query has been Completed by the Query Processor and Query Timings are logged:

    01/27/2012 09:31:18.74    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2jt    Medium    Completed query execution with timings: total:718 dup:0 sec:16 join:0 ft:234 sql:31. Join Retry: 0. Security Trimming Retry: 0. Duplicate removal Retry: 0.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    01/27/2012 09:31:18.76    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    g2jn    Verbose    Verbose query timings: total: 766, other: 454, ft: 0, sql: 31, join: 234, dup: 0, sec: 16, final sort: 0, best bets: 0, results retr: 0, high conf: 0, populate: 31.    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    QP Execute is completed

    01/27/2012 09:31:18.99    w3wp.exe (0x1544)    0x1644    SharePoint Foundation    Monitoring    b4ly    Medium   Leaving Monitored Scope (ExecuteWcfServerOperation). Execution Time=2069.4805    599cd6ce-7c0c-44e8-8983-0be66f7176ad

    The original inbound request is completed (Notice the Correlation ID matches the original execute call to the Web Service – original call above in red)

    01/27/2012 09:31:18.99    w3wp.exe (0x1544)    0x1644    SharePoint Foundation    Monitoring    b4ly    Medium    Leaving Monitored Scope (ExecuteWcfServerOperation). Execution Time=2069.4805    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    Important:  You might notice that the Query Processor decides to execute against SQL first and then the Full-Text index.   The decision making on why this happens is outside the scope of this blog but it’s dependent on the type of Search Query performed.

     

     

    Step 4 - WFE displays search results to the user

    ULS Logs set to Verbose on the WFE that originally serviced the request from Step 1

     

    When the Query Processor returns the results back to the WFE  (Notice this is the completion of the monitored scope in green)  The beginning of this request is at the top in green.

    01/27/2012 11:31:19.52    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Monitoring    b4ly    Verbose    Leaving Monitored Scope (ExecuteWcfOperation:http://tempuri.org/ISearchQueryServiceApplication/Execute). Execution Time=2400.0826    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 11:31:19.81    w3wp.exe (0x1140)    0x120C    SharePoint Server Search    Query    dk91    High    SearchServiceApplicationProxy::Execute--Id: Elapsed Time: 2664 QP Time: 1792 Sql Time: 31    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 11:31:19.81    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Monitoring    b4ly    Verbose    Leaving Monitored Scope (Execute). Execution Time=2703.0805    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 11:31:19.95    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Monitoring    b4ly    Verbose    Leaving Monitored Scope (SharePointSearchRuntime::GetQueryResult). Execution Time=2856.5793    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 11:31:20.09    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Monitoring    b4ly    Verbose    Leaving Monitored Scope (SharePointSearchRuntime::SendRequest). Execution Time=3025.3754    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

    01/27/2012 11:31:20.09    w3wp.exe (0x1140)    0x120C    SharePoint Server Search    Query    dln3    Verbose    GetResults on location LocalSearchIndex for Dirk completed with 5 results    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

     

    The WFE prepares the results for the User

    The WFE takes the above results and builds up the ossearchresults.aspx page by using the following monitored scopes:

    RefinementManager.GetRefinement
    OnPreRender
    CreateChildControls
    AddAssemblyReference
    DataBinding DataFormWebPart
    GetXPathNavigator
    UserPreference.GetUserPreference
    UserPreference.GetFromCache
    Render Ribbon
    SearchCommon::GetCurrentSiteCollectionProperty
    RenderWebPart
    PostRequestExecuteHandler
    EndRequestHandler SPRequest Disposal

     

    Finally when the page is rendered we leave the original Monitored Scope

    01/27/2012 11:31:33.40    w3wp.exe (0x1140)    0x120C    SharePoint Foundation    Monitoring    b4ly    Medium    Leaving Monitored Scope (Request (GET:http://wfe:80/_layouts/OSSSearchResults.aspx?k=Dirk&cs=This%20Site&u=http%3A%2F%2Fwfe)). Execution Time=48385.3272    9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

     

     

    Q&A Portion

    Question:    So how were you able to even identify the start of the Query conversation within Step 2 on the Web Front-End?  

    Answer:       First, download ULSViewer here:   http://archive.msdn.microsoft.com/ULSViewer

    Next, once you open the associated ULS log on the Web Front-End, you can hit (CTRL+M) to bring up the filter window.  Then do   a query like the following:

    Message Contains dirk.   (In my case, I submitted a query dirk.)  

     

    Question:    How did you find the other side of the conversation on the Query Processor under Step 3?

    Answer:       I used ULS Viewer and opened the associated ULS log on the Query Processor.   I then filtered (CTRL+M) for the following:

    Correlation ID Contains 9d7bacd8-0e70-4ffe-a293-cb2c9c41f205

     

    Question:    How did you find the associated Query Processor entries assuming more than one query is firing against the QP?

    Answer:       I used ULS Viewer and did a CTRL+F and queried for dirk.  I found it immediately from this entry:

    01/27/2012 09:31:18.43    w3wp.exe (0x1544)    0x1644    SharePoint Server Search    Query Processor    e2jx    Verbose    Executing SubQuery FT Part:   op: (116) DBOP_and   wKind: (3) DBVALUEKIND_I4: 0   first child:     op: (145) DBOP_content_freetext    

    wKind: (259) DBVALUEKIND_CONTENT: 'Dirk ', method 0, weight        100000000, lcid 0x409     first child:       op: (5) DBOP_column_name       wKind: (258) DBVALUEKIND_ID: 012357bd-1113-171d-1f25-292bb0b0b0b0 2147450879   next sibling:     op: (68) DBOP_equal    

    wKind: (3) DBVALUEKIND_I4: 0     first child:       op: (5) DBOP_column_name       wKind: (258) DBVALUEKIND_ID: 012357bd-1113-171d-1f25-292bb0b0b0b0 2147418095     next sibling:       op: (0) DBOP_scalar_constant       wKind: (12) DBVALUEKIND_VARIANT VT_LPWSTR 'http://wfe'    599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    With this log entry, you can see the category is Query Processor and the query term is defined.   I know from the entry this is request against the Full-Text Index.   Since this is my matching entry, I can grab the correlation ID off the end.  

    Now that I have the correlation ID, I can filter the ULS log with ULS viewer  to see the entire conversation:

    Correlation ID Contains 599cd6ce-7c0c-44e8-8983-0be66f7176ad

     

    Thanks!

    Russ Maxwell, MSFT   Cat face