| Summary: | Header Manager 'merging in class org.apache.jmeter.testelement.property.CollectionProperty' doesn't scale | ||
|---|---|---|---|
| Product: | JMeter - Now in Github | Reporter: | Eric Wolfe <eric.wolfe> |
| Component: | HTTP | Assignee: | JMeter issues mailing list <issues> |
| Status: | RESOLVED INVALID | ||
| Severity: | normal | CC: | eric.wolfe, p.mouawad |
| Priority: | P2 | ||
| Version: | 5.1.1 | ||
| Target Milestone: | JMETER_5.1.1 | ||
| Hardware: | PC | ||
| OS: | All | ||
| Attachments: | Only search once for classes in AccessLogSamperBeanInfo | ||
|
Description
Eric Wolfe
2019-05-15 15:56:41 UTC
working on attaching files... 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 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. 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. 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 :)
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! @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 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. 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 hello, Would you be able to provide a simple test plan reproducing isseu ? Thanks And could you take a few thread dumps when the test is between those two log lines? working on a sample - won't have it ready until next week. 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. 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. 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. 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. This issue has been migrated to GitHub: https://github.com/apache/jmeter/issues/5074 |