Serial port data at high rate problem with timestamp

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?

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

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

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}

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

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"
    }
]

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.

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

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}]

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

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 ?

I will try this. Thanks!

Just ignore the speed node please

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:

  1. Get the timestamp of the first message with Date.now(). Use context or flow variable to save the first time stamp.

  2. 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.

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

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

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?

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.

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.

1 Like

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.