You are viewing a plain text version of this content. The canonical link for it is here.
Posted to solr-user@lucene.apache.org by Jérôme Etévé <je...@gmail.com> on 2009/03/03 20:37:22 UTC
Very long commit time.
Dear solr fans,
I have a solr index of roughly 8M docs and I have here a little
problem when I commit some insertion into it.
The insert itself is very fast, but my commit takes 163 seconds.
Here's the solr trace the commit leaves:
INFO: start commit(optimize=false,waitFlush=false,waitSearcher=true)
03-Mar-2009 20:20:35 org.apache.solr.search.SolrIndexSearcher <init>
INFO: Opening Searcher@7de212f9 main
03-Mar-2009 20:20:35 org.apache.solr.update.DirectUpdateHandler2 commit
INFO: end_commit_flush
03-Mar-2009 20:20:35 org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=71641,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
03-Mar-2009 20:21:52 org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming result for Searcher@7de212f9 main
filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=76905,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
03-Mar-2009 20:21:52 org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
queryResultCache{lookups=24,hits=24,hitratio=1.00,inserts=32,evictions=0,size=32,warmupTime=82406,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming result for Searcher@7de212f9 main
queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=32,evictions=0,size=32,warmupTime=85591,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
documentCache{lookups=720,hits=710,hitratio=0.98,inserts=40,evictions=0,size=40,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming result for Searcher@7de212f9 main
documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
03-Mar-2009 20:23:17 org.apache.solr.core.QuerySenderListener newSearcher
INFO: QuerySenderListener sending requests to Searcher@7de212f9 main
// Then the few warm up queries defined in solrconfig.xml
INFO: Closing Searcher@732d8b11 main
filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=71641,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
queryResultCache{lookups=24,hits=24,hitratio=1.00,inserts=32,evictions=0,size=32,warmupTime=82406,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
documentCache{lookups=720,hits=710,hitratio=0.98,inserts=40,evictions=0,size=40,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
03-Mar-2009 20:23:18 org.apache.solr.update.processor.LogUpdateProcessor finish
INFO: {commit=} 0 163189
03-Mar-2009 20:23:18 org.apache.solr.core.SolrCore execute
INFO: [jobs] webapp=/cjsolr path=/update/ params={} status=0 QTime=163189
I'm sure I'm doing something wrong. Does this 163 seconds commit time
have to do with the commit parameters :
(optimize=false,waitFlush=false,waitSearcher=true) ??
Thanks for any help.
Cheers !!
Jerome.
--
Jerome Eteve.
Chat with me live at http://www.eteve.net
jerome@eteve.net
Re: Very long commit time.
Posted by Yonik Seeley <yo...@lucidimagination.com>.
On Wed, Mar 4, 2009 at 11:04 AM, Jérôme Etévé <je...@gmail.com> wrote:
> Strange, we've got plenty of memory on this box and the swap is zero.
> But well, I'm happy we went around the problem. What's your experience
> with commits with ~10M docs ( and ~128 autowarming count in caches ) ?
Probably depends somewhat on the nature of the filters and queries.
It does sound a little slow, so perhaps they could be optimized in some way.
If you have enough memory, the autowarming queries shouldn't be slower
than the normal queries, so you should be able to use your logs to
find the slow queries and try to figure out why they are slower.
-Yonik
http://www.lucidimagination.com
Re: Very long commit time.
Posted by Jérôme Etévé <je...@gmail.com>.
On Wed, Mar 4, 2009 at 1:21 PM, Yonik Seeley <yo...@lucidimagination.com> wrote:
> On Wed, Mar 4, 2009 at 5:25 AM, Jérôme Etévé <je...@gmail.com> wrote:
>> Great,
>>
>> It went down to less than 10 secs now :)
>> What I don't really understand is that my autowarmCount were pretty
>> low ( like 128 ) and still the autowarming of the caches were very
>> slow.
>>
>> Can you explain more why it can be that slow ?
>
> One possibility is a lack of physical memory available to the OS for
> caching reads on both the old index and the new index. This would
> cause all of the queries to be slower if they ended up doing real disk
> IO for each query/filter being warmed.
Strange, we've got plenty of memory on this box and the swap is zero.
But well, I'm happy we went around the problem. What's your experience
with commits with ~10M docs ( and ~128 autowarming count in caches ) ?
Cheers.
Jerome.
--
Jerome Eteve.
Chat with me live at http://www.eteve.net
jerome@eteve.net
Re: Very long commit time.
Posted by Yonik Seeley <yo...@lucidimagination.com>.
On Wed, Mar 4, 2009 at 5:25 AM, Jérôme Etévé <je...@gmail.com> wrote:
> Great,
>
> It went down to less than 10 secs now :)
> What I don't really understand is that my autowarmCount were pretty
> low ( like 128 ) and still the autowarming of the caches were very
> slow.
>
> Can you explain more why it can be that slow ?
One possibility is a lack of physical memory available to the OS for
caching reads on both the old index and the new index. This would
cause all of the queries to be slower if they ended up doing real disk
IO for each query/filter being warmed.
-Yonik
http://www.lucidimagination.com
Re: Very long commit time.
Posted by Jérôme Etévé <je...@gmail.com>.
Great,
It went down to less than 10 secs now :)
What I don't really understand is that my autowarmCount were pretty
low ( like 128 ) and still the autowarming of the caches were very
slow.
Can you explain more why it can be that slow ?
Cheers !
Jerome.
On Tue, Mar 3, 2009 at 8:00 PM, Yonik Seeley <yo...@lucidimagination.com> wrote:
> Looks like cache autowarming.
> If you have statically defined warming queries in solrconfig.xml, you
> could try setting autowarmCount=0 for all the caches.
>
> -Yonik
> http://www.lucidimagination.com
>
>
> On Tue, Mar 3, 2009 at 2:37 PM, Jérôme Etévé <je...@gmail.com> wrote:
>> Dear solr fans,
>>
>> I have a solr index of roughly 8M docs and I have here a little
>> problem when I commit some insertion into it.
>>
>> The insert itself is very fast, but my commit takes 163 seconds.
>>
>> Here's the solr trace the commit leaves:
>>
>> INFO: start commit(optimize=false,waitFlush=false,waitSearcher=true)
>> 03-Mar-2009 20:20:35 org.apache.solr.search.SolrIndexSearcher <init>
>> INFO: Opening Searcher@7de212f9 main
>> 03-Mar-2009 20:20:35 org.apache.solr.update.DirectUpdateHandler2 commit
>> INFO: end_commit_flush
>> 03-Mar-2009 20:20:35 org.apache.solr.search.SolrIndexSearcher warm
>> INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
>> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=71641,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
>> 03-Mar-2009 20:21:52 org.apache.solr.search.SolrIndexSearcher warm
>> INFO: autowarming result for Searcher@7de212f9 main
>> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=76905,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
>> 03-Mar-2009 20:21:52 org.apache.solr.search.SolrIndexSearcher warm
>> INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
>> queryResultCache{lookups=24,hits=24,hitratio=1.00,inserts=32,evictions=0,size=32,warmupTime=82406,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
>> 03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
>> INFO: autowarming result for Searcher@7de212f9 main
>> queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=32,evictions=0,size=32,warmupTime=85591,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
>> 03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
>> INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
>> documentCache{lookups=720,hits=710,hitratio=0.98,inserts=40,evictions=0,size=40,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
>> 03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
>> INFO: autowarming result for Searcher@7de212f9 main
>> documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
>> 03-Mar-2009 20:23:17 org.apache.solr.core.QuerySenderListener newSearcher
>> INFO: QuerySenderListener sending requests to Searcher@7de212f9 main
>>
>> // Then the few warm up queries defined in solrconfig.xml
>>
>> INFO: Closing Searcher@732d8b11 main
>> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=71641,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
>> queryResultCache{lookups=24,hits=24,hitratio=1.00,inserts=32,evictions=0,size=32,warmupTime=82406,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
>> documentCache{lookups=720,hits=710,hitratio=0.98,inserts=40,evictions=0,size=40,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
>> 03-Mar-2009 20:23:18 org.apache.solr.update.processor.LogUpdateProcessor finish
>> INFO: {commit=} 0 163189
>> 03-Mar-2009 20:23:18 org.apache.solr.core.SolrCore execute
>> INFO: [jobs] webapp=/cjsolr path=/update/ params={} status=0 QTime=163189
>>
>>
>> I'm sure I'm doing something wrong. Does this 163 seconds commit time
>> have to do with the commit parameters :
>> (optimize=false,waitFlush=false,waitSearcher=true) ??
>>
>> Thanks for any help.
>>
>> Cheers !!
>>
>> Jerome.
>>
>> --
>> Jerome Eteve.
>>
>> Chat with me live at http://www.eteve.net
>>
>> jerome@eteve.net
>>
>
--
Jerome Eteve.
Chat with me live at http://www.eteve.net
jerome@eteve.net
Re: Very long commit time.
Posted by Yonik Seeley <yo...@lucidimagination.com>.
Looks like cache autowarming.
If you have statically defined warming queries in solrconfig.xml, you
could try setting autowarmCount=0 for all the caches.
-Yonik
http://www.lucidimagination.com
On Tue, Mar 3, 2009 at 2:37 PM, Jérôme Etévé <je...@gmail.com> wrote:
> Dear solr fans,
>
> I have a solr index of roughly 8M docs and I have here a little
> problem when I commit some insertion into it.
>
> The insert itself is very fast, but my commit takes 163 seconds.
>
> Here's the solr trace the commit leaves:
>
> INFO: start commit(optimize=false,waitFlush=false,waitSearcher=true)
> 03-Mar-2009 20:20:35 org.apache.solr.search.SolrIndexSearcher <init>
> INFO: Opening Searcher@7de212f9 main
> 03-Mar-2009 20:20:35 org.apache.solr.update.DirectUpdateHandler2 commit
> INFO: end_commit_flush
> 03-Mar-2009 20:20:35 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=71641,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
> 03-Mar-2009 20:21:52 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming result for Searcher@7de212f9 main
> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=76905,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
> 03-Mar-2009 20:21:52 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
> queryResultCache{lookups=24,hits=24,hitratio=1.00,inserts=32,evictions=0,size=32,warmupTime=82406,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
> 03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming result for Searcher@7de212f9 main
> queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=32,evictions=0,size=32,warmupTime=85591,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
> 03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming Searcher@7de212f9 main from Searcher@732d8b11 main
> documentCache{lookups=720,hits=710,hitratio=0.98,inserts=40,evictions=0,size=40,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
> 03-Mar-2009 20:23:17 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming result for Searcher@7de212f9 main
> documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
> 03-Mar-2009 20:23:17 org.apache.solr.core.QuerySenderListener newSearcher
> INFO: QuerySenderListener sending requests to Searcher@7de212f9 main
>
> // Then the few warm up queries defined in solrconfig.xml
>
> INFO: Closing Searcher@732d8b11 main
> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=16,evictions=0,size=16,warmupTime=71641,cumulative_lookups=90,cumulative_hits=68,cumulative_hitratio=0.75,cumulative_inserts=22,cumulative_evictions=0}
> queryResultCache{lookups=24,hits=24,hitratio=1.00,inserts=32,evictions=0,size=32,warmupTime=82406,cumulative_lookups=6310,cumulative_hits=268,cumulative_hitratio=0.04,cumulative_inserts=6041,cumulative_evictions=5522}
> documentCache{lookups=720,hits=710,hitratio=0.98,inserts=40,evictions=0,size=40,warmupTime=0,cumulative_lookups=415308,cumulative_hits=283661,cumulative_hitratio=0.68,cumulative_inserts=131647,cumulative_evictions=131105}
> 03-Mar-2009 20:23:18 org.apache.solr.update.processor.LogUpdateProcessor finish
> INFO: {commit=} 0 163189
> 03-Mar-2009 20:23:18 org.apache.solr.core.SolrCore execute
> INFO: [jobs] webapp=/cjsolr path=/update/ params={} status=0 QTime=163189
>
>
> I'm sure I'm doing something wrong. Does this 163 seconds commit time
> have to do with the commit parameters :
> (optimize=false,waitFlush=false,waitSearcher=true) ??
>
> Thanks for any help.
>
> Cheers !!
>
> Jerome.
>
> --
> Jerome Eteve.
>
> Chat with me live at http://www.eteve.net
>
> jerome@eteve.net
>