apache / jmeter

Apache JMeter open-source load testing tool for analyzing and measuring the performance of a variety of services
https://jmeter.apache.org/
Apache License 2.0
8.42k stars 2.1k forks source link

Suspected memory leak #6309

Open bilsch-nice opened 4 months ago

bilsch-nice commented 4 months ago

Expected behavior

Jmeter script with JSR223 PreProcessor vars.put does not leak memory / classes

Actual behavior

I have a very simple script. Its a single http post with a json body and a dynamic variable ${trace_id}. The value of trace_id is being set in a JR223 PreProcessor as follows:

vars.put("trace_id","${__groovy(org.apache.commons.codec.binary.Hex.encodeHexString('${__RandomString(16,abcdefghijklmnopqrstuvwxy0123456789)}'.getBytes('UTF-8')),)}");

When I run the load test I eventually get an out of memory metaspace error. When I profiled a heap dump I took during ramp-up I see a large number of “org.codehaus.groovy.reflection.ClassInfo” classes. From the eclipse MAT:

The class “org.codehaus.groovy.reflection.ClassInfo”, loaded by “org.apache.jmeter.DynamicClassLoader @ 0x7000393f8”, occupies 1,142,999,600 (78.19%) bytes. 

Thread “java.util.TimerThread @ 0x7000012b0 Timer-0” has a local variable or reference to “org.apache.jmeter.DynamicClassLoader @ 0x7000393f8” which is on the shortest path to “class org.codehaus.groovy.reflection.ClassInfo @ 0x7f6ad7f20”. The thread java.util.TimerThread @ 0x7000012b0 Timer-0 keeps local variables with total size 656 (0.00%) bytes.

The stacktrace of this Thread is available. [See stacktrace](file:///C:/Users/Bill.Schwanitz/AppData/Local/Temp/report5826567611452268886/pages/25.html).

Keywords
org.codehaus.groovy.reflection.ClassInfo
org.apache.jmeter.DynamicClassLoader

I hope these come out ok - this is copy/paste from the MAT report.


Accumulated objects in dominator tree:

Accumulated Objects in Dominator Tree 

Class Name

Shallow Heap

Retained Heap

Percentage

[class org.codehaus.groovy.reflection.ClassInfo @ 0x7f6ad7f20](mat://object/0x7f6ad7f20)
 24 1,142,999,600 78.19% 
+[org.codehaus.groovy.reflection.ClassInfo$GlobalClassSet @ 0x7f6ad88e8](mat://object/0x7f6ad88e8)
 16 1,142,999,504 78.19% 
+[org.codehaus.groovy.util.ManagedConcurrentLinkedQueue @ 0x7f6adab78](mat://object/0x7f6adab78)
 24 72 0.00% 
\Total: 2 entries
 40 1,142,999,576 78.19%

All accumulated objects by class:

Class Name

Objects

Shallow Heap

[org.codehaus.groovy.runtime.metaclass.MetaMethodIndex$Entry](mat://object/0x7016ea528)
[First 10 of 7,171,913 objects](mat://query/list_objects+0x70171d498+0x70171d460+0x70171d428+0x70171d3f0+0x70171d3b8+0x70171d380+0x70171d348+0x70171d310+0x70171d2d8+0x70171d2a0) 7,171,913 401,627,128 
[java.lang.Object[]](mat://object/0x70007d520)
[First 10 of 5,117,122 objects](mat://query/list_objects+0x70171d170+0x70171d108+0x70171d0a0+0x70171e5d8+0x70171d030+0x70171c6c0+0x701718af8+0x70171c690+0x701718a90+0x70171c348) 5,117,122 135,216,720 
[org.codehaus.groovy.util.FastArray](mat://object/0x7f6ad8238)
[First 10 of 5,117,122 objects](mat://query/list_objects+0x7016eaa50+0x70171d158+0x70171d0f0+0x70171d088+0x70171e5c0+0x70171d018+0x70171c6d8+0x701718ae0+0x70171c6a8+0x701718a78) 5,117,122 122,810,928 
[java.util.HashMap$Node](mat://object/0x700c947c0)
[First 10 of 2,674,884 objects](mat://query/list_objects+0x701717e40+0x70170d900+0x70170df58+0x701703b08+0x701701de0+0x701701ee8+0x701745c20+0x701745c00+0x701745500+0x7017454e0) 2,674,884 85,596,288 
[org.codehaus.groovy.util.ComplexKeyHashMap$Entry[]](mat://object/0x7f6ad7e40)
[First 10 of 542,728 objects](mat://query/list_objects+0x701748338+0x7016e8700+0x701747d70+0x701747c00+0x701747b38+0x701747cc8+0x701747f88+0x701747ee0+0x701747e38+0x7016ea3f0) 542,728 78,153,728 
[org.codehaus.groovy.util.SingleKeyHashMap$Entry](mat://object/0x7016ea728)
[First 10 of 1,395,704 objects](mat://query/list_objects+0x7017482f8+0x7017482d8+0x7017482b8+0x701748298+0x701748278+0x701748258+0x701748238+0x7017481d8+0x701748138+0x701748118) 1,395,704 44,662,528 
[java.lang.reflect.Method](mat://object/0x700002f80)
[First 10 of 465,682 objects](mat://query/list_objects+0x7016fddc0+0x7016f9c30+0x7016fe550+0x7016fa7c0+0x7016fe4f8+0x7016fa730+0x7016fe4a0+0x7016fa6d8+0x7016fe3f0+0x7016fa5d8) 465,682 40,980,016 
[org.codehaus.groovy.runtime.metaclass.MetaMethodIndex$Entry[]](mat://object/0x7016ea600)
[First 10 of 38,766 objects](mat://query/list_objects+0x70171d4d0+0x7018a5868+0x702351b28+0x701fea940+0x702407760+0x701ffcd10+0x7022052f8+0x701f53638+0x701f4b148+0x702284c10) 38,766 40,319,712 
[java.util.HashMap$Node[]](mat://object/0x700c94848)
[First 10 of 77,545 objects](mat://query/list_objects+0x701717e60+0x70170d920+0x70170df78+0x701703b28+0x701701e00+0x701701f08+0x701745c40+0x701745520+0x701704958+0x70170da08) 77,545 21,399,224 
[groovy.lang.MetaBeanProperty](mat://object/0x7020be0b8)
[First 10 of 620,285 objects](mat://query/list_objects+0x701747a20+0x7017427b8+0x701742718+0x7017426d8+0x701742648+0x701742608+0x7017425c8+0x701742338+0x701742258+0x701742318) 620,285 19,849,120 
[java.lang.reflect.Field](mat://object/0x700b0bd20)
[First 10 of 232,746 objects](mat://query/list_objects+0x70173ec08+0x70173ddf8+0x70173ebc0+0x70173dd70+0x70173eb30+0x70173dbf0+0x70173eae8+0x70173db68+0x70173eaa0+0x70173dae0) 232,746 16,757,712 
[org.codehaus.groovy.reflection.CachedMethod](mat://object/0x7f6ac2800)
[First 10 of 232,841 objects](mat://query/list_objects+0x701700c40+0x7017011c0+0x701701180+0x701701140+0x7017010c0+0x701701000+0x701700e80+0x701700c80+0x701700b80+0x701700740) 232,841 14,901,824 
[java.lang.reflect.Constructor](mat://object/0x7003b5790)
[First 10 of 155,074 objects](mat://query/list_objects+0x7016ec160+0x7016ebf48+0x7016ec118+0x7016ebee8+0x7016ec0d0+0x7016ebe88+0x7016ec1a8+0x7016ebfb0+0x7016ec040+0x7016ebdb8) 155,074 11,165,328 
[org.codehaus.groovy.util.SingleKeyHashMap](mat://object/0x7020bff18)
[First 10 of 465,196 objects](mat://query/list_objects+0x7016e8638+0x701747d58+0x701747be8+0x701747b20+0x701747cb0+0x701747f70+0x701747ec8+0x701747e20+0x7016ea3d8+0x70173c078) 465,196 11,164,704 
[org.codehaus.groovy.util.ReferenceType$SoftRef](mat://object/0x7f6ac62e0)
[First 10 of 271,416 objects](mat://query/list_objects+0x7017471b8+0x701746998+0x701745d08+0x7017455e8+0x701717ee0+0x70170f2f8+0x70170f3c8+0x70170e038+0x70170d9a0+0x70170e108) 271,416 10,856,640 
[byte[]](mat://object/0x70007c538)
[First 10 of 233,046 objects](mat://query/list_objects+0x70173d760+0x70173cf38+0x70173cdf8+0x7f6bcc960+0x7f6bc12d8+0x7f60d25f8+0x7f5afeb38+0x70173dc50+0x70173d968+0x70173d8e8) 233,046 9,635,384 
[org.codehaus.groovy.util.ManagedReference](mat://object/0x7f6acf0d8)
[First 10 of 271,416 objects](mat://query/list_objects+0x7017471a0+0x701746980+0x701745cf0+0x7017455d0+0x701717ec8+0x70170f2e0+0x70170f3b0+0x70170e020+0x70170d988+0x70170e0f0) 271,416 6,513,984 
[java.lang.String](mat://object/0x700063960)
[First 10 of 233,044 objects](mat://query/list_objects+0x70173d748+0x70173cf20+0x70173cde0+0x7f6bcc948+0x7f6bc12c0+0x7f60d25e0+0x7f5afeb20+0x70173dc38+0x70173d950+0x70173d8d0) 233,044 5,593,056 
[java.util.HashMap](mat://object/0x7001674a0)
[First 10 of 116,316 objects](mat://query/list_objects+0x701717e10+0x70170d8d0+0x701747068+0x701746848+0x70170f220+0x70170e8b8+0x701704020+0x70170df28+0x701703ad8+0x701701cf8) 116,316 5,583,168 
[org.codehaus.groovy.runtime.metaclass.MetaMethodIndex$Header](mat://object/0x7016ea8d8)
[First 10 of 155,063 objects](mat://query/list_objects+0x7016ea9b0+0x7016eaa30+0x7016ea9f0+0x7018a2ee8+0x7018a2fa8+0x7018a2f68+0x7018a2f28+0x702350480+0x702351b08+0x70234fd38) 155,063 4,962,016 
[groovy.lang.MetaClassImpl](mat://object/0x7020bd4f0)
[First 10 of 38,766 objects](mat://query/list_objects+0x7016e8520+0x7018a1af8+0x70234d728+0x701fe6540+0x702403360+0x701ff8910+0x702200ef8+0x701f4f238+0x701f46d48+0x702280810) 38,766 4,341,792 
[java.lang.Class[]](mat://object/0x7000f9c40)
[First 10 of 155,395 objects](mat://query/list_objects+0x7016f9a08+0x7016f9e70+0x7016f87c0+0x7016f77d8+0x7016f7730+0x7016f4f40+0x7016f4d50+0x7016f3e58+0x7016f3cf8+0x7016f3c50) 155,395 3,730,632 
[org.codehaus.groovy.reflection.CachedField](mat://object/0x7020beb30)
[First 10 of 116,373 objects](mat://query/list_objects+0x70173f270+0x70173f250+0x70173f210+0x70173f1f0+0x70173f1d0+0x70173f1b0+0x70173f190+0x70173f170+0x70173f150+0x70173f130) 116,373 3,723,936 
[org.codehaus.groovy.reflection.CachedConstructor](mat://object/0x7016eabf8)
[First 10 of 77,537 objects](mat://query/list_objects+0x7016ed078+0x7016ed058+0x7016ed038+0x7016ed098+0x7016ecff8+0x7016ecfd8+0x7016ed018+0x7018a3130+0x7018a3150+0x70234ce40) 77,537 3,101,480 
[org.codehaus.groovy.reflection.CachedClass](mat://object/0x7f6ac5c88)
[First 10 of 38,781 objects](mat://query/list_objects+0x701717c38+0x70170d6f8+0x701746e90+0x701746670+0x70170f048+0x70170e6e0+0x701703e48+0x70170dd50+0x701703900+0x701701b20) 38,781 2,792,232 
Total: 25 of 57 entries; 32 more
 27,101,310 1,142,999,600

I'll keep the hprof file around. Even compressed its 470 meg or so. If having that heap dump would be beneficial for tracking this down please ask. We can figure out how to get the file to someone.

If I disable the JSR223 PreProcessor there is no memory / class growth - it just runs with bad data.

Steps to reproduce the problem

run a request with JSR223 preprocessor as described in actual behavior

JMeter Version

5.6.3

Java Version

jdk-22.0.1

OS Version

ubuntu server

KingRabbid commented 4 months ago

Hi,

OOM aside, why do you need that complicated piece of code? You run a JSR223PreProcessor so you have full access to Groovy runtime, there's no need to call the ${__groovy()} function inside again.

I guess you need a unique value to use as trace identifier, this should be enough: vars.put("trace_id", UUID.randomUUID().toString()) Sample output: ebd7bca8-c365-3b64-8157-11b165df0341

bilsch-nice commented 4 months ago

Hi,

OOM aside, why do you need that complicated piece of code? You run a JSR223PreProcessor so you have full access to Groovy runtime, there's no need to call the ${__groovy()} function inside again.

I guess you need a unique value to use as trace identifier, this should be enough: vars.put("trace_id", UUID.randomUUID().toString()) Sample output: ebd7bca8-c365-3b64-8157-11b165df0341

The format of the trace_id needs to conform to the opentelemetry spec. Its a 32-byte hex string.

I actually switched over to gatling for this load test script. Generating the traceid in scala code directly and its proven stable so I've moved on from this.

Would be interested in someone else being able to re-create the scenario. If I understand the problem just adding the preprocessor with the code I included in this issue should be enough to replicate - don't even need to reference the variable I suspect.

FSchumacher commented 4 months ago

You should not construct dynamic JSR 223 snippets within your tests, as those will end up in the metaspace.

What you did is, for every sample, you created a new text snippet. That snippet gets compiled into a groovy (class), which ends up in the metaspace.

The templating syntax ${...} should be avoided by all means in (groovy) JSR 223 scripts. Those parts get replaced while JMeter runs the test. As you are generating random text for each call of the sampler, you will get a unique script. Another reason to not use templating inside groovy scripts, is that there is often a faster alternative. For your example, I believe the following snippet would be equivalent:

import org.apache.commons.lang3.RandomStringUtils;

String randomString = RandomStringUtils.randomAlphanumeric(16)
String hexString = randomString.getBytes("UTF-8").encodeHex();

vars.put("trace_id", hexString);

Another possibility would be to work with arguments and place the random bits with the templating syntax into the parameters section of the JSR 223 sampler (or pre-processor).