HS : Slow Query Times on ubuntu

lovelyliatroim · **Joined:** Thu Oct 08, 2009 10:34 am **Posts:** 55

Hi Guys,
Im experiencing slow times for my queries and was wondering if you guys ever seen anything like this before. I suspect it is something to do with the reopening of the reader but unfortunately i cant replicate the behaviour locally.

Index size is 1.6g for the class entity index, overall index size is 1.9g. Im using the HS version 3.1 upgraded with lucene 2.9 version (any problems with this combination?? Needed to upgrade due to memory leak in JVM which is patched in 2.9).

If I run the queries on my laptop, XP i get an average response time of 1.2secs for my queries. The same queries on our DEV machine takes on average 10 seconds. Our DEV machine is running on Ubuntu. I know roughly where the time loss is but I dont know why.

Here is my logs from the ubuntu machine, i have switched between SimpleDSDirectory and NIOFSDirectory, both perform miserably.

Quote:

12:42:10,831 [Thread-16] TRACE hibernate.search.impl.SearchFactoryImpl - Targeted indexed classes for [class com.mycompany.FooBar]: [class com.mycompany.FooBar]
12:42:10,831 [Thread-16] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Opening IndexReader for directoryProviders: 1
12:42:10,831 [Thread-16] TRACE hibernate.search.reader.SharingBufferReaderProvider - Opening IndexReader from org.apache.lucene.store.NIOFSDirectory@/var/lucene/shared/com.mycompany.FooBar/2
12:42:17,825 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2218638
12:42:17,825 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2218639
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2218640
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2218641
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2969586
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2969587
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2969588
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2219772
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2219773
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2219774
12:42:17,826 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2219775
12:42:17,827 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2220900
12:42:17,827 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394037
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394038
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394039
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3442546
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3574079
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3574080
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394759
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394760
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394761
12:42:17,828 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3443319
12:42:17,829 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3574550
12:42:17,829 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3574551
12:42:17,829 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394040
12:42:17,829 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394041
12:42:17,830 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3394042
12:42:17,830 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3409174
12:42:17,830 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3409175
12:42:17,830 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3442547
12:42:17,830 [Thread-16] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Closing MultiReader: org.hibernate.search.reader.CacheableMultiReader@18e899c
12:42:17,830 [Thread-16] TRACE hibernate.search.reader.SharingBufferReaderProvider - IndexReader closed.
12:42:17,830 [Thread-16] DEBUG query.Reader - *** Request simulatedLoadRead took 0:00:07.000 to complete NoOfRecordsReturned=30

Now here is the time loss

Quote:

12:42:10,831 [Thread-16] TRACE hibernate.search.reader.SharingBufferReaderProvider - Opening IndexReader from org.apache.lucene.store.NIOFSDirectory@/var/lucene/shared/com.mycompany.FooBar/2
12:42:17,825 [Thread-16] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 2218638

Almost 7 seconds between these logs..........question is what is going on between these 2 logs?? I have been unable to replicate locally but suspect the answer lies in this call

Code:

SharingBufferReaderProvider.java 

public IndexReader openReader(DirectoryProvider... directoryProviders) {
................
readers[index] = directoryLatestReader.refreshAndGet();

Any ideas as to why this is happening on ubuntu??

Index Im querying against looks like so

Quote:

-rw-r--r-- 1 fts fts 1664364628 2010-03-24 05:53 _2m87.cfs
-rw-r--r-- 1 fts fts 287 2010-03-24 05:53 segments_2owj
-rw-r--r-- 1 fts fts 20 2010-03-24 05:53 segments.gen

Cheers,
LL

sanne.grinovero · **Posted:** Wed Mar 24, 2010 5:10 pm

Quote:

Im using the HS version 3.1 upgraded with lucene 2.9 version (any problems with this combination?? Needed to upgrade due to memory leak in JVM which is patched in 2.9).

it's ok as long as you avoid filters :) Some low-level stuff changed in Lucene 2.9 about filtering, not sure if unintentionally as 2.9 was meant to be backwards compatible or because we're driving some non-public APIs.
I would suggest you to use the latest trunk: afaik it's currently ok, and in case some feedback is welcome. There are some nice new experimental things and support for Lucene 2.9, if you need it stable just avoid the new features; definitely avoid the new query API which is in sandbox stadium, but that also would love some feedback.

Quote:

Almost 7 seconds between these logs..........question is what is going on between these 2 logs?? I have been unable to replicate locally but suspect the answer lies in this call

In this call the index is re-opened using indexReader.reopen() which should be the most efficient strategy; so there's some I/O happening there, it has to open the new segments or at least verify there are no new segments to be loaded.

Quote:

i have switched between SimpleDSDirectory and NIOFSDirectory, both perform miserably.

How did you do that? by using system properties? or did you create a new DirectoryProvider?
Could you try java.org.apache.lucene.store.MMapDirectory too? (if having enough ram: read javadocs for warnings)

other things to check:
[*]there was a bug in ext4 causing temporary freezes; should be solved by some times - don't remember the reference sorry, search for it in case you have ext4.
[*]verify it's not a regression in Lucene 2.9.x (which exact version are you using btw?)

lovelyliatroim · **Joined:** Thu Oct 08, 2009 10:34 am **Posts:** 55

Quote:

it's ok as long as you avoid filters :)

Im using filters. Is there a JIRA in relation to the problem with using filters?? Do you think this is one of reasons for the long delay?? Dont see how reopen() though should have anything to do with filters!!

Quote:

I would suggest you to use the latest trunk

From lucene or HS?? Im using lucene version 2.9.2, had to step up because of a VM bug and out of memory exceptions.

Quote:

In this call the index is re-opened using indexReader.reopen() which should be the most efficient strategy; so there's some I/O happening there, it has to open the new segments or at least verify there are no new segments to be loaded.

Why the huge difference between windows and ubuntu?? I could understand something that takes twice as long but not 8-9 times longer!! Have you seen anyone else having this problem and any way to speed it up??

Quote:

How did you do that? by using system properties? or did you create a new DirectoryProvider?
Could you try java.org.apache.lucene.store.MMapDirectory too? (if having enough ram: read javadocs for warnings)

System properties. Havent tried MMapDirectory, will give it a go and see what happens.

Quote:

other things to check:
[*]there was a bug in ext4 causing temporary freezes; should be solved by some times - don't remember the reference sorry, search for it in case you have ext4.
[*]verify it's not a regression in Lucene 2.9.x (which exact version are you using btw?)

Will check these tomorrow, out of office and no access currently.

Thanks for the help Sanne,
LL

sanne.grinovero · **Posted:** Thu Mar 25, 2010 6:58 am

Quote:

From lucene or HS?? Im using lucene version 2.9.2, had to step up because of a VM bug and out of memory exceptions.

I meant you should upgrade Hibernate Search, but only to prevent potential problems when combining more than one filter.

http://opensource.atlassian.com/projects/hibernate/browse/HSEARCH-442 Is the reference on JIRA, it's not a bug on previous versions as Lucene 2.9 wasn't supported before, so it needs these changes to be supported, which is not going to happen before HS 3.2.0

Quote:

Do you think this is one of reasons for the long delay?? Dont see how reopen() though should have anything to do with filters!!

I agree with you, that's not possibly the cause of the delay. I just meant to warn you about the filtering problem because you asked if Lucene 2.9 was compatible.
About the speed difference, I don't know. I just tested on Ubuntu 9.10 myself and couldn't reproduce - sorry this appears to be a Lucene problem or more likely something to do with your filesystem or storage devices - that's why I suggested the other things to check, but I don't really have a clue besides knowing that HS doesn't do anything unusual there.

lovelyliatroim · **Joined:** Thu Oct 08, 2009 10:34 am **Posts:** 55

Quote:

other things to check:
[*]there was a bug in ext4 causing temporary freezes; should be solved by some times - don't remember the reference sorry, search for it in case you have ext4.
[*]verify it's not a regression in Lucene 2.9.x (which exact version are you using btw?)

ext3 and lucene 2.9.2.

Tried out the MMapDirectory but dont have enough memory to use it.

I have added more custom logs to HS code and have pinpointed exactly where the times loss is.

Quote:

14:45:46,578 [Thread-17] TRACE hibernate.search.impl.SearchFactoryImpl - Targeted indexed classes for [class com.mycompany:FooBar]: [class com.mycompany:FooBar]
14:45:46,579 [Thread-17] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Opening IndexReader for directoryProviders: 1
14:45:46,579 [Thread-17] TRACE hibernate.search.reader.SharingBufferReaderProvider - Opening IndexReader from org.apache.lucene.store.NIOFSDirectory@/var/lucene/shared/com.mycompany:FooBar/1
14:45:46,579 [Thread-17] DEBUG hibernate.search.reader.SharingBufferReaderProvider - About to reopen reader
14:45:46,579 [Thread-17] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Reader reopened
14:45:46,579 [Thread-17] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Returning Reader
14:45:46,579 [Thread-17] DEBUG hibernate.search.query.FullTextQueryImpl - Searcher built
14:45:46,579 [Thread-17] DEBUG hibernate.search.query.FullTextQueryImpl - About to build filters
14:45:46,579 [Thread-17] DEBUG hibernate.search.query.FullTextQueryImpl - Built filters
14:45:46,580 [Thread-17] DEBUG hibernate.search.query.QueryHits - About to search
14:45:54,866 [Thread-17] DEBUG hibernate.search.query.QueryHits - Finished the search
14:45:54,866 [Thread-17] DEBUG hibernate.search.query.FullTextQueryImpl - Have query Hits
14:45:54,866 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3192569
14:45:54,866 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 1110166
14:45:54,866 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 5206
14:45:54,867 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 1102658
14:45:54,867 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 1105455
14:45:54,867 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 1107890
14:45:54,867 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 1109632
14:45:54,867 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 1112472
14:45:54,876 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 282633
14:45:54,876 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 282368
14:45:54,876 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3307901
14:45:54,876 [Thread-17] TRACE hibernate.search.engine.DocumentBuilderIndexedEntity - Field id projected as 3444561
14:45:54,876 [Thread-17] DEBUG hibernate.search.query.FullTextQueryImpl - About to get loader
14:45:54,876 [Thread-17] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Closing MultiReader: org.hibernate.search.reader.CacheableMultiReader@18e899c
14:45:54,876 [Thread-17] TRACE hibernate.search.reader.SharingBufferReaderProvider - IndexReader closed.

Time loss is here

Quote:

14:45:46,580 [Thread-17] DEBUG hibernate.search.query.QueryHits - About to search
14:45:54,866 [Thread-17] DEBUG hibernate.search.query.QueryHits - Finished the search

And relates to the code here

Quote:

QueryHits.java
private void updateTopDocs(int n) throws IOException {
log.debug("About to search");
if ( sort == null ) {
topDocs = searcher.search( preparedQuery, filter, n );
}
else {
topDocs = searcher.search( preparedQuery, filter, n, sort );
}
log.debug("Finished the search");

}

Carried out a simpler query without filters on same entity, wildcard search on two columns

Quote:

15:45:33,472 [Thread-15] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Opening IndexReader for directoryProviders: 1
15:45:33,472 [Thread-15] TRACE hibernate.search.reader.SharingBufferReaderProvider - Opening IndexReader from org.apache.lucene.store.NIOFSDirectory@/var/lucene/shared/com.mypackage.FooBar/1
15:45:33,472 [Thread-15] DEBUG hibernate.search.reader.SharingBufferReaderProvider - About to reopen reader
15:45:33,473 [Thread-15] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Reader reopened
15:45:33,473 [Thread-15] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Returning Reader
15:45:33,473 [Thread-15] DEBUG hibernate.search.query.FullTextQueryImpl - Searcher built
15:45:33,473 [Thread-15] DEBUG hibernate.search.query.FullTextQueryImpl - About to build filters
15:45:33,473 [Thread-15] DEBUG hibernate.search.query.QueryHits - About to search
15:45:33,473 [Thread-15] DEBUG hibernate.search.query.QueryHits - Finished the search
15:45:33,473 [Thread-15] DEBUG hibernate.search.query.FullTextQueryImpl - Have query Hits
15:45:33,474 [Thread-15] DEBUG hibernate.search.query.FullTextQueryImpl - About to get loader
15:45:33,474 [Thread-15] TRACE hibernate.search.impl.SearchFactoryImpl - Targeted indexed classes for
15:45:33,503 [Thread-15] TRACE org.hibernate.loader.Loader - done processing result set (15 rows)
15:45:33,503 [Thread-15] TRACE org.hibernate.loader.Loader - total objects hydrated: 0
15:45:33,548 [Thread-15] DEBUG hibernate.search.reader.SharingBufferReaderProvider - Closing MultiReader: org.hibernate.search.reader.CacheableMultiReader@18e899c
15:45:33,562 [Thread-15] TRACE hibernate.search.reader.SharingBufferReaderProvider - IndexReader closed.

The timing on ubuntu is quite good........im a bit stumped as to where to go from here, maybe query design can be better but remember the same queries work fine on windows.........havent stepped up to the latest 3.2. HS version yet. Might help??

sanne.grinovero · **Posted:** Fri Mar 26, 2010 11:39 am

so did I understand well what you wrote, when using a filter it's way slower on Ubuntu only? no problems with filters disabled?

this might still be related to I/O, a complex filter might need to load the whole index, while a simple query doesn't necessarily need. The benefit of filters is mostly reuse - and of course if you have to write the same filtering in the query it will likely perform the same.

Could you verify you are having the same performance when running several queries? it could have just a slow start, after that all segments should be properly cached; that's normal behavior.

lovelyliatroim · **Joined:** Thu Oct 08, 2009 10:34 am **Posts:** 55

Quote:

so did I understand well what you wrote, when using a filter it's way slower on Ubuntu only? no problems with filters disabled?

Yes it looks that way, same query with filters runs good enough on windows 1.2secs, the same query on Ubuntu doesnt. If I simplify the query on ubuntu to just a two column wild card search, the query performs quite good. I have no idea how a wilcard queries works under the hood but i would have thought that it possibly scans the whole index, that peforms under a second so a second read of the whole index in theory shouldnt be taking 8-10seconds unless there is something going on with the file system and it cant take the load?? Any tips on what to look for here to verify that it aint the re-scan that causes the problem?

Quote:

Could you verify you are having the same performance when running several queries? it could have just a slow start, after that all segments should be properly cached; that's normal behavior.

The samples I have shown you are taken from load testing, well i wouldnt even call it load but it is 5 clients simultaneously querying, the period done was on average 1 minute to 2 minutes non stop querying, i havent seen any of the queries timing improving over time.

sanne.grinovero · **Posted:** Mon Mar 29, 2010 4:26 am

Quote:

i would have thought that it possibly scans the whole index

That's true to load the terms enum only, and it would be slow at the first search only.

I asked for some clue to someone working on huge indexes on Ubuntu latest, on his own laptop - he's having very good performance on impressively complex queries and large datasets.
Having no other clues, I'd suggest you to ask on Lucene's mailing list, and please post back if you find a solution it's puzzling me.

Maybe you could run a filesystem I/O test like a benchmark? maybe you're having something bad going on on the server disks, some hardware failing or misconfigured.

jpatel · **Joined:** Tue Jun 28, 2011 11:19 pm **Posts:** 5

I have exactly same problem, don't know what's causing this.
My total combine index is less than 500 MB
Here is how much time its taking to open the reader

DEBUG http-80-4 org.hibernate.transaction.JDBCTransaction 29 Jun 2011 11:15:37,693- current autocommit status: true
DEBUG http-80-4 org.hibernate.transaction.JDBCTransaction 29 Jun 2011 11:15:37,693- disabling autocommit
DEBUG http-80-4 org.hibernate.search.reader.SharingBufferReaderProvider 29 Jun 2011 11:15:37,694- Opening IndexReader for directoryProviders: 1
DEBUG http-80-4 org.hibernate.jdbc.AbstractBatcher 29 Jun 2011 11:15:52,006- about to open PreparedStatement (open PreparedStatements: 0, globally: 0)

Its taking 15 seconds to just open the reader.

We are using CentOs 5.5

Any help/comment would be highly appreciated.

Kind Regards,
Jay

sanne.grinovero · **Posted:** Wed Jun 29, 2011 7:30 pm

Hi Jay,
15 seconds looks indeed a big high, but if you have a slow disk it's possible for the first index opening, after that internal buffers are pooled and subsequent reopening should be much faster. Are you experiencing this speed every time the index is reopened or just the first time?

jpatel · **Joined:** Tue Jun 28, 2011 11:19 pm **Posts:** 5

Hi Sanne,

Thanks a lot for replying.

This happens at random time irrespective of if its a first query or not.
I am not at all experienced with Hibernate Search and hardly know some Java.

We have an application which is making a web request to our search server and that search server process the request and query to indexes and return the XML document back to querying server and then server process the document.

I tried to run the cron job on server which keep making the search request to search server every 2 mins so that reader is always open but that didn't solve the problem too.

I hope you can provide me some help here.

Kind Regards.
Jay

sanne.grinovero · **Posted:** Wed Jun 29, 2011 7:49 pm

are you using some special configuration? Could you paste it?

jpatel · **Joined:** Tue Jun 28, 2011 11:19 pm **Posts:** 5

Hi Sanne,

Here are the settings from my applicationContext.xml

Code:

        
<property name="hibernateProperties">
            <props>
                <prop key="hibernate.dialect">org.hibernate.dialect.SQLServerDialect</prop>
                <prop key="hibernate.show_sql">true</prop>
                <prop key="hibernate.search.default.directory_provider">
                    org.hibernate.search.store.FSDirectoryProvider
                </prop>
                <prop key="hibernate.search.default.indexBase">
                 /sdb1/indexes
                </prop>
                <prop key="hibernate.search.similarity">me.searchengine.rank.MeSimilarity</prop>
                <prop key="hibernate.search.indexing_strategy">manual</prop>
            </props>
        </property>

jpatel · **Joined:** Tue Jun 28, 2011 11:19 pm **Posts:** 5

Hi Sanne,

Any updates or suggestion based on the config I have provided ?

Kind Regards,
Jay

sanne.grinovero · **Posted:** Wed Jul 06, 2011 5:28 am

Hi,
I don't see anything strange in your configuration. How big is the index? are the disks fast enough? are the disks local or networked (I'd really discourage network) ?
And above all, is your application having enough memory? Lucene is quite memory hungry, and apart of tuning the JVM options properly you might also want to check that you have enough physical memory: check you're not swapping heavily.