Serial port data at high rate problem with timestamp

yzerman · 13 March 2023 09:22

Hi, I receive data from the serial port at 50Hz frequency each message. I need to add timestamp to each message, so I do as follow:

msg.timestamp = Date.now()

So the timestamps of the messages needs to be at 20ms each other (because 50Hz frequency), but in the debug console I am receiving inconsistent timestamps as well as equal timestamps that overlaps etc...

Is there a way how to achieve consistent timestamps at 20ms distance each other?

Colin · 13 March 2023 09:42

Can you show us an example of what you are seeing?

Note though, that nodejs is not a realtime system. Occasionally it has to do stuff like memory garbage collection, so to get reliable 20ms sampling you would need a significantly powerful processor. You would probably be better doing the real time stuff in something like an Arduino or other mcu and sending the timestamped data to node-red via mqtt

yzerman · 13 March 2023 10:45

Hi, thanks for your answer. I am using raspberry pi with node-red. I need to read the serial data from external device, so I am using NR. I just need to add a timestamp to each packet from serial. The packets comes at 50Hz. I will make a screenshot of the debug window

yzerman · 13 March 2023 11:40

This is the output from the debug window. The timestamps isn't at 20ms distance each other.

{"timestamp":"1678573635206","P1":1.92,"P2":-0.51,"P3":4.86,"P4":-7.17}
{"timestamp":"1678573635270","P1":1.92,"P2":-0.51,"P3":4.74,"P4":-7.17}
{"timestamp":"1678573635270","P1":1.92,"P2":-0.51,"P3":4.74,"P4":-7.17}
{"timestamp":"1678573635270","P1":1.92,"P2":-0.51,"P3":4.74,"P4":-7.17}
{"timestamp":"1678573635270","P1":1.92,"P2":-0.51,"P3":4.74,"P4":-7.17}
{"timestamp":"1678573635328","P1":1.92,"P2":-0.51,"P3":4.74,"P4":-7.17}

Colin · 13 March 2023 11:44

Can you export the serial node and the nodes after it up to the debug node please?

yzerman · 13 March 2023 12:05

Of course here is the flow:

[
    {
        "id": "b39e02db3febcac7",
        "type": "tab",
        "label": "Flow 5",
        "disabled": false,
        "info": "",
        "env": []
    },
    {
        "id": "afe2a9717e167739",
        "type": "function",
        "z": "b39e02db3febcac7",
        "name": "function 18",
        "func": "let dataArr = msg.payload\nlet timestamp = Date.now()\nlet probeObj = {\n    \"timestamp\":timestamp,\n    \"P1\":dataArr[0],\n    \"P2\":dataArr[1],\n    \"P3\":dataArr[2],\n    \"P4\":dataArr[3]\n}\nmsg.payload = probeObj\nreturn msg;",
        "outputs": 1,
        "noerr": 0,
        "initialize": "",
        "finalize": "",
        "libs": [],
        "x": 430,
        "y": 200,
        "wires": [
            [
                "9dcdf4f625098f97"
            ]
        ]
    },
    {
        "id": "6335ee0f34db9cd0",
        "type": "serial in",
        "z": "b39e02db3febcac7",
        "name": "",
        "serial": "8b47e599abd2db2c",
        "x": 170,
        "y": 200,
        "wires": [
            [
                "afe2a9717e167739"
            ]
        ]
    },
    {
        "id": "9dcdf4f625098f97",
        "type": "msg-speed",
        "z": "b39e02db3febcac7",
        "name": "",
        "frequency": "sec",
        "interval": 1,
        "estimation": false,
        "ignore": false,
        "pauseAtStartup": false,
        "topicDependent": false,
        "x": 650,
        "y": 200,
        "wires": [
            [],
            [
                "2a0df6e570152edc"
            ]
        ]
    },
    {
        "id": "2a0df6e570152edc",
        "type": "debug",
        "z": "b39e02db3febcac7",
        "name": "debug 15",
        "active": true,
        "tosidebar": true,
        "console": false,
        "tostatus": false,
        "complete": "false",
        "statusVal": "",
        "statusType": "auto",
        "x": 840,
        "y": 200,
        "wires": []
    },
    {
        "id": "8b47e599abd2db2c",
        "type": "serial-port",
        "serialport": "/dev/ttyUSB3/",
        "serialbaud": "115200",
        "databits": "8",
        "parity": "none",
        "stopbits": "1",
        "waitfor": "0x80",
        "dtr": "none",
        "rts": "none",
        "cts": "none",
        "dsr": "none",
        "newline": "5",
        "bin": "bin",
        "out": "count",
        "addchar": "",
        "responsetimeout": "10000"
    }
]

Colin · 13 March 2023 12:35

I will have a look shortly. What is the speed node? Is it a contrib node, if so then which? Just in case it is corrupting messages and overlaying data from one onto the next one, disconnect it from the function node and connect the debug node direct to the function node to see what you are getting there. The fact that you see identical timestamps suggests that the message may be getting overwritten.

yzerman · 13 March 2023 14:29

I just put the speed node to measure the rate. Then I deleted it. The debug output is directly to the function

cameo69 · 13 March 2023 14:41

I just quickly ran this and for me it looks good. Probably it is the issue described by @Colin that it is not a realtime environment and if your pi is busy with other things it might become irregular.

Calculated the difference between consecutive timestamps and it looks like this:

You can see that no diff = 0 was recorded (blue numbers for the counter nodes).

The burst function from here (by @JGKK), slightly modified, but very useful for testing:

demo flow (edited, to clear chart before each run):

[{"id":"afe2a9717e167739","type":"function","z":"b39e02db3febcac7","name":"function 18","func":"let dataArr = msg.payload\nlet timestamp = Date.now()\nlet probeObj = {\n    \"timestamp\":timestamp,\n    \"P1\":dataArr[0],\n    \"P2\":dataArr[1],\n    \"P3\":dataArr[2],\n    \"P4\":dataArr[3]\n}\nmsg.payload = probeObj\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":430,"y":200,"wires":[["9dcdf4f625098f97","6996523243997805"]]},{"id":"9dcdf4f625098f97","type":"msg-speed","z":"b39e02db3febcac7","name":"","frequency":"sec","interval":1,"estimation":false,"ignore":false,"pauseAtStartup":false,"topicDependent":false,"x":650,"y":200,"wires":[[],["2a0df6e570152edc"]]},{"id":"2a0df6e570152edc","type":"debug","z":"b39e02db3febcac7","name":"","active":false,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":850,"y":200,"wires":[]},{"id":"88212e65fc6862a8","type":"inject","z":"b39e02db3febcac7","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":220,"y":200,"wires":[["63f795e18b6cfb24","d6c00f0d1c836990"]]},{"id":"8db1084698ed70ff","type":"function","z":"b39e02db3febcac7","name":"burst","func":"var myObj = msg.payload;\nfunction waitSixty () {\n    setTimeout(()=>{\n        flow.set(\"timeout\", false);\n    },10000);\n}\nfunction repeatThirty (variable) {\n    var interval = setInterval(()=>{\n        node.send({payload:variable});\n        var timeout = flow.get(\"timeout\");\n        if (!timeout) { clearInterval(interval) }\n    },20);\n}\nflow.set(\"timeout\",true);\nwaitSixty();\nrepeatThirty(myObj);\nreturn;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":470,"y":260,"wires":[["4085a98fafaf9a0b","afe2a9717e167739"]]},{"id":"4085a98fafaf9a0b","type":"debug","z":"b39e02db3febcac7","name":"","active":false,"tosidebar":true,"console":false,"tostatus":false,"complete":"false","x":630,"y":260,"wires":[]},{"id":"6996523243997805","type":"function","z":"b39e02db3febcac7","name":"calc diff","func":"let ts = msg.payload.timestamp;\nlet lastTS = flow.get('lastTS') || 0;\nflow.set('lastTS', ts);\nlet diff = ts - lastTS;\nif (diff < 10000000000) {\n    msg.payload = diff;\n    return msg;\n}\n","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":660,"y":100,"wires":[["d344787c048eb17f","b54fd4d6c47d83a5","b2c2c61ed6d0c477"]]},{"id":"d344787c048eb17f","type":"ui_chart","z":"b39e02db3febcac7","name":"","group":"8b5cde76.edd58","order":2,"width":0,"height":0,"label":"chart","chartType":"line","legend":"false","xformat":"HH:mm:ss","interpolate":"linear","nodata":"","dot":false,"ymin":"","ymax":"","removeOlder":1,"removeOlderPoints":"","removeOlderUnit":"3600","cutout":0,"useOneColor":false,"useUTC":false,"colors":["#1f77b4","#aec7e8","#ff7f0e","#2ca02c","#98df8a","#d62728","#ff9896","#9467bd","#c5b0d5"],"outputs":1,"useDifferentColor":false,"className":"","x":890,"y":100,"wires":[[]]},{"id":"b54fd4d6c47d83a5","type":"debug","z":"b39e02db3febcac7","name":"","active":false,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":910,"y":60,"wires":[]},{"id":"b2c2c61ed6d0c477","type":"switch","z":"b39e02db3febcac7","name":"","property":"payload","propertyType":"msg","rules":[{"t":"eq","v":"0","vt":"num"},{"t":"else"}],"checkall":"false","repair":false,"outputs":2,"x":890,"y":140,"wires":[["b14466bec234beff"],["a0b79bd3e8916ba8"]]},{"id":"b14466bec234beff","type":"counter","z":"b39e02db3febcac7","name":"counter diff = 0","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":1080,"y":140,"wires":[]},{"id":"a0b79bd3e8916ba8","type":"counter","z":"b39e02db3febcac7","name":"counter else","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":1070,"y":200,"wires":[]},{"id":"63f795e18b6cfb24","type":"delay","z":"b39e02db3febcac7","name":"","pauseType":"delay","timeout":"1","timeoutUnits":"seconds","rate":"1","nbRateUnits":"1","rateUnits":"second","randomFirst":"1","randomLast":"5","randomUnits":"seconds","drop":false,"allowrate":false,"outputs":1,"x":300,"y":260,"wires":[["8db1084698ed70ff"]]},{"id":"d6c00f0d1c836990","type":"change","z":"b39e02db3febcac7","name":"clear chart","rules":[{"t":"set","p":"payload","pt":"msg","to":"[]","tot":"jsonata"},{"t":"set","p":"lastTS","pt":"flow","to":"0","tot":"num"}],"action":"","property":"","from":"","to":"","reg":false,"x":650,"y":40,"wires":[["d344787c048eb17f"]]},{"id":"8b5cde76.edd58","type":"ui_group","name":"","tab":"8f03e639.85956","order":1,"disp":true,"width":"12","collapse":false,"className":""},{"id":"8f03e639.85956","type":"ui_tab","name":"Home","icon":"dashboard","order":4,"disabled":false,"hidden":false}]

Colin · 13 March 2023 15:27

Do you mean the debug you posted is not from the flow you posted?

dceejay · 13 March 2023 15:43

What happens if you use a change node configured to set msg.timestamp to timestamp rather than the function node ? and then debug msg.timestamp
(IE not re-organise the rest of the object)

Next question - what hardware are you running this on ?

yzerman · 13 March 2023 16:10

I will try this. Thanks!

yzerman · 13 March 2023 16:10

Just ignore the speed node please

davidz · 13 March 2023 19:11

As other ppl indicated, Nodejs is asynchronous. You need to handle this issue through software.

If your input message rate is guaranteed at 50Hz by the hardware, then you can do the following:

Get the timestamp of the first message with Date.now(). Use context or flow variable to save the first time stamp.
For each subsequent message, read the saved time stamp from the previous message, simply add 20ms. This is the time stamp for your current message. Save the time stamp again for the next message.

This way, you can guarantee that the messages are separated by 20ms interval.

Background: Our sensor data could arrive in microsecond interval, and we process data this way to guarantee the correct time stamp. We use Microtime() function to get microsecond resolution.

ghayne · 13 March 2023 19:35

This is only the assumed timestamp, not the actual timestamp. This method does not compensate for OS delays.

davidz · 13 March 2023 21:44

This method assumes that the sampling rate is guaranteed, and gets rid of the effect of OS timing uncertainty.

yzerman · 14 March 2023 08:29

Thank you very much for your answer. Unfortunately the rate is not absolutely stable it's 48-52 Hz, randomly in this range. May be to measure the rate each second an update the variable that I will add to each timestamp?

davidz · 16 March 2023 16:43

A stable rate can be ensured with an external hardware buffer that feeds data to the RPI's serial port. If the hardware buffer detects that the serial port is not ready, then the buffer stores the incoming data. When the serial port is ready, then the buffer resumes sending data to the port.

For high speed data rate, the serial in node speed won't be stable no matter how powerful the processor is (because the OS is not real-time). An external hardware buffer is necessary to keep the rate stable.

Colin · 16 March 2023 17:12

I am pretty sure that the port will always be ready. It will accept the data at whatever rate it comes in and buffer it up. It is once it gets into node red that the timing problems arise.

davidz · 17 March 2023 03:29

RPI has a small UART receive hardware buffer, and a larger software buffer provided by the driver. When the buffer is full, then data will be lost.

Sometimes, hardware UART handshaking is used to ensure no data loss (lower the speed automatically when the receiver can not handle the incoming data). But you will have jitter (varying data rate) in this case.

Topic		Replies	Views
Specific Time Interval Data Input Into Database General	7	422	22 March 2021
Node-red-node-serialport not holding custom baud rate General	6	431	15 November 2021
Add milliseconds to timestamp on console logging General	16	2172	17 November 2019
Serial node red raspberry pi/arduino General	1	129	13 January 2024
Factors affecting speed of Node Red. Close to real-time capabilities? General	8	1440	4 December 2020

Serial port data at high rate problem with timestamp

Related Topics