This is being triggered by adding the commitWithin param to
ContentStreamUpdateRequest (request.setCommitWithin(10000);). My
configuration has autoCommit max time of 15s and openSearcher set to false.
I'm assuming that changing openSeracher to true should address this, and
adding the softCommit = true to the request would make the documents
available in the mean time?
On Apr 8, 2014 10:02 AM, "Erick Erickson" <erickerick...@gmail.com> wrote:
> Got a clue how it's being generated? Because it's not going to show
> you documents.
>
>
> commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
>
> openSearcher=false and softCommit=false so the documents will be
> invisible. You need one or the other set to true.
>
> What it will do is close the current segment, open a new one and
> truncate the current transaction log. These may be good things but
> they have nothing to do with making docs visible :).
>
> See:
>
> http://searchhub.org/2013/08/23/understanding-transaction-logs-softcommit-and-commit-in-sorlcloud/
>
> Best,
> Erick
>
> On Mon, Apr 7, 2014 at 8:43 PM, Jamie Johnson <jej2...@gmail.com> wrote:
> > Below is the log showing what I believe to be the commit
> >
> > 07-Apr-2014 23:40:55.846 INFO [catalina-exec-5]
> > org.apache.solr.update.processor.LogUpdateProcessor.finish [forums]
> > webapp=/solr path=/update/extract
> >
> params={uprefix=attr_&literal.source_id=e4bb4bb6-96ab-4f8f-8a2a-1cf37dc1bcce&literal.content_group=File&
> > literal.id
> =e4bb4bb6-96ab-4f8f-8a2a-1cf37dc1bcce&literal.forum_id=3&literal.content_type=application/octet-stream&wt=javabin&literal.uploaded_by=+&version=2&literal.content_type=application/octet-stream&literal.file_name=exclusions}
> > {add=[e4bb4bb6-96ab-4f8f-8a2a-1cf37dc1bcce (1464785652471037952)]} 0 563
> > 07-Apr-2014 23:41:10.847 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.DirectUpdateHandler2.commit start
> >
> commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
> > 07-Apr-2014 23:41:10.847 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: commit: start
> > 07-Apr-2014 23:41:10.848 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: commit: enter lock
> > 07-Apr-2014 23:41:10.848 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: commit: now prepare
> > 07-Apr-2014 23:41:10.848 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: prepareCommit: flush
> > 07-Apr-2014 23:41:10.849 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: index before flush _y(4.6):C1
> > _10(4.6):C1 _11(4.6):C1 _12(4.6):C1
> > 07-Apr-2014 23:41:10.849 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DW][commitScheduler-10-thread-1]: commitScheduler-10-thread-1
> > startFullFlush
> > 07-Apr-2014 23:41:10.849 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DW][commitScheduler-10-thread-1]: anyChanges? numDocsInRam=1
> deletes=true
> > hasTickets:false pendingChangesInFullFlush: false
> > 07-Apr-2014 23:41:10.850 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DWFC][commitScheduler-10-thread-1]: addFlushableState
> > DocumentsWriterPerThread [pendingDeletes=gen=0, segment=_14,
> > aborting=false, numDocsInRAM=1, deleteQueue=DWDQ: [ generation: 2 ]]
> > 07-Apr-2014 23:41:10.852 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DWPT][commitScheduler-10-thread-1]: flush postings as segment _14
> numDocs=1
> > 07-Apr-2014 23:41:10.904 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DWPT][commitScheduler-10-thread-1]: new segment has 0 deleted docs
> > 07-Apr-2014 23:41:10.904 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DWPT][commitScheduler-10-thread-1]: new segment has no vectors; norms;
> no
> > docValues; prox; freqs
> > 07-Apr-2014 23:41:10.904 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DWPT][commitScheduler-10-thread-1]: flushedFiles=[_14.nvd,
> > _14_Lucene41_0.pos, _14_Lucene41_0.tip, _14_Lucene41_0.tim, _14.nvm,
> > _14.fdx, _14_Lucene41_0.doc, _14.fnm, _14.fdt]
> > 07-Apr-2014 23:41:10.905 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DWPT][commitScheduler-10-thread-1]: flushed codec=Lucene46
> > 07-Apr-2014 23:41:10.905 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DWPT][commitScheduler-10-thread-1]: flushed: segment=_14 ramUsed=0.122
> MB
> > newFlushedSize(includes docstores)=0.003 MB docs/MB=322.937
> > 07-Apr-2014 23:41:10.907 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DW][commitScheduler-10-thread-1]: publishFlushedSegment seg-private
> > updates=null
> > 07-Apr-2014 23:41:10.907 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: publishFlushedSegment
> > 07-Apr-2014 23:41:10.907 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: push deletes 1 deleted terms (unique
> > count=1) bytesUsed=1024 delGen=4 packetCount=1 totBytesUsed=1024
> > 07-Apr-2014 23:41:10.907 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: publish sets newSegment delGen=5
> > seg=_14(4.6):C1
> > 07-Apr-2014 23:41:10.908 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IFD][commitScheduler-10-thread-1]: now checkpoint "_y(4.6):C1
> _10(4.6):C1
> > _11(4.6):C1 _12(4.6):C1 _14(4.6):C1" [5 segments ; isCommit = false]
> > 07-Apr-2014 23:41:10.908 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IFD][commitScheduler-10-thread-1]: 0 msec to checkpoint
> > 07-Apr-2014 23:41:10.908 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: apply all deletes during flush
> > 07-Apr-2014 23:41:10.908 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: applyDeletes: infos=[_y(4.6):C1,
> > _10(4.6):C1, _11(4.6):C1, _12(4.6):C1, _14(4.6):C1] packetCount=1
> > 07-Apr-2014 23:41:10.909 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: seg=_12(4.6):C1 segGen=3 coalesced
> > deletes=[CoalescedUpdates(termSets=1,queries=0,numericUpdates=0)]
> > newDelCount=0
> > 07-Apr-2014 23:41:10.909 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: seg=_11(4.6):C1 segGen=3 coalesced
> > deletes=[CoalescedUpdates(termSets=1,queries=0,numericUpdates=0)]
> > newDelCount=0
> > 07-Apr-2014 23:41:10.909 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: seg=_10(4.6):C1 segGen=3 coalesced
> > deletes=[CoalescedUpdates(termSets=1,queries=0,numericUpdates=0)]
> > newDelCount=0
> > 07-Apr-2014 23:41:10.909 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: seg=_y(4.6):C1 segGen=3 coalesced
> > deletes=[CoalescedUpdates(termSets=1,queries=0,numericUpdates=0)]
> > newDelCount=0
> > 07-Apr-2014 23:41:10.910 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: applyDeletes took 2 msec
> > 07-Apr-2014 23:41:10.910 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: prune
> > sis=org.apache.lucene.index.SegmentInfos@6960fd3b minGen=6 packetCount=1
> > 07-Apr-2014 23:41:10.910 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: pruneDeletes: prune 1 packets; 0
> packets
> > remain
> > 07-Apr-2014 23:41:10.910 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DW][commitScheduler-10-thread-1]: commitScheduler-10-thread-1
> > finishFullFlush success=true
> > 07-Apr-2014 23:41:10.911 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [TMP][commitScheduler-10-thread-1]: findMerges: 5 segments
> > 07-Apr-2014 23:41:10.930 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [TMP][commitScheduler-10-thread-1]: seg=_y(4.6):C1 size=0.038 MB
> [floored]
> > 07-Apr-2014 23:41:10.930 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [TMP][commitScheduler-10-thread-1]: seg=_12(4.6):C1 size=0.020 MB
> > [floored]
> > 07-Apr-2014 23:41:10.931 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [TMP][commitScheduler-10-thread-1]: seg=_10(4.6):C1 size=0.004 MB
> > [floored]
> > 07-Apr-2014 23:41:10.931 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [TMP][commitScheduler-10-thread-1]: seg=_14(4.6):C1 size=0.003 MB
> > [floored]
> > 07-Apr-2014 23:41:10.932 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [TMP][commitScheduler-10-thread-1]: seg=_11(4.6):C1 size=0.003 MB
> > [floored]
> > 07-Apr-2014 23:41:10.932 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [TMP][commitScheduler-10-thread-1]: allowedSegmentCount=1 vs count=5
> > (eligible count=5) tooBigCount=0
> > 07-Apr-2014 23:41:10.933 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [CMS][commitScheduler-10-thread-1]: now merge
> > 07-Apr-2014 23:41:10.933 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [CMS][commitScheduler-10-thread-1]: index: _y(4.6):C1 _10(4.6):C1
> > _11(4.6):C1 _12(4.6):C1 _14(4.6):C1
> > 07-Apr-2014 23:41:10.933 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [CMS][commitScheduler-10-thread-1]: no more merges pending; now return
> > 07-Apr-2014 23:41:10.933 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: startCommit(): start
> > 07-Apr-2014 23:41:10.934 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: startCommit index=_y(4.6):C1
> _10(4.6):C1
> > _11(4.6):C1 _12(4.6):C1 _14(4.6):C1 changeCount=3
> > 07-Apr-2014 23:41:10.939 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: done all syncs: [_y.nvd,
> > _10_Lucene41_0.tip, _12.fdt, _10_Lucene41_0.tim, _11_Lucene41_0.doc,
> > _12.fdx, _12.si, _y.fdt, _y_Lucene41_0.tip, _y.fdx, _y.nvm, _14.fdx,
> > _14.fdt, _11_Lucene41_0.tip, _12_Lucene41_0.doc, _11_Lucene41_0.tim,
> > _11.fdx, _10.nvd, _11.fdt, _10.nvm, _12_Lucene41_0.tip,
> _12_Lucene41_0.pos,
> > _12_Lucene41_0.tim, _12.fnm, _14.fnm, _10.fdt, _14_Lucene41_0.pos, _
> 11.si,
> > _14_Lucene41_0.tip, _y.si, _14_Lucene41_0.tim, _11.nvd,
> _14_Lucene41_0.doc,
> > _10.fdx, _10_Lucene41_0.doc, _11.nvm, _y.fnm, _12.nvd, _14.nvd, _10.fnm,
> _
> > 14.si, _11_Lucene41_0.pos, _14.nvm, _y_Lucene41_0.tim, _10.si,
> > _10_Lucene41_0.pos, _11.fnm, _y_Lucene41_0.pos, _12.nvm,
> _y_Lucene41_0.doc]
> > 07-Apr-2014 23:41:10.940 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: commit: pendingCommit != null
> > 07-Apr-2014 23:41:10.971 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: commit: wrote segments file
> "segments_25"
> > 07-Apr-2014 23:41:10.971 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IFD][commitScheduler-10-thread-1]: now checkpoint "_y(4.6):C1
> _10(4.6):C1
> > _11(4.6):C1 _12(4.6):C1 _14(4.6):C1" [5 segments ; isCommit = true]
> > 07-Apr-2014 23:41:10.972 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.core.SolrDeletionPolicy.onCommit
> > SolrDeletionPolicy.onCommit: commits: num=2
> > commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@
> /Users/jjohnson/Development/servers/apache-tomee-plus-1.6.0/solr/forums/data/index
> > lockFactory=org.apache.lucene.store.NativeFSLockFactory@455f2a2c;
> > maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_24,generation=76}
> > commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@
> /Users/jjohnson/Development/servers/apache-tomee-plus-1.6.0/solr/forums/data/index
> > lockFactory=org.apache.lucene.store.NativeFSLockFactory@455f2a2c;
> > maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_25,generation=77}
> > 07-Apr-2014 23:41:10.973 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.core.SolrDeletionPolicy.updateCommits newest commit
> > generation = 77
> > 07-Apr-2014 23:41:10.973 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IFD][commitScheduler-10-thread-1]: deleteCommits: now decRef commit
> > "segments_24"
> > 07-Apr-2014 23:41:10.973 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IFD][commitScheduler-10-thread-1]: delete "segments_24"
> > 07-Apr-2014 23:41:10.974 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IFD][commitScheduler-10-thread-1]: 2 msec to checkpoint
> > 07-Apr-2014 23:41:10.974 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: commit: done
> > 07-Apr-2014 23:41:10.974 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DW][commitScheduler-10-thread-1]: anyChanges? numDocsInRam=0
> deletes=false
> > hasTickets:false pendingChangesInFullFlush: false
> > 07-Apr-2014 23:41:10.975 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: nrtIsCurrent: infoVersion matches:
> > false; DW changes: false; BD changes: false
> > 07-Apr-2014 23:41:10.975 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: flush at getReader
> > 07-Apr-2014 23:41:10.975 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DW][commitScheduler-10-thread-1]: commitScheduler-10-thread-1
> > startFullFlush
> > 07-Apr-2014 23:41:10.975 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DW][commitScheduler-10-thread-1]: anyChanges? numDocsInRam=0
> deletes=false
> > hasTickets:false pendingChangesInFullFlush: false
> > 07-Apr-2014 23:41:10.976 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: apply all deletes during flush
> > 07-Apr-2014 23:41:10.976 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: applyDeletes: no deletes; skipping
> > 07-Apr-2014 23:41:10.976 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [BD][commitScheduler-10-thread-1]: prune
> > sis=org.apache.lucene.index.SegmentInfos@6960fd3b minGen=6 packetCount=0
> > 07-Apr-2014 23:41:10.978 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: return reader version=155
> > reader=StandardDirectoryReader(segments_25:155:nrt _y(4.6):C1 _10(4.6):C1
> > _11(4.6):C1 _12(4.6):C1 _14(4.6):C1)
> > 07-Apr-2014 23:41:10.978 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [DW][commitScheduler-10-thread-1]: commitScheduler-10-thread-1
> > finishFullFlush success=true
> > 07-Apr-2014 23:41:10.978 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.LoggingInfoStream.message
> > [IW][commitScheduler-10-thread-1]: getReader took 3 msec
> > 07-Apr-2014 23:41:10.979 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.search.SolrIndexSearcher.<init> Opening
> Searcher@76a4ccarealtime
> > 07-Apr-2014 23:41:10.980 INFO [commitScheduler-10-thread-1]
> > org.apache.solr.update.DirectUpdateHandler2.commit end_commit_flush
> >
> >
> > On Mon, Apr 7, 2014 at 11:43 AM, Erick Erickson <erickerick...@gmail.com
> >wrote:
> >
> >> What does the call look like? Are you setting opening a new searcher
> >> or not? That should be in the log line where the commit is recorded...
> >>
> >> FWIW,
> >> Erick
> >>
> >> On Sun, Apr 6, 2014 at 5:37 PM, Jamie Johnson <jej2...@gmail.com>
> wrote:
> >> > I'm running solr 4.6.0 and am noticing that commitWithin doesn't seem
> to
> >> > work when I am using the /update/extract request handler. It looks
> like
> >> a
> >> > commit is happening from the logs, but the documents don't become
> >> available
> >> > for search until I do a commit manually. Could this be some type of
> >> > configuration issue?
> >>
>
