That's strange. Are you saying that after you see the "No uncommitted changes.
Skipping IW.commit." message, that some time later the docs will appear
even though you haven't updated them after you see the message above?
I have upon occasion seen people get fooled by either browser or container
caching, have you checked for those? This is on the assumption that your "No
uncommitted changes" message is actually accurate and is for an interval other
than the one you're looking at. But that's a wild guess.
How are you sending updates to Solr?
I notice a couple of things on a very quick look:
1> you have your rambuffersize set to 1G. I've rarely seen this do
much good past 128M, you might want some of this RAM back
2> your soft commit is set to 18 seconds. This should show you docs
added 20 seconds ago.
3> You've set <nrtMode>false</nrtMode>. I'm assuming here that you're
NOT running ZooKeeper?
But this is puzzling. This hasn't been reported by others, so I'm
tending to think about something innocent-seeming about your setup
that is causing this but confess I haven't a clue what.
Erick
On Fri, Jun 6, 2014 at 6:47 AM, Justin Sweeney
<justin.sweene...@gmail.com> wrote:
> Hi,
>
> An application I am working on indexes documents to a Solr index. This Solr
> index is setup as a single node, without any replication. This index is
> running Solr 4.5.0.
>
> We have noticed an issue lately that is causing some problems for our
> application. The problem is that we add/update a number of documents in the
> Solr index and we have the index setup to autoCommit (hard) once every 30
> minutes. In the Solr logs, I am able to see the add command to Solr and I
> can also see Solr start the hard commit. When this hard commit occurs, we
> see the following message:
> INFO - 2014-06-04 20:13:55.135;
> org.apache.solr.update.DirectUpdateHandler2; No uncommitted changes.
> Skipping IW.commit.
>
> This only happens sometimes, but Solr will go hours (we have seen 6-12
> hours of this behavior) before it does a hard commit where it find changes.
> After the hard commit where the changes are found, we are then able to
> search for and find the documents that were added hours ago, but up until
> that point the documents are not searchable.
>
> We tried enabling autoSoftCommit every 5 minutes in the hope that this
> would help, but we are seeing the same behavior.
>
> Here is a sampling of the logs showing this occurring (I've trimmed it down
> to just show what is happening):
>
> INFO - 2014-06-05 20:00:41.300;
>>> org.apache.solr.update.processor.LogUpdateProcessor; [zoomCollection]
>>> webapp=/solr path=/update params={wt=javabin&version=2} {add=[359453225]} 0
>>> 0
>>
>> INFO - 2014-06-05 20:00:41.376;
>>> org.apache.solr.update.processor.LogUpdateProcessor; [zoomCollection]
>>> webapp=/solr path=/update params={wt=javabin&version=2} {add=[347170717]} 0
>>> 1
>>
>> INFO - 2014-06-05 20:00:51.527;
>>> org.apache.solr.update.DirectUpdateHandler2; start
>>> commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
>>
>> INFO - 2014-06-05 20:00:51.533; org.apache.solr.search.SolrIndexSearcher;
>>> Opening Searcher@257c43d main
>>
>> INFO - 2014-06-05 20:00:51.533;
>>> org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
>>
>> INFO - 2014-06-05 20:00:51.545; org.apache.solr.core.QuerySenderListener;
>>> QuerySenderListener sending requests to Searcher@257c43d
>>> main{StandardDirectoryReader(segments_acl:1367002775953
>>> _2f28(4.5):C13583563/4081507 _2gl6(4.5):C2754573/193533
>>> _2g21(4.5):C1046256/296354 _2ge2(4.5):C835858/206139
>>> _2gqd(4.5):C383500/31051 _2gmu(4.5):C125197/32491 _2grl(4.5):C46906/1255
>>> _2gpj(4.5):C66480/16562 _2gra(4.5):C364/22 _2gr1(4.5):C36064/2556
>>> _2gqg(4.5):C42504/21515 _2gqm(4.5):C26821/12659 _2gqu(4.5):C24172/10240
>>> _2gqy(4.5):C697/215 _2gr2(4.5):C878/352 _2gr7(4.5):C28135/11775
>>> _2gr9(4.5):C3276/1341 _2grb(4.5):C5/1 _2grc(4.5):C3247/1219 _2grd(4.5):C6/1
>>> _2grf(4.5):C5/2 _2grg(4.5):C23659/10967 _2grh(4.5):C1 _2grj(4.5):C1
>>> _2grk(4.5):C5160/1482 _2grm(4.5):C1210/351 _2grn(4.5):C3957/1372
>>> _2gro(4.5):C7734/2207 _2grp(4.5):C220/36)}
>>
>> INFO - 2014-06-05 20:00:51.546; org.apache.solr.core.SolrCore;
>>> [zoomCollection] webapp=null path=null
>>> params={event=newSearcher&q=d_name:ibm&distrib=false} hits=38 status=0
>>> QTime=0
>>
>> INFO - 2014-06-05 20:00:51.546; org.apache.solr.core.QuerySenderListener;
>>> QuerySenderListener done.
>>
>> INFO - 2014-06-05 20:00:51.547; org.apache.solr.core.SolrCore;
>>> [zoomCollection] Registered new searcher Searcher@257c43d
>>> main{StandardDirectoryReader(segments_acl:1367002775953
>>> _2f28(4.5):C13583563/4081507 _2gl6(4.5):C2754573/193533
>>> _2g21(4.5):C1046256/296354 _2ge2(4.5):C835858/206139
>>> _2gqd(4.5):C383500/31051 _2gmu(4.5):C125197/32491 _2grl(4.5):C46906/1255
>>> _2gpj(4.5):C66480/16562 _2gra(4.5):C364/22 _2gr1(4.5):C36064/2556
>>> _2gqg(4.5):C42504/21515 _2gqm(4.5):C26821/12659 _2gqu(4.5):C24172/10240
>>> _2gqy(4.5):C697/215 _2gr2(4.5):C878/352 _2gr7(4.5):C28135/11775
>>> _2gr9(4.5):C3276/1341 _2grb(4.5):C5/1 _2grc(4.5):C3247/1219 _2grd(4.5):C6/1
>>> _2grf(4.5):C5/2 _2grg(4.5):C23659/10967 _2grh(4.5):C1 _2grj(4.5):C1
>>> _2grk(4.5):C5160/1482 _2grm(4.5):C1210/351 _2grn(4.5):C3957/1372
>>> _2gro(4.5):C7734/2207 _2grp(4.5):C220/36)}
>>
>> INFO - 2014-06-05 20:01:10.557;
>>> org.apache.solr.update.DirectUpdateHandler2; start
>>> commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
>>
>> INFO - 2014-06-05 20:01:10.559; org.apache.solr.core.SolrCore;
>>> [zoomCollection] webapp=/solr path=/select
>>> params={fl=d_ticker,d_location,d_id,d_source_count,d_xml_domain,d_cik,d_keyword_count,d_xml_name,d_xml_contact,d_main_domain,d_location_code&start=0&q=d_domain:("
>>> www.northwestcollege.edu")&wt=javabin&version=2&rows=999999} hits=4
>>> status=0 QTime=40
>>
>> INFO - 2014-06-05 20:01:10.563; org.apache.solr.search.SolrIndexSearcher;
>>> Opening Searcher@69f90ad1 main
>>
>> INFO - 2014-06-05 20:01:10.564;
>>> org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
>>
>> INFO - 2014-06-05 20:01:10.579; org.apache.solr.core.QuerySenderListener;
>>> QuerySenderListener sending requests to Searcher@69f90ad1
>>> main{StandardDirectoryReader(segments_acl:1367002775953
>>> _2f28(4.5):C13583563/4081507 _2gl6(4.5):C2754573/193533
>>> _2g21(4.5):C1046256/296354 _2ge2(4.5):C835858/206139
>>> _2gqd(4.5):C383500/31051 _2gmu(4.5):C125197/32491 _2grl(4.5):C46906/1255
>>> _2gpj(4.5):C66480/16562 _2gra(4.5):C364/22 _2gr1(4.5):C36064/2556
>>> _2gqg(4.5):C42504/21515 _2gqm(4.5):C26821/12659 _2gqu(4.5):C24172/10240
>>> _2gqy(4.5):C697/215 _2gr2(4.5):C878/352 _2gr7(4.5):C28135/11775
>>> _2gr9(4.5):C3276/1341 _2grb(4.5):C5/1 _2grc(4.5):C3247/1219 _2grd(4.5):C6/1
>>> _2grf(4.5):C5/2 _2grg(4.5):C23659/10967 _2grh(4.5):C1 _2grj(4.5):C1
>>> _2grk(4.5):C5160/1482 _2grm(4.5):C1210/351 _2grn(4.5):C3957/1372
>>> _2gro(4.5):C7734/2207 _2grp(4.5):C220/36)}
>>
>> INFO - 2014-06-05 20:01:10.580; org.apache.solr.core.SolrCore;
>>> [zoomCollection] webapp=null path=null
>>> params={event=newSearcher&q=d_name:ibm&distrib=false} hits=38 status=0
>>> QTime=1
>>
>> INFO - 2014-06-05 20:01:10.580; org.apache.solr.core.QuerySenderListener;
>>> QuerySenderListener done.
>>
>> INFO - 2014-06-05 20:01:10.580; org.apache.solr.core.SolrCore;
>>> [zoomCollection] Registered new searcher Searcher@69f90ad1
>>> main{StandardDirectoryReader(segments_acl:1367002775953
>>> _2f28(4.5):C13583563/4081507 _2gl6(4.5):C2754573/193533
>>> _2g21(4.5):C1046256/296354 _2ge2(4.5):C835858/206139
>>> _2gqd(4.5):C383500/31051 _2gmu(4.5):C125197/32491 _2grl(4.5):C46906/1255
>>> _2gpj(4.5):C66480/16562 _2gra(4.5):C364/22 _2gr1(4.5):C36064/2556
>>> _2gqg(4.5):C42504/21515 _2gqm(4.5):C26821/12659 _2gqu(4.5):C24172/10240
>>> _2gqy(4.5):C697/215 _2gr2(4.5):C878/352 _2gr7(4.5):C28135/11775
>>> _2gr9(4.5):C3276/1341 _2grb(4.5):C5/1 _2grc(4.5):C3247/1219 _2grd(4.5):C6/1
>>> _2grf(4.5):C5/2 _2grg(4.5):C23659/10967 _2grh(4.5):C1 _2grj(4.5):C1
>>> _2grk(4.5):C5160/1482 _2grm(4.5):C1210/351 _2grn(4.5):C3957/1372
>>> _2gro(4.5):C7734/2207 _2grp(4.5):C220/36)}
>>
>> INFO - 2014-06-05 20:14:25.707;
>>> org.apache.solr.update.DirectUpdateHandler2; start
>>> commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
>>
>> INFO - 2014-06-05 20:14:25.708;
>>> org.apache.solr.update.DirectUpdateHandler2; No uncommitted changes.
>>> Skipping IW.commit.
>>
>> INFO - 2014-06-05 20:14:25.714; org.apache.solr.search.SolrIndexSearcher;
>>> Opening Searcher@4010a5b9 main
>>
>> INFO - 2014-06-05 20:14:25.714;
>>> org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
>>
>> INFO - 2014-06-05 20:14:25.725; org.apache.solr.core.QuerySenderListener;
>>> QuerySenderListener sending requests to Searcher@4010a5b9
>>> main{StandardDirectoryReader(segments_acl:1367002775953
>>> _2f28(4.5):C13583563/4081507 _2gl6(4.5):C2754573/193533
>>> _2g21(4.5):C1046256/296354 _2ge2(4.5):C835858/206139
>>> _2gqd(4.5):C383500/31051 _2gmu(4.5):C125197/32491 _2grl(4.5):C46906/1255
>>> _2gpj(4.5):C66480/16562 _2gra(4.5):C364/22 _2gr1(4.5):C36064/2556
>>> _2gqg(4.5):C42504/21515 _2gqm(4.5):C26821/12659 _2gqu(4.5):C24172/10240
>>> _2gqy(4.5):C697/215 _2gr2(4.5):C878/352 _2gr7(4.5):C28135/11775
>>> _2gr9(4.5):C3276/1341 _2grb(4.5):C5/1 _2grc(4.5):C3247/1219 _2grd(4.5):C6/1
>>> _2grf(4.5):C5/2 _2grg(4.5):C23659/10967 _2grh(4.5):C1 _2grj(4.5):C1
>>> _2grk(4.5):C5160/1482 _2grm(4.5):C1210/351 _2grn(4.5):C3957/1372
>>> _2gro(4.5):C7734/2207 _2grp(4.5):C220/36)}
>>
>> INFO - 2014-06-05 20:14:25.725; org.apache.solr.core.SolrCore;
>>> [zoomCollection] webapp=null path=null
>>> params={event=newSearcher&q=d_name:ibm&distrib=false} hits=38 status=0
>>> QTime=0
>>
>> INFO - 2014-06-05 20:14:25.726; org.apache.solr.core.QuerySenderListener;
>>> QuerySenderListener done.
>>
>> INFO - 2014-06-05 20:14:25.726; org.apache.solr.core.SolrCore;
>>> [zoomCollection] Registered new searcher Searcher@4010a5b9
>>> main{StandardDirectoryReader(segments_acl:1367002775953
>>> _2f28(4.5):C13583563/4081507 _2gl6(4.5):C2754573/193533
>>> _2g21(4.5):C1046256/296354 _2ge2(4.5):C835858/206139
>>> _2gqd(4.5):C383500/31051 _2gmu(4.5):C125197/32491 _2grl(4.5):C46906/1255
>>> _2gpj(4.5):C66480/16562 _2gra(4.5):C364/22 _2gr1(4.5):C36064/2556
>>> _2gqg(4.5):C42504/21515 _2gqm(4.5):C26821/12659 _2gqu(4.5):C24172/10240
>>> _2gqy(4.5):C697/215 _2gr2(4.5):C878/352 _2gr7(4.5):C28135/11775
>>> _2gr9(4.5):C3276/1341 _2grb(4.5):C5/1 _2grc(4.5):C3247/1219 _2grd(4.5):C6/1
>>> _2grf(4.5):C5/2 _2grg(4.5):C23659/10967 _2grh(4.5):C1 _2grj(4.5):C1
>>> _2grk(4.5):C5160/1482 _2grm(4.5):C1210/351 _2grn(4.5):C3957/1372
>>> _2gro(4.5):C7734/2207 _2grp(4.5):C220/36)}
>>
>> INFO - 2014-06-05 21:14:26.949;
>>> org.apache.solr.update.DirectUpdateHandler2; start
>>> commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
>>
>> INFO - 2014-06-05 21:14:36.727; org.apache.solr.core.SolrDeletionPolicy;
>>> SolrDeletionPolicy.onCommit: commits: num=2
>>
>>
>>> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@/data/solr-data/index
>>> lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@26041cb3;
>>> maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_acl,generation=13413}
>>
>>
>>> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@/data/solr-data/index
>>> lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@26041cb3;
>>> maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_acm,generation=13414}
>>
>> INFO - 2014-06-05 21:14:36.728; org.apache.solr.core.SolrDeletionPolicy;
>>> newest commit generation = 13414
>>
>> INFO - 2014-06-05 21:14:36.749; org.apache.solr.search.SolrIndexSearcher;
>>> Opening Searcher@5bf20a8a main
>>
>> INFO - 2014-06-05 21:14:36.750;
>>> org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
>>
>> INFO - 2014-06-05 21:14:36.759; org.apache.solr.core.QuerySenderListener;
>>> QuerySenderListener sending requests to Searcher@5bf20a8a
>>> main{StandardDirectoryReader(segments_acm:1367002775958
>>> _2f28(4.5):C13583563/4088615 _2gl6(4.5):C2754573/202192
>>> _2g21(4.5):C1046256/298243 _2ge2(4.5):C835858/208834
>>> _2gqd(4.5):C383500/35732 _2gmu(4.5):C125197/33714 _2grl(4.5):C46906/3282
>>> _2gpj(4.5):C66480/17459 _2gra(4.5):C364/40 _2gr1(4.5):C36064/3442
>>> _2gqg(4.5):C42504/22410 _2gqm(4.5):C26821/13787 _2gqu(4.5):C24172/10804
>>> _2gqy(4.5):C697/231 _2gr2(4.5):C878/382 _2gr7(4.5):C28135/12761
>>> _2gr9(4.5):C3276/1478 _2grb(4.5):C5/1 _2grc(4.5):C3247/1323 _2grd(4.5):C6/1
>>> _2grf(4.5):C5/2 _2grg(4.5):C23659/11895 _2grh(4.5):C1 _2grj(4.5):C1
>>> _2grk(4.5):C5160/1982 _2grm(4.5):C1210/531 _2grn(4.5):C3957/1790
>>> _2gro(4.5):C7734/3504 _2grp(4.5):C220/106 _2grq(4.5):C72751/30166
>>> _2grr(4.5):C1)}
>>
>> INFO - 2014-06-05 21:14:36.759; org.apache.solr.core.SolrCore;
>>> [zoomCollection] webapp=null path=null
>>> params={event=newSearcher&q=d_name:ibm&distrib=false} hits=38 status=0
>>> QTime=0
>>
>> INFO - 2014-06-05 21:14:36.760; org.apache.solr.core.QuerySenderListener;
>>> QuerySenderListener done.
>>
>> INFO - 2014-06-05 21:14:36.760; org.apache.solr.core.SolrCore;
>>> [zoomCollection] Registered new searcher Searcher@5bf20a8a
>>> main{StandardDirectoryReader(segments_acm:1367002775958
>>> _2f28(4.5):C13583563/4088615 _2gl6(4.5):C2754573/202192
>>> _2g21(4.5):C1046256/298243 _2ge2(4.5):C835858/208834
>>> _2gqd(4.5):C383500/35732 _2gmu(4.5):C125197/33714 _2grl(4.5):C46906/3282
>>> _2gpj(4.5):C66480/17459 _2gra(4.5):C364/40 _2gr1(4.5):C36064/3442
>>> _2gqg(4.5):C42504/22410 _2gqm(4.5):C26821/13787 _2gqu(4.5):C24172/10804
>>> _2gqy(4.5):C697/231 _2gr2(4.5):C878/382 _2gr7(4.5):C28135/12761
>>> _2gr9(4.5):C3276/1478 _2grb(4.5):C5/1 _2grc(4.5):C3247/1323 _2grd(4.5):C6/1
>>> _2grf(4.5):C5/2 _2grg(4.5):C23659/11895 _2grh(4.5):C1 _2grj(4.5):C1
>>> _2grk(4.5):C5160/1982 _2grm(4.5):C1210/531 _2grn(4.5):C3957/1790
>>> _2gro(4.5):C7734/3504 _2grp(4.5):C220/106 _2grq(4.5):C72751/30166
>>> _2grr(4.5):C1)}
>>
>>
> I've also shared via Google Drive a more complete log for a period of time
> where this is occurring, as well as our solrconfig.xml in case that is
> useful.
>
> Any ideas on why the Solr commit is not finding any changes despite the
> clear logging of the adds. For some reason, after hours of this it will
> find changes and commit everything, including the documents that were
> skipped previously.
>
> Thanks for any assistance!
>
> Justin Sweeney
>
> solr_commit_issue.log
> <https://docs.google.com/file/d/0B7jKxYrZOSvac21nV0JuRWF0SW8/edit?usp=drive_web>
>
> solrconfig.xml
> <https://docs.google.com/file/d/0B7jKxYrZOSvaRUY2QzhUN2tQYmM/edit?usp=drive_web>
>
