WebSocket Sampler hangs on for 5000ms

[tidus5]

When using this websocket sampler to test a simple echo websocket server, very often the sampler will hangs on for 5000ms.

I created Thread Group with 1 thread, 1 second Ramp-up , Loog Count:300. And I added View Results Tree , Summary Report.

The Summary Report shows: WebSocket Sampler	300	22	4	5005	288.1521990584528	0.0	44.37213429965981	46.42882316780062	0.0	1071.4633333333334
TOTAL	300	22	4	5005	288.1521990584528	0.0	44.37213429965981	46.42882316780062	0.0	1071.4633333333334

the Max time is 5005ms.

In View Results Tree, one sample shows: Thread Name: Thread Group 1-1 Sample Start: 2019-08-13 17:59:44 CST Load time: 5005 Connect Time: 0 Latency: 0 Size in bytes: 1068 Sent bytes:0 Headers size in bytes: 0 Body size in bytes: 1068 Sample Count: 1 Error Count: 0 Data type ("text"|"bin"|""): Response code: 200 Response message:

[Execution Flow]

• Opening new connection
• Using response message pattern ""
• Using disconnect pattern ""
• Waiting for the server connection for 5000 MILLISECONDS
• WebSocket conection has been opened
• Connection established
• Waiting for messages for 20000 MILLISECONDS
• Received frame #1 (12 bytes); matched response pattern
• Received message #2 (4 bytes); matched response pattern
• WebSocket conection has been successfully closed by the server
• WebSocket session closed by the client
• WebSocket client closed by the client

[Variables]

• Message count: 2

[Problems]

SampleResult fields: ContentType: DataEncoding: UTF-8

---

the next sampler shows: Thread Name: Thread Group 1-1 Sample Start: 2019-08-13 17:59:49 CST Load time: 5 Connect Time: 0 Latency: 0 Size in bytes: 1068 Sent bytes:0 Headers size in bytes: 0 Body size in bytes: 1068 Sample Count: 1 Error Count: 0 Data type ("text"|"bin"|""): Response code: 200 Response message:

[Execution Flow]

• Opening new connection
• Using response message pattern ""
• Using disconnect pattern ""
• Waiting for the server connection for 5000 MILLISECONDS
• WebSocket conection has been opened
• Connection established
• Waiting for messages for 20000 MILLISECONDS
• Received frame #1 (12 bytes); matched response pattern
• Received message #2 (4 bytes); matched response pattern
• WebSocket conection has been successfully closed by the server
• WebSocket session closed by the client
• WebSocket client closed by the client

[Variables]

• Message count: 2

[Problems]

SampleResult fields: ContentType: DataEncoding: UTF-8

[tidus5]

Here is the Jmeter log with debug level. It seems that jmeter also got hanged.

2019-08-13 18:06:39,929 DEBUG o.a.j.g.AbstractJMeterGuiComponent: setting element to enabled: true 2019-08-13 18:06:39,929 DEBUG o.a.j.g.GuiPackage: Gui retrieved = org.apache.jmeter.visualizers.SummaryReport[Summary Report,0,0,0x0,invalid,layout=java.awt.BorderLayout,alignmentX=0.0,alignmentY=0.0,border=,flags=9,maximumSize=,minimumSize=,preferredSize=] 2019-08-13 18:06:39,929 DEBUG o.a.j.g.GuiPackage: Updating gui to new node 2019-08-13 18:06:39,934 DEBUG o.a.j.g.GuiPackage: Gui retrieved = org.apache.jmeter.visualizers.SummaryReport[Summary Report,0,0,0x0,invalid,layout=java.awt.BorderLayout,alignmentX=0.0,alignmentY=0.0,border=,flags=9,maximumSize=,minimumSize=,preferredSize=] 2019-08-13 18:06:39,935 DEBUG o.a.j.g.GuiPackage: Updating current node Summary Report 2019-08-13 18:06:39,935 DEBUG o.a.j.g.GuiPackage: Gui retrieved = org.apache.jmeter.visualizers.SummaryReport[Summary Report,0,0,0x0,invalid,layout=java.awt.BorderLayout,alignmentX=0.0,alignmentY=0.0,border=,flags=9,maximumSize=,minimumSize=,preferredSize=] 2019-08-13 18:06:39,935 DEBUG o.a.j.g.AbstractJMeterGuiComponent: setting element to enabled: true 2019-08-13 18:06:39,935 DEBUG o.a.j.g.GuiPackage: Gui retrieved = org.apache.jmeter.visualizers.SummaryReport[Summary Report,0,0,0x0,invalid,layout=java.awt.BorderLayout,alignmentX=0.0,alignmentY=0.0,border=,flags=9,maximumSize=,minimumSize=,preferredSize=] 2019-08-13 18:06:39,935 DEBUG o.a.j.g.GuiPackage: Updating gui to new node 2019-08-13 18:06:40,059 DEBUG o.a.j.v.ViewResultsFullVisualizer: Expanded: [[Root]] 2019-08-13 18:06:40,059 DEBUG o.a.j.v.ViewResultsFullVisualizer: Elements: [Root] 2019-08-13 18:06:44,890 DEBUG o.e.j.i.SelectorManager: Stopped org.eclipse.jetty.io.SelectorManager$ManagedSelector@57dabace keys=0 selected=0 2019-08-13 18:06:44,890 DEBUG o.e.j.u.c.AbstractLifeCycle: STOPPED org.eclipse.jetty.io.SelectorManager$ManagedSelector@57dabace keys=0 selected=0 2019-08-13 18:06:44,890 DEBUG o.e.j.u.c.AbstractLifeCycle: stopping org.eclipse.jetty.io.SelectorManager$ManagedSelector@6b36dc10 keys=0 selected=0 2019-08-13 18:06:44,890 DEBUG o.e.j.i.SelectorManager: Stopping org.eclipse.jetty.io.SelectorManager$ManagedSelector@6b36dc10 keys=0 selected=0 2019-08-13 18:06:44,890 DEBUG o.e.j.i.SelectorManager: Queued change org.eclipse.jetty.io.SelectorManager$ManagedSelector$Stop@1ef67ecf 2019-08-13 18:06:44,890 DEBUG o.e.j.i.SelectorManager: Selector loop woken up from select, 0/0 selected