[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16609536#comment-16609536
]
Michael McCandless commented on LUCENE-7882:
Thanks for the explanation [~hypothesisx86]; that makes sense.
> 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
>Priority: Major
> Attachments: demo.patch
>
>
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
(v7.6.3#76005)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16599076#comment-16599076
]
Tony Xu commented on LUCENE-7882:
-
Oh I forgot to paste the test output.
2
Loading class , using
Loaderorg.apache.lucene.expressions.js.JavascriptCompiler$Loader@3973f90b
Loading class , using
Loaderorg.apache.lucene.expressions.js.JavascriptCompiler$Loader@3973f90b
Loading class , using
Loaderorg.apache.lucene.expressions.js.JavascriptCompiler$Loader@3973f90b
3.0
Loading class , using
Loaderorg.apache.lucene.expressions.js.JavascriptCompiler$Loader@2a44f939
Loading class , using
Loaderorg.apache.lucene.expressions.js.JavascriptCompiler$Loader@2a44f939
Loading class , using
Loaderorg.apache.lucene.expressions.js.JavascriptCompiler$Loader@2a44f939
3.0
> 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
>Priority: Major
> Attachments: demo.patch
>
>
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
(v7.6.3#76005)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16599071#comment-16599071
]
Tony Xu commented on LUCENE-7882:
-
To explain why Mike saw a many threads getting blocked on a monitor. I wrote an
unit test to demonstrate the issue.
Basically each compiled expression is defined in a new ClassLoader and when the
expression's evaluation needs to invoke an external method (in this case *ln*
that maps to *java.lang.Math#log*), the new classLoader needs to load that
class. The classloading work is delegated to the parent classloader which uses
itself as a monitor for synchronization.
The problem was many compiled expression's defining classloaders share the same
parent and were trying to load a class via the parent in the evaluate method.
This led to more contention on the parent classloader's monitor.
[^demo.patch]
> 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
>Priority: Major
> Attachments: demo.patch
>
>
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
(v7.6.3#76005)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16599043#comment-16599043
]
Robert Muir commented on LUCENE-7882:
-
Well I think it needs to be tested on a modern JVM (e.g. latest release) to see
if that bug even still happens at all. And I don't agree that a cache certainly
makes it faster, we need to see real numbers to see if it matters. Historically
it has been far too difficult to remove such caches, e.g. scoring used to cache
sqrt() but then sqrt() got faster and the cache became unnecessary.
I don't want to see Accountable here as that won't help the issue. There is
more than just heap memory involved with compiled classes.
> 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
>Priority: Major
>
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
(v7.6.3#76005)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16599040#comment-16599040
]
Uwe Schindler commented on LUCENE-7882:
---
IMHO, caching the compiled expressions is not Lucene's responsibility. You can
do this easy with any caching library.
> 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
>Priority: Major
>
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
(v7.6.3#76005)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16599031#comment-16599031
]
Michael McCandless commented on LUCENE-7882:
But even once the JVM fixes its bugs and we can safely re-compile all
expressions per query, it should still be faster to avoid that recompilation
when you can?
I think also the lack of {{Accountable}} on a compiled expression makes caching
dangerous – we would have no good way to measure how much RAM is consumed by it.
> 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
>Priority: Major
>
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
(v7.6.3#76005)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16597774#comment-16597774
]
Robert Muir commented on LUCENE-7882:
-
I really still think we shouldn't add any java-level caches to lucene (which
could easily end out turning into leaks) to workaround any bug in openjdk. They
fix bugs often, probably best to spend the time running the test with a newer
JVM instead.
> 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
>Priority: Major
>
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
(v7.6.3#76005)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16597756#comment-16597756
]
Tony Xu commented on LUCENE-7882:
-
A simple idea here can be caching the compiled Expression instances.
One way of doing it is to have a class that wraps the *JavascriptCompiler* and
it makes sure one unique expression text only get compiled once and cached.
Note that errors can be cached, too, because same invalid expression should
fail at exactly the same point (e.g the ParseException)! Future compilation of
the same expression should return the cached compilation result.
This new class can be a static so we cache compilation in JVM scope or it can
be instantiable so the caller decides the scope.
> 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
>Priority: Major
>
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
(v7.6.3#76005)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16074552#comment-16074552
]
Dawid Weiss commented on LUCENE-7882:
-
As far as I understand it should sweep code cache from time to time...
http://markmail.org/thread/acpxk7ogdunvfhry
Don't know whether there is a compaction strategy (whether the already compiled
code can be relocated around); if not, then the free size tells you nothing
about fragmentation and lookup for a free block may be slowing things down.
An interesting problem.
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16074536#comment-16074536
]
Michael McCandless commented on LUCENE-7882:
Sorry, I did not experience a full hang/deadlock: I only experienced that the
QPS capacity of the searcher went down drastically for periods of time. The
pattern is odd ... at first the QPS is high, then it gradually slows down, then
it enters periods where it's extremely slow, like 10X slower than "normal" for
maybe ~20-30 seconds, then it gets somewhat faster again, then another super
slow period. But it never outright hangs.
It is odd to me that the code cache was allowed to grow to nearly it's maximum
size; seems like these methods should very quickly become dead since after that
one query executes, it should no longer be referenced.
bq. Can you repeat and add -XX:+UseCodeCacheFlushing switch, see if this helps?
OK I'll try that, may be a while before I can though. Though from its
description it seems like it shouldn't be necessary here, i.e. the JVM should
be able to tell, quickly, that these methods are not referenced anymore. But I
know very little about this part of the JVM!
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16074399#comment-16074399
]
Dawid Weiss commented on LUCENE-7882:
-
Here is a bit more in-depth info.
https://docs.oracle.com/javase/8/embedded/develop-apps-platforms/codecache.htm
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16074396#comment-16074396
]
Dawid Weiss commented on LUCENE-7882:
-
Code cache is an area I don't have much experience with. It's interesting the
cache grows without being pruned though -- zombie methods are effectively dead
code, should be freed over time. Can you repeat and add
{{-XX:+UseCodeCacheFlushing}} switch, see if this helps?
Separately from that, the hang you experienced is another thing to worry about.
Could be an interaction with code cache (resource deadlock somewhere). Sigh.
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
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=22Kb 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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 a
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16057319#comment-16057319
]
Dawid Weiss commented on LUCENE-7882:
-
These one-off class loaders should be gc-ed if there are no root refs pointing
at anything they declared. This should be relatively easy to verify if you dump
the heap incrementally over time (yourkit is your friend here).
The blocked thread is possibly a related issue (if they do have some
synchronization going on internally), but I don't see where that could occur.
Try the things Robert mentioned. Interesting stuff.
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16056605#comment-16056605
]
Robert Muir commented on LUCENE-7882:
-
I know i have benchmarked that its definitely slower not to reuse. But
compiling a new one per-query was not that much overhead with lower concurrency
and tests did not run as long as yours.
Each one gets its own loader for the reason it can be GC'ed properly (you can
test that this works). But i am not sure that java land is the issue. Maybe you
just have codecache scanning/sweeping during a safepoint and thats how it
looks? Or maybe its related to class dictionaries and stuff in the JDK, i dont
know.
Maybe run with some improved debugging such as a better profiler, enable
compilation log, look at codecache stats (they are at least in JMX), etc. Maybe
try disabling inlining (at least for expression evaluation) to hope for a
better stacktrace.
I know this stuff is a PITA but it would be good to understand before adding a
cache (as it would then hang onto cached classes and maybe have other
downsides/user annoyances related to that).
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16056533#comment-16056533
]
Michael McCandless commented on LUCENE-7882:
That's a great question [~dawid.weiss]; I don't know the answer. Maybe
[~jdconradson] or [~rcmuir] knows?
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
[jira] [Commented] (LUCENE-7882) Maybe expression compiler should cache recently compiled expressions?
[
https://issues.apache.org/jira/browse/LUCENE-7882?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16053984#comment-16053984
]
Dawid Weiss commented on LUCENE-7882:
-
It probably does because they're loaded into their own class loaders?
> 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=0x7eea7000a000 nid=0x1ea8a
> waiting for monitor entry [0x7eea867dd000]
>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
