[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16074108#comment-16074108
]
Michael McCandless commented on LUCENE-7882:
--------------------------------------------
I ran my searcher instance with {{-XX:+PrintSafepointStatistics
-XX:+PrintCodeCacheOnCompilation -XX:+PrintCompilation}} and I see the
CodeCache getting close to full over time, e.g.:
{noformat}
CodeCache: size=245760Kb used=229999Kb max_used=230003Kb free=15760Kb
[GC (Allocation Failure) 2872668K->1304388K(16581312K), 0.1226819 secs]
10708156 764218 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes)
10708156 764217 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes)
10708162 764219 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes)
CodeCache: size=245760Kb used=230003Kb max_used=230007Kb free=15756Kb
CodeCache: size=245760Kb used=230007Kb max_used=230011Kb free=15752Kb
CodeCache: size=245760Kb used=230011Kb max_used=230015Kb free=15748Kb
10708178 764220 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes)
CodeCache: size=245760Kb used=230015Kb max_used=230020Kb free=15744Kb
10708192 764221 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes)
{noformat}
And then periodically I see tons and tons of lines like this at once:
{noformat}
11108619 689344 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes) made not entrant
11108619 689541 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes) made not entrant
11108619 689540 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes) made not entrant
11108619 689543 4
org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression::evaluate
(21 bytes) made not entrant
{noformat}
And also {{made zombie}}:
{noformat}
11236528 748217 4 (method) made zombie
11236528 748210 4 (method) made zombie
11236528 748211 4 (method) made zombie
11236528 748207 4 (method) made zombie
11236528 748206 4 (method) made zombie
11236528 748203 4 (method) made zombie
11236528 748200 4 (method) made zombie
11236528 748198 4 (method) made zombie
11236528 748196 4 (method) made zombie
{noformat}
I think net/net Java is just working hard to clean up all the one-off compiled
methods I was creating by not re-using my expression...
> Maybe expression compiler should cache recently compiled expressions?
> ---------------------------------------------------------------------
>
> Key: LUCENE-7882
> URL: https://issues.apache.org/jira/browse/LUCENE-7882
> Project: Lucene - Core
> Issue Type: Improvement
> Components: modules/expressions
> Reporter: Michael McCandless
>
> I've been running search performance tests using a simple expression
> ({{_score + ln(1000+unit_sales)}}) for sorting and hit this odd bottleneck:
> {noformat}
> "pool-1-thread-30" #70 prio=5 os_prio=0 tid=0x00007eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x00007eea867dd000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at
> org.apache.lucene.expressions.js.JavascriptCompiler$CompiledExpression.evaluate(_score
> + ln(1000+unit_sales))
> at
> org.apache.lucene.expressions.ExpressionFunctionValues.doubleValue(ExpressionFunctionValues.java:49)
> at
> com.amazon.lucene.OrderedVELeafCollector.collectInternal(OrderedVELeafCollector.java:123)
> at
> com.amazon.lucene.OrderedVELeafCollector.collect(OrderedVELeafCollector.java:108)
> at
> org.apache.lucene.search.MultiCollectorManager$Collectors$LeafCollectors.collect(MultiCollectorManager.java:102)
> at
> org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:241)
> 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:658)
> at org.apache.lucene.search.IndexSearcher$5.call(IndexSearcher.java:600)
> at org.apache.lucene.search.IndexSearcher$5.call(IndexSearcher.java:597)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> I couldn't see any {{synchronized}} in the sources here, so I'm not sure
> which object monitor it's blocked on.
> I was accidentally compiling a new expression for every query, and that
> bottleneck would cause overall QPS to slow down drastically (~4X slower after
> ~1 hour of redline tests), as if the JVM is getting slower and slower to
> evaluate each expression the more expressions I had compiled.
> I tested JDK 9-ea and it also kept slowing down over time as the performance
> test ran.
> Maybe we should put a small cache in front of the expressions compiler to
> make it less trappy? Or maybe we can get to the root cause of why the JVM
> slows down more and more, the more expressions you compile?
> I won't have time to work on this in the near future so if anyone else feels
> the itch, please scratch it!
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
