ScorerDocQueue.java's downHeap showing up as frequent hotspot in profiling - ideas why?

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|

ScorerDocQueue.java's downHeap showing up as frequent hotspot in profiling - ideas why?

Aaron Daubman
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