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,expungeDeletes=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,version=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,version=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
>>
>
>
