Troubleshooting: Long load times for query response pages
Slow response times to search queries can have various causes. A systematic process for investigating such delays is provided.
Problem
Long delays in loading a search result page or category page might be due to preprocessing, postprocessing, or even REST service issues on the side of the WebSphere Commerce server. A systematic investigation that eliminates WebSphere Commerce causes and identifies Search server-related issues can quickly find the cause.
, then the first step is to identify whether the problem lies with the Search server, or with WebSphere Commerce itself. If the issue is on the Search side, you can test each of the query stages (preprocessing, query execution, and postprocessing) to determine which is the source of the delay. With the query lifecycle stage determined, the final step is to isolate the specific process that is causing the delay.
Eliminating causes on the WebSphere Commerce side
If all you know, initially, is that query responses are taking too long, then determine whether it is the Search server or WebSphere Commerce that is causing the problem. For instance, say that a search for the word "coffee" is taking 25 seconds to complete. You can start troubleshooting on the WebSphere Commerce side by enabling Performance Logger tracing. Review the logging data in the Performance Measurement Tool. The Operation Performance Report (from the report-operations.csv file) shows how long each query operation took. Say that the REST request to retrieve product data for the coffee search is shown to be taking over 20 seconds to respond to the WebSphere Commerce server with the search results. Since 80% of the query delay is due to activities in the Search server, it is reasonable to look there for answers.
Solution
- Time is required for the construction of the search query.
- Execution of the search query takes time.
- Time is also required for any further processing of the search query's results before it is returned to the WebSphere Commerce server.
com.ibm.commerce.foundation.logging.ServiceLogger=finest
tracing enabled, the log
shows the elapsed time for each class that is called by the
process.[12/16/15 10:38:34:054 EST] 00000028 ServiceLogger <
REST <com.ibm.commerce.foundation.server.services.rest.search.expression.solr.SolrRESTSearchBasedMerchandisingExpressionProvider>
<elapsed:1032ms> RETURN
[12/16/15 10:38:34:066 EST] 00000028 ServiceLogger <
REST <com.ibm.commerce.foundation.server.services.rest.search.expression.solr.SolrRESTSearchTermAssociationExpressionProvider>
<elapsed:11ms> RETURN
[12/16/15 10:38:34:076 EST] 00000028 ServiceLogger <
REST <com.ibm.commerce.foundation.server.services.rest.search.expression.solr.SolrRESTSearchByKeywordRelevancyExpressionProvider>
<elapsed:10ms>
…
<com.ibm.commerce.foundation.server.services.rest.search.expression.solr.SolrRESTSearchExpressionProvider>
<elapsed:1119ms> RETURN
In
this example, the SolrRESTSearchBasedMerchandisingExpressionProvider
class took
1032 ms of the total 1119 ms for processing expression providers. This class is used to process
search rules and apply relevant search rules to the search query. You can use similar
troubleshooting for the query preprocessors to identify any that are running for a long period.<response>
<lst name="responseHeader">
<int name= "status">0</int>
<int name="QTime">52</int>
<lst name="params">
<Str name="q">coffee</str>
<Str name="ps">2</str>
<Str name="debugQuery">true</str>
<Str name="fl">name</str>
<Str name="pf">name^100</str>
<Str name="defType">edismax</str>
<result name="response" numFound="52" start="0 >
In
the example, QTime represents how long the search query took to complete in
milliseconds. The params list includes all the parameters of the search query,
and the values used for each parameter. numFound shows how many Solr documents
were found in the index based on the search query. Using this data, you can confirm how long the search query itself took to complete in relation to the entire scenario (for instance, a 52 ms search query versus a 15-second page load). If the search query had a high QTime, you can review the parameters of the query to confirm that the complexity of the query is expected.
<lst name="debug">
<Str name="rawquerystring">coffee</str>
<Str name="querystring">coffee</str>
<Str name="parsedquery">
(+DisjunctionMaxQuery((defaultSearch:coffe)) ())/no coord
</str>
<Str name="parsedquery_toString">+(defaultSearch:coffe) ()</str>
<lst name="explain">
<Str name=" 17010">
2.0115635 = (MATCH) sum of: 2.0115635 = (MATCH)
weight(defaultSearch:coffe in 3057) [DefaultSimilarity] , result of:
2.0115635 = score(doc=3057 = termFreq=3.0 ) , product of:
0.99999994 = queryWeight, product of: 5.3091516 =
idf(docFreq=52, maxDocs=3942) 0.188354 = queryNorm 2.0115638
= fieldWeight in 3057 , product of: 1.7320508 = tf(freq=3.0), with
freq of: 3.0 = termFreq=3.0 5.3091516 = idf(docFreq=52,
maxDocs=3942) 0.21875 = fieldNorm(doc=3057)
</str>
The
debug parameter is added to the query response if a
debugQuery=true
parameter is added to the search query.
parsedquery shows what the search query looks like after the parameters of the
query are processed. The explain parameter contains the relevancy score
calculations for each catentry_id in the result. With this data, if the query
had a high QTime, you can review the parsedquery to
confirm how complex it is. A search for a single search term can quickly become complex if functions
such as search term associations, search rules, boosting, or phrase slop are used. <lst name="process">
<double ">50.0</double>
<lst name="wc_query">
<double name="time">40.0</double>
<lst name="wc facet">
<double name="time">0.0</double>
<lst name="mlt">
<double name="time">0.0</double>
<lst name="stats">
<double name="time">0.0</double>
<lst name="debug">
<double name="time">10.0</double>
<lst name="wc_spellcheck">
<double name="time">0.0</double>
com.ibm.commerce.foundation.logging.ServiceLogger=finest
tracing is enabled, the
log shows the time taken by each post-processing
class.[3/14/16 14:12:08:469 CDT] 00000029 ServiceLogger <
REST <com.ibm.commerce.foundation.server.services.rest.search.postprocessor.solr.SolrRESTSearchCatalogEntryViewAttributesQueryPostprocessor>
<elapsed:19609ms> RETURN
…
[3/14/16 14:12:08:469 CDT] 00000029 ServiceLogger <
REST <com.ibm.commerce.foundation.server.services.rest.search.processor.solr.SolrRESTSearchExpressionProcessor>
<elapsed:19890ms> RETURN
In
this example, the SolrRESTSearchCatalogEntryViewAttributesQueryPostprocessor
took
19.6 seconds out of 19.9 seconds for processing query post-processors. Further investigation by
using the tracing logs can help you determine why this query post-processor is taking so long to
run.