Bug 63442 - Header Manager 'merging in class org.apache.jmeter.testelement.property.CollectionProperty' doesn't scale
Summary: Header Manager 'merging in class org.apache.jmeter.testelement.property.Colle...
Status: RESOLVED INVALID
Alias: None
Product: JMeter
Classification: Unclassified
Component: HTTP (show other bugs)
Version: 5.1.1
Hardware: PC All
: P2 normal (vote)
Target Milestone: JMETER_5.1.1
Assignee: JMeter issues mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-05-15 15:56 UTC by Eric Wolfe
Modified: 2019-05-22 20:56 UTC (History)
2 users (show)



Attachments
Only search once for classes in AccessLogSamperBeanInfo (2.07 KB, patch)
2019-05-15 20:12 UTC, Felix Schumacher
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Eric Wolfe 2019-05-15 15:56:41 UTC
We need to simulate automated third-party systems hitting our public APIs. We don't want wait times between the the calls, because these are not humans that need to think but other computers which don't wait very long between actions. I noticed that the script is taking 3x longer than I would expect from the API call time totals. After studying the debug logging I noticed that 'merging in class ...CollectionProperty' is taking a long time to complete, usually 7 seconds but can be over 10 seconds using -n (CLI). I tried running in GUI mode. With a visualizer attached this operation usually took a few milliseconds (100 or less). Max is about 3 seconds. Without the visualizer in GUI mode 7 seconds seems to be the norm.

Note this behavior is also observed on a Windows Server 2016 build server.
Comment 1 Eric Wolfe 2019-05-15 15:57:24 UTC
working on attaching files...
Comment 2 Philippe Mouawad 2019-05-15 16:03:05 UTC
Hello,
Thanks for report.

I am not sure to understand your report.

1/ Are you saying response times are better in GUI mode vs NON GUI mode ?
2/ How are you measuring those response times for this merge operation ?
3/ Can you give more details on your testing approach ?

Thank you
Comment 3 Eric Wolfe 2019-05-15 19:30:01 UTC
files were too large to attach.

Logs, JTLs and schematic views are located here.  
 https://app.box.com/s/2k1o958g70bxox7cave8i3bm6288ipk5

I don't really care about GUI mode; the concern is that command line run takes too much time.  I mentioned GUI mode trying to provide context on what I tried before opening this ticket up.  

While creating a 'small sample' of the code for this incident I noticed that the class merge took just 1 millisecond in the log file.  

So, for small JMX runs there is no problem.  
However for larger JMX with several components you can see in the log file that the class merge takes 7-8 seconds before every single API call.
Comment 4 Eric Wolfe 2019-05-15 19:41:52 UTC
files were too large to attach.

Logs, JTLs and schematic views are located here.  
 https://app.box.com/s/2k1o958g70bxox7cave8i3bm6288ipk5

I don't really care about GUI mode; the concern is that command line run takes too much time.  I mentioned GUI mode trying to provide context on what I tried before opening this ticket up.  

While creating a 'small sample' of the code for this incident I noticed that the class merge took just 1 millisecond in the log file.  

So, for small JMX runs there is no problem.  
However for larger JMX with several components you can see in the log file that the class merge takes 7-8 seconds before every single API call.
Comment 5 Felix Schumacher 2019-05-15 20:12:59 UTC
Created attachment 36588 [details]
Only search once for classes in AccessLogSamperBeanInfo

I think this comes from the AccessLogSamplerBeanInfo, that is refetching the list of classes for different implementations again and again.

Can you try the attached patch, if it helps your use case? Note I haven't tried it, I will go to sleep now :)
Comment 6 Eric Wolfe 2019-05-16 00:57:38 UTC
I was cloning the repo when I got called for a family problem.  I'm not able to try the patch today.  I'm not a java guy, but I will try to figure out how patch and build tomorrow.  Thank you very much for taking a look so quickly!
Comment 7 Felix Schumacher 2019-05-17 17:01:47 UTC
@Eric did you find time to check?

Author: fschumacher
Date: Fri May 17 17:00:32 2019
New Revision: 1859442

URL: http://svn.apache.org/viewvc?rev=1859442&view=rev
Log:
Reduce scanning for LogParser implementations in AccessLogSamplerBeanInfo.

I am not sure, that it fixes 63442, but it seems nonsense to re-scan all classes
over and over again. The classpath doesn't change that often.

Bugzilla 63442

Modified:
    jmeter/trunk/src/protocol/http/org/apache/jmeter/protocol/http/sampler/AccessLogSamplerBeanInfo.java
    jmeter/trunk/xdocs/changes.xml
Comment 8 Eric Wolfe 2019-05-17 17:56:16 UTC
In between planning meetings yesterday and today I got the latest JDK and ANT, Got eclipse run and built Jmeter locally.  

When I run the tests I get an error complaining about many groovy scripts:

2019-05-17 12:50:23,723 ERROR o.a.j.p.j.s.JSR223Sampler: Problem in JSR223 script [Script] - Generate SubscriberFirstName SubscriberLastName SubscriberLogin, message: javax.script.ScriptException: org.codehaus.groovy.control.MultipleCompilationErrorsException: startup failed:
Script1.groovy: 1: unable to resolve class org.apache.commons.lang.RandomStringUtils
 @ line 1, column 1.
   import org.apache.commons.lang.RandomStringUtils;

I believe this is due to a namespace mismatch as I see everything in the jmeter code is using org.apache.commons.lang3.StringUtils but that is just a guess at this time.  

Changing the scripts to use lang3 caused a different error.  

So I'm thinking of either just replacing the many scripts with hardcodes right now just to test the results as I don't know what the right way to solve this problem is being new to the Java world.
Comment 9 Eric Wolfe 2019-05-17 19:18:04 UTC
The patch did not help:

2019-05-17 14:01:57,158 DEBUG o.a.j.t.p.AbstractProperty: merging in class org.apache.jmeter.testelement.property.CollectionProperty
2019-05-17 14:02:03,468 DEBUG o.a.j.g.GuiPackage: Updating current node View Results Tree
Comment 10 Philippe Mouawad 2019-05-17 19:23:29 UTC
hello,
Would you be able to provide a simple test plan reproducing isseu ?

Thanks
Comment 11 Felix Schumacher 2019-05-17 21:54:57 UTC
And could you take a few thread dumps when the test is between those two log lines?
Comment 12 Eric Wolfe 2019-05-17 21:57:55 UTC
working on a sample - won't have it ready until next week.
Comment 13 Felix Schumacher 2019-05-18 10:17:06 UTC
Can you tell us more about the settings you used? Like the size of JVM heap, the number of threads you used. Which visualizer did you activate/add to make it run faster?

I always look for GC problems when I have unexplainable pauses. Try to enable GC logging and look for full GCs.

If you use Java 11 you can enable the JVM flightrecorder, which might provide useful insight to where the time is spent.
Comment 14 Eric Wolfe 2019-05-22 17:43:47 UTC
I have added a sample.zip to the shared box account.  It has a sample jmx which uses an include controller who only job is to ping Google.  I was able to reproduce the issue using this simple setup.  There is some noise in the log from groovy complaining about something which I couldn't figure out, but the results of the merging in the class were the same.  

I tried some thread dumps following the instructions found here: https://stackoverflow.com/questions/3843461/jmeter-load-test-thread-dump

No luck on the thread dumps.  The only data was 'errorlevel=1'

I was using java 8.  I switched to 12 jdk and reconfirmed the issue.  Then turned on the flight recorder for 60 seconds.  The results are uploaded as sample.jfr.  


Also ran with the line set VERBOSE_GC=-Xlog:gc*,gc+age=trace,gc+heap=debug:file=gc_jmeter_%%p.log in the jmeter.bat uncommented in order to turn on GC logging.  Results are uploaded as gc_jmeter_<XXX>.log files.  

As to your question: "Can you tell us more about the settings you used? Like the size of JVM heap, the number of threads you used. Which visualizer did you activate/add to make it run faster?"

I have no idea what the JVM heap is set to - default.  One thread is running for the group.  When the 'View Result Tree' listener was attached it seemed to run faster.  Not sure that result is reproducible.
Comment 15 Felix Schumacher 2019-05-22 20:16:14 UTC
Could it be, that you misunderstood the scope of the timers in JMeter?

Every timer on the same level as the samplers will be added together. That probably explains, why you observe long sleep intervals.

If you want to add a special timer to one of your samplers, add it as a child to that sampler, or use a Flow Control Action.
Comment 16 Eric Wolfe 2019-05-22 20:56:35 UTC
You nailed it.  Sorry for the rookie mistake. It would have been helpful if the debug logs would have included '200 millisecond wait starting' messages.