Lucene-based search is slow as well?

[panokhin]

Based on the advice I've received in http://forums.alfresco.com/viewtopic.php?t=1908 I've redone search performance testing using the Alfresco's native Lucene-based API.

The model is like this: Site->Buyer->Buyer->Notice->LangProperty (please see http://forums.alfresco.com/viewtopic.php?t=1908 for the complete model definition)
There are about 5600 of LangProperties, 5600 of Notices and 800 of Buyers.
The computer has two AMD Opterons 252 and 8Gb memory, connecting to Oracle remotely on the local net.
I'm using Alfresco SDK 1.3 version with minor modifications for Oracle and our custom model.
I ran this query, while logged in as "admin":
"PATH:\"//dg:notices/dg:langProperties\" AND @dg\\ropText:\"loan\""
and results (around 300 objects) were given in between 60 and 70 seconds on different runs.
Similar queries on our own DB schema using Oracle Intermedia with the same hardware setup mostly return in under 8 seconds.

Here are statistics for different queries:

 "PATH:\"//dg:notices/dg:langProperties\" AND @dg\\:propText:\"loan\""
Duration: 63463
Size: 331

"PATH:\"//dg:notices/dg:langProperties\" AND @dg\\:propText:\"solicitation\""
Duration: 1013
Size: 4

"PATH:\"//dg:notices/dg:langProperties\" AND @dg\\:propText:\"water\""
Duration: 39908
Size: 218
‍‍‍‍‍‍‍‍‍‍‍‍‍

It looks to me that query time depends directly on the number of objects in the result.
I would also say that 200-300 objects in a result is typical for our system and 1 minute response time is unacceptable for an interactive service.

As far as I understand, statistically, 7-8 seconds is the most time people would wait in front of a monitor.
Based on the above statistics, under 8 seconds search times are achievable only for results with ~50 objects. And I'd guess on average in a big system search result would be bigger than that.

So the question is, do you think there is any way to cut down these search times? And if yes, in what way?

Thanks,
Philipp.

[andy]

Hi

This is much higher than I would expect.

Can you tell me how long the following take:

1) "PATH:\"//dg:notices/dg:langProperties\""

2) "@dg\\ropText:\"loan\""

3) "+PATH:\"//dg:notices/dg:langProperties\" +@dg\\ropText:\"loan\""

4) "ISNODE:*"

How are you running the queries? Which API?

Regards

Andy

[panokhin]

Here are the statistics:

"PATH:\"//dg:notices/dg:langProperties\""
Duration: 788858
Size: 5596

"@dg\\:propText:\"loan\""
Duration: 72269
Size: 390

"+PATH:\"//dg:notices/dg:langProperties\" +@dg\\:propText:\"loan\""
Duration: 63902
Size: 331

"ISNODE:*"
Duration: 6334553
Size: 15339
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

I'm using the following code to do querying:

            Session sessionJCR = repository.login(new SimpleCredentials("admin","admin".toCharArray()));
            Node rootNode = sessionJCR.getRootNode();
            SearchParameters sp = new SearchParameters();
            NodeRef rootNodeRef = JCRNodeRef.getNodeRef(rootNode);
            sp.addStore(rootNodeRef.getStoreRef());
            sp.setLanguage(SearchService.LANGUAGE_LUCENE);
            sp.setQuery(…);
            ResultSet results = registry.getSearchService().query(sp);
‍‍‍‍‍‍‍‍‍‍

[andy]

Hi

What exactly are you timing?
Does it take as long if you repeat the queries?
Are you running all of these queries cold or one after the other?


ISNODE:* is very fast in lucene.
After that permissions should be applied to the results.

You could trying limiting the results set.

This is way longer than expected.

How much memory has the JVM got?
How much CPU time does the JVM get?
How much work is the database doing?

Regards

Andy

[panokhin]

After analyzing SQL generated by Alfresco queries, I think I found the reason for poor performance.
By the look of it, for every node hit returned from Lucene search to Alfresco, 5 separate SQL queries are issued to retrieve the node permissions and properties (see below). Of course, on different DBs these queries would take different time to run, but still they are run for EVERY node in the result set.
In my opinion, it's a fundamental flaw in the design, which stems from separation of the search and result retrieval. Since search is handled by Lucene outside of persistence layer, Hibernate gets a set of IDs as an input, so it has to run separate queries for each ID. Therefore none of the Hibernate's retrieval optimization strategies (like fetch="subselect" in the mapping file) are used.
This probably could be remedied by issuing a mirror query in Hibernate with the IDs from Lucene using IN clause and fetch="subselect", though IN queries are considerably slower in most databases.
Untill then, unfortunately, I doubt that Alfresco's performance would be adequate for production-sized systems.

select * from node_status nodestatus0_, node nodeimpl1_, store storeimpl2_, access_control_list dbaccessco3_, access_control_entry entries4_, node_properties properties5_, node_aspects aspects6_
where nodestatus0_.node_id=nodeimpl1_.id(+) and nodeimpl1_.protocol=storeimpl2_.protocol(+) and nodeimpl1_.identifier=storeimpl2_.identifier(+) and nodeimpl1_.id=dbaccessco3_.node_id(+) and dbaccessco3_.id=entries4_.acl_id(+) and nodeimpl1_.id=properties5_.node_id(+) and nodeimpl1_.id=aspects6_.node_id(+) and nodestatus0_.protocol=? and nodestatus0_.identifier=? and nodestatus0_.guid=?

select * from child_assoc parentasso0_, node nodeimpl1_, store storeimpl2_, access_control_list dbaccessco3_ 
where parentasso0_.parent_node_id=nodeimpl1_.id(+) and nodeimpl1_.protocol=storeimpl2_.protocol(+) and nodeimpl1_.identifier=storeimpl2_.identifier(+) and nodeimpl1_.id=dbaccessco3_.node_id(+) and parentasso0_.child_node_id=?

select * from node_aspects aspects0_ where aspects0_.node_id=?

select * from node_properties properties0_ where properties0_.node_id=?

select * from node_status nodestatus0_, node nodeimpl1_, store storeimpl2_, access_control_list dbaccessco3_, access_control_entry entries4_, node_properties properties5_, node_aspects aspects6_
where nodestatus0_.node_id=nodeimpl1_.id(+) and nodeimpl1_.protocol=storeimpl2_.protocol(+) and nodeimpl1_.identifier=storeimpl2_.identifier(+) and nodeimpl1_.id=dbaccessco3_.node_id(+) and dbaccessco3_.id=entries4_.acl_id(+) and nodeimpl1_.id=properties5_.node_id(+) and nodeimpl1_.id=aspects6_.node_id(+) and nodestatus0_.protocol=? and nodestatus0_.identifier=? and nodestatus0_.guid=?
‍‍‍‍‍‍‍‍‍‍‍‍‍‍

[andy]

Hi

It is possible to request a limited results set that will only consider the first n entries. Are you going to display all the results? See the options on the SearchParameters object.

The hibernate configuration can be optimised for given use cases….however…

It seems you are getting no benefit from the L2 cache in hibernate, or any other of our caches.
How long do the queries take if you do not run them all against a cold repository (and therefore have to populate everything each time)? Run a mixed pattern of all your queries over time. How does this behave?

All your data should be held in memory after the first few queries.
(Which is what oracle will be doing …)

We will be adding pre-fetching to populate the L1 cache using a list of nodes at some point. The result set can then use this.

The query speed is till very slow. You seem to be getting 26 queries/second from your DB … ( 331*5/64)
Which version of oracle are you using?
Is TCP_NODELAY true for the DB connection?
What is the cpu load on the DB and repository during your queries?


Regards

Andy