200 ms delay in MQTT dispatch with Mosquitto vs. Mosca

[ralight]

migrated from Bugzilla #482714
status UNCONFIRMED severity normal in component Mosquitto for 1.4
Reported in version 1.4 on platform PC
Assigned to: Roger Light

On 2015-11-20 12:28:36 -0500, Cefn Hoile wrote:

Greetings and thanks for all your work on Mosquitto as a reference MQTT Websockets server in our work. Any ideas what we can be getting wrong in our build or configuration of Mosquitto to create HUGE delays in dispatch? Had a good go at investigating alternative configurations, but suspect there's something obvious we've missed.

We built 1.4.2 against libwebsockets.so.3.0.0 with only two changes - adding websocket support (WITH_WEBSOCKETS) and removing SRV (WITH_SRV)

However, we're really surprised to see a consistent 200ms delay in sending through Mosquitto versus Mosca which you can see in the logs below. What takes 147 milliseconds for Mosca seems to take 2200 milliseconds for Mosquitto! Of course with QoS2 this doubles.

Comma-separated timestamps are shown with 'absolute', 'relative to the start of the test', and 'relative to the last logged event' in milliseconds. In both cases, the client and server are co-hosted on localhost.

Our test suite has an MQTT.js websockets client which subscribes globally, sends a single message, then each time it gets notified of its last message, it sends the next message in the series, timestamping the events to calculate round trip time. The only difference between the Mosca and Mosquitto test cases are the launchServer and killServer implementations (separate implementation provided for each flavour of server).

You can see the test code for "Can ping back messages to test roundtrip time" at https://gist.github.com/cefn/be716b3099ba2194b473

The mosquitto.conf we are using looks like...

listener 3000 127.0.0.1
protocol websockets

MOSQUITTO Log
1448039685811:0 Connected
1448039686010:199:199 Subscribed
1448039686011:200:1 Sending msg:0
1448039686209:398:198 Received msg:0
1448039686210:399:1 Sending msg:1
1448039686409:598:199 Received msg:1
1448039686409:598:0 Sending msg:2
1448039686608:797:199 Received msg:2
1448039686608:797:0 Sending msg:3
1448039686808:997:200 Received msg:3
1448039686809:998:1 Sending msg:4
1448039687009:1198:200 Received msg:4
1448039687009:1198:0 Sending msg:5
1448039687209:1398:200 Received msg:5
1448039687209:1398:0 Sending msg:6
1448039687410:1599:201 Received msg:6
1448039687410:1599:0 Sending msg:7
1448039687610:1799:200 Received msg:7
1448039687610:1799:0 Sending msg:8
1448039687811:2000:201 Received msg:8
1448039687811:2000:0 Sending msg:9
1448039688012:2201:201 Received msg:9

MOSCA Log
1448039633828:0 Connected
1448039633854:26:26 Subscribed
1448039633854:26:0 Sending msg:0
1448039633873:45:19 Received msg:0
1448039633873:45:0 Sending msg:1
1448039633888:60:15 Received msg:1
1448039633888:60:0 Sending msg:2
1448039633902:74:14 Received msg:2
1448039633902:74:0 Sending msg:3
1448039633910:82:8 Received msg:3
1448039633911:83:1 Sending msg:4
1448039633919:91:8 Received msg:4
1448039633919:91:0 Sending msg:5
1448039633930:102:11 Received msg:5
1448039633930:102:0 Sending msg:6
1448039633942:114:12 Received msg:6
1448039633942:114:0 Sending msg:7
1448039633954:126:12 Received msg:7
1448039633954:126:0 Sending msg:8
1448039633966:138:12 Received msg:8
1448039633966:138:0 Sending msg:9
1448039633975:147:9 Received msg:9

Hope this test case is digestible and happy to investigate by running further diagnostics following your guidance if you have the time to look into it.

Thanks,

Cefn

[ralight]

Fixed in 1.4.13.