Greetings, In a recent batch of solr 3.6.1 slow response time queries the profiler highlighted downHeap (line 212) in SoorerDocQueue.java as averaging more than 60ms across the 16 calls I was looking at and showing it spiking up over 100ms - which, after looking at the code (two int comparisons?!?) I am at a loss to explain:
Here's the source: https://github.com/apache/lucene-solr/blob/6b8783bfa59351878c59e47deaa7739d95150a22/lucene/core/src/java/org/apache/lucene/util/ScorerDocQueue.java#L212 Here's the invocation trace of one of the many similar: ---snip--- Thread.run:722 (0ms self time, 416 ms total time) QueuedThreadPool$3.run:526 (0ms self time, 416 ms total time) QueuedThreadPool.runJob:595 (0ms self time, 416 ms total time) ExecutorCallback$ExecutorCallbackInvoker.run:130 (0ms self time, 416 ms total time) ExecutorCallback$ExecutorCallbackInvoker.call:124 (0ms self time, 416 ms total time) AbstractConnection$1.onCompleted:63 (0ms self time, 416 ms total time) AbstractConnection$1.onCompleted:71 (0ms self time, 416 ms total time) HttpConnection.onFillable:253 (0ms self time, 416 ms total time) HttpChannel.run:246 (0ms self time, 416 ms total time) Server.handle:403 (0ms self time, 416 ms total time) HandlerWrapper.handle:97 (0ms self time, 416 ms total time) IPAccessHandler.handle:204 (0ms self time, 416 ms total time) HandlerCollection.handle:110 (0ms self time, 416 ms total time) ContextHandlerCollection.handle:258 (0ms self time, 416 ms total time) ScopedHandler.handle:136 (0ms self time, 416 ms total time) ContextHandler.doScope:973 (0ms self time, 416 ms total time) SessionHandler.doScope:174 (0ms self time, 416 ms total time) ServletHandler.doScope:358 (0ms self time, 416 ms total time) ContextHandler.doHandle:1044 (0ms self time, 416 ms total time) SessionHandler.doHandle:213 (0ms self time, 416 ms total time) SecurityHandler.handle:540 (0ms self time, 416 ms total time) ScopedHandler.handle:138 (0ms self time, 416 ms total time) ServletHandler.doHandle:429 (0ms self time, 416 ms total time) ServletHandler$CachedChain.doFilter:1274 (0ms self time, 416 ms total time) SolrDispatchFilter.doFilter:260 (0ms self time, 416 ms total time) SolrDispatchFilter.execute:365 (0ms self time, 416 ms total time) SolrCore.execute:1376 (0ms self time, 416 ms total time) RequestHandlerBase.handleRequest:129 (0ms self time, 416 ms total time) SearchHandler.handleRequestBody:186 (0ms self time, 416 ms total time) QueryComponent.process:394 (0ms self time, 416 ms total time) SolrIndexSearcher.search:375 (0ms self time, 416 ms total time) SolrIndexSearcher.getDocListC:1176 (0ms self time, 416 ms total time) SolrIndexSearcher.getDocListNC:1296 (0ms self time, 416 ms total time) IndexSearcher.search:364 (0ms self time, 416 ms total time) IndexSearcher.search:581 (0ms self time, 416 ms total time) FilteredQuery$2.score:169 (0ms self time, 416 ms total time) BooleanScorer2.advance:320 (0ms self time, 416 ms total time) ReqExclScorer.advance:112 (0ms self time, 416 ms total time) DisjunctionSumScorer.advance:229 (52ms self time, 416 ms total time) DisjunctionSumScorer.advanceAfterCurrent:171 (0ms self time, 308 ms total time) ScorerDocQueue.topNextAndAdjustElsePop:120 (0ms self time, 308 ms total time) ScorerDocQueue.checkAdjustElsePop:135 (0ms self time, 111 ms total time) ScorerDocQueue.downHeap:212 (111ms self time, 111 ms total time) ---snip--- Any ideas on what is causing this seemingly inordinate amount of time in downHeap? Is this symptomatic of anything in particular? Thanks, as always! Aaron
