Uploaded image for project: 'Dev - Nexus Repo'
  1. Dev - Nexus Repo
  2. NEXUS-22760

POST /service/extdirect/poll/rapture_State_get lists all tasks from the database

    XMLWordPrintable

    Details

    • Notability:
      3

      Description

      POST /service/extdirect/poll/rapture_State_get resource is a UI polling endpoint that merely checks of the server is still alive when an end user is using the UI.

      The polling status interval is configured in UI: Settings under Anonymous user status interval and Authenticated user status interval.

      Problem

      For each poll request, regardless of what the user is looking at, all the tasks are listed from the database. This is needless activity in the least, but also can be a performance issue is there are a lot of tasks. Logs proving this activity:

      2020-02-13 11:30:41,417-0400 DEBUG [qtp725126432-53] *SYSTEM org.eclipse.jetty.server.Server - REQUEST POST /service/extdirect/poll/rapture_State_get on HttpChannelOverHttp@1b8149b1{r=1,c=false,c=false/false,a=DISPATCHED,uri=//localhost:8081/service/extdirect/poll/rapture_State_get,age=0}
      
      2020-02-13 11:30:41,439-0400 TRACE [qtp725126432-53] admin org.sonatype.nexus.common.stateguard.GuardedInterceptor - Invoking: GuardImpl{allowed=[STARTED]} -> public java.util.List org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI.listsTasks()
      2020-02-13 11:30:41,439-0400 TRACE [qtp725126432-53] admin org.sonatype.nexus.transaction.Operations - Invoking: @org.sonatype.nexus.transaction.Transactional(reason=transaction, commitOn=[], retryOn=[class com.orientechnologies.common.concur.ONeedRetryException, class com.orientechnologies.orient.core.exception.ORecordNotFoundException], swallow=[]) -> org.sonatype.nexus.orient.transaction.OrientOperations$$Lambda$302/1143264172@2e043b53
      2020-02-13 11:30:41,440-0400 TRACE [qtp725126432-53] admin org.sonatype.nexus.transaction.TransactionalWrapper - BEGIN org.sonatype.nexus.orient.transaction.OrientTransaction@28d8b82a : public java.lang.Object org.sonatype.nexus.orient.transaction.OrientOperations$$Lambda$302/1143264172.call()
      2020-02-13 11:30:41,440-0400 TRACE [qtp725126432-53] admin org.sonatype.nexus.quartz.internal.orient.InstanceCreator - New instance: class org.quartz.impl.JobDetailImpl
      2020-02-13 11:30:41,440-0400 TRACE [qtp725126432-53] admin org.sonatype.nexus.quartz.internal.orient.InstanceCreator - New instance: class org.quartz.impl.JobDetailImpl
      2020-02-13 11:30:41,440-0400 TRACE [qtp725126432-53] admin org.sonatype.nexus.quartz.internal.orient.InstanceCreator - New instance: class org.quartz.impl.JobDetailImpl
      ...
      2020-02-13 11:30:41,515-0400 TRACE [qtp725126432-53] admin org.sonatype.nexus.transaction.TransactionalWrapper - COMMIT org.sonatype.nexus.orient.transaction.OrientTransaction@28d8b82a : public java.lang.Object org.sonatype.nexus.orient.transaction.OrientOperations$$Lambda$302/1143264172.call()
      2020-02-13 11:30:41,534-0400 DEBUG [qtp725126432-53] admin com.softwarementors.extjs.djn.Timer -   - Java method dispatch time (StateComponent.rapture_State_get): 99.12 ms.
      2020-02-13 11:30:41,534-0400 DEBUG [qtp725126432-53] admin com.softwarementors.extjs.djn.router.processor.poll.PollRequestProcessor - ResponseData data (POLL)=>{"data":{"success":true,"data":{}},"name":"rapture_State_get","type":"event"}
      2020-02-13 11:30:41,535-0400 DEBUG [qtp725126432-53] *SYSTEM org.eclipse.jetty.server.Server - handled=true async=false committed=false on HttpChannelOverHttp@1b8149b1{r=1,c=false,c=false/false,a=DISPATCHED,uri=//localhost:8081/service/extdirect/poll/rapture_State_get,age=118}
      

      In one case, it was noticed these polling requests lead to over 350+ BLOCKED threads trying to list all these tasks:

      a RUNNABLE blocking thread inside a transaction
      qtp1832889421-587912" #587912 prio=5 os_prio=0 tid=0x00007f4fd400a800 nid=0x6d48 runnable [0x00007f495d99c000]
         java.lang.Thread.State: RUNNABLE
       at java.util.LinkedHashMap.newNode(LinkedHashMap.java:256)
       at java.util.HashMap.putVal(HashMap.java:630)
       at java.util.HashMap.put(HashMap.java:611)
       at com.orientechnologies.orient.core.db.record.OTrackedMap.put(OTrackedMap.java:68)
       at com.orientechnologies.orient.core.serialization.serializer.record.binary.ORecordSerializerBinaryV0.readEmbeddedMap(ORecordSerializerBinaryV0.java:580)
       at com.orientechnologies.orient.core.serialization.serializer.record.binary.ORecordSerializerBinaryV0.deserializeValue(ORecordSerializerBinaryV0.java:472)
       at com.orientechnologies.orient.core.serialization.serializer.record.binary.ORecordSerializerBinaryV0.readEmbeddedMap(ORecordSerializerBinaryV0.java:576)
       at com.orientechnologies.orient.core.serialization.serializer.record.binary.ORecordSerializerBinaryV0.deserializeValue(ORecordSerializerBinaryV0.java:472)
       at com.orientechnologies.orient.core.serialization.serializer.record.binary.ORecordSerializerBinaryV0.deserialize(ORecordSerializerBinaryV0.java:277)
       at com.orientechnologies.orient.core.serialization.serializer.record.binary.ORecordSerializerBinary.fromStream(ORecordSerializerBinary.java:80)
       at com.orientechnologies.orient.core.record.impl.ODocument.deserializeFields(ODocument.java:1854)
       at org.sonatype.nexus.orient.entity.EntityAdapter.readEntity(EntityAdapter.java:283)
       at org.sonatype.nexus.orient.entity.IterableEntityAdapter.transformEntity(IterableEntityAdapter.java:63)
       at org.sonatype.nexus.orient.entity.IterableEntityAdapter$$Lambda$346/358415132.apply(Unknown Source)
       at com.google.common.collect.Iterators$6.transform(Iterators.java:788)
       at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:47)
       at com.google.common.collect.Iterators$5.computeNext(Iterators.java:638)
       at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:141)
       at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:136)
       at com.google.common.collect.Iterators$5.computeNext(Iterators.java:637)
       at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:141)
       at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:136)
       at org.sonatype.nexus.quartz.internal.orient.JobStoreImpl.getJobKeys(JobStoreImpl.java:436)
       at org.sonatype.nexus.quartz.internal.orient.JobStoreImpl.lambda$9(JobStoreImpl.java:426)
       at org.sonatype.nexus.quartz.internal.orient.JobStoreImpl$$Lambda$398/3814570.execute(Unknown Source)
       at org.sonatype.nexus.quartz.internal.orient.JobStoreImpl$$Lambda$399/1489743818.apply(Unknown Source)
       at org.sonatype.nexus.orient.transaction.OrientOperations.lambda$1(OrientOperations.java:55)
       at org.sonatype.nexus.orient.transaction.OrientOperations$$Lambda$324/1081119355.call(Unknown Source)
       at org.sonatype.nexus.transaction.OperationPoint.proceed(OperationPoint.java:64)
       at org.sonatype.nexus.transaction.TransactionalWrapper.proceedWithTransaction(TransactionalWrapper.java:57)
       at org.sonatype.nexus.transaction.Operations.proceedWithTransaction(Operations.java:232)
       at org.sonatype.nexus.transaction.Operations.transactional(Operations.java:223)
       at org.sonatype.nexus.transaction.Operations.call(Operations.java:166)
       at org.sonatype.nexus.orient.transaction.OrientOperations.call(OrientOperations.java:55)
       at org.sonatype.nexus.quartz.internal.orient.JobStoreImpl.execute(JobStoreImpl.java:204)
       - locked <0x00000006c77359e0> (a java.lang.Object)
       at org.sonatype.nexus.quartz.internal.orient.JobStoreImpl.getJobKeys(JobStoreImpl.java:426)
       at org.quartz.core.QuartzScheduler.getJobKeys(QuartzScheduler.java:1433)
       at org.quartz.impl.StdScheduler.getJobKeys(StdScheduler.java:470)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI.allTasks(QuartzSchedulerSPI.java:710)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI.listsTasks(QuartzSchedulerSPI.java:534)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI$$EnhancerByGuice$$3d6904c0.CGLIB$listsTasks$14(<generated>)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI$$EnhancerByGuice$$3d6904c0$$FastClassByGuice$$a098333.invoke(<generated>)
       at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
       at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:76)
       at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
       at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:272)
       at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:53)
       at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:77)
       at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI$$EnhancerByGuice$$3d6904c0.listsTasks(<generated>)
       at org.sonatype.nexus.scheduling.TaskSchedulerImpl.listsTasks(TaskSchedulerImpl.java:133)
       at org.sonatype.nexus.coreui.internal.BrowseStateContributor.getRepositoryNamesForRunningTasks(BrowseStateContributor.java:65)
       at org.sonatype.nexus.coreui.internal.BrowseStateContributor.getState(BrowseStateContributor.java:57)
       at org.sonatype.nexus.rapture.internal.state.StateComponent.getState(StateComponent.java:87)
       at org.sonatype.nexus.rapture.internal.state.StateComponent$$EnhancerByGuice$$c680be9.CGLIB$getState$0(<generated>)
      
      Example BLOCKED thread
      "qtp1832889421-569479" #569479 prio=5 os_prio=0 tid=0x00007f4860003000 nid=0xf7e6 waiting for monitor entry [0x00007f47ae8b1000]
         java.lang.Thread.State: BLOCKED (on object monitor)
       at org.sonatype.nexus.quartz.internal.orient.JobStoreImpl.execute(JobStoreImpl.java:200)
       - waiting to lock <0x00000006c77359e0> (a java.lang.Object)
       at org.sonatype.nexus.quartz.internal.orient.JobStoreImpl.getJobKeys(JobStoreImpl.java:426)
       at org.quartz.core.QuartzScheduler.getJobKeys(QuartzScheduler.java:1433)
       at org.quartz.impl.StdScheduler.getJobKeys(StdScheduler.java:470)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI.allTasks(QuartzSchedulerSPI.java:710)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI.listsTasks(QuartzSchedulerSPI.java:534)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI$$EnhancerByGuice$$3d6904c0.CGLIB$listsTasks$14(<generated>)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI$$EnhancerByGuice$$3d6904c0$$FastClassByGuice$$a098333.invoke(<generated>)
       at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
       at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:76)
       at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
       at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:272)
       at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:53)
       at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:77)
       at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55)
       at org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI$$EnhancerByGuice$$3d6904c0.listsTasks(<generated>)
       at org.sonatype.nexus.scheduling.TaskSchedulerImpl.listsTasks(TaskSchedulerImpl.java:133)
       at org.sonatype.nexus.coreui.internal.BrowseStateContributor.getRepositoryNamesForRunningTasks(BrowseStateContributor.java:65)
       at org.sonatype.nexus.coreui.internal.BrowseStateContributor.getState(BrowseStateContributor.java:57)
       at org.sonatype.nexus.rapture.internal.state.StateComponent.getState(StateComponent.java:87)
       at org.sonatype.nexus.rapture.internal.state.StateComponent$$EnhancerByGuice$$c680be9.CGLIB$getState$0(<generated>)
       at org.sonatype.nexus.rapture.internal.state.StateComponent$$EnhancerByGuice$$c680be9$$FastClassByGuice$$f5589e80.invoke(<generated>)
      
      ...
      
       at org.sonatype.nexus.extdirect.internal.ExtDirectDispatcher.invokeMethod(ExtDirectDispatcher.java:82)
       at com.softwarementors.extjs.djn.router.dispatcher.DispatcherBase.dispatch(DispatcherBase.java:63)
       at com.softwarementors.extjs.djn.router.processor.poll.PollRequestProcessor.process(PollRequestProcessor.java:145)
       at org.sonatype.nexus.extdirect.internal.ExtDirectServlet$3.processPollRequest(ExtDirectServlet.java:262)
       at com.softwarementors.extjs.djn.servlet.DirectJNgineServlet.processRequest(DirectJNgineServlet.java:636)
       at com.softwarementors.extjs.djn.servlet.DirectJNgineServlet.doPost(DirectJNgineServlet.java:595)
       at org.sonatype.nexus.extdirect.internal.ExtDirectServlet.doPost(ExtDirectServlet.java:137)
      
      

      Expected

      Avoid needless database transactions in polling requests, especially if they require locks.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              mjohnson Matt Johnson
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Wes Wannemacher
              Team:
              NXRM - Neo
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title