Odd hot MVEL

Elastic Stack Elasticsearch
1

Does anyone know what might be causing MVEL to do this:
100.3% (501.3ms out of 500ms) cpu usage by thread
'elasticsearch[elastic1002][search][T#23]'
9/10 snapshots sharing following 47 elements
java.lang.Throwable.fillInStackTrace(Native Method)
java.lang.Throwable.fillInStackTrace(Throwable.java:782)
java.lang.Throwable.(Throwable.java:265)
java.lang.Exception.(Exception.java:66)
java.lang.RuntimeException.(RuntimeException.java:62)

java.lang.IllegalArgumentException.(IllegalArgumentException.java:53)
sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source)

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.GetterAccessor.getValue(GetterAccessor.java:43)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MapAccessorNest.getValue(MapAccessorNest.java:54)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.VariableAccessor.getValue(VariableAccessor.java:37)

org.elasticsearch.common.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:108)

org.elasticsearch.common.mvel2.MVELRuntime.execute(MVELRuntime.java:86)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:106)

org.elasticsearch.common.mvel2.ast.Substatement.getReducedValueAccelerated(Substatement.java:44)

org.elasticsearch.common.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:114)

org.elasticsearch.common.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:114)

org.elasticsearch.common.mvel2.compiler.ExecutableAccessor.getValue(ExecutableAccessor.java:42)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MethodAccessor.executeAndCoerce(MethodAccessor.java:164)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MethodAccessor.getValue(MethodAccessor.java:73)

org.elasticsearch.common.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:108)

org.elasticsearch.common.mvel2.MVELRuntime.execute(MVELRuntime.java:86)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119)

org.elasticsearch.script.mvel.MvelScriptEngineService$MvelSearchScript.run(MvelScriptEngineService.java:191)

org.elasticsearch.script.mvel.MvelScriptEngineService$MvelSearchScript.runAsDouble(MvelScriptEngineService.java:206)

org.elasticsearch.common.lucene.search.function.ScriptScoreFunction.score(ScriptScoreFunction.java:54)

It isn't an error. Looking at MVEL's source it looks like it catches this
error and works around it by inspecting the function, casting the arguments
appropriately, and they retying. I imagine it'd be nice and fast if I
didn't get the types wrong but it works anyway which feels a bit trappy at
scale.

I know this is caused by scoring tons of documents in a FunctionScore which
is a pretty strong argument for moving all FunctionScoring into a rescore
for protection but what in the world am I doing with MVEL to make it do
this?

My candidate MVEL looks like this:
log10( ($doc['a'].empty ? 0 : $doc['a']) + ($doc['b'].empty ? 0 :
$doc['b']) + 2 )

I'm trying to reproduce it with the debugger and Elasticsearch's tests but
I haven't had any luck yet so I'd love to hear if anyone else has seen this.

Nik

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CAPmjWd1aX7vNR3L5ORHWROKvR6fMM6BkUNVSFVxKbpR8DwT4_g%40mail.gmail.com.
For more options, visit https://groups.google.com/groups/opt_out.

2

Sorry to resurrect a dead thread, but I figured it out:

High level:

  1. Hit ~1 million documents with a script score.
  2. Do something like (doc['foo'].empty ? 0 : doc['foo'].value) * doc['bar'].
    The .empty is the key here.
  3. If most of the documents don't have a foo then this is really slow.
    Like, two seconds slow.
  4. Instead, switch to this (doc['foo'].isEmpty() ? 0 : doc['foo'].value) *
    doc['bar']. That is faster. .36 seconds or so. Not super speedy, but much
    better.

On Wed, Jan 8, 2014 at 10:44 AM, Nikolas Everett nik9000@gmail.com wrote:

Does anyone know what might be causing MVEL to do this:
100.3% (501.3ms out of 500ms) cpu usage by thread
'elasticsearch[elastic1002][search][T#23]'
9/10 snapshots sharing following 47 elements
java.lang.Throwable.fillInStackTrace(Native Method)
java.lang.Throwable.fillInStackTrace(Throwable.java:782)
java.lang.Throwable.(Throwable.java:265)
java.lang.Exception.(Exception.java:66)
java.lang.RuntimeException.(RuntimeException.java:62)

java.lang.IllegalArgumentException.(IllegalArgumentException.java:53)
sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source)

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.GetterAccessor.getValue(GetterAccessor.java:43)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MapAccessorNest.getValue(MapAccessorNest.java:54)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.VariableAccessor.getValue(VariableAccessor.java:37)

org.elasticsearch.common.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:108)

org.elasticsearch.common.mvel2.MVELRuntime.execute(MVELRuntime.java:86)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:106)

org.elasticsearch.common.mvel2.ast.Substatement.getReducedValueAccelerated(Substatement.java:44)

org.elasticsearch.common.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:114)

org.elasticsearch.common.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:114)

org.elasticsearch.common.mvel2.compiler.ExecutableAccessor.getValue(ExecutableAccessor.java:42)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MethodAccessor.executeAndCoerce(MethodAccessor.java:164)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MethodAccessor.getValue(MethodAccessor.java:73)

org.elasticsearch.common.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:108)

org.elasticsearch.common.mvel2.MVELRuntime.execute(MVELRuntime.java:86)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119)

org.elasticsearch.script.mvel.MvelScriptEngineService$MvelSearchScript.run(MvelScriptEngineService.java:191)

org.elasticsearch.script.mvel.MvelScriptEngineService$MvelSearchScript.runAsDouble(MvelScriptEngineService.java:206)

org.elasticsearch.common.lucene.search.function.ScriptScoreFunction.score(ScriptScoreFunction.java:54)

It isn't an error. Looking at MVEL's source it looks like it catches this
error and works around it by inspecting the function, casting the arguments
appropriately, and they retying. I imagine it'd be nice and fast if I
didn't get the types wrong but it works anyway which feels a bit trappy at
scale.

I know this is caused by scoring tons of documents in a FunctionScore
which is a pretty strong argument for moving all FunctionScoring into a
rescore for protection but what in the world am I doing with MVEL to make
it do this?

My candidate MVEL looks like this:
log10( ($doc['a'].empty ? 0 : $doc['a']) + ($doc['b'].empty ? 0 :
$doc['b']) + 2 )

I'm trying to reproduce it with the debugger and Elasticsearch's tests but
I haven't had any luck yet so I'd love to hear if anyone else has seen this.

Nik

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CAPmjWd3WCWxjTuoZZzmwtqG29Ld1dOrmT0yr9kZHat%3D0rPsqPg%40mail.gmail.com.
For more options, visit https://groups.google.com/groups/opt_out.

3

Great catch. Which Elasticsearch version and which JDK?

Thankfully my documents are uniform, so I have been able to skip isEmpty
checks.

--
Ivan

On Tue, Feb 11, 2014 at 7:52 AM, Nikolas Everett nik9000@gmail.com wrote:

Sorry to resurrect a dead thread, but I figured it out:
In MVEL .empty can be way way way slower then .isEmpty() · Issue #5086 · elastic/elasticsearch · GitHub

High level:

  1. Hit ~1 million documents with a script score.
  2. Do something like (doc['foo'].empty ? 0 : doc['foo'].value) *
    doc['bar']. The .empty is the key here.
  3. If most of the documents don't have a foo then this is really slow.
    Like, two seconds slow.
  4. Instead, switch to this (doc['foo'].isEmpty() ? 0 : doc['foo'].value)
  • doc['bar']. That is faster. .36 seconds or so. Not super speedy, but
    much better.

On Wed, Jan 8, 2014 at 10:44 AM, Nikolas Everett nik9000@gmail.comwrote:

Does anyone know what might be causing MVEL to do this:
100.3% (501.3ms out of 500ms) cpu usage by thread
'elasticsearch[elastic1002][search][T#23]'
9/10 snapshots sharing following 47 elements
java.lang.Throwable.fillInStackTrace(Native Method)
java.lang.Throwable.fillInStackTrace(Throwable.java:782)
java.lang.Throwable.(Throwable.java:265)
java.lang.Exception.(Exception.java:66)
java.lang.RuntimeException.(RuntimeException.java:62)

java.lang.IllegalArgumentException.(IllegalArgumentException.java:53)
sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source)

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.GetterAccessor.getValue(GetterAccessor.java:43)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MapAccessorNest.getValue(MapAccessorNest.java:54)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.VariableAccessor.getValue(VariableAccessor.java:37)

org.elasticsearch.common.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:108)

org.elasticsearch.common.mvel2.MVELRuntime.execute(MVELRuntime.java:86)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:106)

org.elasticsearch.common.mvel2.ast.Substatement.getReducedValueAccelerated(Substatement.java:44)

org.elasticsearch.common.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:114)

org.elasticsearch.common.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:114)

org.elasticsearch.common.mvel2.compiler.ExecutableAccessor.getValue(ExecutableAccessor.java:42)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MethodAccessor.executeAndCoerce(MethodAccessor.java:164)

org.elasticsearch.common.mvel2.optimizers.impl.refl.nodes.MethodAccessor.getValue(MethodAccessor.java:73)

org.elasticsearch.common.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:108)

org.elasticsearch.common.mvel2.MVELRuntime.execute(MVELRuntime.java:86)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123)

org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119)

org.elasticsearch.script.mvel.MvelScriptEngineService$MvelSearchScript.run(MvelScriptEngineService.java:191)

org.elasticsearch.script.mvel.MvelScriptEngineService$MvelSearchScript.runAsDouble(MvelScriptEngineService.java:206)

org.elasticsearch.common.lucene.search.function.ScriptScoreFunction.score(ScriptScoreFunction.java:54)

It isn't an error. Looking at MVEL's source it looks like it catches
this error and works around it by inspecting the function, casting the
arguments appropriately, and they retying. I imagine it'd be nice and fast
if I didn't get the types wrong but it works anyway which feels a bit
trappy at scale.

I know this is caused by scoring tons of documents in a FunctionScore
which is a pretty strong argument for moving all FunctionScoring into a
rescore for protection but what in the world am I doing with MVEL to make
it do this?

My candidate MVEL looks like this:
log10( ($doc['a'].empty ? 0 : $doc['a']) + ($doc['b'].empty ? 0 :
$doc['b']) + 2 )

I'm trying to reproduce it with the debugger and Elasticsearch's tests
but I haven't had any luck yet so I'd love to hear if anyone else has seen
this.

Nik

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/CAPmjWd3WCWxjTuoZZzmwtqG29Ld1dOrmT0yr9kZHat%3D0rPsqPg%40mail.gmail.com
.

For more options, visit https://groups.google.com/groups/opt_out.

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CALY%3DcQCZpWMyknE_pcap81stwq3dTBMsLSHmQ1o9Kv7yqQJB-w%40mail.gmail.com.
For more options, visit https://groups.google.com/groups/opt_out.

4

On Tue, Feb 11, 2014 at 11:26 AM, Ivan Brusic ivan@brusic.com wrote:

Great catch. Which Elasticsearch version and which JDK?

Thankfully my documents are uniform, so I have been able to skip isEmpty
checks.

I believe I started seeing it on 0.90.6. I'm running 0.90.10 in production
now and see it. I verified it again master as well on my laptop.
Production is OpenJDK 1.7.0_25 and my laptop is OpenJDK 1.7.0_51. The
stack trace I linked came from 0.90.10.

I know 1.7.0_51 is known not to work well but it isn't causing this.

Nik

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CAPmjWd1M0pO%3DjBb53%2BLu%2BM8TVwkPorOOwezfTRDh8K_RZyV80g%40mail.gmail.com.
For more options, visit https://groups.google.com/groups/opt_out.