[ 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