Bug 61556 - Clarify in documentation performance impacts of ${} var usage in IfController and groovy
Summary: Clarify in documentation performance impacts of ${} var usage in IfController...
Status: RESOLVED FIXED
Alias: None
Product: JMeter
Classification: Unclassified
Component: Main (show other bugs)
Version: 3.2
Hardware: All All
: P2 enhancement (vote)
Target Milestone: ---
Assignee: JMeter issues mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-09-21 11:15 UTC by Justin McCartney
Modified: 2017-10-05 20:29 UTC (History)
2 users (show)



Attachments
Groovy condition evaluation jmx (9.89 KB, application/xml)
2017-09-21 11:15 UTC, Justin McCartney
Details
Jexl condition evaluation jmx (9.76 KB, application/xml)
2017-09-21 11:16 UTC, Justin McCartney
Details
JS condition evaluation jmx (9.68 KB, application/xml)
2017-09-21 11:16 UTC, Justin McCartney
Details
Jmeter 3.1 summary results (7.95 KB, text/plain)
2017-09-21 11:17 UTC, Justin McCartney
Details
Jmeter 3.2 summary results (6.87 KB, text/plain)
2017-09-21 11:17 UTC, Justin McCartney
Details
Mem Jmeter 3.1 Groovy evaluation (94.57 KB, image/png)
2017-09-21 11:18 UTC, Justin McCartney
Details
Mem Jmeter 3.1 Jexl evaluation (63.09 KB, image/png)
2017-09-21 11:18 UTC, Justin McCartney
Details
Mem Jmeter 3.1 JS evaluation (106.94 KB, image/png)
2017-09-21 11:19 UTC, Justin McCartney
Details
Mem Jmeter 3.2 Groovy evaluation (93.55 KB, image/png)
2017-09-21 11:20 UTC, Justin McCartney
Details
Mem Jmeter 3.2 Jexl evaluation (73.92 KB, image/png)
2017-09-21 11:20 UTC, Justin McCartney
Details
Mem Jmeter 3.2 JS evaluation (132.82 KB, image/png)
2017-09-21 11:21 UTC, Justin McCartney
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Justin McCartney 2017-09-21 11:15:56 UTC
Created attachment 35346 [details]
Groovy condition evaluation jmx

There appears to be a regression in performance with the move from 3.1 to 3.2 in the evaluation of IfController in JS.  This appears to be a slow memory leak and only was noticeable in running tests with 500 tps over a period of 4 hours.

Jexl evaluation appears to be the same as before.  Groovy evaluation can also lead to a OOM in metaspace, although this is not limited by default in Jmeter! Which it should be.

I attached some examples tests, which execute a debug controller with a delay, then evaluates a condition before executing another debug controller with the same delay.  Metaspace limited to 256mb.  The condition is of the form: "${SOME_VALUE}" != "DEFAULT"

Summary of results (test files attached)

Jmeter 3.2

Groovy evaluation = failed after 3 mins with out of memory in metaspace.
JS evaluation = 1808 transactions/s
Jexl evaluation = 1980 transactions/s

Jmeter 3.1

Groovy evaluation = 223 transactions/s
JS evaluation = 1963 transactions/s
Jexl evaluation = 1982 transactions/s

I have attached the results as well as screen shots of the metaspace and cpu through jvisualvm.

So here are two issues really:

1.  Performance degradation (possible slow metaspace leak) on JS evaluation in IfController.
2.  Documentation needs to be clearer on not using variable replacement in Groovy scripts either in JSR233 components or in Groovy functions such as in the IfController.

${__groovy( "${SOME_VAR}" != "DEFAULT" )}

is going to be much slower than

${__groovy(vars.get("SOME_VAR") != "NULL" )}

I assume the later is cached and re-used while the former involve more classes being created each time and eventually leads to a leak.  What I don't understand is why the space is not freed up in the metaspace, I would expect it to be slower but not to cause a OOM and that is the behaviour that differs from 3.1 to 3.2 but I've not run the tests for longer than 5 mins.

We first noticed the issue on longer tests (4 hr) were the throughput was trending downward towards the end of the test and noticed that the metaspace was growing throughout the test execution.  This test makes use of quite a few IfController evaluations in the form:

"${SOME_VAR}" != "DEFAULT"

These are with Interpret Condition as Variable expression = false.

On reverting back to Jmeter 3.1 we did not see the degradation in throughput as the test continued.
Comment 1 Justin McCartney 2017-09-21 11:16:20 UTC
Created attachment 35347 [details]
Jexl condition evaluation jmx
Comment 2 Justin McCartney 2017-09-21 11:16:44 UTC
Created attachment 35348 [details]
JS condition evaluation jmx
Comment 3 Justin McCartney 2017-09-21 11:17:02 UTC
Created attachment 35349 [details]
Jmeter 3.1 summary results
Comment 4 Justin McCartney 2017-09-21 11:17:27 UTC
Created attachment 35350 [details]
Jmeter 3.2 summary results
Comment 5 Justin McCartney 2017-09-21 11:18:22 UTC
Created attachment 35351 [details]
Mem Jmeter 3.1 Groovy evaluation
Comment 6 Justin McCartney 2017-09-21 11:18:40 UTC
Created attachment 35352 [details]
Mem Jmeter 3.1 Jexl evaluation
Comment 7 Justin McCartney 2017-09-21 11:19:31 UTC
Created attachment 35353 [details]
Mem Jmeter 3.1 JS evaluation
Comment 8 Justin McCartney 2017-09-21 11:20:19 UTC
Created attachment 35354 [details]
Mem Jmeter 3.2 Groovy evaluation
Comment 9 Justin McCartney 2017-09-21 11:20:39 UTC
Created attachment 35355 [details]
Mem Jmeter 3.2 Jexl evaluation
Comment 10 Justin McCartney 2017-09-21 11:21:02 UTC
Created attachment 35356 [details]
Mem Jmeter 3.2 JS evaluation
Comment 11 Philippe Mouawad 2017-09-21 11:24:19 UTC
Hello,
Thanks for report.
Could you try JMeter 3.2 with groovy version used in 3.1 ?

Thanks
Comment 12 Justin McCartney 2017-09-22 08:45:21 UTC
Hi Philippe,

I tested again with Groovy evaluations using the 3.2 Jmeter with the Groovy lib from 3.1 (labelled groovy-all-2.4.7.jar).

I still see the OOM metaspace at ~3mins.

So there didn't seem to be much difference there.

Justin
Comment 13 Philippe Mouawad 2017-09-22 08:49:18 UTC
Hello,
Are you running JMeter 3.1 and 3.2 with same Java version ?

Thanks
Comment 14 Justin McCartney 2017-09-22 09:50:19 UTC
Hi,

yes all tests were executed with the same Java version no matter what version of Jmeter.

> java -version
java version "1.8.0_144"
Java(TM) SE Runtime Environment (build 1.8.0_144-b01)
Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode)
Comment 15 Philippe Mouawad 2017-09-23 19:29:38 UTC
Hello,
Thanks for your feedback.
Few notes:

- 3.2 switched from Rhino to Nashorn. If you diagnose a leak, it would be a Java leak IMO
- Regarding Groovy, the memory leak you see is due to Groovy, it disappears if you add this -Dgroovy.use.classvalue=true. See http://jmeter.apache.org/usermanual/component_reference.html#JSR223_Sampler. I don't reproduce OOM with this setting but throughput is negatively affected.
- I agree with your note on Metaspace, we should indeed add -XX:MaxMetaspaceSize=256m

Now what I don't understand is the difference in behaviour between 3.1 and 3.2 when using same groovy version. Are you sure you removed the new groovy jar in 3.2 when testing old one ?

The second strange thing, is performance regression in JS between 3.1 and 3.2, in the tests I made, Nashorn was outperforming Rhino.

Would it be possible to attach your log file and ensure you're using fresh versions of 3.1 and 3.2 without any plugin and using same exact settings if not already done ?


Thank you
Comment 16 Justin McCartney 2017-09-27 13:05:29 UTC
Hi Philippe,

Groovy

I verified again and the (3.2 default included) groovy jar is definitely removed.  The only Groovy jar on the class path is groovy-all-2.4.7.jar.  I re-executed the test with 3.2 and received the same result, OOM metaspace.

I see that your Jmeter docs you linked to do actually mention not to be use variable replacement for Groovy scripts which is good.  However, I think this should be added to the IfController docs as it should be clearer there that using variable replacement will have a negative impact on performance.  Also some examples could be provided to give clarity on the correct syntax to use.

The function help for __groovy could also do with this information.

There seem to be other metaspace bugs against later versions of Groovy, e.g.: https://issues.apache.org/jira/browse/GROOVY-8189

Javascript

I currently haven't got a simple test that shows the problems we encountered with our long running load tests in 3.2 vs earlier Jmeter.  I will try and re-execute the tests, but I might not get a slot to execute the tests until early next week.  I would ignore anything related to JS until then.
Comment 17 Philippe Mouawad 2017-09-27 18:44:00 UTC
(In reply to Justin McCartney from comment #16)
> Hi Philippe,
> 
> Groovy
> 
> I verified again and the (3.2 default included) groovy jar is definitely
> removed.  The only Groovy jar on the class path is groovy-all-2.4.7.jar.  I
> re-executed the test with 3.2 and received the same result, OOM metaspace.
> 
> I see that your Jmeter docs you linked to do actually mention not to be use
> variable replacement for Groovy scripts which is good.  However, I think
> this should be added to the IfController docs as it should be clearer there
> that using variable replacement will have a negative impact on performance. 
> Also some examples could be provided to give clarity on the correct syntax
> to use.
> 
> The function help for __groovy could also do with this information.
> 
> There seem to be other metaspace bugs against later versions of Groovy,
> e.g.: https://issues.apache.org/jira/browse/GROOVY-8189
> 
> Javascript
> 
> I currently haven't got a simple test that shows the problems we encountered
> with our long running load tests in 3.2 vs earlier Jmeter.  I will try and
> re-execute the tests, but I might not get a slot to execute the tests until
> early next week.  I would ignore anything related to JS until then.

Hello Justin,
Would you be ready to contribute a PR for documentation improvements ?

- http://jmeter.apache.org/building.html

I'll be happy to merge it.
Thanks
Regards
Comment 18 Philippe Mouawad 2017-10-03 19:37:12 UTC
Hi Justin,
Any feedback on this issue ?

Thanks
Regards
Comment 19 Justin McCartney 2017-10-04 08:18:26 UTC
(In reply to Philippe Mouawad from comment #18)
> Hi Justin,
> Any feedback on this issue ?
> 
> Thanks
> Regards

Hi Philippe,

sorry I have been busy on other tasks but I am currently adding to the docs and should hopefully have a pull request for the doc update today.

I still need to get time to re-execute the long duration tests in relation to the JS change from 3.1 to 3.2, but I might not get a slot for that until late next week.

Thanks,

Justin
Comment 20 Justin McCartney 2017-10-04 09:09:10 UTC
Added pull request for documentation changes: 

https://github.com/apache/jmeter/pull/314
Comment 21 Philippe Mouawad 2017-10-05 20:28:30 UTC
Author: pmouawad
Date: Thu Oct  5 20:28:05 2017
New Revision: 1811257

URL: http://svn.apache.org/viewvc?rev=1811257&view=rev
Log:
Bug 61556 - Clarify in documentation performance impacts of ${} var usage in IfController and groovy
Contributed by  Justin McCartney
This closes #314
Bugzilla Id: 61556

Modified:
    jmeter/trunk/xdocs/changes.xml
    jmeter/trunk/xdocs/usermanual/component_reference.xml
    jmeter/trunk/xdocs/usermanual/functions.xml
Comment 22 Philippe Mouawad 2017-10-05 20:28:53 UTC
Thanks a lot for your PR.