Slow Query Report

Avatar

Avatar

danc74795494

Avatar

danc74795494

danc74795494

03-04-2019

We use Oracle database as DocumentNode store. During AEM start up, AEM was trying to recover some documents and it reported a very slow query.  This happened many times and it took 24+ hours to finish the recovery process. Does anyone have similar issue and any idea to resolve the issue?

Logs:

03.04.2019 03:01:26.563 *WARN* [FelixStartLevel] org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport Slow Query Report SQL=select ID, MODIFIED, MODCOUNT, CMODCOUNT, HASBINARY, DELETEDONCE, DATA, BDATA from NODES where ID > ? and MODIFIED >= ? order by ID FETCH FIRST 100 ROWS ONLY; time=11715307 ms;

03.04.2019 03:01:26.687 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStoreJDBC Long running query on NODES with 100 hits (limited to 100), elapsed time 11715431ms (configured QUERYTIMELIMIT 10000), params minid '10:/etc/workflow/instances/server2/2019-04-01_4/update_asset_8/history/1554154806566/workItem/metaData' maxid 'null' excludeKeyPatterns [] conditions [_modified >= 1554129510] limit 100. Read 12714 chars from DATA and 0 bytes from BDATA. Check calling method.

java.lang.Exception: call stack

at org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStoreJDBC.query(RDBDocumentStoreJDBC.java:603)

at org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStore.internalQuery(RDBDocumentStore.java:1485)

at org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStore.query(RDBDocumentStore.java:249)

at org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.nextBatch(Utils.java:648)

at org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.computeNext(Utils.java:633)

at org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.computeNext(Utils.java:622)

at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)

at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)

at com.google.common.collect.Iterators$7.computeNext(Iterators.java:645)

at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)

at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)

at org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:145)

at org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:120)

at org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recoverCandidates(LastRevRecoveryAgent.java:297)

at org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:104)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.checkLastRevRecovery(DocumentNodeStore.java:524)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.<init>(DocumentNodeStore.java:469)

at org.apache.jackrabbit.oak.plugins.document.DocumentMK$Builder.getNodeStore(DocumentMK.java:722)

at org.apache.jackrabbit.oak.plugins.document.DocumentMK.<init>(DocumentMK.java:141)

at org.apache.jackrabbit.oak.plugins.document.DocumentMK$Builder.open(DocumentMK.java:989)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.registerNodeStore(DocumentNodeStoreService.java:478)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.registerNodeStoreIfPossible(DocumentNodeStoreService.java:374)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.bindBlobStore(DocumentNodeStoreService.java:557)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)

at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)

at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)

at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)

at org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:41)

at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1660)

at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1636)

at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:370)

at org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:731)

at org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:700)

at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)

at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)

at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)

at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)

at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)

at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:120)

at org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:991)

at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:839)

at org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:546)

at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4557)

at org.apache.felix.framework.Felix.registerService(Felix.java:3549)

at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:348)

at org.apache.jackrabbit.oak.plugins.blob.datastore.AbstractDataStoreService.activate(AbstractDataStoreService.java:97)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)

at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)

at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)

at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)

at org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:295)

at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:302)

at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:113)

at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:866)

at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:833)

at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:724)

at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:399)

at org.apache.felix.scr.impl.config.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:676)

at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339)

at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:360)

at org.apache.felix.scr.impl.Activator.access$000(Activator.java:53)

at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:260)

at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)

at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)

at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)

at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)

at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)

at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)

at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)

at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)

at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)

at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)

at org.apache.felix.framework.Felix.startBundle(Felix.java:2172)

at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)

at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)

at java.lang.Thread.run(Thread.java:745)

03.04.2019 05:03:44.243 *WARN* [FelixStartLevel] org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport Slow Query Report SQL=select ID, MODIFIED, MODCOUNT, CMODCOUNT, HASBINARY, DELETEDONCE, DATA, BDATA from NODES where ID > ? and MODIFIED >= ? order by ID FETCH FIRST 100 ROWS ONLY; time=7337434 ms;

03.04.2019 05:03:44.258 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStoreJDBC Long running query on NODES with 100 hits (limited to 100), elapsed time 7337449ms (configured QUERYTIMELIMIT 10000), params minid '10:/oak:index/cqPayloadPath/:index/%2Fcontent%2Fdam%2Fusmepcom%2Ferecords%2Frecruit%2FH1606%2FH1606605%2FH1606605420%2FDD_4-3%2F1.0%2Fjcr%3Acontent%2Frenditions%2F/etc/workflow/instances/server2/2019-04-01_3/update_asset_748' maxid 'null' excludeKeyPatterns [] conditions [_modified >= 1554129510] limit 100. Read 9700 chars from DATA and 0 bytes from BDATA. Check calling method.

java.lang.Exception: call stack

at org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStoreJDBC.query(RDBDocumentStoreJDBC.java:603)

at org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStore.internalQuery(RDBDocumentStore.java:1485)

at org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStore.query(RDBDocumentStore.java:249)

at org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.nextBatch(Utils.java:648)

at org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.computeNext(Utils.java:633)

at org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.computeNext(Utils.java:622)

at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)

at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)

at com.google.common.collect.Iterators$7.computeNext(Iterators.java:645)

at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)

at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)

at org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:145)

at org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:120)

at org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recoverCandidates(LastRevRecoveryAgent.java:297)

at org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:104)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.checkLastRevRecovery(DocumentNodeStore.java:524)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.<init>(DocumentNodeStore.java:469)

at org.apache.jackrabbit.oak.plugins.document.DocumentMK$Builder.getNodeStore(DocumentMK.java:722)

at org.apache.jackrabbit.oak.plugins.document.DocumentMK.<init>(DocumentMK.java:141)

at org.apache.jackrabbit.oak.plugins.document.DocumentMK$Builder.open(DocumentMK.java:989)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.registerNodeStore(DocumentNodeStoreService.java:478)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.registerNodeStoreIfPossible(DocumentNodeStoreService.java:374)

at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.bindBlobStore(DocumentNodeStoreService.java:557)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)

at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)

at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)

at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)

at org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:41)

at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1660)

at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1636)

at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:370)

at org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:731)

at org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:700)

at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)

at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)

at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)

at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)

at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)

at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:120)

at org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:991)

at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:839)

at org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:546)

at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4557)

at org.apache.felix.framework.Felix.registerService(Felix.java:3549)

at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:348)

at org.apache.jackrabbit.oak.plugins.blob.datastore.AbstractDataStoreService.activate(AbstractDataStoreService.java:97)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)

at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)

at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)

at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)

at org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:295)

at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:302)

at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:113)

at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:866)

at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:833)

at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:724)

at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:399)

at org.apache.felix.scr.impl.config.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:676)

at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339)

at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:360)

at org.apache.felix.scr.impl.Activator.access$000(Activator.java:53)

at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:260)

at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)

at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)

at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)

at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)

at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)

at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)

at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)

at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)

at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)

at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)

at org.apache.felix.framework.Felix.startBundle(Felix.java:2172)

at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)

at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)

at java.lang.Thread.run(Thread.java:745)

Accepted Solutions (0)

Answers (0)