[OAK-8067] Measure fsync (called when closing the NRT index) and try to reduce disk I/O

• Type: Improvement
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.10.1
• Component/s: lucene
• Assignee: Thomas Mueller
• Reporter: Thomas Mueller
• Created: 21/Feb/19 09:34
• Updated: 28/Feb/19 05:27
• Resolved: 22/Feb/19 08:52

Description

We have seen the following stack trace, and saw that fsync was seemingly very slow on the system.

Two issues: (1) fsync seems to be very slow here (2) fsync is called while holding a lock.

(2) should be resolved by lazy-loading indexes.

"oak-lucene-22" daemon prio=1 tid=0x6b1 nid=0xffffffff runnable
   java.lang.Thread.State: RUNNABLE
	atjava.io.FileDescriptor.sync(Native Method)
	at org.apache.lucene.store.FSDirectory.fsync(FSDirectory.java:505)
	at org.apache.lucene.store.FSDirectory.sync(FSDirectory.java:307)
	at org.apache.lucene.store.NRTCachingDirectory.sync(NRTCachingDirectory.java:219)
	at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:4489)
	at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:2953)
	- locked <0x20595abf> (a java.lang.Object)
	at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3049)
	- locked <0x20595abf> (a java.lang.Object)
	at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1041)
	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:932)
	- locked <0x20595abf> (a java.lang.Object)
	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:894)
	at org.apache.jackrabbit.oak.plugins.index.lucene.hybrid.NRTIndex.close(NRTIndex.java:206)
	at org.apache.jackrabbit.oak.plugins.index.lucene.hybrid.NRTIndexFactory.closeLast(NRTIndexFactory.java:133)
	at org.apache.jackrabbit.oak.plugins.index.lucene.hybrid.NRTIndexFactory.createIndex(NRTIndexFactory.java:89)
	- locked <0x85f9b65> (a org.apache.jackrabbit.oak.plugins.index.lucene.hybrid.NRTIndexFactory)
	at org.apache.jackrabbit.oak.plugins.index.lucene.LuceneIndexNodeManager.open(LuceneIndexNodeManager.java:73)
	at org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker$1.leave(IndexTracker.java:154)
	at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:152)
	at org.apache.jackrabbit.oak.composite.CompositeNodeState$WrappingDiff.childNodeChanged(CompositeNodeState.java:309)
	at org.apache.jackrabbit.oak.composite.CompositeNodeState$ChildrenDiffFilter.childNodeChanged(CompositeNodeState.java:256)
	at org.apache.jackrabbit.oak.plugins.document.JsopNodeStateDiffer.compareExisting(JsopNodeStateDiffer.java:100)
	at org.apache.jackrabbit.oak.plugins.document.JsopNodeStateDiffer.access$000(JsopNodeStateDiffer.java:27)
	at org.apache.jackrabbit.oak.plugins.document.JsopNodeStateDiffer$1.childNodeChanged(JsopNodeStateDiffer.java:65)
	at org.apache.jackrabbit.oak.plugins.document.DiffCache.parseJsopDiff(DiffCache.java:118)
	at org.apache.jackrabbit.oak.plugins.document.JsopNodeStateDiffer.compare(JsopNodeStateDiffer.java:51)
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.compare(DocumentNodeStore.java:1766)
	at org.apache.jackrabbit.oak.plugins.document.AbstractDocumentNodeState.compareAgainstBaseState(AbstractDocumentNodeState.java:113)
	at org.apache.jackrabbit.oak.composite.CompositeNodeState.compareAgainstBaseState(CompositeNodeState.java:163)
	at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:147)
	at org.apache.jackrabbit.oak.composite.CompositeNodeState$WrappingDiff.childNodeChanged(CompositeNodeState.java:309)
	at org.apache.jackrabbit.oak.composite.CompositeNodeState$ChildrenDiffFilter.childNodeChanged(CompositeNodeState.java:256)
	at org.apache.jackrabbit.oak.plugins.document.JsopNodeStateDiffer.compareExisting(JsopNodeStateDiffer.java:100)
	at org.apache.jackrabbit.oak.plugins.document.JsopNodeStateDiffer.access$000(JsopNodeStateDiffer.java:27)
	at org.apache.jackrabbit.oak.plugins.document.JsopNodeStateDiffer$1.childNodeChanged(JsopNodeStateDiffer.java:65)
	at org.apache.jackrabbit.oak.plugins.document.DiffCache.parseJsopDiff(DiffCache.java:118)
	at org.apache.jackrabbit.oak.plugins.document.JsopNodeStateDiffer.compare(JsopNodeStateDiffer.java:51)
	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.compare(DocumentNodeStore.java:1766)
	at org.apache.jackrabbit.oak.plugins.document.AbstractDocumentNodeState.compareAgainstBaseState(AbstractDocumentNodeState.java:113)
	at org.apache.jackrabbit.oak.composite.CompositeNodeState.compareAgainstBaseState(CompositeNodeState.java:163)
	at org.apache.jackrabbit.oak.spi.commit.EditorDiff.process(EditorDiff.java:51)
	at org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.diffAndUpdate(IndexTracker.java:165)
	- locked <0x67aaaebc> (a org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
	at org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.update(IndexTracker.java:120)
	- locked <0x67aaaebc> (a org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
	at org.apache.jackrabbit.oak.plugins.index.lucene.LuceneIndexProvider.contentChanged(LuceneIndexProvider.java:73)
	at org.apache.jackrabbit.oak.spi.commit.BackgroundObserver$1$1.call(BackgroundObserver.java:127)
	at org.apache.jackrabbit.oak.spi.commit.BackgroundObserver$1$1.call(BackgroundObserver.java:121)
	atjava.util.concurrent.FutureTask.run(FutureTask.java:264)
	atjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	atjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	atjava.lang.Thread.run(Thread.java:834)