Search query awful performances

[ilocatelli2]

Hi

I'm experiencing a big performance problem on query performance on a CQ 5.4 instance.

Some info:

CQ 5.4 - all hotfixes applied

repository.xml and workspace.xml optimizations done (index cache set to 150000),  bundle cache size to 1024 Mb... even indexInMemory set to true (is it doing something really good?)

Memory: 10 Gb

Repository: approx 500.000 pages  ... some millions of nodes

Workspace: approx 30Gb... Lucene index folder: approx 30Gb    Datastore: approx 500 Gb

Restarting CQ, no editors working on it, going in site admin and simply making a search with the simple 'searchfield' placed on the top right corner.

This is the equivalent query reported in error.log:

ROOT=group: limit=6, excerpt=true, offset=0[
{group=group: or=true[
{0_fulltext=fulltext: relPath=jcr:content, fulltext=auto*}
{1_fulltext=fulltext: relPath=jcr:content/@jcr:title, fulltext=auto*}
{2_fulltext=fulltext: relPath=jcr:content/@jcr:description, fulltext=auto*}
]}
{path=path: path=/content}
{type=type: type=nt:hierarchyNode}
{orderByScore=orderby: sort=desc, orderby=@jcr:score}
]

Time required to complete... incredibly long.... about 15 minutes... here follows time spent from error.log.

19.12.2013 20:30:15.538 *INFO* [10.46.128.3 [1387480183910] GET /content.search.json HTTP/1.1] com.day.cq.search.impl.builder.QueryImpl xpath query took 1231613 ms
19.12.2013 20:30:15.538 *INFO* [10.46.128.3 [1387480183910] GET /content.search.json HTTP/1.1] com.day.cq.search.impl.builder.QueryImpl >> xpath query returned 46263 results
19.12.2013 20:30:15.538 *INFO* [10.46.128.3 [1387480183910] GET /content.search.json HTTP/1.1] com.day.cq.search.impl.builder.QueryImpl entire query execution took 1231613 ms
19.12.2013 20:30:15.538 *INFO* [10.46.128.3 [1387480486038] GET /content.search.json HTTP/1.1] com.day.cq.search.impl.builder.QueryImpl xpath query took 929500 ms
19.12.2013 20:30:15.538 *INFO* [10.46.128.3 [1387480486038] GET /content.search.json HTTP/1.1] com.day.cq.search.impl.builder.QueryImpl >> xpath query returned 46263 results
19.12.2013 20:30:15.538 *INFO* [10.46.128.3 [1387480486038] GET /content.search.json HTTP/1.1] com.day.cq.search.impl.builder.QueryImpl entire query execution took 929500 ms

During query execution I analyzed disk resources with a performance monitor. I'm attaching the screen capture. Many lucene index files opened and a lot of I/O activity.

I'm really concerned about this situation. After first execution caches are populated and other queries will progressively take less time... they start to be 'normal'. But as soon as caches are discarded, bad performances come back.

This situation is creating a lot of problems to editorial activity and also to search functionalities on publish site.

I understand that JCR does not have direct support for ordering... so the OOTB query done by CQ in this case is really heavy... but... hey... we cannot think to make queries without ordering results :)

The same situation with a SQL Query on a database would be completed in few seconds, not minutes. So I would like to think that there is some I/O problem that is forcing a query to last 15 minutes instead of 5 seconds as it should be at max.

Any help will be really appreciated.

[smacdonald2008]

I will send an email to the Performance team and get them to comment on this forum thread. 

[Sham_HC]

In my experience Performance issue has various cause & factors to be considered so need step by step approach.  I would recommend get official help by filling daycare ticket.

[Jörg_Hoh · Accepted solution]

Lucene is a reverse-index; you can imagine it as a huge hashmap with this relation:

{term} => {position1, position2, ...}

Now, when you do a fulltext search, you have look at many many terms to find all matches of "auto*".

The next step in your query is to create the build the path of each item found in the index. The path of every item in the lucene index is not stored in the index, instead the persistence manager is consulted to provide the name of the parent node, as much as needed. As you have a constraint "must be below /content", the search implementation must iterate through all parent nodes of all found items to satisfy this constraint.

Of course this doesn't explain why your query took soo much time. To analyze this we would need more information on the details of your specific bottleneck. Some other recommendations:

• You might want to get rid of the path constraint, especially if you know, that it occurs only there.
• Update to a later version; in newer versions of JCR some optimizations of the query engine have been implemented, which might improve performance of your query.

Jörg