[ANNOUNCE] node-red-contrib-msg-profiler: 1.0.0 beta

Share Your Nodes
1

Hi folks,

Last week I had somewhere a delay in my flow, but I was not sure which of my nodes was causing that. Could have found it by adding a bunch of debug nodes, or other workarounds. But lately in my daily job I have to work with some expensive performance tools, so I wanted to have a tool in Node-RED that could offer a root cause analysis in an easy way.

So I posted my question, to ask whether something like that existed already. And although the solution from @Steve-Mcl is a very clever one, I decide to develop my own node. One of the main reasons for this decision, is that I have not played yet with the Node-RED messaging hooks. And I have to admit that this is some nice stuff!

So the first 1.0.0 beta of my node-red-contrib-msg-profiler is now available on Github :champagne: :clinking_glasses: :partying_face:

It allows you to trace messages through your flow, and collect timing information for each node where the msg passes through:

image

You can use this node "inline", to start profiling of messages passing through. But you can also select which other nodes you want to start the profiling/tracking. I have copied the latter functionality from the Catch node, so all credits for that feature go to Nick!

Here is a demo that shows how to select which node should initiate tracing on messages that pass through them:

msg_profiling_demo

As always, all 'constructive' feedback is very welcome!!

Have fun with it,
Bart

P.S. I can really advise other Node-RED contributors to start playing with hooks. Those hooks can offer us lots of very useful information, e.g. for troubleshooting...

13 Likes
2

Good stuff Bart.

Although, as often happens, it's the type of feature I would have loved to have had a discussion about first. To give us a chance to see if this effort could have been diverted into the tools we already have, such as the Debugger.

But that aside, no doubt this will be useful.

2 Likes
3

Hey Nick,
Yes indeed I also thought this would be a nice feature for the debugger. As you can see in my original question I wrote: "via the flow debugger perhaps". But to be clear: I don't expect anybody here to read all millions of questions that are posted every day! And you meanwhile know that my nature keeps preventing me from mentioning people :wink:

Anyway, let's just use this node as an experiment. We discuss about it with the community, add new features, and so on ...
And at the end, we can learn from the real life experiences of our users. See which features are really useful, which could have been implemented better in another way, which features are useles, ...

And if this feature ever gets integrated e.g. into the debugger, then I simply put on my readme that my node has become obsolete and people should use the debugger instead.

At least now I finally had a good reason to start playing with the hooks, and hopefully others get ideas in that direction also. Those hooks can collect a real treasure of information :+1:.

3 Likes
4

It would be handy if the output format included the name of the node, and if it was in a structure amenable for conversion to a (bar) chart node for example ..

1 Like
5

Thanks @dceejay for the good feedback!
Had a quick look now, but I don't see the node name at first sight:

image

Any tips? Then I will add it tonight.
Perhaps I should also include the node type? So people can filter out some node types afterwards if they are not interested in some nodes. Although of course the percentages would have to be recalculated in that case...

A bar chart. I like it!
But do you mean separate arrays (labels, values) instead of 1 array with objects?

6

actually ... I do...

It would happen quicker if you helped write that code instead...

Does the selected node shown actually have the name field set to a value ?

7

Now I need a helping hand... What is the best way to get started with such a big feature integration? That I have a look at the debugger, and I create my own proposal of how I would do it. And that I discuss that proposal first on Discourse, and only afterwards in a discussion on Github designs? Or is there perhaps already an existing list of ideas somewhere, from which I should start?
Please don't tell me that I need to join Slack, because I have a real bad relationship with that tool :wink:

1 Like
8

As soon as I find some spare time, I will try to contribute this functionality somehow to the core (e.g. the Node-RED debugger). But meanwhile I have to continue with my personal home automation project. The lady of the house wants better video surveillance, so I really needed such a msg profiler to quickly find bottlenecks in the new nodes that I am developing.

Anyway got great feedback so far, that I can use without doubts for my own project during the christmas holidays. So I have quickly implemented the feedback:

  • The output now contains also the node names, which is much more human readable compared to the node identifiers:

    image

  • The node types have been added to the output, so I can easily filter out node types that are of no interest to me...

  • I have added a new section on the readme page about how you can easily visualize the profiling results in a bar chart and a pie chart:

    image
    image702Ă—337 21.4 KB

If anybody has other nice feature requests, don't hesitate to share it here!

Thanks to Dave's idea of these charts, this node is now mature enough for me to help with my camera related developments. So I am back on track after this unplanned sidetrack of my main Node-RED project :wink:

2 Likes
9

  1. I tried this morning my node for the first time on my camera flow, and it was within a few seconds clear in which node my performance bottleneck was located:

    image

    Seems that one of my new (video surveillance related) nodes is not ready for production yet :wink:
    I just love this kind of monitoring tools :partying_face: :clinking_glasses: :champagne:

  2. But there is still an issue, because some of my nodes have multiple send events for a single output message :frowning_face:. Don't see immediately a bug in my code. Will need to investigate further tonight.

  3. I have now also added a section about using line charts on my readme page. That way you can easily see timing variations over time. In the provided example flow you see for example that a timer in NodeJs isn't always executed at exactly the same interval (which is not obvious for some users):

    profiling_a_timer

  4. And I have also added a section on the readme, about using a profile to have live monitoring of the performance of your Node-RED system. And trigger alerts if a performance bottleneck is occuring:

    image

As mentioned before: don't hesitate to provide some feedback here (about use cases, and so on...). That is the only way we can learn which features are needed. Then we can determine more easily afterwards how to fit this kind of stuff e.g. in the Node-RED debugger, or somewhere else perhaps... I would like to learn for example how this kind of stuff would fit into a sidebar, like the Node-RED editor...

Now back to the familly stuff...
Have a nice weekend !!!

2 Likes
10

Hmmm, this was an annoying bug to troubleshoot. Because you arrive in the hooks handler code for every message that passes by. The troubles were caused by nodes with multiple outputs, and nodes with multiple wires on their output. Because when the message is not being cloned, the same message instance arrives N times. So I had to avoid storing N duplicate events sequentially in the trace.

I have fixed this on Github and it seems to me that it is solved now:

  1. Tracing of a flow with multiple wires connected to a single output:

    image

    [{"id":"1d8b715f721d6fed","type":"function","z":"dd961d75822d1f62","name":"Node A","func":"setTimeout(function() {\n    node.send(msg);\n}, 500)","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":480,"y":1580,"wires":[["b40c7ffe9b98c220"]]},{"id":"51c0e723aef7652d","type":"inject","z":"dd961d75822d1f62","name":"Inject message","props":[{"p":"payload"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"Hello timer","payloadType":"str","x":140,"y":1580,"wires":[["821a8a029655639f"]]},{"id":"821a8a029655639f","type":"msg-time-profiler","z":"dd961d75822d1f62","inputField":"topic","outputField":"_msgtracing","profileMode":"inline","autoStart":true,"outputs":1,"name":"","x":310,"y":1580,"wires":[["1d8b715f721d6fed","ce0c0139dbeeea58"]]},{"id":"de0b0f503f12baa9","type":"comment","z":"dd961d75822d1f62","name":"500 msec","info":"","x":480,"y":1540,"wires":[]},{"id":"b3081b851780b60f","type":"comment","z":"dd961d75822d1f62","name":"1000 msec","info":"","x":480,"y":1640,"wires":[]},{"id":"b40c7ffe9b98c220","type":"debug","z":"dd961d75822d1f62","name":"Chain completed","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":690,"y":1580,"wires":[]},{"id":"ce0c0139dbeeea58","type":"function","z":"dd961d75822d1f62","name":"Node B","func":"setTimeout(function() {\n    node.send(msg);\n}, 1000)","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":480,"y":1680,"wires":[["b40c7ffe9b98c220"]]}]

    Results in two ouput messages, each with their own trace:

    image

  2. Tracing of a flow with multiple outputs:

    image
    image738Ă—146 10.8 KB

    [{"id":"c6f324e54dd2c2cd","type":"function","z":"dd961d75822d1f62","name":"Node B","func":"setTimeout(function() {\n    node.send(msg);\n}, 500)","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":660,"y":1820,"wires":[["5930dbaf7155a20d"]]},{"id":"591d671e4248dc27","type":"inject","z":"dd961d75822d1f62","name":"Inject message","props":[{"p":"payload"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"Hello timer","payloadType":"str","x":140,"y":1860,"wires":[["2bc61eff6e739891"]]},{"id":"2bc61eff6e739891","type":"msg-time-profiler","z":"dd961d75822d1f62","inputField":"topic","outputField":"_msgtracing","profileMode":"inline","autoStart":true,"outputs":1,"name":"","x":310,"y":1860,"wires":[["4763479df3e21952"]]},{"id":"8bb2caa2c63cf485","type":"comment","z":"dd961d75822d1f62","name":"500 msec","info":"","x":660,"y":1780,"wires":[]},{"id":"252c643e4c9a1041","type":"comment","z":"dd961d75822d1f62","name":"1000 msec","info":"","x":660,"y":1880,"wires":[]},{"id":"5930dbaf7155a20d","type":"debug","z":"dd961d75822d1f62","name":"Chain completed","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":870,"y":1860,"wires":[]},{"id":"488bcdbec480ee33","type":"function","z":"dd961d75822d1f62","name":"Node C","func":"setTimeout(function() {\n    node.send(msg);\n}, 1000)","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":660,"y":1920,"wires":[["5930dbaf7155a20d"]]},{"id":"4763479df3e21952","type":"function","z":"dd961d75822d1f62","name":"Node A","func":"setTimeout(function() {\n    node.send([msg, msg]);\n}, 200)","outputs":2,"noerr":0,"initialize":"","finalize":"","libs":[],"x":480,"y":1860,"wires":[["c6f324e54dd2c2cd"],["488bcdbec480ee33"]]},{"id":"8fd8524291af6940","type":"comment","z":"dd961d75822d1f62","name":"200 msec","info":"","x":480,"y":1820,"wires":[]}]

    Which again results in two output messages, each with their own trace:

    image

And after fixing this, I can now see immediately which of my new experimental nodes is too slow:

image

So I am not aware of any other issues at the moment...

Would be nice if some folks could start testing this node, and share their feedback!

11

Such a profiler is also very useful to solve certain discussions on Discourse. For example people that ask whether there is a dramatic performance difference between e.g. setting the payload value:

  • Via Javascript code
  • Via a Change node

Well you can create a simple test flow, and share that in the discussion. For example:

image
image968Ă—338 18.6 KB 

[{"id":"ab0390c5559b6a04","type":"function","z":"dd961d75822d1f62","name":"msg.payload = \"test1\"","func":"msg.payload = \"test1\";\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":640,"y":2180,"wires":[["317e073a12af4a5a"]]},{"id":"c7f153d4a5c6901b","type":"inject","z":"dd961d75822d1f62","name":"Inject message","props":[{"p":"payload"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"Hello timer","payloadType":"str","x":280,"y":2180,"wires":[["3c41739798bfb3ea"]]},{"id":"3c41739798bfb3ea","type":"msg-time-profiler","z":"dd961d75822d1f62","inputField":"topic","outputField":"_msgtracing","profileMode":"inline","autoStart":true,"outputs":1,"name":"","x":450,"y":2180,"wires":[["ab0390c5559b6a04"]]},{"id":"ceb8c364016af1cb","type":"debug","z":"dd961d75822d1f62","name":"Chain completed","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":1130,"y":2180,"wires":[]},{"id":"317e073a12af4a5a","type":"change","z":"dd961d75822d1f62","name":"msg.payload = \"test2\"","rules":[{"t":"set","p":"payload","pt":"msg","to":"test2","tot":"str"}],"action":"","property":"","from":"","to":"","reg":false,"x":890,"y":2180,"wires":[["ceb8c364016af1cb"]]}]

And then they can see by themselves very easily which one of both is faster:

image

In this case the numbers (in millisecs) are rather similar in duration.

And such small values are neglectable, unless you have a very high data rate of course ...

2 Likes
12

...and many discussions about the speed of jsonata

1 Like
13

Thank you for making this. I had been using a simple function node containing

// input should contain msg.time as a timestamp
const x = new Date();
msg.payload = x.getTime();
msg.cost = msg.payload - msg.time;
return { "cost": msg.cost };

but this looks way better.

1 Like