0
votes

I am using JackRabbit oak implementation in my Spring Boot project. My application creates multiple nodes in jcr repository with integration of PostgreSQL db. There are already huge amount of node data available in jcr repository.

But, whenever I start/restart my application I gets below logs frequently.

{"@timestamp":"2020-05-13T13:33:06.721+05:30","@version":1,"message":"Slow Query Report SQL=select ID, MODIFIED, MODCOUNT, CMODCOUNT, HASBINARY, DELETEDONCE, VERSION, SDTYPE, SDMAXREVTIME, DATA, BDATA from DB_NODES where ID > ? and MODIFIED >= ? order by ID FETCH FIRST 100 ROWS ONLY; time=10963 ms;","logger_name":"org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport","thread_name":"main","level":"WARN","level_value":30000}
{"@timestamp":"2020-05-13T13:33:06.998+05:30","@version":1,"message":"Long running query on mango_NODES with 100 hits (limited to 100), elapsed time 11238ms (configured QUERYTIMELIMIT 10000), params minid '5:/oak:index/nodetype/:index/spr%3Atask/id1' maxid 'null' excludeKeyPatterns [] conditions [_modified >= 1584429305] limit 100. Result range: '5:/oak:index/nodetype/:index/spr%3Atask/id1'...'5:/oak:index/spr_task_jcr_created/:index/2019-05-03T04%3A31%3A29.882Z/id3'. Read 20094 chars from DATA and 0 bytes from BDATA. Check calling method.","logger_name":"org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStoreJDBC","thread_name":"main","level":"INFO","level_value":20000,"stack_trace":"java.lang.Exception: call stack\r\n\tat org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStoreJDBC.query(RDBDocumentStoreJDBC.java:522)\r\n\tat org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStore.internalQuery(RDBDocumentStore.java:1769)\r\n\tat org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStore.query(RDBDocumentStore.java:297)\r\n\tat org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.nextBatch(Utils.java:684)\r\n\tat org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.computeNext(Utils.java:668)\r\n\tat org.apache.jackrabbit.oak.plugins.document.util.Utils$2$1.computeNext(Utils.java:658)\r\n\tat com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)\r\n\tat com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)\r\n\tat com.google.common.collect.Iterators$7.computeNext(Iterators.java:650)\r\n\tat com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)\r\n\tat com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)\r\n\tat com.google.common.collect.TransformedIterator.hasNext(TransformedIterator.java:43)\r\n\tat com.google.common.collect.Iterators$7.computeNext(Iterators.java:650)\r\n\tat com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)\r\n\tat com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)\r\n\tat com.google.common.collect.Iterators$6.hasNext(Iterators.java:617)\r\n\tat org.apache.jackrabbit.oak.plugins.document.NodeDocumentSweeper.performSweep(NodeDocumentSweeper.java:152)\r\n\tat org.apache.jackrabbit.oak.plugins.document.NodeDocumentSweeper.sweep(NodeDocumentSweeper.java:122)\r\n\tat org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:244)\r\n\tat org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:195)\r\n\tat org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recoverCandidates(LastRevRecoveryAgent.java:533)\r\n\tat org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent.recover(LastRevRecoveryAgent.java:161)\r\n\tat org.apache.jackrabbit.oak.plugins.document.RecoveryHandlerImpl.recoverInternal(RecoveryHandlerImpl.java:74)\r\n\tat org.apache.jackrabbit.oak.plugins.document.RecoveryHandlerImpl.recover(RecoveryHandlerImpl.java:57)\r\n\tat org.apache.jackrabbit.oak.plugins.document.ClusterNodeInfo.createInstance(ClusterNodeInfo.java:565)\r\n\tat org.apache.jackrabbit.oak.plugins.document.ClusterNodeInfo.getInstance(ClusterNodeInfo.java:438)\r\n\tat org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.<init>(DocumentNodeStore.java:554)\r\n\tat org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBuilder.build(DocumentNodeStoreBuilder.java:174)\r\n\tat com.cms.common.helper.RepositoryUtil.createRepo(RepositoryUtil.java:119)\r\n\tat com.cms.common.helper.RepositoryUtil.createRepo(RepositoryUtil.java:138)\r\n\tat com.cms.common.helper.RepositoryUtil.getRepository(RepositoryUtil.java:217)\r\n\tat com.cms.common.helper.RepositoryUtil.getSession(RepositoryUtil.java:231)\r\n\tat com.cms.services.RepositoryInitialization.createCustomNode(RepositoryInitialization.java:39)\r\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\r\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\r\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\r\n\tat java.lang.reflect.Method.invoke(Method.java:498)\r\n\tat org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:366)\r\n\tat org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeInitMethods(InitDestroyAnnotationBeanPostProcessor.java:311)\r\n\tat org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeInitialization(InitDestroyAnnotationBeanPostProcessor.java:134)\r\n\tat org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:407)\r\n\tat org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1622)\r\n\tat org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:553)\r\n\tat org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:481)\r\n\tat org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:312)\r\n\tat org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)\r\n\tat org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:308)\r\n\tat org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)\r\n\tat org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:756)\r\n\tat org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:867)\r\n\tat org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:542)\r\n\tat org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:123)\r\n\tat org.springframework.boot.SpringApplication.refresh(SpringApplication.java:666)\r\n\tat org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:353)\r\n\tat org.springframework.boot.SpringApplication.run(SpringApplication.java:300)\r\n\tat org.springframework.boot.SpringApplication.run(SpringApplication.java:1082)\r\n\tat org.springframework.boot.SpringApplication.run(SpringApplication.java:1071)\r\n\tat com.cms.services.CMSServicesApplication.main(CMSServicesApplication.java:36)\r\n"}
{"@timestamp":"2020-05-13T13:33:26.999+05:30","@version":1,"message":"Sweep on cluster node [4]: 24501 nodes scanned in 7.799 min (~3141/m) - last interval 4500 nodes in 60.27 s (~4479/m)","logger_name":"org.apache.jackrabbit.oak.plugins.document.NodeDocumentSweeper","thread_name":"main","level":"INFO","level_value":20000}
{"@timestamp":"2020-05-13T14:24:58.069+05:30","@version":1,"message":"Recovery for cluster node [4]: 4701 nodes scanned in 60.38 s (~4671/m) - last interval 4701 nodes in 60.38 s (~4671/m)","logger_name":"org.apache.jackrabbit.oak.plugins.document.LastRevRecoveryAgent","thread_name":"main","level":"INFO","level_value":20000}

It seems that all the nodes are getting scanned from repository, and so application taking very long time to get start. Is there any way to start application quite quickly or do I need to do any implementation changes in my jcr implementation?

1

1 Answers

0
votes

This will happen if you shut down the repository without properly closing it.

Upon startup, the system will scan for incomplete commits. That can take a long time depending on the number of nodes, and whether your version has the change for https://issues.apache.org/jira/browse/OAK-8002.