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

REST asset resource times out on large repositories

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 3.5.0, 3.28.0
    • Fix Version/s: None
    • Component/s: Database, REST
    • Story Points:
      5
    • Notability:
      3

      Description

      Using a big db with 3 million assets, the below request to the asset REST resource on such a big repository times out:

      >curl -i -u admin:admin123 http://localhost:8081/service/siesta/rest/beta/assets?repositoryId=mavenMemTest
      HTTP/1.1 500 Server Error
      Date: Mon, 14 Aug 2017 12:46:33 GMT
      Server: Nexus/3.5.1-SNAPSHOT (PRO)
      X-Frame-Options: SAMEORIGIN
      X-Content-Type-Options: nosniff
      Content-Type: text/plain;charset=utf-8
      X-Siesta-FaultId: 9b195a83-8146-4af5-8aa3-6b1bf12b1345
      Content-Length: 149
      
      ERROR: (ID 9b195a83-8146-4af5-8aa3-6b1bf12b1345) java.lang.IllegalStateException: Timed out reading query result from queue 30e10ad5 after 60 seconds
      

      nexus.log:

      2017-08-14 14:47:36,043+0200 WARN  [qtp1669823652-75] admin org.sonatype.nexus.siesta.internal.UnexpectedExceptionMapper - (ID 9b195a83-8146-4af5-8aa3-6b1bf12b1345) Unexpected exception: java.lang.IllegalStateException: Timed out reading query result from queue 30e10ad5 after 60 seconds
      java.lang.IllegalStateException: Timed out reading query result from queue 30e10ad5 after 60 seconds
              at org.sonatype.nexus.repository.storage.OrientAsyncHelper$QueueConsumingIterable.hasNext(OrientAsyncHelper.java:201)
              at com.google.common.collect.TransformedIterator.hasNext(TransformedIterator.java:42)
              at com.google.common.collect.Iterators.addAll(Iterators.java:366)
              at com.google.common.collect.Lists.newArrayList(Lists.java:165)
              at com.google.common.collect.Lists.newArrayList(Lists.java:150)
              at org.sonatype.nexus.repository.browse.internal.BrowseServiceImpl.getAssets(BrowseServiceImpl.java:329)
              at org.sonatype.nexus.repository.browse.internal.BrowseServiceImpl.browseAssets(BrowseServiceImpl.java:188)
              at org.sonatype.nexus.repository.browse.internal.resources.AssetsResource.getAssets(AssetsResource.java:101)
              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.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140)
              at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:294)
              at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:248)
              at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:235)
              at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:402)
              at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:209)
              at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:227)
              at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
              at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
              at org.sonatype.nexus.siesta.internal.resteasy.ComponentContainerImpl.service(ComponentContainerImpl.java:106)
              at org.sonatype.nexus.siesta.SiestaServlet.service(SiestaServlet.java:137)
              at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
              at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:286)
              at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:276)
              at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:181)
              at com.google.inject.servlet.DynamicServletPipeline.service(DynamicServletPipeline.java:71)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:85)
              at com.sonatype.nexus.analytics.internal.RestRequestCollector.doFilter(RestRequestCollector.java:80)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
              at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:112)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
              at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61)
              at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
              at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
              at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
              at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)
              at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
              at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
              at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
              at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)
              at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)
              at org.sonatype.nexus.security.SecurityFilter.executeChain(SecurityFilter.java:85)
              at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
              at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
              at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
              at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383)
              at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
              at org.sonatype.nexus.security.SecurityFilter.doFilterInternal(SecurityFilter.java:101)
              at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
              at com.sonatype.nexus.licensing.internal.LicensingRedirectFilter.doFilter(LicensingRedirectFilter.java:108)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
              at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:97)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
              at org.sonatype.nexus.internal.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:68)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
              at org.sonatype.nexus.internal.web.EnvironmentFilter.doFilter(EnvironmentFilter.java:102)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
              at org.sonatype.nexus.internal.web.HeaderPatternFilter.doFilter(HeaderPatternFilter.java:98)
              at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
              at com.google.inject.servlet.DynamicFilterPipeline.dispatch(DynamicFilterPipeline.java:104)
              at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:135)
              at org.sonatype.nexus.bootstrap.osgi.DelegatingFilter.doFilter(DelegatingFilter.java:73)
              at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
              at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
              at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
              at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
              at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
              at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1158)
              at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
              at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
              at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1090)
              at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
              at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
              at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:175)
              at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
              at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
              at org.eclipse.jetty.server.Server.handle(Server.java:517)
              at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308)
              at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242)
              at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
              at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
              at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75)
              at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213)
              at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147)
              at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
              at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
              at java.lang.Thread.run(Thread.java:745)
      2017-08-14 14:47:36,144+0200 WARN  [qtp1669823652-75] admin org.sonatype.nexus.siesta.internal.UnexpectedExceptionMapper - (ID 9b195a83-8146-4af5-8aa3-6b1bf12b1345) Response: [500] 'ERROR: (ID 9b195a83-8146-4af5-8aa3-6b1bf12b1345) java.lang.IllegalStateException: Timed out reading query result from queue 30e10ad5 after 60 seconds'; mapped from: java.lang.IllegalStateException: Timed out reading query result from queue 30e10ad5 after 60 seconds
      

      An explain select * from asset where bucket=#40:0 order by @rid asc limit 10; shows that OrientDB ends up reading all 3 millions assets of the bucket to satisfy the query for the first 10 assets:

      {
          "result": [
              {
                  "@type": "d",
                  "@version": 0,
                  "documentReads": 3000003,
                  "fullySortedByIndex": false,
                  "documentAnalyzedCompatibleClass": 3000003,
                  "recordReads": 3000003,
                  "fetchingFromTargetElapsed": 64004,
                  "indexIsUsedInOrderBy": false,
                  "compositeIndexUsed": 1,
                  "current": "#55:374250",
                  "involvedIndexes": [
                      "asset_bucket_name_idx"
                  ],
                  "limit": 10,
                  "orderByElapsed": 83,
                  "evaluated": 3000003,
                  "elapsed": 64230.816,
                  "resultType": "collection",
                  "resultSize": 10,
                  "@fieldTypes": "documentReads=l,documentAnalyzedCompatibleClass=l,recordReads=l,fetchingFromTargetElapsed=l,compositeIndexUsed=l,current=x,involvedIndexes=e,orderByElapsed=l,evaluated=l,elapsed=f"
              }
          ],
          "notification": "Query executed in 64.243 sec. Returned 1 record(s)"
      }
      

      The expensive bit is the ORDER BY @rid part of the query which apparently was needed to resolve NEXUS-12539.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              Unassigned Unassigned
              Reporter:
              bentmann Benjamin Bentmann
              Last Updated By:
              Joe Tom Joe Tom
              Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated:
                Date of First Response:

                  tigCommentSecurity.panel-title