{"action":"created","issue":{"url":"https://api.github.com/repos/eclipse/mosquitto/issues/433","repository_url":"https://api.github.com/repos/eclipse/mosquitto","labels_url":"https://api.github.com/repos/eclipse/mosquitto/issues/433/labels{/name}","comments_url":"https://api.github.com/repos/eclipse/mosquitto/issues/433/comments","events_url":"https://api.github.com/repos/eclipse/mosquitto/issues/433/events","html_url":"https://github.com/eclipse/mosquitto/issues/433","id":225463870,"number":433,"title":"High latency (~40 ms) when sending successive messages in a row - missing TCP_NODELAY","user":{"login":"verybadsoldier","id":364469,"avatar_url":"https://avatars3.githubusercontent.com/u/364469?v=4","gravatar_id":"","url":"https://api.github.com/users/verybadsoldier","html_url":"https://github.com/verybadsoldier","followers_url":"https://api.github.com/users/verybadsoldier/followers","following_url":"https://api.github.com/users/verybadsoldier/following{/other_user}","gists_url":"https://api.github.com/users/verybadsoldier/gists{/gist_id}","starred_url":"https://api.github.com/users/verybadsoldier/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/verybadsoldier/subscriptions","organizations_url":"https://api.github.com/users/verybadsoldier/orgs","repos_url":"https://api.github.com/users/verybadsoldier/repos","events_url":"https://api.github.com/users/verybadsoldier/events{/privacy}","received_events_url":"https://api.github.com/users/verybadsoldier/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":19,"created_at":"2017-05-01T16:14:16Z","updated_at":"2018-02-14T23:56:30Z","closed_at":null,"author_association":"NONE","body":"I am experiencing quite a high latency when sending two messages in a row (~40 ms). The client receives the first message near instantly but the second message is delayed in the broker. A single message is fine. This behavior is 100% reproducible for me.\r\nI tried several things to figure where the delay happens. I hope I am not barking up the wrong tree here. I did the same test with emqttd and there is no delay at all.\r\n\r\n**Setup:**\r\n* Broker mosquitto 1.4.8 at `192.168.2.33` on Ubuntu 16.04.2 LTS in a VM hosted on Windows 10 on an Intel i5.\r\n* Client 1 `192.168.2.230` MQTT.fx 1.3.1 on Windows 10\r\n* Client 2 `192.168.2.36` Ubuntu using mosquitto_pub\r\n* Client 1 subscribed to topic `latency`, Client 2 publishes messages to topic `latency`\r\n\r\nThis is how the network traffic does look in ngrep when publishing two successive messages to one topic:\r\n```\r\nT 2017/05/01 17:20:34.695801 192.168.2.36:42932 -> 192.168.2.33:1883 [AP]\r\n  0...latency1\r\nT 2017/05/01 17:20:34.695843 192.168.2.33:1883 -> 192.168.2.230:5747 [AP]\r\n  0...latency1\r\nT 2017/05/01 17:20:34.699322 192.168.2.36:42934 -> 192.168.2.33:1883 [AP]\r\n  0...latency2\r\nT 2017/05/01 17:20:34.736158 192.168.2.33:1883 -> 192.168.2.230:5747 [AP]\r\n  0...latency2\r\n```\r\nSo the message `latency1` published by client 192.168.2.36 arrives at the broker at `17:20:34.695801` and is published to client 192.168.2.230 `17:20:34.695843`. So only 42 us later.\r\nThen message `latency2` comes in at `17:20:34.699322` but this time the broker publishes it at `17:20:34.736158` to the client. **So ~35 ms later**. I would expect the same low latency as for the first message.\r\n\r\nI think that message2 is held back within the broker machine until the TCP-ACK packet for message1 is received, which is quite strange IMO.\r\n\r\nI am reproducing this as follows:\r\n\r\n\r\n1. On Client 2: Publish two messages in a row to one topic\r\n`mosquitto_pub -h 192.168.2.33 -t latency -m 1; mosquitto_pub -h 192.168.2.33 -t latency -m 2`\r\n2. On the broker machine (192.168.2.33) I am using ngrep to see timestamps for incoming and outgoing messages:\r\n`ngrep latency -q -t`\r\n3. ngrep output is (as seen above):\r\n```\r\nT 2017/05/01 17:20:34.695801 192.168.2.36:42932 -> 192.168.2.33:1883 [AP]\r\n  0...latency1\r\nT 2017/05/01 17:20:34.695843 192.168.2.33:1883 -> 192.168.2.230:5747 [AP]\r\n  0...latency1\r\nT 2017/05/01 17:20:34.699322 192.168.2.36:42934 -> 192.168.2.33:1883 [AP]\r\n  0...latency2\r\nT 2017/05/01 17:20:34.736158 192.168.2.33:1883 -> 192.168.2.230:5747 [AP]\r\n  0...latency2\r\n```\r\n---\r\nI can see using `strace` with command `sudo strace -p 80684 -e read,write -r`that the process mosquitto is writing the network message to the socket as soon as it read the message from the incoming socket:\r\n```\r\nstrace: Process 80684 attached\r\n     0.000000 read(11, \"sendmail: all\\n# /etc/hosts.allow\"..., 4096) = 425\r\n     0.000112 read(11, \"\", 4096)        = 0\r\n     0.000114 read(11, \"# /etc/hosts.deny: list of hosts\"..., 4096) = 711\r\n     0.000038 read(11, \"\", 4096)        = 0\r\n     0.000176 read(10, \"\\20\", 1)        = 1\r\n     0.000039 read(10, \"\\\"\", 1)         = 1\r\n     0.000033 read(10, \"\\0\\6MQIsdp\\3\\2\\0<\\0\\24mosqpub/10847-ubun\"..., 34) = 34\r\n     0.000074 write(3, \"1493653233: Sending CONNACK to m\"..., 59) = 59\r\n     0.000059 write(10, \" \\2\\0\\0\", 4)   = 4\r\n     0.000752 read(10, \"0\", 1)          = 1\r\n     0.000117 read(10, \"\\n\", 1)         = 1\r\n     0.000207 read(10, \"\\0\\7latency1\", 10) = 10\r\n     0.000143 write(9, \"0\\n\\0\\7latency1\", 12) = 12\r\n     0.000199 read(10, \"\\340\", 1)       = 1\r\n     0.000051 read(10, \"\\0\", 1)         = 1\r\n     0.003352 read(11, \"sendmail: all\\n# /etc/hosts.allow\"..., 4096) = 425\r\n     0.000108 read(11, \"\", 4096)        = 0\r\n     0.000540 read(11, \"# /etc/hosts.deny: list of hosts\"..., 4096) = 711\r\n     0.000236 read(11, \"\", 4096)        = 0\r\n     0.000592 read(10, \"\\20\", 1)        = 1\r\n     0.000157 read(10, \"\\\"\", 1)         = 1\r\n     0.000165 read(10, \"\\0\\6MQIsdp\\3\\2\\0<\\0\\24mosqpub/10848-ubun\"..., 34) = 34\r\n     0.000080 write(10, \" \\2\\0\\0\", 4)   = 4\r\n     0.000786 read(10, \"0\", 1)          = 1\r\n     0.000195 read(10, \"\\n\", 1)         = 1\r\n     0.000181 read(10, \"\\0\\7latency2\", 10) = 10\r\n     0.000080 write(9, \"0\\n\\0\\7latency2\", 12) = 12\r\n     0.000445 read(10, \"\\340\", 1)       = 1\r\n     0.000103 read(10, \"\\0\", 1)         = 1\r\n     0.164655 read(8, \"1\", 1)           = 1\r\n     0.000078 read(8, \"&\", 1)           = 1\r\n     0.000066 read(8, \"\\0\\35home/rgbww_a020a61624ea/clock1\"..., 38) = 38\r\n```\r\n\r\nThe lines in question:\r\n```\r\n     0.000207 read(10, \"\\0\\7latency1\", 10) = 10\r\n     0.000143 write(9, \"0\\n\\0\\7latency1\", 12) = 12\r\n```\r\nand\r\n```\r\n     0.000181 read(10, \"\\0\\7latency2\", 10) = 10\r\n     0.000080 write(9, \"0\\n\\0\\7latency2\", 12) = 12\r\n```\r\n\r\nOnly a few microseconds between reading and writing the data which seems great.\r\n\r\n---\r\nBut when using Wireshark to analyze whats happening on the TCP stack we can see that message1 arrives at the broker and gets published to client2 very quickly. Then message2 arrives but it is not published to client2 immediately. It only gets published right after the ACK packet from client2 for message1 arrives at the broker:\r\n![image](https://cloud.githubusercontent.com/assets/364469/25585005/c02cbfa8-2e98-11e7-85d2-07e0faa52af9.png)\r\n\r\n---\r\nSo is this an expected behavior with mosquitto? For me it seems like Linux TCP stack is holding the second packet back which would not be a mosquitto issue then, but as I said when I try with emqttd then everything is fine.\r\n"},"comment":{"url":"https://api.github.com/repos/eclipse/mosquitto/issues/comments/365784759","html_url":"https://github.com/eclipse/mosquitto/issues/433#issuecomment-365784759","issue_url":"https://api.github.com/repos/eclipse/mosquitto/issues/433","id":365784759,"user":{"login":"mschwartz","id":329637,"avatar_url":"https://avatars1.githubusercontent.com/u/329637?v=4","gravatar_id":"","url":"https://api.github.com/users/mschwartz","html_url":"https://github.com/mschwartz","followers_url":"https://api.github.com/users/mschwartz/followers","following_url":"https://api.github.com/users/mschwartz/following{/other_user}","gists_url":"https://api.github.com/users/mschwartz/gists{/gist_id}","starred_url":"https://api.github.com/users/mschwartz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mschwartz/subscriptions","organizations_url":"https://api.github.com/users/mschwartz/orgs","repos_url":"https://api.github.com/users/mschwartz/repos","events_url":"https://api.github.com/users/mschwartz/events{/privacy}","received_events_url":"https://api.github.com/users/mschwartz/received_events","type":"User","site_admin":false},"created_at":"2018-02-14T23:56:30Z","updated_at":"2018-02-14T23:56:30Z","author_association":"NONE","body":"I like the code in your last commit!\r\n"}}
{"actor":{"display_login":"mschwartz"}}