doubled/halved performance?

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

doubled/halved performance?

Mike Klaas
I'm seeing some interesting behaviour when doing benchmarks of query  
and facet performance.  Note that the query cache is disabled, and  
the index is entirely in the OS disk cache.  filterCache is fully  
primed.

Often when repeatedly measuring the same query, I'll see pretty  
consistent results (within a few ms), but occasionally a run which is  
almost exactly half the time:

240ms vs. 120ms:

solr: DEBUG    INFO: /select/  
facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
ax&version=2.2&rows=1 0 239
solr: DEBUG    INFO: /select/  
facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
ax&version=2.2&rows=1 0 237
solr: DEBUG    INFO: /select/  
facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
ax&version=2.2&rows=1 0 120
solr: DEBUG    INFO: /select/  
facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
ax&version=2.2&rows=1 0 120
solr: DEBUG    INFO: /select/  
facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
ax&version=2.2&rows=1 0 237
solr: DEBUG    INFO: /select/  
facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
ax&version=2.2&rows=1 0 238

The strange thing is that the execution time is halved across _all_  
parts of query processing:

101.0   total time
   1.0   setup/query parsing
   68.0   main query
   30.0   faceting
   0.0   pre fetch
   2.0   debug

201.0   total time
   1.0   setup/query parsing
   138.0   main query
   58.0   faceting
   0.0   pre fetch
   4.0   debug

I can't really think of a plausible explanation.  Fortuitous  
instruction pipelining?  It is hard to imagine a cause that wouldn't  
exhibit consistency.

-Mike
Reply | Threaded
Open this post in threaded view
|

Re: doubled/halved performance?

Yonik Seeley-2
On 10/11/07, Mike Klaas <[hidden email]> wrote:

> I'm seeing some interesting behaviour when doing benchmarks of query
> and facet performance.  Note that the query cache is disabled, and
> the index is entirely in the OS disk cache.  filterCache is fully
> primed.
>
> Often when repeatedly measuring the same query, I'll see pretty
> consistent results (within a few ms), but occasionally a run which is
> almost exactly half the time:
>
> 240ms vs. 120ms:
>
> solr: DEBUG    INFO: /select/
> facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
> ax&version=2.2&rows=1 0 239
> solr: DEBUG    INFO: /select/
> facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
> ax&version=2.2&rows=1 0 237
> solr: DEBUG    INFO: /select/
> facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
> ax&version=2.2&rows=1 0 120
> solr: DEBUG    INFO: /select/
> facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
> ax&version=2.2&rows=1 0 120
> solr: DEBUG    INFO: /select/
> facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
> ax&version=2.2&rows=1 0 237
> solr: DEBUG    INFO: /select/
> facet=true&debugQuery=true&indent=on&start=0&q=www&facet.field=t&qt=dism
> ax&version=2.2&rows=1 0 238
>
> The strange thing is that the execution time is halved across _all_
> parts of query processing:
>
> 101.0   total time
>    1.0          setup/query parsing
>    68.0         main query
>    30.0         faceting
>    0.0          pre fetch
>    2.0          debug
>
> 201.0   total time
>    1.0          setup/query parsing
>    138.0        main query
>    58.0         faceting
>    0.0          pre fetch
>    4.0          debug
>
> I can't really think of a plausible explanation.  Fortuitous
> instruction pipelining?  It is hard to imagine a cause that wouldn't
> exhibit consistency.

So the queries are one at a time, the index isn't changing, and
nothing else happening in the system?
It would be easier to explain an occasional long query than an
occasional short one.
It's weird how the granularity seems to be on the basis of a request
(if the speedup sometimes happened half way through, then you'd get an
average of the times).

You could try -Xbatch to see if it's hotspot somehow, but I doubt that's it.

-Yonik
Reply | Threaded
Open this post in threaded view
|

Re: doubled/halved performance?

Mike Klaas
On 11-Oct-07, at 2:37 PM, Yonik Seeley wrote:

> On 10/11/07, Mike Klaas <[hidden email]> wrote:
>> I'm seeing some interesting behaviour when doing benchmarks of query
>> and facet performance.  Note that the query cache is disabled, and
>> the index is entirely in the OS disk cache.  filterCache is fully
>> primed.
>>
>> Often when repeatedly measuring the same query, I'll see pretty
>> consistent results (within a few ms), but occasionally a run which is
>> almost exactly half the time:
>>
>> I can't really think of a plausible explanation.  Fortuitous
>> instruction pipelining?  It is hard to imagine a cause that wouldn't
>> exhibit consistency.
>
> So the queries are one at a time, the index isn't changing, and
> nothing else happening in the system?

The index is completely static, and I'm just sending the same query  
sequentially.  I provoke a slowdown by sending a few requests in  
parallel.  There is the odd bit of db activity on the system, but it  
is rare and covered by the other processor regardless.

> It would be easier to explain an occasional long query than an
> occasional short one.
> It's weird how the granularity seems to be on the basis of a request
> (if the speedup sometimes happened half way through, then you'd get an
> average of the times).

Indeed, this is what surprised me the most.

> You could try -Xbatch to see if it's hotspot somehow, but I doubt  
> that's it.

with -Xbatch everything runs more slowly, but the 2x effect is still  
present.

Anyway, it is strange but not really a problem.  This is on a dev box  
only; I might run a similar test on a production box sometime.

Thanks,
-Mike