| Summary: | jmeter GUI hangs when viewing Big JSON body with no space | ||
|---|---|---|---|
| Product: | JMeter - Now in Github | Reporter: | Frederic Girard <youri.andropov> |
| Component: | HTTP | Assignee: | JMeter issues mailing list <issues> |
| Status: | RESOLVED FIXED | ||
| Severity: | major | CC: | p.mouawad |
| Priority: | P2 | ||
| Version: | 5.1.1 | ||
| Target Milestone: | --- | ||
| Hardware: | PC | ||
| OS: | All | ||
| Attachments: |
thread dumps & GC logs
thread dump Test plan to show problems with long lines |
||
|
Description
Frederic Girard
2019-07-30 08:21:01 UTC
(In reply to Frederic Girard from comment #0) > Hello, while doing a simple HTTP test, I notice that jmeter GUI freezes > everytimes. > Jmeter log shows that the test finishes normally, no error reported, but the > GUI is frozen. > > One of these requests' responses is huge (~7 MB), i think that's the reason > of the freeze. I thought it was caused by the "result tree view", but the > GUI hangs even if this listener is disabled. > > When I enable the "save response as MD5 hash", the GUI does not hang, but I > can no more use response assertions... > > FYI, I'm working in GUI mode only while creating/debugging scripts, and I > work with a 768 MB heap. > > Is there any way to prevent this freeze ? Hello, 1/ When does the freeze happen exactly ? 2/ Could you provide the response of 7MB, or confirm what it contains does not contain spaces ? Is it textual ? 3/ When it freezes can you try doing 3 consecutive thread dumps at 5s interval (use jstack) ? 4/ Could you enable verbose gc by removing rem from line 154 of jmeter.bat : rem set VERBOSE_GC=-verbose:gc -Xloggc:gc_jmeter_%%p.log -XX:+PrintGCDetails -XX:+PrintGCCause -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintAdaptiveSizePolicy and provide gc_jmeter_XXX.log generated ? Thank you Created attachment 36691 [details]
thread dumps & GC logs
Philippe, 1) jmeter freezes as soon as the huge response is received 2) Not sure I can provide the full response. It is full text (JSON), and contains many spaces (63336). 3&4) Please see attached file. Note that I usually use IBM J9 SDK, but here I made the thread dumps with the Oracle HotSpot. Same problem happens. GC seems frenetic when the response is received. Not sure G1 GC is appropriate with such big objects : humongous allocations are costly. Maybe CMS is better. Nevertheless, with IBM J9 and gencon strategy, the problem is the same. Regards. It looks like the problem is caused by long log entry.
Frederic, can you please check if `jmeter.log` contains very long lines?
I think JMeter should truncate lines it shows in LoggerPanel.
As of now, the only limit there is "show only 1000 latest messages",
however each message might be big, so it might take time to display 1000 of those.
If we limit individual messages with something like "1000 chars maximum", then it would be much more responsive.
Note: even if we improve LoggerPanel, the logging of those long messages itself take time anyway, so it would be nice to know what is the source of the messages.
Relevant stacktrace is:
"AWT-EventQueue-0" #20 prio=6 os_prio=0 tid=0x000000001b073800 nid=0xe04 waiting on condition [0x000000001c40d000]
java.lang.Thread.State: RUNNABLE
at org.fife.ui.rsyntaxtextarea.DefaultTokenFactory.augmentTokenList(DefaultTokenFactory.java:77)
at org.fife.ui.rsyntaxtextarea.DefaultTokenFactory.createToken(DefaultTokenFactory.java:126)
at org.fife.ui.rsyntaxtextarea.TokenMakerBase.addToken(TokenMakerBase.java:134)
at org.fife.ui.rsyntaxtextarea.modes.PlainTextTokenMaker.addToken(PlainTextTokenMaker.java:268)
at org.fife.ui.rsyntaxtextarea.modes.PlainTextTokenMaker.yylex(PlainTextTokenMaker.java:625)
at org.fife.ui.rsyntaxtextarea.modes.PlainTextTokenMaker.getTokenList(PlainTextTokenMaker.java:338)
at org.fife.ui.rsyntaxtextarea.RSyntaxDocument.getTokenListForLine(RSyntaxDocument.java:431)
at org.fife.ui.rsyntaxtextarea.SyntaxView.getLineWidth(SyntaxView.java:306)
at org.fife.ui.rsyntaxtextarea.SyntaxView.possiblyUpdateLongLine(SyntaxView.java:784)
at org.fife.ui.rsyntaxtextarea.SyntaxView.updateDamage(SyntaxView.java:836)
at org.fife.ui.rsyntaxtextarea.SyntaxView.insertUpdate(SyntaxView.java:490)
at javax.swing.plaf.basic.BasicTextUI$RootView.insertUpdate(BasicTextUI.java:1610)
at javax.swing.plaf.basic.BasicTextUI$UpdateHandler.insertUpdate(BasicTextUI.java:1869)
at javax.swing.text.AbstractDocument.fireInsertUpdate(AbstractDocument.java:201)
at org.fife.ui.rsyntaxtextarea.RSyntaxDocument.fireInsertUpdate(RSyntaxDocument.java:187)
at javax.swing.text.AbstractDocument.handleInsertString(AbstractDocument.java:748)
at javax.swing.text.AbstractDocument.insertString(AbstractDocument.java:707)
at javax.swing.text.PlainDocument.insertString(PlainDocument.java:130)
at javax.swing.text.AbstractDocument.replace(AbstractDocument.java:669)
at javax.swing.text.JTextComponent.setText(JTextComponent.java:1669)
at org.apache.jmeter.gui.LoggerPanel.updateLogEntries(LoggerPanel.java:148)
- locked <0x00000000d0e2d7a8> (a org.apache.jmeter.gui.util.JSyntaxTextArea)
at org.apache.jmeter.gui.LoggerPanel.lambda$initWorker$0(LoggerPanel.java:130)
at org.apache.jmeter.gui.LoggerPanel$$Lambda$57/1973093841.actionPerformed(Unknown Source)
at javax.swing.Timer.fireActionPerformed(Timer.java:313)
Hello Vladimir, Yes it does. As I can't rely on the tree view listener, I'm logging the full response into jmeter log. This response is 7 496 223 bytes long. I have a JSR223 post processor with : log.info "Response=" + new String(prev.getResponseData()) When I disable this loggging, jmeter GUI does not freeze but as soon as I try to check the response in the result tree view, the GUI freezes. >When I disable this loggging, jmeter GUI does not freeze but as soon as I try to check the response in the result tree view, the GUI freezes.
Please comment the logging statement, make GUI freeze and capture a new thread dump
Created attachment 36692 [details]
thread dump
Done. Are there newlines in the JSON data or only normal spaces and tabs? If I remember correctly, rsyntaxtextarea is really problematic on data that has looong lines. You might get away by pretty printing your JSON data in a post processor or by extracting parts of the JSON data. Felix, as you see, it is not "just rsyntaxtextarea"
ViewResultsInTree suffers as well:
"AWT-EventQueue-0" #20 prio=6 os_prio=0 tid=0x000000001b126800 nid=0x13c0 runnable [0x000000001c33c000]
java.lang.Thread.State: RUNNABLE
at javax.swing.text.GapContent.getChars(GapContent.java:213)
at javax.swing.text.AbstractDocument.getText(AbstractDocument.java:810)
at javax.swing.text.WrappedPlainView.loadText(WrappedPlainView.java:309)
at javax.swing.text.WrappedPlainView.calculateBreakPosition(WrappedPlainView.java:235)
at javax.swing.text.WrappedPlainView$WrappedLine.breakLines(WrappedPlainView.java:782)
at javax.swing.text.WrappedPlainView$WrappedLine.getPreferredSpan(WrappedPlainView.java:561)
at javax.swing.text.View.getMinimumSpan(View.java:250)
at javax.swing.text.BoxView.calculateMajorAxisRequirements(BoxView.java:871)
at javax.swing.text.BoxView.checkRequests(BoxView.java:930)
at javax.swing.text.BoxView.setSpanOnAxis(BoxView.java:329)
at javax.swing.text.BoxView.layout(BoxView.java:709)
at javax.swing.text.BoxView.setSize(BoxView.java:397)
at javax.swing.text.WrappedPlainView.setSize(WrappedPlainView.java:388)
at javax.swing.plaf.basic.BasicTextUI$RootView.setSize(BasicTextUI.java:1722)
at javax.swing.plaf.basic.BasicTextUI.getPreferredSize(BasicTextUI.java:912)
at javax.swing.JComponent.getPreferredSize(JComponent.java:1662)
at javax.swing.JEditorPane.getPreferredSize(JEditorPane.java:1333)
at javax.swing.JViewport.getViewSize(JViewport.java:999)
at javax.swing.plaf.basic.BasicScrollPaneUI.syncScrollPaneWithViewport(BasicScrollPaneUI.java:278)
at javax.swing.plaf.basic.BasicScrollPaneUI$Handler.stateChanged(BasicScrollPaneUI.java:1034)
at javax.swing.JViewport.fireStateChanged(JViewport.java:1369)
at javax.swing.JViewport.setView(JViewport.java:969)
at javax.swing.JScrollPane.setViewportView(JScrollPane.java:1007)
at org.apache.jmeter.visualizers.RenderAsText.showTextResponse(RenderAsText.java:38)
at org.apache.jmeter.visualizers.RenderAsText.renderResult(RenderAsText.java:31)
at org.apache.jmeter.visualizers.ViewResultsFullVisualizer.valueChanged(ViewResultsFullVisualizer.java:392)
at org.apache.jmeter.visualizers.ViewResultsFullVisualizer.valueChanged(ViewResultsFullVisualizer.java:365)
at javax.swing.JTree.fireValueChanged(JTree.java:2934)
at javax.swing.JTree$TreeSelectionRedirector.valueChanged(JTree.java:3398)
at javax.swing.tree.DefaultTreeSelectionModel.fireValueChanged(DefaultTreeSelectionModel.java:635)
at javax.swing.tree.DefaultTreeSelectionModel.notifyPathChange(DefaultTreeSelectionModel.java:1093)
at javax.swing.tree.DefaultTreeSelectionModel.setSelectionPaths(DefaultTreeSelectionModel.java:294)
at javax.swing.tree.DefaultTreeSelectionModel.setSelectionPath(DefaultTreeSelectionModel.java:188)
at javax.swing.JTree.setSelectionPath(JTree.java:1641)
at javax.swing.plaf.basic.BasicTreeUI.selectPathForEvent(BasicTreeUI.java:2393)
at javax.swing.plaf.basic.BasicTreeUI$Handler.handleSelection(BasicTreeUI.java:3609)
at javax.swing.plaf.basic.BasicTreeUI$Handler.mousePressed(BasicTreeUI.java:3548)
at java.awt.Component.processMouseEvent(Component.java:6536)
The response is a linearized (single line) JSON with no carriage return, no indenting spaces or tabs. (In reply to Vladimir Sitnikov from comment #10) > Felix, as you see, it is not "just rsyntaxtextarea" > > ViewResultsInTree suffers as well: Right, but it is in the calculation of the width of lines to break them apart, so it would still be helpful to try to pretty print the large json structure (if it shortens the lines), don't you think? > > > "AWT-EventQueue-0" #20 prio=6 os_prio=0 tid=0x000000001b126800 nid=0x13c0 > runnable [0x000000001c33c000] > java.lang.Thread.State: RUNNABLE > at javax.swing.text.GapContent.getChars(GapContent.java:213) > at > javax.swing.text.AbstractDocument.getText(AbstractDocument.java:810) > at > javax.swing.text.WrappedPlainView.loadText(WrappedPlainView.java:309) > at > javax.swing.text.WrappedPlainView.calculateBreakPosition(WrappedPlainView. > java:235) > at > javax.swing.text.WrappedPlainView$WrappedLine.breakLines(WrappedPlainView. > java:782) > > Right, but it is in the calculation of the width of lines to break them apart, so it would still be helpful to try to pretty print the large json structure (if it shortens the lines), don't you think? 1) An option to pretty-print based on the content type makes sense. However it might "defeat" regular expressions because "user-visible" json would be different from the one that came from the network. However I do support the idea of pretty-printing by default 2) Even though we have content type, it is not always right. For instance, they might sent the data as text/plain, and we have very little clue on how to pretty-print. 3) We might want to implement an option to "forcibly add newlines" for lines exceeding N characters. A plus would be to put that newlines in-between word breaks so it won't tear words. That might be a decent workaround. 4) It might be a Java-related issue. For instance, they say https://bugs.openjdk.java.net/browse/JDK-4202291 is fixed in Java 6 So it might be JMeter code is doing something wrong. We might want to analyze what is causing that slowness. For instance, what if we limit "the maximum width" of the textview? Would it influence text wrapping algorithm? (In reply to Vladimir Sitnikov from comment #13) > > Right, but it is in the calculation of the width of lines to break them apart, so it would still be helpful to try to pretty print the large json structure (if it shortens the lines), don't you think? > > 1) An option to pretty-print based on the content type makes sense. However > it might "defeat" regular expressions because "user-visible" json would be > different from the one that came from the network. > However I do support the idea of pretty-printing by default I didn't think about pretty printing by us, but by the user (at least in this case), but we could think about it. > > 2) Even though we have content type, it is not always right. For instance, > they might sent the data as text/plain, and we have very little clue on how > to pretty-print. right. No idea here, we could try to guess the content, but I am pretty sure this would be a bad idea. > > 3) We might want to implement an option to "forcibly add newlines" for lines > exceeding N characters. A plus would be to put that newlines in-between word > breaks so it won't tear words. That might be a decent workaround. As kind of a fallback pretty printer? That could work (with the addition of soft and hard breaks in the case there are no word boundaries) > > 4) It might be a Java-related issue. For instance, they say > https://bugs.openjdk.java.net/browse/JDK-4202291 is fixed in Java 6 > So it might be JMeter code is doing something wrong. We might want to > analyze what is causing that slowness. > For instance, what if we limit "the maximum width" of the textview? Would it > influence text wrapping algorithm? Or the fix has not been implemented or re-surfaced? There is mentioned that adding a newline to the text would be a workaround. @Frederic could you try to add a newline at the end of your data? > I didn't think about pretty printing by us, but by the user Note: pretty printing takes time in production systems, so JMeter can't enforce everybody to pretty-print their data. JavaScript is often minified, and the issue would be very same there. > As kind of a fallback pretty printer? Exactly. It seems to be not that hard to implement, and it would probably solve UI freezes. I'm sure it wouldn't be a good idea to force the pretty print of HTTP responses, because the response report wouldn't be reliable (think about response assertions).
>> @Frederic could you try to add a newline at the end of your data?
Could you please be more specific ? I don't understand what you mean.
Do you want me to add a " + '\r\n' " at the end of my log.info ?
Or do you want me to alter the SampleResult ?
(In reply to Frederic Girard from comment #16) > I'm sure it wouldn't be a good idea to force the pretty print of HTTP > responses, because the response report wouldn't be reliable (think about > response assertions). > > >> @Frederic could you try to add a newline at the end of your data? > > Could you please be more specific ? I don't understand what you mean. > Do you want me to add a " + '\r\n' " at the end of my log.info ? > Or do you want me to alter the SampleResult ? I would like you to try two things. First add the new line to the log.info and second try to re-format the data in a post processor and see, if it helps when you have the view results tree enabled again. Hello, I did both tests. 1) addind a carriage return in the log.info had no effect. 2) I'm using JsonOutput to prettyPrint the json response, and jmeter does not freeze, until I click on the sample in the result tree view. The output is 269246 lines long in jmeter log. Is there any solution to this problem? In my case, the screen freezes even if json is pretty(json format). Because my test is a 400kb value encoded base64 in the data. base54 data is single line. Please help me. Looks like the way out is to make JMeter hard-wrap the long lines. For instance, add an artificial line break after every 10000 chars in the line. It should probably add a warning in the UI that the content has been "wrapped" (== lines added) somehow. WDYT? Yes, that is one possible way. Another would probably be to replace such texts with shortened versions of it. Maybe replacing all but the ten to twenty chars of a long (really long) text with an ellipsis (and maybe an info marker that says: 'has been shortened, click here to reveal all text and suffer')? I'm afraid we can't un-shorten as it is JDK that goes into CPU spin loop trying to layout the glyphs (see https://gist.github.com/luminorena/5871e7b6596cc89ff6aa426ceaa64290#file-gistfile1-txt-L229-L264 ) I thought of replacing the text with the shortened version, before displaying it and a button, that replaces (back) the 'replaced' version of the text. If we really put the original text in that view, the CPU will be spinning, of course.
So both versions would swap the text with a new variant. One version would look for long texts and place CRs in there (s/(\w{100})/\1\n/g) and the other one shortening it (s/\b(\w{20})\w{60,}(\w{20})\b/\1...\2/g). Both would display a warning that the text has been altered. Both could add a button to re-insert the original version and let the CPU spin up.
> let the CPU spin up.
I am afraid it never really end spinning.
We could add a button like "unfold 100 more chars" :)
However, that does not seem to be usable anyway, so the simplest approach of inserting artificial newlines should be sufficient for everybody.
In my experience it will come to an end (it might take a long time to get there, though), but either way, if you want to implement such a workaround, I think our users would thank you. I've created https://github.com/apache/jmeter/pull/694 that should address the issue. It turns out Java's BreakIterator is quite fast when iterating over word and character boundaries. Created attachment 38181 [details]
Test plan to show problems with long lines
The attached test plan generates samples with long lines (with and without spaces).
Without PR 694 I can display the samples with index lower than 15 without a real impact. With PR 694 all samples will display quite fast.
One problem that remains (it is not new), is that the biggest sample is displayed as garbage. But to be fair, this garbage is shown earlier, when PR 694 is not applied.
I've committed the workaround in https://github.com/apache/jmeter/pull/694, so JMeter 5.5+ would add hard wraps when rendering long responses. commit c2f29ccfd1e2619ae2960c96bd54e76e2ba0e03b Author: Felix Schumacher <felix.schumacher@internetallee.de> AuthorDate: Sat Feb 19 19:41:27 2022 +0100 Setup GUI in Swing thread This seems to be the right thing to do and it fixes an exception, that happens on startup after the code for Bug 63620 has been incorporated. The exception was: ERROR o.a.j.g.u.JSyntaxTextArea: Dubious problem while setting text to SOMETHING java.lang.NullPointerException: null at org.fife.ui.rsyntaxtextarea.WrappedSyntaxView.updateMetrics(WrappedSyntaxView.java:1081) ~[rsyntaxtextarea-3.1.3.jar:3.1.3] at org.fife.ui.rsyntaxtextarea.WrappedSyntaxView.getPreferredSpan(WrappedSyntaxView.java:618) ~[rsyntaxtextarea-3.1.3.jar:3.1.3] at org.fife.ui.rsyntaxtextarea.WrappedSyntaxView.calculateBreakPosition(WrappedSyntaxView.java:114) ~[rsyntaxtextarea-3.1.3.jar:3.1.3] at org.fife.ui.rsyntaxtextarea.WrappedSyntaxView$WrappedLine.calculateLineCount(WrappedSyntaxView.java:1191) ~[rsyntaxtextarea-3.1.3.jar:3.1.3] at org.fife.ui.rsyntaxtextarea.WrappedSyntaxView$WrappedLine.handleDocumentEvent(WrappedSyntaxView.java:1440) ~[rsyntaxtextarea-3.1.3.jar:3.1.3] at org.fife.ui.rsyntaxtextarea.WrappedSyntaxView$WrappedLine.insertUpdate(WrappedSyntaxView.java:1464) ~[rsyntaxtextarea-3.1.3.jar:3.1.3] at org.fife.ui.rsyntaxtextarea.WrappedSyntaxView.insertUpdate(WrappedSyntaxView.java:705) ~[rsyntaxtextarea-3.1.3.jar:3.1.3] at javax.swing.plaf.basic.BasicTextUI$RootView.insertUpdate(BasicTextUI.java:1706) ~[?:?] at javax.swing.plaf.basic.BasicTextUI$UpdateHandler.insertUpdate(BasicTextUI.java:1965) ~[?:?] at javax.swing.text.AbstractDocument.fireInsertUpdate(AbstractDocument.java:203) ~[?:?] at org.fife.ui.rsyntaxtextarea.RSyntaxDocument.fireInsertUpdate(RSyntaxDocument.java:187) ~[rsyntaxtextarea-3.1.3.jar:3.1.3] at javax.swing.text.AbstractDocument.handleInsertString(AbstractDocument.java:757) ~[?:?] at javax.swing.text.AbstractDocument.insertString(AbstractDocument.java:716) ~[?:?] at javax.swing.text.PlainDocument.insertString(PlainDocument.java:131) ~[?:?] at javax.swing.text.AbstractDocument.replace(AbstractDocument.java:675) ~[?:?] at javax.swing.text.JTextComponent.setText(JTextComponent.java:1729) ~[?:?] at org.apache.jmeter.gui.util.JSyntaxTextArea.setInitialText(JSyntaxTextArea.java:296) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.testbeans.gui.TextAreaEditor.setValue(TextAreaEditor.java:112) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.testbeans.gui.GenericTestBeanCustomizer.setEditorValue(GenericTestBeanCustomizer.java:479) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.testbeans.gui.GenericTestBeanCustomizer.setObject(GenericTestBeanCustomizer.java:511) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.testbeans.gui.TestBeanGUI.setValues(TestBeanGUI.java:323) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.testbeans.gui.TestBeanGUI.configure(TestBeanGUI.java:307) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.gui.tree.JMeterTreeModel.addComponent(JMeterTreeModel.java:162) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.gui.tree.JMeterTreeModel.addSubTree(JMeterTreeModel.java:131) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.gui.tree.JMeterTreeModel.addSubTree(JMeterTreeModel.java:123) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.gui.GuiPackage.addSubTree(GuiPackage.java:554) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.gui.action.Load.insertLoadedTree(Load.java:199) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.gui.action.Load.insertLoadedTree(Load.java:235) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.JMeter.startGui(JMeter.java:431) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at org.apache.jmeter.JMeter.start(JMeter.java:566) [ApacheJMeter_core.jar:5.5-SNAPSHOT] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:564) ~[?:?] at org.apache.jmeter.NewDriver.main(NewDriver.java:257) Which seemed to happen on the main thread. Part of [Bug 63620] Fix GUI freeze when viewing response body with long lines Bugzilla Id: 63620 --- src/core/src/main/java/org/apache/jmeter/JMeter.java | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) This issue has been migrated to GitHub: https://github.com/apache/jmeter/issues/5128 |