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

2019-02-21 Thread Thomas Mueller (JIRA)


[ 
https://issues.apache.org/jira/browse/OAK-8067?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16774863#comment-16774863
 ] 

Thomas Mueller commented on OAK-8067:
-

http://svn.apache.org/r1854115 (trunk)

FYI [~catholicon]

> Measure fsync (called when closing the NRT index) and try to reduce disk I/O
> 
>
> Key: OAK-8067
> URL: https://issues.apache.org/jira/browse/OAK-8067
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
>
> 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.
> {noformat}
> "oak-lucene-22" daemon prio=1 tid=0x6b1 nid=0x 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

[jira] [Commented] (OAK-8067) Measure fsync (called when closing the NRT index)

2019-02-21 Thread Thomas Mueller (JIRA)


[ 
https://issues.apache.org/jira/browse/OAK-8067?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16774850#comment-16774850
 ] 

Thomas Mueller commented on OAK-8067:
-

As we have "FileUtils.deleteQuietly(indexDir)" right after closing, I think it 
should be fine to also call "deleteAll()" before closing. deleteQuietly will 
just try to delete, and errors to delete are silently ignored. So possibly it's 
not always deleted. So, I'm not sure about concurrent usage of the index, what 
happens in case of power failure, or when the index isn't removed.

I will add "deleteAll" by default, but use a different setting that allows to 
disable just that.

> Measure fsync (called when closing the NRT index)
> -
>
> Key: OAK-8067
> URL: https://issues.apache.org/jira/browse/OAK-8067
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
>
> 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.
> {noformat}
> "oak-lucene-22" daemon prio=1 tid=0x6b1 nid=0x 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.plugin

[jira] [Commented] (OAK-8067) Measure fsync (called when closing the NRT index)

2019-02-21 Thread Thomas Mueller (JIRA)


[ 
https://issues.apache.org/jira/browse/OAK-8067?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16774143#comment-16774143
 ] 

Thomas Mueller commented on OAK-8067:
-

I removed the "deleteAll" call.

Still, I kept close(false), meaning merge won't be done sometimes. I wonder if 
that's a problem or not?

> Measure fsync (called when closing the NRT index)
> -
>
> Key: OAK-8067
> URL: https://issues.apache.org/jira/browse/OAK-8067
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
>
> 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.
> {noformat}
> "oak-lucene-22" daemon prio=1 tid=0x6b1 nid=0x 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.do

[jira] [Commented] (OAK-8067) Measure fsync (called when closing the NRT index)

2019-02-21 Thread Thomas Mueller (JIRA)


[ 
https://issues.apache.org/jira/browse/OAK-8067?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16774145#comment-16774145
 ] 

Thomas Mueller commented on OAK-8067:
-

http://svn.apache.org/r1854057

> Measure fsync (called when closing the NRT index)
> -
>
> Key: OAK-8067
> URL: https://issues.apache.org/jira/browse/OAK-8067
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
>
> 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.
> {noformat}
> "oak-lucene-22" daemon prio=1 tid=0x6b1 nid=0x 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.plu