[ https://issues.apache.org/jira/browse/OAK-4861?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15592080#comment-15592080 ]
Wim Symons commented on OAK-4861: --------------------------------- Hi we have exactly the same issue as you have. Except it uses almost all of our CPU. Stacktrace: "pool-7-thread-4" - Thread t@114 java.lang.Thread.State: RUNNABLE at org.apache.jackrabbit.oak.plugins.index.lucene.OakDirectory$OakIndexFile.<init>(OakDirectory.java:255) at org.apache.jackrabbit.oak.plugins.index.lucene.OakDirectory$OakIndexFile.<init>(OakDirectory.java:205) at org.apache.jackrabbit.oak.plugins.index.lucene.OakDirectory$OakIndexInput.<init>(OakDirectory.java:404) at org.apache.jackrabbit.oak.plugins.index.lucene.OakDirectory$OakIndexInput.clone(OakDirectory.java:412) at org.apache.jackrabbit.oak.plugins.index.lucene.OakDirectory$OakIndexInput.clone(OakDirectory.java:388) at org.apache.lucene.codecs.BlockTreeTermsReader$FieldReader.<init>(BlockTreeTermsReader.java:481) at org.apache.lucene.codecs.BlockTreeTermsReader.<init>(BlockTreeTermsReader.java:176) at org.apache.lucene.codecs.lucene41.Lucene41PostingsFormat.fieldsProducer(Lucene41PostingsFormat.java:437) at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:116) at org.apache.lucene.index.SegmentReader.<init>(SegmentReader.java:96) at org.apache.lucene.index.ReadersAndUpdates.getReader(ReadersAndUpdates.java:141) at org.apache.lucene.index.BufferedUpdatesStream.applyDeletesAndUpdates(BufferedUpdatesStream.java:279) - locked <7e04344b> (a org.apache.lucene.index.BufferedUpdatesStream) at org.apache.lucene.index.IndexWriter.applyAllDeletesAndUpdates(IndexWriter.java:3191) - locked <50c64b3b> (a org.apache.lucene.index.IndexWriter) at org.apache.lucene.index.IndexWriter.maybeApplyDeletes(IndexWriter.java:3182) - locked <50c64b3b> (a org.apache.lucene.index.IndexWriter) at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:3155) - locked <50c64b3b> (a org.apache.lucene.index.IndexWriter) at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:3123) at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:988) at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:932) - locked <6c1af558> (a java.lang.Object) at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:894) at org.apache.jackrabbit.oak.plugins.index.lucene.LuceneIndexEditorContext.closeWriter(LuceneIndexEditorContext.java:250) at org.apache.jackrabbit.oak.plugins.index.lucene.LuceneIndexEditor.leave(LuceneIndexEditor.java:214) at org.apache.jackrabbit.oak.plugins.index.IndexUpdate.leave(IndexUpdate.java:252) at org.apache.jackrabbit.oak.spi.commit.VisibleEditor.leave(VisibleEditor.java:63) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.process(EditorDiff.java:56) at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.updateIndex(AsyncIndexUpdate.java:491) at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.runWhenPermitted(AsyncIndexUpdate.java:433) at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.run(AsyncIndexUpdate.java:325) - locked <5472cf2> (a org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate) at org.apache.sling.commons.scheduler.impl.QuartzJobExecutor.execute(QuartzJobExecutor.java:115) at org.quartz.core.JobRunShell.run(JobRunShell.java:202) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Locked ownable synchronizers: - locked <788eb307> (a java.util.concurrent.ThreadPoolExecutor$Worker) We have it on oak-lucene version 1.2.16 on AEM 6.1 SP1. What I also did is to attach a Java debugger to the AEM process and set a logging breakpoint at OakDirectory.java:255. If I enable the breakpoint, CPU drops to 2-3%. If I disable the breakpoint CPU rises again to 50%. So I think it is a concurrency issue. I also have a trace level output as mentioned above, but nothing to see there. To be complete, we are using a segment datastore (TarMK), CopyOnRead is enabled, CopyOnWrite is disabled and the number of threads is 5. Did you find a solution for this already? At the moment all our production instances have this issue. We opened a P1 ticket at Daycare, but so far no luck. > 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:0x0000000001E69C00, > j9thread_t:0x00007FFFBE101CB0, java/lang/Thread:0x00000001077FE938, 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:0x00000001) > 3XMTHREADINFO2 (native stack address range from:0x00007FFFC696A000, > to:0x00007FFFC69AB000, 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.<init>(OakDirectory.java:255(Compiled > Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexFile.<init>(OakDirectory.java:201(Compiled > Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/plugins/index/lucene/OakDirectory$OakIndexInput.<init>(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.<init>(BlockTreeTermsReader.java:481(Compiled > Code)) > 4XESTACKTRACE at > org/apache/lucene/codecs/BlockTreeTermsReader.<init>(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.<init>(SegmentCoreReaders.java:116(Compiled > Code)) > 4XESTACKTRACE at > org/apache/lucene/index/SegmentReader.<init>(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@0x00000002245B4100, entry > count: 1) > 4XESTACKTRACE at > org/apache/lucene/index/IndexWriter.applyAllDeletesAndUpdates(IndexWriter.java:3191(Compiled > Code)) > 5XESTACKTRACE (entered lock: > org/apache/lucene/index/IndexWriter@0x00000002245B4050, entry count: 3) > 4XESTACKTRACE at > org/apache/lucene/index/IndexWriter.maybeApplyDeletes(IndexWriter.java:3182(Compiled > Code)) > 5XESTACKTRACE (entered lock: > org/apache/lucene/index/IndexWriter@0x00000002245B4050, entry count: 2) > 4XESTACKTRACE at > org/apache/lucene/index/IndexWriter.doFlush(IndexWriter.java:3155(Compiled > Code)) > 5XESTACKTRACE (entered lock: > org/apache/lucene/index/IndexWriter@0x00000002245B4050, entry count: 1) > 4XESTACKTRACE at > org/apache/lucene/index/IndexWriter.flush(IndexWriter.java:3123(Compiled > Code)) > 4XESTACKTRACE at > org/apache/lucene/index/IndexWriter.closeInternal(IndexWriter.java:988(Compiled > Code)) > 4XESTACKTRACE at > org/apache/lucene/index/IndexWriter.close(IndexWriter.java:932(Compiled Code)) > 5XESTACKTRACE (entered lock: java/lang/Object@0x00000002245B9398, entry > count: 1) > 4XESTACKTRACE at > org/apache/lucene/index/IndexWriter.close(IndexWriter.java:894(Compiled Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexEditorContext.closeWriter(LuceneIndexEditorContext.java:235(Compiled > Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexEditor.leave(LuceneIndexEditor.java:207(Compiled > Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/plugins/index/IndexUpdate.leave(IndexUpdate.java:250(Compiled > Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/spi/commit/VisibleEditor.leave(VisibleEditor.java:63(Compiled > Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/spi/commit/EditorDiff.process(EditorDiff.java:56(Compiled > Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/plugins/index/AsyncIndexUpdate.updateIndex(AsyncIndexUpdate.java:372(Compiled > Code)) > 4XESTACKTRACE at > org/apache/jackrabbit/oak/plugins/index/AsyncIndexUpdate.run(AsyncIndexUpdate.java:322(Compiled > Code)) > 5XESTACKTRACE (entered lock: > org/apache/jackrabbit/oak/plugins/index/AsyncIndexUpdate@0x000000010447CCF0, > entry count: 1) > 4XESTACKTRACE at > org/apache/sling/commons/scheduler/impl/QuartzJobExecutor.execute(QuartzJobExecutor.java:115(Compiled > Code)) > 4XESTACKTRACE at > org/quartz/core/JobRunShell.run(JobRunShell.java:202(Compiled Code)) > 4XESTACKTRACE at > java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1157(Compiled > Code)) > 4XESTACKTRACE at > java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627) > 4XESTACKTRACE at java/lang/Thread.run(Thread.java:809) > {noformat} > I don't think, that we had such a behaviour a few months ago. -- This message was sent by Atlassian JIRA (v6.3.4#6332)