Add milliseconds to timestamp on console logging

The timestamp provided as part of the Debug node console logging does not include milliseconds, and is not following the ISO format, is there a way to change this ?

Can you clarify which timestamp you mean please. Possibly a screenshot would be useful.

I think they mean this one
image

@T0T4R4 if you do mean the one at the top of the debug message, why do you need that to more precision? Generally it will not be that accurate anyway as it is the time the debug node gets round to displaying it. Depending on the power of your processor that might well be good fractions of a second late. I am not certain but I suspect that is generated in the browser in which case if you look at it on two browsers at the same time they would not even show the same value if shown to milliseconds. I may be wrong on this one though.

As Colin points out - it is added at the browser end when it processes the message so may not be particularly accurate. I guess we could look to make it clickable to cycle through various formats (currently it is in toLocaleString).

Thanks guys. Yes I indeed meant the one showing both on the debugger window and the node-red console. Is there a better logging strategy that you would recommend ?

I think you may need to explain your actual need.

Personally, if I were looking for detailed timing data, I wouldn't use the general log. Instead, I would use a separate log file.

But it really all depends on what you actually want to achieve.

That is exactly my need. Maybe the node-red-contrib-advance-logger plugin could do that...

Is this on your own custom node or is it for your flow in general?

Honestly, trying to time flows down to the millisecond is a waste of time since there are far too many variables. It might sometimes be worth it in your own custom node but it would certainly be the last step.

Don't forget that node.js is not a real-time system.

I have never written any custom node :smiley:
I'm not really meaning real time, but the issue with the current displays is that I have no garantee that logged messages are displayed in the order they are generated.

Actually, you do have a guarantee, especially if you are using Node-RED v1+. It is just that it is more complex than you might like.

You need to understand a little about how JavaScript works in regard to asynchronous programming.

The log messages are output in order, its just that some nodes will do actions async so that the output order might not be what you initially expect. Depending on the action, that order might not be entirely predictable either though that is less common (an async action might take a variable amount of time to complete).

Have a read of Nick's blog post about the changes for NR v1 in regard to execution order.

Possibly a more useful question is what you might be doing that is time dependent and how the flow might be better organised. Feel free to create a new thread on that subject :smiley:

1 Like

Heaps thanks I got it. I just indeed as well updated node from v0.20 to v1.0.1 without passing by the changelog :smiley: yeah i know that's bad...

Would you be able to point me at that blog post ?

2 Likes

Ummm go to the top of the page and click the blog menu item...

Well you do in that the timestamps are added at the point they are written to the sidebar log in the browser - so later arriving messages will always be after earlier ones. And on the browser side they are pulled off the websocket queue in the order they were pushed on at the server side... - so yes it does depend what order they were pushed on - if they come from the same node then they will always be in order - if they come from all over your flow, then the order they appear is the order they were output to the queue.

2 Likes

Thanks heaps guys, it's all clear now.

So can we say that in v1.0 NR schedules the messages a bit like a preemptive scheduler ? (and pre-1.0 is was non-preemptive)

Urm, no, I don't think so.

It isn't about scheduling, it is about JavaScript's intrinsic loop and its method of asynchronous code handling.

JS is not entirely linear, while it is generally single-threaded, it is able to defer actions to subsequent loop executions so that it doesn't have to wait for slow events to complete.

With something as complex as Node-RED, it can be difficult to know whether a node will process anything as async but you can generally assume that anything that might be slow - such as file actions - will be executed as asynchronous tasks.

1 Like