Try looking at your warming queries. Create a warming query that will not return ay results. See if it helps returning commits faster.
Thx -----Original Message----- From: Bill Au [mailto:bill.w...@gmail.com] Sent: Friday, May 27, 2011 3:47 PM To: solr-user@lucene.apache.org Subject: Re: very slow commits and overlapping commits I managed to get a thread dump during a slow commit: "resin-tcp-connection-*:5062-129" Id=12721 in RUNNABLE total cpu time=391530.0000ms user time=390620.0000ms at java.lang.String.intern(Native Method) at org.apache.lucene.util.SimpleStringInterner.intern(SimpleStringInterner.java:74) at org.apache.lucene.util.StringHelper.intern(StringHelper.java:36) at org.apache.lucene.index.FieldInfos.read(FieldInfos.java:356) at org.apache.lucene.index.FieldInfos.(FieldInfos.java:71) at org.apache.lucene.index.SegmentReader$CoreReaders.(SegmentReader.java:116) at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:638) at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:608) at org.apache.lucene.index.IndexWriter$ReaderPool.get(IndexWriter.java:691) at org.apache.lucene.index.IndexWriter$ReaderPool.get(IndexWriter.java:667) at org.apache.lucene.index.DocumentsWriter.applyDeletes(DocumentsWriter.java:956) at org.apache.lucene.index.IndexWriter.applyDeletes(IndexWriter.java:5207) at org.apache.lucene.index.IndexWriter.doFlushInternal(IndexWriter.java:4370) at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:4209) at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:4200) at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:2195) at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:2158) at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:2122) at org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:230) at org.apache.solr.update.DirectUpdateHandler2.closeWriter(DirectUpdateHandler2.java:181) at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:409) at org.apache.solr.update.processor.RunUpdateProcessor.processCommit(RunUpdateProcessorFactory.java:85) at org.apache.solr.handler.RequestHandlerUtils.handleCommit(RequestHandlerUtils.java:107) at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:48) at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:131) at org.apache.solr.core.SolrCore.execute(SolrCore.java:1316) at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:338) at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:241) at com.caucho.server.dispatch.FilterFilterChain.doFilter(FilterFilterChain.java:70) at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:173) at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:229) at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:274) at com.caucho.server.port.TcpConnection.run(TcpConnection.java:511) at com.caucho.util.ThreadPool.runTasks(ThreadPool.java:520) at com.caucho.util.ThreadPool.run(ThreadPool.java:442) at java.lang.Thread.run(Thread.java:619) It looks like Lucene's StringHelper is hardcoding the max size of the hash table of SimpleStringInterner to 1024 and I might be hitting that limit, causing an actual call to java.lang.String.intern(). I think I need to reduce the number of fields in my index. Any other things I can do to help in this case. Bill On Wed, May 25, 2011 at 11:28 AM, Bill Au <bill.w...@gmail.com> wrote: > I am taking a snapshot after every commit. From looking at the > snapshots, it does not look like the delay in caused by segments > merging because I am not seeing any large new segments after a commit. > > I still can't figure out why there is a 2 minutes gap between "start > commit" and "SolrDelectionPolicy.onCommit". Will changing the > deletion policy make any difference? I am using the default deletion policy > now. > > Bill > > 2011/5/21 Erick Erickson <erickerick...@gmail.com> > >> Well, committing less offside a possibilty <g>. Here's what's >> probably happening. When you pass certain thresholds, segments are >> merged which can take quite some time. His are you triggering >> commits? If it's external, think about using auto commit instead. >> >> Best >> Erick >> On May 20, 2011 6:04 PM, "Bill Au" <bill.w...@gmail.com> wrote: >> > On my Solr 1.4.1 master I am doing commits regularly at a fixed >> interval. >> I >> > noticed that from time to time commit will take longer than the >> > commit interval, causing commits to overlap. Then things will get >> > worse as >> commit >> > will take longer and longer. Here is the logs for a long commit: >> > >> > >> > [2011-05-18 23:47:30.071] start >> > >> >> commit(optimize=false,waitFlush=false,waitSearcher=false,expungeDelet >> es=false) >> > [2011-05-18 23:49:48.119] SolrDeletionPolicy.onCommit: >> > commits:num=2 >> > [2011-05-18 23:49:48.119] >> > >> >> commit{dir=/var/opt/resin3/5062/solr/data/index,segFN=segments_5cpa,v >> ersion=1247782702272,generation=249742,filenames=[_4dqu_2g.del, >> > _4e66.tis, _4e3r.tis, _4e59.nrm, _4e68_1.del, _4e4n.prx, _4e4n.fnm, >> > _4e67.fnm, _4e3r.frq, _4e3r.tii, _4e6d.fnm, _4e6c.prx, _4e68.fdx, >> _4e68.nrm, >> > _4e6a.frq, _4e68.fdt, _4dqu.fnm, _4e4n.tii, _4e69.fdx, _4e69.fdt, >> _4e0e.nrm, >> > _4e4n.tis, _4e6e.fnm, _4e3r.prx, _4e66.fnm, _4e3r.nrm, _4e0e.prx, >> _4e4c.fdx, >> > _4dx1.prx, _4e5v.frq, _4e3r.fdt, _4e4c.tis, _4e41_6.del, _4e6b.tis, >> > _4e6b_1.del, _4e4y_3.del, _4e6b.tii, _4e3r.fdx, _4dx1.nrm, >> > _4e4y.frq, _4e4c.fdt, _4e4c.tii, _4e6d.fdt, _4e5k.fnm, _4e41.fnm, >> > _4e69.fnm, >> _4e67.fdt, >> > _4e0e.tii, _4dty_h.del, _4e6b.fnm, _4e0e_h.del, _4e6d.fdx, >> > _4e67.fdx, _4e0e.tis, _4e5v.nrm, _4dx1.fnm, _4e5v.tii, _4dqu.fdt, >> > segments_5cpa, _4e5v.prx, _4dqu.fdx, _4e59.fnm, _4e6d.prx, >> > _4e59_5.del, _4e4c.prx, _4e4c.nrm, _4e5k.prx, _4e66.fdx, _4dty.frq, >> > _4e6c.frq, _4e5v.tis, >> _4e6e.tii, >> > _4e66.fdt, _4e6b.fdx, _4e68.prx, _4e59.fdx, _4e6e.fdt, _4e41.prx, >> _4dx1.tii, >> > _4dx1.fdt, _4e6b.fdt, _4e5v_4.del, _4e4n.fdt, _4e6e.fdx, _4dx1.fdx, >> > _4e41.nrm, _4e4n.fdx, _4e6e.tis, _4e66.tii, _4e4c.fnm, _4e6b.prx, >> _4e67.prx, >> > _4e0e.fnm, _4e4n.nrm, _4e67.nrm, _4e5k.nrm, _4e6a.prx, _4e68.fnm, >> > _4e4c_4.del, _4dx1.tis, _4e6e.nrm, _4e59.tii, _4e68.tis, _4e67.frq, >> > _4e3r.fnm, _4dty.nrm, _4e4y.prx, _4e6e.prx, _4dty.tis, _4e4y.tis, >> _4e6b.nrm, >> > _4e6a.fdt, _4e4n.frq, _4e6d.frq, _4e59.fdt, _4e6a.fdx, _4e6a.fnm, >> _4dqu.tii, >> > _4e41.tii, _4e67_1.del, _4e41.tis, _4dty.fdt, _4e69.tis, _4dqu.frq, >> > _4dty.fdx, _4dx1.frq, _4e6e.frq, _4e66_1.del, _4e69.prx, _4e6d.tii, >> > _4e5k.tii, _4e0e.fdt, _4dqu.tis, _4e6d.tis, _4e69.nrm, _4dqu.prx, >> _4e4y.fnm, >> > _4e67.tis, _4e69_1.del, _4e6d.nrm, _4e6c.tis, _4e0e.fdx, _4e6c.tii, >> > _4dx1_n.del, _4e5v.fnm, _4e5k.tis, _4e59.tis, _4e67.tii, _4dqu.nrm, >> > _4e5k_8.del, _4e6c.fdx, _4e6c.fdt, _4e41.frq, _4e4y.fdx, _4e69.frq, >> > _4e6a.tis, _4dty.prx, _4e66.frq, _4e5k.frq, _4e6a.tii, _4e69.tii, >> _4e6c.nrm, >> > _4dty.fnm, _4e59.prx, _4e59.frq, _4e66.prx, _4e68.frq, _4e5k.fdx, >> _4e4y.tii, >> > _4e6c.fnm, _4e0e.frq, _4e6b.frq, _4e41.fdt, _4e4n_2.del, _4dty.tii, >> > _4e4y.fdt, _4e66.nrm, _4e4c.frq, _4e6a.nrm, _4e5k.fdt, _4e3r_i.del, >> > _4e5v.fdt, _4e4y.nrm, _4e68.tii, _4e5v.fdx, _4e41.fdx] >> > [2011-05-18 23:49:48.119] >> > >> >> commit{dir=/var/opt/resin3/5062/solr/data/index,segFN=segments_5cpb,v >> ersion=1247782702273,generation=249743,filenames=[_4dqu_2g.del, >> > _4e66.tis, _4e59.nrm, _4e3r.tis, _4e4n.fnm, _4e67.fnm, _4e3r.tii, >> _4e6d.fnm, >> > _4e68.fdx, _4e68.fdt, _4dqu.fnm, _4e4n.tii, _4e69.fdx, _4e69.fdt, >> _4e4n.tis, >> > _4e6e.fnm, _4e0e.prx, _4e4c.tis, _4e5v.frq, _4e4y_3.del, >> > _4e6b_1.del, _4e4c.tii, _4e6f.fnm, _4e5k.fnm, _4e6c_1.del, >> > _4e41.fnm, _4dx1.fnm, _4e5v.nrm, _4e5v.tii, _4e5v.prx, _4e5k.prx, >> > _4e4c.nrm, _4dty.frq, >> _4e66.fdx, >> > _4e5v.tis, _4e66.fdt, _4e6e.tii, _4e59.fdx, _4e6b.fdx, _4e41.prx, >> _4e6b.fdt, >> > _4e41.nrm, _4e6e.tis, _4e4c.fnm, _4e66.tii, _4e6b.prx, _4e0e.fnm, >> _4e5k.nrm, >> > _4e6a.prx, _4e6e.nrm, _4e59.tii, _4e67.frq, _4dty.nrm, _4e4y.tis, >> _4e6a.fdt, >> > _4e6b.nrm, _4e59.fdt, _4e6a.fdx, _4e41.tii, _4e41.tis, _4e67_1.del, >> > _4dty.fdt, _4dty.fdx, _4e69.tis, _4e66_1.del, _4e6e.frq, _4e5k.tii, >> > _4dqu.prx, _4e67.tis, _4e69_1.del, _4e6c.tis, _4e6c.tii, _4e5v.fnm, >> > _4e5k.tis, _4e59.tis, _4e67.tii, _4e6c.fdx, _4e4y.fdx, _4e41.frq, >> _4e6c.fdt, >> > _4dty.prx, _4e66.frq, _4e69.tii, _4e6c.nrm, _4e59.frq, _4e66.prx, >> _4e5k.fdx, >> > _4e68.frq, _4e4y.tii, _4e4n_2.del, _4e41.fdt, _4e6b.frq, _4e4y.fdt, >> > _4e66.nrm, _4e4c.frq, _4e3r_i.del, _4e5k.fdt, _4e4y.nrm, _4e41.fdx, >> > _4e4n.prx, _4e68_1.del, _4e3r.frq, _4e6f.fdt, _4e6f.fdx, _4e6c.prx, >> > _4e68.nrm, _4e6a.frq, _4e0e.nrm, _4e3r.prx, _4e66.fnm, _4e3r.nrm, >> _4e4c.fdx, >> > _4dx1.prx, _4e3r.fdt, _4e41_6.del, _4e6b.tis, _4e3r.fdx, _4e6b.tii, >> > _4dx1.nrm, _4e4y.frq, _4e4c.fdt, _4e6d.fdt, _4e69.fnm, _4dty_h.del, >> > _4e0e.tii, _4e67.fdt, _4e0e_h.del, _4e6b.fnm, _4e6d.fdx, _4e67.fdx, >> > _4e0e.tis, _4dqu.fdt, segments_5cpb, _4dqu.fdx, _4e59.fnm, >> > _4e59_5.del, _4e6d.prx, _4e4c.prx, _4e6c.frq, _4e68.prx, _4e6e.fdt, >> > _4dx1.tii, >> _4dx1.fdt, >> > _4e4n.fdt, _4e5v_4.del, _4e6e.fdx, _4dx1.fdx, _4e4n.fdx, _4e6f.nrm, >> > _4e4n.nrm, _4e67.prx, _4e67.nrm, _4e68.fnm, _4e4c_4.del, _4dx1.tis, >> > _4e68.tis, _4e3r.fnm, _4e6f.prx, _4e4y.prx, _4dty.tis, _4e6e.prx, >> _4e4n.frq, >> > _4e6d.frq, _4dqu.tii, _4e6a.fnm, _4dx1.frq, _4dqu.frq, _4e69.prx, >> _4e6d.tii, >> > _4e0e.fdt, _4dqu.tis, _4e69.nrm, _4e6d.tis, _4e4y.fnm, _4e0e.fdx, >> _4e6d.nrm, >> > _4dx1_n.del, _4dqu.nrm, _4e6f.tii, _4e5k_8.del, _4e6f.frq, >> > _4e69.frq, _4e6a.tis, _4e6f.tis, _4e5k.frq, _4e6a.tii, _4dty.fnm, >> > _4e59.prx, >> _4e6c.fnm, >> > _4e0e.frq, _4dty.tii, _4e6a.nrm, _4e5v.fdt, _4e68.tii, _4e5v.fdx] >> > [2011-05-18 23:49:48.121] newest commit = 1247782702273 >> > [2011-05-18 23:49:49.851] Opening Searcher@488d12e4 main >> > [2011-05-18 23:49:51.534] autowarming Searcher@488d12e4 main from >> > Searcher@64b2933f main >> > [2011-05-18 23:49:51.534] >> > >> >> fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0, >> size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative >> _hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} >> > [2011-05-18 23:49:51.535] end_commit_flush >> > [2011-05-18 23:49:51.536] {commit=} 0 141468 >> > >> > >> > I noticed that there is a 2 minutes gap between the "start commit ..." >> > message and the "SolrDeletionPolicy.onCommit:.." message. Is Solr >> removing >> > old commits during this time? Is is normal to take this long to >> > delete >> old >> > commits? >> > >> > Bill >> > > ******************Legal Disclaimer*************************** "This communication may contain confidential and privileged material for the sole use of the intended recipient. Any unauthorized review, use or distribution by others is strictly prohibited. If you have received the message in error, please advise the sender by reply email and delete the message. Thank you." *********************************************************
