Observation & Question about MQTT Node Timing

General
1

Before you all roll on the floor laughing I know that this observation has little impact in real life, but I wondered why it was happening.

I was re-doing a small flow using a watt2kwhr node attached to an MQTT node and checking the output of that node against the existing flow to make sure I did not mess things up. I noticed that the outputs of the 2 watt2kwhr nodes was not the same - panic.

I then start looking at the output of the MQTT nodes. The msg had a current time attached as it came out of the MQTT node. Using an inject node in place of the MQTT node gave exactly the same number of milliseconds for each of these small flow outputs.

However, with the MQTT nodes providing the input there was a difference between the two of 2 milliseconds. Further investigation showed that this difference became larger the more MQTT nodes there were between node 1 and node 2 (as in, placed on the Flow Tab)

Of course this was noticeable in the output of the watt2kwhr because that node relies on the difference in time between 2 input msgs.

The question is, why does this happen because in computing timing 2 milliseconds is quite a long time?

2

Can you show us your flow - its a little hard to determine from text. Mark where and how the timestamps are generated.

3

Note the data is in msg.data. On my system there is about 10 - 11 milliseconds difference because of the number of MQTT nodes between the two. If I add one node after another that difference drops to 2 milliseconds

[{"id":"31aadcfc53f96ec7","type":"debug","z":"6938459deb189e43","name":"Tester","active":false,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":610,"y":2260,"wires":[]},{"id":"c421576e353fedeb","type":"mqtt in","z":"6938459deb189e43","name":"Smart Socket 01 Status In","topic":"tuya2mqtt/Smart Socket 01/status","qos":"2","datatype":"auto-detect","broker":"ee05e0d9.9118e","nl":false,"rap":true,"rh":0,"inputs":0,"x":150,"y":2260,"wires":[["f8879a5a373ff9a5"]]},{"id":"f8879a5a373ff9a5","type":"change","z":"6938459deb189e43","name":"Tuya Data to Payload","rules":[{"t":"set","p":"data","pt":"msg","to":"$type(payload.data.dps.\"19\") = \"number\" ? {\"voltage\": payload.data.dps.\"20\"  / 10, \"current\": payload.data.dps.\"18\"  / 1000, \"power\": payload.data.dps.\"19\"  / 10, \"last_seen\": $millis()} : 0","tot":"jsonata"},{"t":"set","p":"payload","pt":"msg","to":"data.power","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":420,"y":2260,"wires":[["31aadcfc53f96ec7"]]},{"id":"f17a3325d0a7dab2","type":"mqtt in","z":"6938459deb189e43","name":"Smart Socket 01 Status In","topic":"tuya2mqtt/Smart Socket 01/status","qos":"2","datatype":"auto-detect","broker":"ee05e0d9.9118e","nl":false,"rap":true,"rh":0,"inputs":0,"x":150,"y":2320,"wires":[["e3e9cd2f29690baa"]]},{"id":"d17a3dcf9f8027e2","type":"debug","z":"6938459deb189e43","name":"MQTT In","active":false,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":620,"y":2320,"wires":[]},{"id":"e3e9cd2f29690baa","type":"change","z":"6938459deb189e43","name":"Tuya Data to Payload","rules":[{"t":"set","p":"data","pt":"msg","to":"$type(payload.data.dps.\"19\") = \"number\" ? {\"voltage\": payload.data.dps.\"20\"  / 10, \"current\": payload.data.dps.\"18\"  / 1000, \"power\": payload.data.dps.\"19\"  / 10, \"last_seen\": $millis()} : 0","tot":"jsonata"},{"t":"set","p":"payload","pt":"msg","to":"data.power","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":420,"y":2320,"wires":[["d17a3dcf9f8027e2"]]},{"id":"ee05e0d9.9118e","type":"mqtt-broker","name":"MQTT","broker":"192.168.1.21","port":"1883","clientid":"","autoConnect":true,"usetls":false,"compatmode":false,"protocolVersion":"4","keepalive":"60","cleansession":true,"birthTopic":"","birthQos":"0","birthPayload":"","birthMsg":{},"closeTopic":"","closeQos":"0","closePayload":"","closeMsg":{},"willTopic":"","willQos":"0","willPayload":"","willMsg":{},"userProps":"","sessionExpiry":""}]

The input message is; (although this was just what I was using. The input and the change node can be edited, as long as the change node adds $millis() to a msg property)

{"topic":"tuya2mqtt/Smart Socket 01/status","payload":{"data":{"devId":"6000521040f520dee7f7","dps":{"19":45,"20":2387},"t":1670360383},"deviceId":"6000521040f520dee7f7","deviceName":"Smart Socket 01"},"qos":1,"retain":false,"_msgid":"8a097bf4f19e70f5"}
4

You have not explained what you are timing. A flow including the timing node would have been better.

However, I can guess what is going on When the MQTT nodes receive a message they will both do it at approximately the same time. However, since node red is single threaded they will actually be sent one after the other and will be queued at the second nodes in the sequence, also any other nodes in the flows file that have messages ready to service will have their go. Then one of the Change nodes will do its operation and send on the result. Then the second Change will do its operation and will send on the result, and again any other nodes in the flow that have anything to do will do it (in fact they might get in between the two change nodes. Finally the first debug node will service its message and the second will service its. All this is going on at the same time as any other nodes in the flow file are doing there things, including the timing nodes themselves.

So, to summarise, a message does not flow through the nodes to completion before another message goes through its node, they all happen in parallel.

5

Hi Colin. There is no timing node because I was not actually timing anything, just noting that messages out of the MQTT nodes have delays. I just looked at the last_seen property of the 2 flows.

If both change nodes are connected to the same MQTT node, or an inject node, then the times are exactly the same (even with a more complex change node in one flow).

The explanation you provided is what I assumed (but you know what assuming does), but as I noted, the times are significantly different at computer speeds, so I was not sure.

6

Honestly, 2 ms for a TCP/IP network interaction seems perfectly normal to me.

7

OK, thank you. As I said at the start, it wasn't something I am going to stress over, it was just something I wondered about.

Thank you everyone for your input

8

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.