[jira] [Updated] (OAK-4861) AsyncIndexUpdate consuming constantly 1 CPU core
[
https://issues.apache.org/jira/browse/OAK-4861?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
angela updated OAK-4861:
Component/s: query
> AsyncIndexUpdate consuming constantly 1 CPU core
>
>
> Key: OAK-4861
> URL: https://issues.apache.org/jira/browse/OAK-4861
> Project: Jackrabbit Oak
> Issue Type: Improvement
> Components: query
>Affects Versions: 1.0.31
>Reporter: Jörg Hoh
>
> The AsyncIndexUpdate thread takes a long time on some of our environments to
> update the index for a few nodes:
> {noformat}
> 28.09.2016 18:23:49.405 *DEBUG* [pool-11-thread-1]
> org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate AsyncIndex (async)
> update run completed in 3,369 min. Indexed 14 nodes
> {noformat}
> I set the log to DEBUG for investigation and during the time I saw constantly
> such times; this instance is a test instance and there was no activity from
> the outside during this time. I also can confirm such times from other
> environments.
> The immediately visible problem is that this instance (and others as well)
> constantly consume at least 1 CPU core, no matter what activity happens on
> the system. This only happens on the master node of our DocumentNodeStore
> clusters.
> I did a number of threaddumps during investigation and a common stacktrace
> for the AsyncIndexUpdate was like this:
> {noformat}
> 3XMTHREADINFO "pool-11-thread-1" J9VMThread:0x01E69C00,
> j9thread_t:0x7FFFBE101CB0, java/lang/Thread:0x0001077FE938, state:R,
> prio=5
> 3XMJAVALTHREAD (java/lang/Thread getId:0x10A, isDaemon:false)
> 3XMTHREADINFO1 (native thread ID:0x3C781, native priority:0x5, native
> policy:UNKNOWN, vmstate:CW, vm thread flags:0x0001)
> 3XMTHREADINFO2 (native stack address range from:0x7FFFC696A000,
> to:0x7FFFC69AB000, size:0x41000)
> 3XMCPUTIME CPU usage total: 992425.397213554 secs, current
> category="Application"
> 3XMHEAPALLOC Heap bytes allocated since last GC cycle=735893672 (0x2BDCD8A8)
> 3XMTHREADINFO3 Java callstack:
> 4XESTACKTRACE at
> com/google/common/collect/Lists.newArrayList(Lists.java:128(Compiled Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexFile.(OakDirectory.java:255(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexFile.(OakDirectory.java:201(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.(OakDirectory.java:400(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.clone(OakDirectory.java:408(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.clone(OakDirectory.java:384(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/store/Directory$SlicedIndexInput.clone(Directory.java:288(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/store/Directory$SlicedIndexInput.clone(Directory.java:269(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/BlockTreeTermsReader$FieldReader.(BlockTreeTermsReader.java:481(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/BlockTreeTermsReader.(BlockTreeTermsReader.java:176(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/lucene41/Lucene41PostingsFormat.fieldsProducer(Lucene41PostingsFormat.java:437(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/SegmentCoreReaders.(SegmentCoreReaders.java:116(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/SegmentReader.(SegmentReader.java:96(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/ReadersAndUpdates.getReader(ReadersAndUpdates.java:141(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/BufferedUpdatesStream.applyDeletesAndUpdates(BufferedUpdatesStream.java:279(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/BufferedUpdatesStream@0x0002245B4100, entry
> count: 1)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.applyAllDeletesAndUpdates(IndexWriter.java:3191(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 3)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.maybeApplyDeletes(IndexWriter.java:3182(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 2)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.doFlush(IndexWriter.java:3155(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 1)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.flush(IndexWriter.java:3123(Compiled
> Code))
> 4XESTACKTRACE at
[jira] [Updated] (OAK-4861) AsyncIndexUpdate consuming constantly 1 CPU core
[
https://issues.apache.org/jira/browse/OAK-4861?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Elemer Kisch updated OAK-4861:
--
Attachment: (was: si09ent-cqa-243-async-index-update.log)
> AsyncIndexUpdate consuming constantly 1 CPU core
>
>
> Key: OAK-4861
> URL: https://issues.apache.org/jira/browse/OAK-4861
> Project: Jackrabbit Oak
> Issue Type: Improvement
>Affects Versions: 1.0.31
>Reporter: Jörg Hoh
>
> The AsyncIndexUpdate thread takes a long time on some of our environments to
> update the index for a few nodes:
> {noformat}
> 28.09.2016 18:23:49.405 *DEBUG* [pool-11-thread-1]
> org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate AsyncIndex (async)
> update run completed in 3,369 min. Indexed 14 nodes
> {noformat}
> I set the log to DEBUG for investigation and during the time I saw constantly
> such times; this instance is a test instance and there was no activity from
> the outside during this time. I also can confirm such times from other
> environments.
> The immediately visible problem is that this instance (and others as well)
> constantly consume at least 1 CPU core, no matter what activity happens on
> the system. This only happens on the master node of our DocumentNodeStore
> clusters.
> I did a number of threaddumps during investigation and a common stacktrace
> for the AsyncIndexUpdate was like this:
> {noformat}
> 3XMTHREADINFO "pool-11-thread-1" J9VMThread:0x01E69C00,
> j9thread_t:0x7FFFBE101CB0, java/lang/Thread:0x0001077FE938, state:R,
> prio=5
> 3XMJAVALTHREAD (java/lang/Thread getId:0x10A, isDaemon:false)
> 3XMTHREADINFO1 (native thread ID:0x3C781, native priority:0x5, native
> policy:UNKNOWN, vmstate:CW, vm thread flags:0x0001)
> 3XMTHREADINFO2 (native stack address range from:0x7FFFC696A000,
> to:0x7FFFC69AB000, size:0x41000)
> 3XMCPUTIME CPU usage total: 992425.397213554 secs, current
> category="Application"
> 3XMHEAPALLOC Heap bytes allocated since last GC cycle=735893672 (0x2BDCD8A8)
> 3XMTHREADINFO3 Java callstack:
> 4XESTACKTRACE at
> com/google/common/collect/Lists.newArrayList(Lists.java:128(Compiled Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexFile.(OakDirectory.java:255(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexFile.(OakDirectory.java:201(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.(OakDirectory.java:400(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.clone(OakDirectory.java:408(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.clone(OakDirectory.java:384(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/store/Directory$SlicedIndexInput.clone(Directory.java:288(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/store/Directory$SlicedIndexInput.clone(Directory.java:269(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/BlockTreeTermsReader$FieldReader.(BlockTreeTermsReader.java:481(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/BlockTreeTermsReader.(BlockTreeTermsReader.java:176(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/lucene41/Lucene41PostingsFormat.fieldsProducer(Lucene41PostingsFormat.java:437(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/SegmentCoreReaders.(SegmentCoreReaders.java:116(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/SegmentReader.(SegmentReader.java:96(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/ReadersAndUpdates.getReader(ReadersAndUpdates.java:141(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/BufferedUpdatesStream.applyDeletesAndUpdates(BufferedUpdatesStream.java:279(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/BufferedUpdatesStream@0x0002245B4100, entry
> count: 1)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.applyAllDeletesAndUpdates(IndexWriter.java:3191(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 3)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.maybeApplyDeletes(IndexWriter.java:3182(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 2)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.doFlush(IndexWriter.java:3155(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 1)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.flush(IndexWriter.java:3123(Compiled
>
[jira] [Updated] (OAK-4861) AsyncIndexUpdate consuming constantly 1 CPU core
[
https://issues.apache.org/jira/browse/OAK-4861?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Elemer Kisch updated OAK-4861:
--
Attachment: si09ent-cqa-243-async-index-update.log
> AsyncIndexUpdate consuming constantly 1 CPU core
>
>
> Key: OAK-4861
> URL: https://issues.apache.org/jira/browse/OAK-4861
> Project: Jackrabbit Oak
> Issue Type: Improvement
>Affects Versions: 1.0.31
>Reporter: Jörg Hoh
> Attachments: si09ent-cqa-243-async-index-update.log
>
>
> The AsyncIndexUpdate thread takes a long time on some of our environments to
> update the index for a few nodes:
> {noformat}
> 28.09.2016 18:23:49.405 *DEBUG* [pool-11-thread-1]
> org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate AsyncIndex (async)
> update run completed in 3,369 min. Indexed 14 nodes
> {noformat}
> I set the log to DEBUG for investigation and during the time I saw constantly
> such times; this instance is a test instance and there was no activity from
> the outside during this time. I also can confirm such times from other
> environments.
> The immediately visible problem is that this instance (and others as well)
> constantly consume at least 1 CPU core, no matter what activity happens on
> the system. This only happens on the master node of our DocumentNodeStore
> clusters.
> I did a number of threaddumps during investigation and a common stacktrace
> for the AsyncIndexUpdate was like this:
> {noformat}
> 3XMTHREADINFO "pool-11-thread-1" J9VMThread:0x01E69C00,
> j9thread_t:0x7FFFBE101CB0, java/lang/Thread:0x0001077FE938, state:R,
> prio=5
> 3XMJAVALTHREAD (java/lang/Thread getId:0x10A, isDaemon:false)
> 3XMTHREADINFO1 (native thread ID:0x3C781, native priority:0x5, native
> policy:UNKNOWN, vmstate:CW, vm thread flags:0x0001)
> 3XMTHREADINFO2 (native stack address range from:0x7FFFC696A000,
> to:0x7FFFC69AB000, size:0x41000)
> 3XMCPUTIME CPU usage total: 992425.397213554 secs, current
> category="Application"
> 3XMHEAPALLOC Heap bytes allocated since last GC cycle=735893672 (0x2BDCD8A8)
> 3XMTHREADINFO3 Java callstack:
> 4XESTACKTRACE at
> com/google/common/collect/Lists.newArrayList(Lists.java:128(Compiled Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexFile.(OakDirectory.java:255(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexFile.(OakDirectory.java:201(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.(OakDirectory.java:400(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.clone(OakDirectory.java:408(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.clone(OakDirectory.java:384(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/store/Directory$SlicedIndexInput.clone(Directory.java:288(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/store/Directory$SlicedIndexInput.clone(Directory.java:269(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/BlockTreeTermsReader$FieldReader.(BlockTreeTermsReader.java:481(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/BlockTreeTermsReader.(BlockTreeTermsReader.java:176(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/codecs/lucene41/Lucene41PostingsFormat.fieldsProducer(Lucene41PostingsFormat.java:437(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/SegmentCoreReaders.(SegmentCoreReaders.java:116(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/SegmentReader.(SegmentReader.java:96(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/ReadersAndUpdates.getReader(ReadersAndUpdates.java:141(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/lucene/index/BufferedUpdatesStream.applyDeletesAndUpdates(BufferedUpdatesStream.java:279(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/BufferedUpdatesStream@0x0002245B4100, entry
> count: 1)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.applyAllDeletesAndUpdates(IndexWriter.java:3191(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 3)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.maybeApplyDeletes(IndexWriter.java:3182(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 2)
> 4XESTACKTRACE at
> org/apache/lucene/index/IndexWriter.doFlush(IndexWriter.java:3155(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/lucene/index/IndexWriter@0x0002245B4050, entry count: 1)
> 4XESTACKTRACE at
>
