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 Installing plugin #1 (12 bytes); matched response pattern
• Received message Hi, does the websocket sampler need to be configured with the webserver and port details? #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 Installing plugin #1 (12 bytes); matched response pattern
• Received message Hi, does the websocket sampler need to be configured with the webserver and port details? #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