# Odd hot MVEL

**URL:** <https://discuss.elastic.co/t/odd-hot-mvel/15145>\
**Category:** Elasticsearch\
**Created:** [January 8, 2014, 3:44pm UTC](https://discuss.elastic.co/t/odd-hot-mvel/15145 "2014-01-08T15:44:17Z")\
**Posts on this page:** 5\
**Page:** 1

<div class="post-metadata">

**Author:** ![nik9000](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nik9000/32/44947_2.png) [@nik9000](https://discuss.elastic.co/u/nik9000)\
**Post date:** [January 8, 2014, 3:44pm UTC](https://discuss.elastic.co/t/odd-hot-mvel/15145/1 "2014-01-08T15:44:17Z")

</div>

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](mailto:elasticsearch+unsubscribe@googlegroups.com).  
To view this discussion on the web visit [https://groups.google.com/d/msgid/elasticsearch/CAPmjWd1aX7vNR3L5ORHWROKvR6fMM6BkUNVSFVxKbpR8DwT4\_g%40mail.gmail.com](https://groups.google.com/d/msgid/elasticsearch/CAPmjWd1aX7vNR3L5ORHWROKvR6fMM6BkUNVSFVxKbpR8DwT4_g%40mail.gmail.com).  
For more options, visit [https://groups.google.com/groups/opt\_out](https://groups.google.com/groups/opt_out).

---

<div class="post-metadata">

**Author:** ![nik9000](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nik9000/32/44947_2.png) [@nik9000](https://discuss.elastic.co/u/nik9000)\
**Post date:** [February 11, 2014, 3:52pm UTC](https://discuss.elastic.co/t/odd-hot-mvel/15145/2 "2014-02-11T15:52:39Z")

</div>

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

> <https://github.com/elastic/elasticsearch/issues/5086>
>
> This happens when you use \`.empty\` to check if a field is empty and it actually …is empty. I've made a gist to reproduce it: https://gist.github.com/nik9000/8937202
> 
> 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.
> 
> I'm not completely sure what is happening but my guess is that the MVEL optimizer is optimizing .empty is a call to .isEmpty on an instance of either ScriptDocValues or ScriptDocValues.Empty. When it hits the wrong one it recovers by catching an IllegalArgumentException thrown by the JVM and then does some munging. The act of filling in the stack trace for that IllegalArgumentException is really really really slow. So slow, I see it in the hot threads: https://gist.github.com/nik9000/8937335 .
> 
> Workaround: use \`.isEmpty()\` instead of \`.empty\`.
> 
> I'm not sure what the fix ought to be.

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](mailto: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](mailto:elasticsearch+unsubscribe@googlegroups.com).  
To view this discussion on the web visit [https://groups.google.com/d/msgid/elasticsearch/CAPmjWd3WCWxjTuoZZzmwtqG29Ld1dOrmT0yr9kZHat%3D0rPsqPg%40mail.gmail.com](https://groups.google.com/d/msgid/elasticsearch/CAPmjWd3WCWxjTuoZZzmwtqG29Ld1dOrmT0yr9kZHat%3D0rPsqPg%40mail.gmail.com).  
For more options, visit [https://groups.google.com/groups/opt\_out](https://groups.google.com/groups/opt_out).

---

<div class="post-metadata">

**Author:** ![Ivan](https://avatars.discourse-cdn.com/v4/letter/i/df788c/32.png) [@Ivan](https://discuss.elastic.co/u/Ivan)\
**Post date:** [February 11, 2014, 4:26pm UTC](https://discuss.elastic.co/t/odd-hot-mvel/15145/3 "2014-02-11T16:26:00Z")

</div>

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](mailto: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](https://github.com/elasticsearch/elasticsearch/issues/5086)
> 
> 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](mailto: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](mailto:elasticsearch+unsubscribe@googlegroups.com).  
> To view this discussion on the web visit  
> [https://groups.google.com/d/msgid/elasticsearch/CAPmjWd3WCWxjTuoZZzmwtqG29Ld1dOrmT0yr9kZHat%3D0rPsqPg%40mail.gmail.com](https://groups.google.com/d/msgid/elasticsearch/CAPmjWd3WCWxjTuoZZzmwtqG29Ld1dOrmT0yr9kZHat%3D0rPsqPg%40mail.gmail.com)  
> .
> 
> For more options, visit [https://groups.google.com/groups/opt\_out](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](mailto: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](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](https://groups.google.com/groups/opt_out).

---

<div class="post-metadata">

**Author:** ![nik9000](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nik9000/32/44947_2.png) [@nik9000](https://discuss.elastic.co/u/nik9000)\
**Post date:** [February 11, 2014, 4:43pm UTC](https://discuss.elastic.co/t/odd-hot-mvel/15145/4 "2014-02-11T16:43:56Z")

</div>

On Tue, Feb 11, 2014 at 11:26 AM, Ivan Brusic [ivan@brusic.com](mailto: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](mailto: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](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](https://groups.google.com/groups/opt_out).

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [July 6, 2017, 1:51am UTC](https://discuss.elastic.co/t/odd-hot-mvel/15145/5 "2017-07-06T01:51:01Z")

</div>