Details
Major 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.
