Re: Slower queries with 7.3.1?
Thanks Deepak. I think I understand the cause of the slowdown. There are some flamegraphs (from stack sampling) on SOLR-12407. I also captured some traces using yourkit. On Sun, May 27, 2018 at 1:21 PM, Deepak Goel wrote: > Is it possible to profile the code to find the exact points which are > taking more time comparatively? > > On Sun, 27 May 2018, 06:02 Will Currie, wrote: > > > I raised https://issues.apache.org/jira/browse/SOLR-12407. In case > anybody > > else sees a similar slowdown with boosts. > > > > On Sat, May 26, 2018 at 4:10 PM, Will Currie wrote: > > > > > I did some more (micro)benchmarking with a single query. Setting the > > query > > > cache size to zero I see 400ms response time on 7.2 and 600ms on 7.3. > > > Running curl in a loop on my laptop. ~4M docs. ~3G index. 1M total hits > > > for the query.. Yup. I'm reluctant to post the query. It has multiple > > 300+ > > > character streams of if,product,map calls in multiple boost parameters. > > > > > > I realise my query is likely ridiculous (inefficient, better done > another > > > way, etc) but LUCENE-8099 mentions: > > > "Re performance: there shouldn't be any reason for things to be slower > > ... > > > It might be useful to add some examples of these queries to the > benchmark > > > tests though." > > > > > > Maybe I have such a benchmark.. Grasping at straws guess, I noticed 7.2 > > > sticks with floats. 7.3 does a few frames of math with doubles before > > > returning to floats. > > > > > > jstack from 7.2: > > > > > > "qtp2136344592-24" #24 prio=5 os_prio=31 tid=0x7f80630e5000 > > nid=0x7103 > > > runnable [0x749bb000] > > >java.lang.Thread.State: RUNNABLE > > > at org.apache.lucene.queries.function.valuesource. > > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > > at org.apache.lucene.queries.function.valuesource. > > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > > at org.apache.lucene.queries.function.valuesource. > IfFunction$1.floatVal( > > > IfFunction.java:64) > > > at org.apache.lucene.queries.function.valuesource. > > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > > at org.apache.lucene.queries.function.valuesource. > > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > > at org.apache.lucene.queries.function.valuesource. > IfFunction$1.floatVal( > > > IfFunction.java:64) > > > at org.apache.lucene.queries.function.valuesource. > IfFunction$1.floatVal( > > > IfFunction.java:64) > > > at org.apache.lucene.queries.function.valuesource. > > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > > at org.apache.lucene.queries.function.valuesource. > > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > > * at > > > > > org.apache.lucene.queries.function.BoostedQuery$CustomScorer.score( > BoostedQuery.java:124)* > > > at org.apache.lucene.search.TopScoreDocCollector$ > > > SimpleTopScoreDocCollector$1.collect(TopScoreDocCollector.java:64) > > > at org.apache.lucene.search.Weight$DefaultBulkScorer. > > > scoreAll(Weight.java:233) > > > at org.apache.lucene.search.Weight$DefaultBulkScorer. > > > score(Weight.java:184) > > > at org.apache.lucene.search.BulkScorer.score(BulkScorer.java:39) > > > at org.apache.lucene.search.IndexSearcher.search( > IndexSearcher.java:660) > > > at org.apache.lucene.search.IndexSearcher.search( > IndexSearcher.java:462) > > > at org.apache.solr.search.SolrIndexSearcher.buildAndRunCollectorChain( > > > SolrIndexSearcher.java:215) > > > > > > jstack from 7.3.1: > > > > > > "qtp559670971-25" #25 prio=5 os_prio=31 tid=0x7fe23fa0c000 > nid=0x7303 > > > runnable [0x7b024000] > > >java.lang.Thread.State: RUNNABLE > > > at org.apache.lucene.queries.function.valuesource. > IfFunction$1.floatVal( > > > IfFunction.java:64) > > > at org.apache.lucene.queries.function.valuesource. > > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > > at org.apache.lucene.queries.function.valuesource. > > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > > at org.apache.lucene.queries.function.valuesource. > IfFunction$1.floatVal( > > > IfFunction.java:64) > > > at org.apache.lucene.queries.function.valuesource. > > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > > at org.apache.lucene.queries.function.valuesource. > > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > > at org.apache.lucene.queries.function.valuesource. > IfFunction$1.floatVal( > > > IfFunction.java:64) > > > at org.apache.lucene.queries.function.valuesource. > IfFunction$1.floatVal( > > > IfFunction.java:64) > > > at org.apache.lucene.queries.function.valuesource. > > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > > at org.apache.lucene.queries.function.valuesource. > > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > > * at > > > > > org.apache.lucene.queries.function.docvalues.FloatDocValues.doubleVal( > FloatDocValues.java:67)* > > > * at > > > > > org.apache.lu
Re: Slower queries with 7.3.1?
Is it possible to profile the code to find the exact points which are taking more time comparatively? On Sun, 27 May 2018, 06:02 Will Currie, wrote: > I raised https://issues.apache.org/jira/browse/SOLR-12407. In case anybody > else sees a similar slowdown with boosts. > > On Sat, May 26, 2018 at 4:10 PM, Will Currie wrote: > > > I did some more (micro)benchmarking with a single query. Setting the > query > > cache size to zero I see 400ms response time on 7.2 and 600ms on 7.3. > > Running curl in a loop on my laptop. ~4M docs. ~3G index. 1M total hits > > for the query.. Yup. I'm reluctant to post the query. It has multiple > 300+ > > character streams of if,product,map calls in multiple boost parameters. > > > > I realise my query is likely ridiculous (inefficient, better done another > > way, etc) but LUCENE-8099 mentions: > > "Re performance: there shouldn't be any reason for things to be slower > ... > > It might be useful to add some examples of these queries to the benchmark > > tests though." > > > > Maybe I have such a benchmark.. Grasping at straws guess, I noticed 7.2 > > sticks with floats. 7.3 does a few frames of math with doubles before > > returning to floats. > > > > jstack from 7.2: > > > > "qtp2136344592-24" #24 prio=5 os_prio=31 tid=0x7f80630e5000 > nid=0x7103 > > runnable [0x749bb000] > >java.lang.Thread.State: RUNNABLE > > at org.apache.lucene.queries.function.valuesource. > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > at org.apache.lucene.queries.function.valuesource. > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > > IfFunction.java:64) > > at org.apache.lucene.queries.function.valuesource. > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > at org.apache.lucene.queries.function.valuesource. > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > > IfFunction.java:64) > > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > > IfFunction.java:64) > > at org.apache.lucene.queries.function.valuesource. > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > at org.apache.lucene.queries.function.valuesource. > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > * at > > > org.apache.lucene.queries.function.BoostedQuery$CustomScorer.score(BoostedQuery.java:124)* > > at org.apache.lucene.search.TopScoreDocCollector$ > > SimpleTopScoreDocCollector$1.collect(TopScoreDocCollector.java:64) > > at org.apache.lucene.search.Weight$DefaultBulkScorer. > > scoreAll(Weight.java:233) > > at org.apache.lucene.search.Weight$DefaultBulkScorer. > > score(Weight.java:184) > > at org.apache.lucene.search.BulkScorer.score(BulkScorer.java:39) > > at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:660) > > at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:462) > > at org.apache.solr.search.SolrIndexSearcher.buildAndRunCollectorChain( > > SolrIndexSearcher.java:215) > > > > jstack from 7.3.1: > > > > "qtp559670971-25" #25 prio=5 os_prio=31 tid=0x7fe23fa0c000 nid=0x7303 > > runnable [0x7b024000] > >java.lang.Thread.State: RUNNABLE > > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > > IfFunction.java:64) > > at org.apache.lucene.queries.function.valuesource. > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > at org.apache.lucene.queries.function.valuesource. > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > > IfFunction.java:64) > > at org.apache.lucene.queries.function.valuesource. > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > at org.apache.lucene.queries.function.valuesource. > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > > IfFunction.java:64) > > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > > IfFunction.java:64) > > at org.apache.lucene.queries.function.valuesource. > > ProductFloatFunction.func(ProductFloatFunction.java:41) > > at org.apache.lucene.queries.function.valuesource. > > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > > * at > > > org.apache.lucene.queries.function.docvalues.FloatDocValues.doubleVal(FloatDocValues.java:67)* > > * at > > > org.apache.lucene.queries.function.ValueSource$WrappedDoubleValuesSource$1.doubleValue(ValueSource.java:217)* > > * at > > > org.apache.lucene.search.DoubleValues$1.doubleValue(DoubleValues.java:48)* > > * at > > > org.apache.lucene.queries.function.FunctionScoreQuery$MultiplicativeBoostValuesSource$1.doubleValue(FunctionScoreQuery.java:199)* > > * at > > > org.apache.lucene.queries.function.FunctionScoreQuery$FunctionScoreWeight$1.score(FunctionScoreQuery.java:171)* > >
Re: Slower queries with 7.3.1?
I raised https://issues.apache.org/jira/browse/SOLR-12407. In case anybody else sees a similar slowdown with boosts. On Sat, May 26, 2018 at 4:10 PM, Will Currie wrote: > I did some more (micro)benchmarking with a single query. Setting the query > cache size to zero I see 400ms response time on 7.2 and 600ms on 7.3. > Running curl in a loop on my laptop. ~4M docs. ~3G index. 1M total hits > for the query.. Yup. I'm reluctant to post the query. It has multiple 300+ > character streams of if,product,map calls in multiple boost parameters. > > I realise my query is likely ridiculous (inefficient, better done another > way, etc) but LUCENE-8099 mentions: > "Re performance: there shouldn't be any reason for things to be slower ... > It might be useful to add some examples of these queries to the benchmark > tests though." > > Maybe I have such a benchmark.. Grasping at straws guess, I noticed 7.2 > sticks with floats. 7.3 does a few frames of math with doubles before > returning to floats. > > jstack from 7.2: > > "qtp2136344592-24" #24 prio=5 os_prio=31 tid=0x7f80630e5000 nid=0x7103 > runnable [0x749bb000] >java.lang.Thread.State: RUNNABLE > at org.apache.lucene.queries.function.valuesource. > ProductFloatFunction.func(ProductFloatFunction.java:41) > at org.apache.lucene.queries.function.valuesource. > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > IfFunction.java:64) > at org.apache.lucene.queries.function.valuesource. > ProductFloatFunction.func(ProductFloatFunction.java:41) > at org.apache.lucene.queries.function.valuesource. > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > IfFunction.java:64) > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > IfFunction.java:64) > at org.apache.lucene.queries.function.valuesource. > ProductFloatFunction.func(ProductFloatFunction.java:41) > at org.apache.lucene.queries.function.valuesource. > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > * at > org.apache.lucene.queries.function.BoostedQuery$CustomScorer.score(BoostedQuery.java:124)* > at org.apache.lucene.search.TopScoreDocCollector$ > SimpleTopScoreDocCollector$1.collect(TopScoreDocCollector.java:64) > at org.apache.lucene.search.Weight$DefaultBulkScorer. > scoreAll(Weight.java:233) > at org.apache.lucene.search.Weight$DefaultBulkScorer. > score(Weight.java:184) > at org.apache.lucene.search.BulkScorer.score(BulkScorer.java:39) > at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:660) > at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:462) > at org.apache.solr.search.SolrIndexSearcher.buildAndRunCollectorChain( > SolrIndexSearcher.java:215) > > jstack from 7.3.1: > > "qtp559670971-25" #25 prio=5 os_prio=31 tid=0x7fe23fa0c000 nid=0x7303 > runnable [0x7b024000] >java.lang.Thread.State: RUNNABLE > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > IfFunction.java:64) > at org.apache.lucene.queries.function.valuesource. > ProductFloatFunction.func(ProductFloatFunction.java:41) > at org.apache.lucene.queries.function.valuesource. > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > IfFunction.java:64) > at org.apache.lucene.queries.function.valuesource. > ProductFloatFunction.func(ProductFloatFunction.java:41) > at org.apache.lucene.queries.function.valuesource. > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > IfFunction.java:64) > at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal( > IfFunction.java:64) > at org.apache.lucene.queries.function.valuesource. > ProductFloatFunction.func(ProductFloatFunction.java:41) > at org.apache.lucene.queries.function.valuesource. > MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) > * at > org.apache.lucene.queries.function.docvalues.FloatDocValues.doubleVal(FloatDocValues.java:67)* > * at > org.apache.lucene.queries.function.ValueSource$WrappedDoubleValuesSource$1.doubleValue(ValueSource.java:217)* > * at > org.apache.lucene.search.DoubleValues$1.doubleValue(DoubleValues.java:48)* > * at > org.apache.lucene.queries.function.FunctionScoreQuery$MultiplicativeBoostValuesSource$1.doubleValue(FunctionScoreQuery.java:199)* > * at > org.apache.lucene.queries.function.FunctionScoreQuery$FunctionScoreWeight$1.score(FunctionScoreQuery.java:171)* > at org.apache.lucene.search.TopScoreDocCollector$ > SimpleTopScoreDocCollector$1.collect(TopScoreDocCollector.java:64) > at org.apache.lucene.search.Weight$DefaultBulkScorer. > scoreAll(Weight.java:233) > at org.apache.lucene.search.Weight$DefaultBulkScorer. > score(Weight.java:184) > at org.apache.lucene.search.BulkScorer.score(BulkScorer.java:39) > at o
Re: Slower queries with 7.3.1?
I did some more (micro)benchmarking with a single query. Setting the query cache size to zero I see 400ms response time on 7.2 and 600ms on 7.3. Running curl in a loop on my laptop. ~4M docs. ~3G index. 1M total hits for the query.. Yup. I'm reluctant to post the query. It has multiple 300+ character streams of if,product,map calls in multiple boost parameters. I realise my query is likely ridiculous (inefficient, better done another way, etc) but LUCENE-8099 mentions: "Re performance: there shouldn't be any reason for things to be slower ... It might be useful to add some examples of these queries to the benchmark tests though." Maybe I have such a benchmark.. Grasping at straws guess, I noticed 7.2 sticks with floats. 7.3 does a few frames of math with doubles before returning to floats. jstack from 7.2: "qtp2136344592-24" #24 prio=5 os_prio=31 tid=0x7f80630e5000 nid=0x7103 runnable [0x749bb000] java.lang.Thread.State: RUNNABLE at org.apache.lucene.queries.function.valuesource.ProductFloatFunction.func(ProductFloatFunction.java:41) at org.apache.lucene.queries.function.valuesource.MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal(IfFunction.java:64) at org.apache.lucene.queries.function.valuesource.ProductFloatFunction.func(ProductFloatFunction.java:41) at org.apache.lucene.queries.function.valuesource.MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal(IfFunction.java:64) at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal(IfFunction.java:64) at org.apache.lucene.queries.function.valuesource.ProductFloatFunction.func(ProductFloatFunction.java:41) at org.apache.lucene.queries.function.valuesource.MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) * at org.apache.lucene.queries.function.BoostedQuery$CustomScorer.score(BoostedQuery.java:124)* at org.apache.lucene.search.TopScoreDocCollector$SimpleTopScoreDocCollector$1.collect(TopScoreDocCollector.java:64) at org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:233) at org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:184) at org.apache.lucene.search.BulkScorer.score(BulkScorer.java:39) at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:660) at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:462) at org.apache.solr.search.SolrIndexSearcher.buildAndRunCollectorChain(SolrIndexSearcher.java:215) jstack from 7.3.1: "qtp559670971-25" #25 prio=5 os_prio=31 tid=0x7fe23fa0c000 nid=0x7303 runnable [0x7b024000] java.lang.Thread.State: RUNNABLE at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal(IfFunction.java:64) at org.apache.lucene.queries.function.valuesource.ProductFloatFunction.func(ProductFloatFunction.java:41) at org.apache.lucene.queries.function.valuesource.MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal(IfFunction.java:64) at org.apache.lucene.queries.function.valuesource.ProductFloatFunction.func(ProductFloatFunction.java:41) at org.apache.lucene.queries.function.valuesource.MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal(IfFunction.java:64) at org.apache.lucene.queries.function.valuesource.IfFunction$1.floatVal(IfFunction.java:64) at org.apache.lucene.queries.function.valuesource.ProductFloatFunction.func(ProductFloatFunction.java:41) at org.apache.lucene.queries.function.valuesource.MultiFloatFunction$1.floatVal(MultiFloatFunction.java:82) * at org.apache.lucene.queries.function.docvalues.FloatDocValues.doubleVal(FloatDocValues.java:67)* * at org.apache.lucene.queries.function.ValueSource$WrappedDoubleValuesSource$1.doubleValue(ValueSource.java:217)* * at org.apache.lucene.search.DoubleValues$1.doubleValue(DoubleValues.java:48)* * at org.apache.lucene.queries.function.FunctionScoreQuery$MultiplicativeBoostValuesSource$1.doubleValue(FunctionScoreQuery.java:199)* * at org.apache.lucene.queries.function.FunctionScoreQuery$FunctionScoreWeight$1.score(FunctionScoreQuery.java:171)* at org.apache.lucene.search.TopScoreDocCollector$SimpleTopScoreDocCollector$1.collect(TopScoreDocCollector.java:64) at org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:233) at org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:184) at org.apache.lucene.search.BulkScorer.score(BulkScorer.java:39) at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:660) at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:462) at org.apache.solr.search.SolrIndexSearcher.buildAndRunCollectorChain(SolrIndexSearcher.java:215) What's the history behind Scorer returning floats but other code using doubles? Sorry if this is the wrong list to vommit out jstack dumps.
Slower queries with 7.3.1?
I'm seeing 0.5s increase in avg and p99 latencies after upgrading from 7.2 to 7.3.1. Eg 1s avg to 1.5s avg. I've tried upgrading from java 8 to 10 (9 being EOL) suspecting https://issues.apache.org/jira/browse/LUCENE-7966. No help. I'm using boost queries. Probably abusing boost queries. Jstack led me to https://issues.apache.org/jira/browse/LUCENE-8099. I can't see any benchmarking of boost queries in the nightly benchmarks listed https://home.apache.org/~mikemccand/lucenebench/. Anybody else seeing longer query times after an upgrade to 7.3.1? Thanks!
