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

performance regression in search REST API

    XMLWordPrintable

    Details

    • Notability:
      2

      Description

      A customer was sending search queries into 3.16 on a regular basis which sorted by versions:

      GET /service/rest/v1/search?sort=version&repository=snapshots

      In a sample set of provided 3.16 logs from the customer, is ~14k calls to /service/rest/v1/search, the slowest was ~7.8s and the quickest was ~2.9s

      The customer upgraded to 3.20.1, and using a sample request.log they provided we confirmed there were 988 search calls in a request.log, with the quickest at ~45s and the slowest at ~53s.

      Example thread stacks one can find in a thread dump taken during a slow search that are symptomatic to this problem.

      "qtp1758350105-19802773" #19802773 prio=5 os_prio=0 tid=0x00007ff00c063000 nid=0x109b1 waiting on condition [0x00007fef29fef000]
         java.lang.Thread.State: WAITING (parking)
      	at sun.misc.Unsafe.park(Native Method)
      	- parking to wait for  <0x0000000766f342a8> (a org.elasticsearch.common.util.concurrent.BaseFuture$Sync)
      	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
      	at org.elasticsearch.common.util.concurrent.BaseFuture$Sync.get(BaseFuture.java:280)
      	at org.elasticsearch.common.util.concurrent.BaseFuture.get(BaseFuture.java:120)
      	at org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:42)
      	at org.sonatype.nexus.repository.search.SearchServiceImpl.executeSearch(SearchServiceImpl.java:633)
      	at org.sonatype.nexus.repository.search.SearchServiceImpl.search(SearchServiceImpl.java:582)
      	at org.sonatype.nexus.repository.rest.internal.resources.SearchResource.search(SearchResource.java:137)
      	at sun.reflect.GeneratedMethodAccessor202.invoke(Unknown Source)
      	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:109)
      	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 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.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 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 com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at com.sonatype.nexus.licensing.internal.LicensingRedirectFilter.doFilter(LicensingRedirectFilter.java:114)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:112)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at org.sonatype.nexus.internal.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:79)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at org.sonatype.nexus.internal.web.EnvironmentFilter.doFilter(EnvironmentFilter.java:101)
      	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:1602)
      	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
      	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
      	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
      	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
      	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
      	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
      	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
      	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
      	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
      	at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:239)
      	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
      	at org.eclipse.jetty.server.Server.handle(Server.java:505)
      	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370)
      	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267)
      	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
      	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
      	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
      	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:698)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:804)
      	at java.lang.Thread.run(Thread.java:748)
      
      "elasticsearch[65E59C3A-D85B5975-C824480A-DE10E3BF-2D66BE08][search][T#7]" #901 daemon prio=5 os_prio=0 tid=0x00007ff0240a1000 nid=0x439 sleeping[0x00007fef2a1f3000]
         java.lang.Thread.State: TIMED_WAITING (sleeping)
      	at java.lang.Thread.sleep(Native Method)
      	at java.lang.Thread.sleep(Thread.java:340)
      	at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
      	at org.sonatype.nexus.repository.selector.internal.ContentAuthPluginScript.run(ContentAuthPluginScript.java:99)
      	at org.elasticsearch.index.query.ScriptQueryParser$ScriptQuery$1$1.get(ScriptQueryParser.java:171)
      	at org.apache.lucene.search.RandomAccessWeight$1.matches(RandomAccessWeight.java:63)
      	at org.elasticsearch.common.lucene.Lucene$3.get(Lucene.java:765)
      	at org.elasticsearch.common.lucene.search.FilteredCollector$1.collect(FilteredCollector.java:54)
      	at org.apache.lucene.search.TimeLimitingCollector$1.collect(TimeLimitingCollector.java:158)
      	at org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:221)
      	at org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:172)
      	at org.apache.lucene.search.BulkScorer.score(BulkScorer.java:39)
      	at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:821)
      	at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:535)
      	at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:384)
      	at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:113)
      	at org.elasticsearch.search.SearchService.loadOrExecuteQueryPhase(SearchService.java:372)
      	at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:385)
      	at org.elasticsearch.search.action.SearchServiceTransportAction$SearchQueryTransportHandler.messageReceived(SearchServiceTransportAction.java:368)
      	at org.elasticsearch.search.action.SearchServiceTransportAction$SearchQueryTransportHandler.messageReceived(SearchServiceTransportAction.java:365)
      	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:33)
      	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:77)
      	at org.elasticsearch.transport.TransportService$4.doRun(TransportService.java:378)
      	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      	at java.lang.Thread.run(Thread.java:748)
      

      Diagnosis

      Changes were made to the search code in 3.18.0 to address other reported performance issues in earlier versions. These changes have been identified to cause a performance regression specifically in the sort by versions case - possibly other cases.

      Expected

      Restore similar performance characteristics of the search queries as in previous versions.

      Workaround

      Support customers can contact Sonatype for a patch that has been shown to address the issue, until such time a fix has been shipped.

        Attachments

        1. fail.png
          320 kB
          Michael Martz

          Activity

            People

            Assignee:
            dbradicich Damian Bradicich
            Reporter:
            plynch Peter Lynch
            Last Updated By:
            Wes Wannemacher Wes Wannemacher
            Team:
            NXRM - Neo
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:
              Date of First Response:

                tigCommentSecurity.panel-title