Re: Slow Commits

[Jim Murphy <ji...@pobox.com>]

Just an update to the list.  It appears that memory was the culprit.  I
attached a JMX console to the running Tomcat instance and monitored memory
usage.  Used Total memory stayed ~900MB till a commit then jumped to m Xmx
setting of 1.2GB where the "peak" flatlined and fell down likely after an
OOM exception.  I upped the Xmx to 2GB and commits are happening much better
- in the 1 minute range.


Jim



Jim Murphy wrote:
> 
> Thanks Jerome,
> 
> 
> 1. I have shut off autowarming by setting params to 0.
> 2. My JVM Settings: -Xmx1200m -Xms1200m -XX:-UseGCOverheadLimit
> -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=50
> 3. I am using autocommits - every 60000 ms.  But the commit blocks all the
> master request threadpool threads as it spends 2-3 minutes commiting.
> 4. I'm reluctant to NOT waitFlush since I don't want commits stacking up. 
> 
> 
> Any other thoughts?
> 
> Thanks
> 
> Jim
> 
> 
> 
> 
> Jérôme Etévé wrote:
>> 
>> Hi, here's two thing that can slow down commits:
>> 
>> 1) Autowarming the caches.
>> 2) The Java old generation object garbage collection.
>> 
>> You can try:
>> - Turning autowarming off (set autowarmCount="0"  in the caches
>> configuration)
>> - If you use the sun jvm, use  -XX:+UseConcMarkSweepGC to get a less
>> blocking garbage collection.
>> 
>> You may also try to:
>> - Not wait for the new searcher when you commit. The commit will then
>> be instant from your posting application point of view. ( option
>> waitSearcher=false  ).
>> - Leave the commits to the server ( by setting autocommits in the
>> solrconfig.xml). This is the best strategy if you've got lot of
>> concurrent processes who posts.
>> 
>> Cheers.
>> 
>> Jerome.
>> 
>> 2009/10/28 Jim Murphy <ji...@pobox.com>:
>>>
>>> Hi All,
>>>
>>> We have 8 solr shards, index is ~ 90M documents 190GB.  :)
>>>
>>> 4 of the shards have acceptable commit time - 30-60 seconds.  The other
>>> 4
>>> have drifted over the last couple months to but up around 2-3 minutes. 
>>> This
>>> is killing our write throughput as you can imagine.
>>>
>>> I've included a log dump of a typical commit.  Not the large time period
>>> (3:40) between the start commit log message and the OnCommit log
>>> message.
>>> So, I think warming issues are not relevant.
>>>
>>> Any ideas what to debug at this point?
>>>
>>> I'm about to issue an optimize and see where that goes.  Its been a
>>> while
>>> since I did that.
>>>
>>> Cheers,
>>>
>>> Jim
>>>
>>>
>>>
>>>
>>> Oct 28, 2009 11:47:02 AM org.apache.solr.update.DirectUpdateHandler2
>>> commit
>>> INFO: start commit(optimize=false,waitFlush=true,waitSearcher=true)
>>> Oct 28, 2009 11:50:43 AM org.apache.solr.core.SolrDeletionPolicy
>>> onCommit
>>> INFO: SolrDeletionPolicy.onCommit: commits:num=2
>>>
>>> commit{dir=/master/data/index,segFN=segments_8us4,version=1228872482131,generation=413140,filenames=[segments_8us4,
>>> _alae.fnm, _ai
>>> lk.tis, _ala9.fnm, _ala9.fdx, _alac.fnm, _al9w_h.del, _alab.prx,
>>> _ala9.fdt,
>>> _a61p_b76.del, _alab.fnm, _al8x.frq, _al7i_2f.del, _akh1.tis,
>>> _add1.frq, _alae.tis, _alad_1.del, _alaa.fnm, _alad.nrm, _al9w.frq,
>>> _alae.tii, _ailk.tii, _add1.tis, _alac.tii, _akuu.tis, _add1.tii, _ail
>>> k.frq, _alac.tis, _7zfh.tii, _962y.tis, _ala7.frq, _ah91.prx, _akuu.tii,
>>> _alab_3.del, _ah91.fnm, _7zfh.tis, _ala8.frq, _962y.tii, _alae.pr
>>> x, _a61p.fdt, _akuu.frq, _a61p.fdx, _al7i.fdx, _al2o.tis, _al9w.tis,
>>> _ala7.fnm, _a61p.frq, _akzu.fnm, _9wzn.fnm, _akh1.prx, _al7i.fdt, _al
>>> a9_2.del, _962y.prx, _al7i.prx, _al9w.tii, _alaa_4.del, _al7i.frq,
>>> _ah91.tii, _ala8.nrm, _962y.fdt, _add1_62u.del, _alae.nrm, _ah91.tis, _
>>> 962y.fdx, _akh1.fnm, _al8x.prx, _al2o.tii, _ala7.fdx, _ala9.prx,
>>> _ala7.fdt,
>>> _al9w.prx, _ala8.prx, _akh1.tii, _al2o.fdx, _7zfh.frq, _alac_3
>>> .del, _akzu.tii, _akzu.fdt, _alad.fnm, _akzu.tis, _alab.nrm, _akzu.fdx,
>>> _al2o.fnm, _al2o.fdt, _alaa.prx, _alaa.nrm, _962y.fnm, _ala7.prx,
>>> _alaa.tis, _ailk.fdt, _akzu_8d.del, _alac.frq, _akzu.prx, _ala9.nrm,
>>> _ailk.prx, _ala9.tis, _alaa.tii, _alae.frq, _add1.fnm, _7zfh.prx, _al
>>> 9w.fnm, _ala9.tii, _ala9.frq, _962y.nrm, _alab.frq, _ala8.fdx,
>>> _al8x.fnm,
>>> _a61p.prx, _7zfh.fnm, _ala8.fdt, _ailk.fdx, _alaa.frq, _7zfh.fdx
>>> , _al7i.tis, _ah91.fdt, _ailk.fnm, _9wzn_i0m.del, _ah91.fdx, _al7i.tii,
>>> _ailk_24j.del, _alad.fdx, _al8x.tii, _alae.fdx, _add1.prx, _akuu.f
>>> nm, _al8x.tis, _ah91.frq, _ala8.fnm, _7zfh.fdt, _alad.fdt, _alae_1.del,
>>> _alae.fdt, _akzu.frq, _a61p.fnm, _9wzn.frq, _ala8.tii, _7zfh_1gsd.
>>> del, _7zfh.nrm, _ala7_6.del, _a61p.tis, _9wzn.tii, _alad.frq, _alad.tii,
>>> _akuu.fdt, _alab.tii, _ala8.tis, _962y_xgg.del, _akh1.frq, _akuu.
>>> fdx, _alab.tis, _al7i.fnm, _alad.tis, _alac.nrm, _alab.fdx, _ala8_5.del,
>>> _add1.fdx, _ala7.tii, _akuu_cc.del, _alab.fdt, _9wzn.prx, _alaa.f
>>> dx, _al9w.fdt, _al2o.frq, _akh1_nf.del, _alac.prx, _akh1.fdx, _alaa.fdt,
>>> _al9w.fdx, _al8x_17.del, _add1.fdt, _al2o.prx, _akh1.fdt, _alad.p
>>> rx, _akuu.prx, _962y.frq, _al2o_66.del, _alac.fdt, _ala7.tis, _a61p.tii,
>>> _alac.fdx, _al8x.fdt, _9wzn.tis, _9wzn.fdt, _al8x.fdx, _9wzn.fdx,
>>>  _ah91_35l.del]
>>>
>>> commit{dir=/master/data/index,segFN=segments_8us5,version=1228872482132,generation=413141,filenames=[_ala9.fnm,
>>> _alaa_5.del, _alab
>>> .fnm, _962y_xgh.del, _al8x.frq, _akh1.tis, _add1.frq, _alae.tis,
>>> _7zfh_1gse.del, _alad.nrm, _alae.tii, _akuu.tis, _ah91_35m.del,
>>> _ailk.frq
>>> , _7zfh.tii, _962y.tis, _akuu.tii, _ah91.prx, _7zfh.tis, _ala8.frq,
>>> _962y.tii, _ala7.fnm, _akzu.fnm, _9wzn.fnm, _ala9_2.del, _ala8.nrm, _a
>>> laf.fnm, _alae.nrm, _ala9.prx, _ailk_24k.del, _alaf.prx, _al9w.prx,
>>> _ala8.prx, _akh1.tii, _akzu.tii, _akzu.tis, _alad.fnm, _al2o.fnm, _962
>>> y.fnm, _al8x_18.del, _ala7_7.del, _alaa.tis, _ala9.nrm, _ala9.tis,
>>> _alaa.tii, _962y.nrm, _ala9.tii, _a61p.prx, _add1_62v.del, _al8x.fnm, _
>>> 7zfh.fnm, _al7i_2g.del, _ailk.fnm, _al8x.tii, _al8x.tis, _ala8.fnm,
>>> _akzu.frq, _9wzn.frq, _7zfh.nrm, _akuu.fdt, _alad.tii, _akuu.fdx, _aku
>>> u_cd.del, _a61p_b77.del, _alad.tis, _al2o_67.del, _add1.fdx, _9wzn.prx,
>>> _al9w.fdt, _add1.fdt, _al9w.fdx, _akuu.prx, _962y.frq, _9wzn.fdt,
>>> _alab_4.del, _9wzn.fdx, segments_8us5, _alac_4.del, _alae.fnm,
>>> _ailk.tis,
>>> _ala9.fdx, _alac.fnm, _ala9.fdt, _alab.prx, _alae_2.del, _alaa.f
>>> nm, _alad_1.del, _al9w.frq, _ailk.tii, _add1.tis, _alac.tii, _add1.tii,
>>> _alac.tis, _ala7.frq, _ah91.fnm, _a61p.fdt, _alae.prx, _akuu.frq,
>>> _a61p.fdx, _akh1_ng.del, _al7i.fdx, _al2o.tis, _al9w.tis, _a61p.frq,
>>> _akh1.prx, _9wzn_i0n.del, _al7i.fdt, _al7i.prx, _962y.prx, _al9w.tii,
>>>  _al7i.frq, _ah91.tii, _962y.fdt, _akh1.fnm, _962y.fdx, _ah91.tis,
>>> _al8x.prx, _al2o.tii, _ala7.fdx, _ala7.fdt, _alaf.fdx, _alaf.fdt, _al2o
>>> .fdx, _7zfh.frq, _akzu.fdt, _alaf.nrm, _akzu.fdx, _alab.nrm, _al2o.fdt,
>>> _alaa.prx, _alaa.nrm, _ala7.prx, _ailk.fdt, _akzu.prx, _alac.frq,
>>> _ailk.prx, _alaf.tii, _alaf_1.del, _alae.frq, _add1.fnm, _alaf.tis,
>>> _7zfh.prx, _al9w.fnm, _ala9.frq, _alab.frq, _ala8.fdx, _akzu_8e.del, _
>>> ala8.fdt, _ailk.fdx, _alaa.frq, _al7i.tis, _7zfh.fdx, _al9w_i.del,
>>> _ah91.fdt, _al7i.tii, _ah91.fdx, _alad.fdx, _akuu.fnm, _add1.prx, _alae
>>> .fdx, _ah91.frq, _7zfh.fdt, _alad.fdt, _alae.fdt, _a61p.fnm, _alaf.frq,
>>> _ala8.tii, _a61p.tis, _9wzn.tii, _alad.frq, _ala8.tis, _alab.tii,
>>> _akh1.frq, _alab.tis, _al7i.fnm, _alab.fdx, _alac.nrm, _ala8_5.del,
>>> _ala7.tii, _alab.fdt, _alaa.fdx, _al2o.frq, _akh1.fdx, _alac.prx, _ala
>>> a.fdt, _al2o.prx, _akh1.fdt, _alad.prx, _ala7.tis, _alac.fdt, _a61p.tii,
>>> _9wzn.tis, _al8x.fdt, _alac.fdx, _al8x.fdx]
>>> Oct 28, 2009 11:50:43 AM org.apache.solr.core.SolrDeletionPolicy
>>> updateCommits
>>> INFO: last commit = 1228872482132
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher <init>
>>> INFO: Opening Searcher@5df12234 main
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.update.DirectUpdateHandler2
>>> commit
>>> INFO: end_commit_flush
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher warm
>>> INFO: autowarming Searcher@5df12234 main from Searcher@50e40833 main
>>>
>>> fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cu
>>> mulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher warm
>>> INFO: autowarming result for Searcher@5df12234 main
>>>
>>> fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cu
>>> mulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher warm
>>> INFO: autowarming Searcher@5df12234 main from Searcher@50e40833 main
>>>
>>> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumula
>>> tive_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher warm
>>> INFO: autowarming result for Searcher@5df12234 main
>>>
>>> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumula
>>> tive_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher warm
>>> INFO: autowarming Searcher@5df12234 main from Searcher@50e40833 main
>>>
>>> queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,c
>>> umulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher warm
>>> INFO: autowarming result for Searcher@5df12234 main
>>>
>>> queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,c
>>> umulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher warm
>>> INFO: autowarming Searcher@5df12234 main from Searcher@50e40833 main
>>>
>>> documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumu
>>> lative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher warm
>>> INFO: autowarming result for Searcher@5df12234 main
>>>
>>> documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumu
>>> lative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.core.QuerySenderListener
>>> newSearcher
>>> INFO: QuerySenderListener sending requests to Searcher@5df12234 main
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.core.QuerySenderListener
>>> newSearcher
>>> INFO: QuerySenderListener done.
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.core.SolrCore registerSearcher
>>> INFO: [] Registered new searcher Searcher@5df12234 main
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.search.SolrIndexSearcher close
>>> INFO: Closing Searcher@50e40833 main
>>>
>>> fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cu
>>> mulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>>
>>> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumula
>>> tive_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>>
>>> queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,c
>>> umulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>>
>>> documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumu
>>> lative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.core.SolrDeletionPolicy onInit
>>> INFO: SolrDeletionPolicy.onInit: commits:num=1
>>>
>>> commit{dir=/master/data/index,segFN=segments_8us5,version=1228872482132,generation=413141,filenames=[_ala9.fnm,
>>> _alaa_5.del, _alab
>>> .fnm, _962y_xgh.del, _al8x.frq, _akh1.tis, _add1.frq, _alae.tis,
>>> _7zfh_1gse.del, _alad.nrm, _alae.tii, _akuu.tis, _ah91_35m.del,
>>> _ailk.frq
>>> , _7zfh.tii, _962y.tis, _akuu.tii, _ah91.prx, _7zfh.tis, _ala8.frq,
>>> _962y.tii, _ala7.fnm, _akzu.fnm, _9wzn.fnm, _ala9_2.del, _ala8.nrm, _a
>>> laf.fnm, _alae.nrm, _ala9.prx, _ailk_24k.del, _alaf.prx, _al9w.prx,
>>> _ala8.prx, _akh1.tii, _akzu.tii, _akzu.tis, _alad.fnm, _al2o.fnm, _962
>>> y.fnm, _al8x_18.del, _ala7_7.del, _alaa.tis, _ala9.nrm, _ala9.tis,
>>> _alaa.tii, _962y.nrm, _ala9.tii, _a61p.prx, _add1_62v.del, _al8x.fnm, _
>>> 7zfh.fnm, _al7i_2g.del, _ailk.fnm, _al8x.tii, _al8x.tis, _ala8.fnm,
>>> _akzu.frq, _9wzn.frq, _7zfh.nrm, _akuu.fdt, _alad.tii, _akuu.fdx, _aku
>>> u_cd.del, _a61p_b77.del, _alad.tis, _al2o_67.del, _add1.fdx, _9wzn.prx,
>>> _al9w.fdt, _add1.fdt, _al9w.fdx, _akuu.prx, _962y.frq, _9wzn.fdt,
>>> _alab_4.del, _9wzn.fdx, segments_8us5, _alac_4.del, _alae.fnm,
>>> _ailk.tis,
>>> _ala9.fdx, _alac.fnm, _ala9.fdt, _alab.prx, _alae_2.del, _alaa.f
>>> nm, _alad_1.del, _al9w.frq, _ailk.tii, _add1.tis, _alac.tii, _add1.tii,
>>> _alac.tis, _ala7.frq, _ah91.fnm, _a61p.fdt, _alae.prx, _akuu.frq,
>>> _a61p.fdx, _akh1_ng.del, _al7i.fdx, _al2o.tis, _al9w.tis, _a61p.frq,
>>> _akh1.prx, _9wzn_i0n.del, _al7i.fdt, _al7i.prx, _962y.prx, _al9w.tii,
>>>  _al7i.frq, _ah91.tii, _962y.fdt, _akh1.fnm, _962y.fdx, _ah91.tis,
>>> _al8x.prx, _al2o.tii, _ala7.fdx, _ala7.fdt, _alaf.fdx, _alaf.fdt, _al2o
>>> .fdx, _7zfh.frq, _akzu.fdt, _alaf.nrm, _akzu.fdx, _alab.nrm, _al2o.fdt,
>>> _alaa.prx, _alaa.nrm, _ala7.prx, _ailk.fdt, _akzu.prx, _alac.frq,
>>> _ailk.prx, _alaf.tii, _alaf_1.del, _alae.frq, _add1.fnm, _alaf.tis,
>>> _7zfh.prx, _al9w.fnm, _ala9.frq, _alab.frq, _ala8.fdx, _akzu_8e.del, _
>>> ala8.fdt, _ailk.fdx, _alaa.frq, _al7i.tis, _7zfh.fdx, _al9w_i.del,
>>> _ah91.fdt, _al7i.tii, _ah91.fdx, _alad.fdx, _akuu.fnm, _add1.prx, _alae
>>> .fdx, _ah91.frq, _7zfh.fdt, _alad.fdt, _alae.fdt, _a61p.fnm, _alaf.frq,
>>> _ala8.tii, _a61p.tis, _9wzn.tii, _alad.frq, _ala8.tis, _alab.tii,
>>> _akh1.frq, _alab.tis, _al7i.fnm, _alab.fdx, _alac.nrm, _ala8_5.del,
>>> _ala7.tii, _alab.fdt, _alaa.fdx, _al2o.frq, _akh1.fdx, _alac.prx, _ala
>>> a.fdt, _al2o.prx, _akh1.fdt, _alad.prx, _ala7.tis, _alac.fdt, _a61p.tii,
>>> _9wzn.tis, _al8x.fdt, _alac.fdx, _al8x.fdx]
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.core.SolrDeletionPolicy
>>> updateCommits
>>> INFO: last commit = 1228872482132
>>> Oct 28, 2009 11:50:45 AM
>>> org.apache.solr.update.processor.LogUpdateProcessor
>>> finish
>>> INFO: {add=[8e0d826fd83005f535bc930dac9fe65f]} 0 222916
>>> Oct 28, 2009 11:50:45 AM org.apache.solr.core.SolrCore execute
>>> INFO: [] webapp=/solrmaster path=/update params={} status=0 QTime=222916
>>> Oct 28,
>>> --
>>> View this message in context:
>>> http://www.nabble.com/Slow-Commits-tp26097538p26097538.html
>>> Sent from the Solr - User mailing list archive at Nabble.com.
>>>
>>>
>> 
>> 
>> 
>> -- 
>> Jerome Eteve.
>> http://www.eteve.net
>> jerome@eteve.net
>> 
>> 
> 
> 

-- 
View this message in context: http://old.nabble.com/Slow-Commits-tp26097538p26284779.html
Sent from the Solr - User mailing list archive at Nabble.com.