flow-timer. A simple subflow to measure time taken in parts of your flows.

About flow-timer

flow-timer is a simple subflow to measure (in MS) the time an operation or flow takes. It is designed to be placed inline with a node or flow so as to have minimal impact (i.e. there is no branching & this avoid unnecessary msg cloning)

The main flow is a demo showing the difference in speed when sorting larger datasets in a function node vs JSONata

Usage

It is far harder to describe than do...

Quick instructions...

Drop 2 subflow instances onto the editor and put then before and after the node(s) to measure. Be sure to set the "Measure" names the same on both nodes. Lastly set the first nodes "operation" to "start" & the 2nd nodes "operation" to "stop"

Longer instructions...

• Drop an instance of the flow-timer node inline with your flow (before the node you want to start measurement).
  • Set the flow-timer property "Measure" to some-name (e.g. function1)
  • Set the flow-timer property "Operation" to start
• Drop another instance of the flow-timer node inline with your flow (after the node you want to end measurement).
  • Set the flow-timer property "Measure" to the same value as the 1st subflow (e.g. function1)
  • Set the flow-timer property "Operation" to stop

Subflow properties...

The demo flow...

The results (msg)...

The results (global)...

NOTES

• The results are saved in an object named "flow_timers" in global context
• The subflow uses the servers Date.now() for time measurement (as opposed to process.hrtime) so results will not be super accurate but good enough to gauge performance.

Subflow only...

[{"id":"9a693308.7ebaf","type":"subflow","name":"flow-timer","info":"","category":"","in":[{"x":80,"y":100,"wires":[{"id":"7fc82258.93e36c"}]}],"out":[{"x":440,"y":100,"wires":[{"id":"7fc82258.93e36c","port":0}]}],"env":[{"name":"name","type":"str","value":"measure","ui":{"icon":"font-awesome/fa-tag","label":{"en-US":"Timer Name"},"type":"input","opts":{"types":["str","env"]}}},{"name":"operation","type":"str","value":"start","ui":{"icon":"font-awesome/fa-cog","label":{"en-US":"Operation"},"type":"select","opts":{"opts":[{"l":{"en-US":"start"},"v":"start"},{"l":{"en-US":"stop"},"v":"stop"},{"l":{"en-US":"msg.topic"},"v":"msg.topic"},{"l":{"en-US":"msg.operation"},"v":"msg.operation"},{"l":{"en-US":"msg.payload"},"v":"msg.payload"}]}}}],"meta":{"module":"node-red-contrib-flow-performance","type":"flow-performance","version":"1.0.1","author":"Steve-Mcl","desc":"Inline flow performance measure node","keywords":"node-red performance","license":"MIT"},"color":"#DAEAAA","icon":"node-red/timer.svg","status":{"x":280,"y":160,"wires":[{"id":"7fc82258.93e36c","port":1}]}},{"id":"7fc82258.93e36c","type":"function","z":"9a693308.7ebaf","name":"do operation","func":"// @ts-ignore\nvar name = msg.perfName || env.get(\"name\");\n// @ts-ignore\nvar operation = msg.perfOperation || env.get(\"operation\");\nvar measures = global.get(\"flow_timers\") || {};\nvar measure = measures[name] || {};\n\nfunction doOp(measure, op){\n    if(operation === \"start\"){\n        measure.start = Date.now();//change to process.hrtime\n        measure.stop = null;\n        measure.durationMs = null;\n    } else if(operation === \"stop\") {\n        measure.stop = Date.now();//change to process.hrtime\n        measure.durationMs = measure.start ? measure.stop - measure.start : null;\n        msg._performance = measure;\n    }\n}\n\n\nif(operation === \"start\"){\n    doOp(measure, operation);\n} else if(operation === \"stop\") {\n    doOp(measure, operation);\n    node.send([null, { payload: { text: name + \": \" + measure.durationMs + \"ms\" }}]);\n} else if(operation === \"msg.topic\") {\n    operation = msg.topic;\n    doOp(measure, operation);\n} else if(operation === \"msg.operation\") {\n    operation = msg.operation;\n    doOp(measure, operation);\n} else if(operation === \"msg.payload\") {\n    operation = msg.payload;\n    doOp(measure, operation);\n} else {\n    return [msg, null];\n}\nmeasures[name] = measure;\nglobal.set(\"flow_timers\", measures);\n\nreturn [msg, null];","outputs":2,"noerr":0,"initialize":"","finalize":"","libs":[],"x":250,"y":100,"wires":[[],[]]}]

Copy[{"id":"9a693308.7ebaf","type":"subflow","name":"flow-timer","info":"","category":"","in":[{"x":80,"y":100,"wires":[{"id":"7fc82258.93e36c"}]}],"out":[{"x":440,"y":100,"wires":[{"id":"7fc82258.93e36c","port":0}]}],"env":[{"name":"name","type":"str","value":"measure","ui":{"icon":"font-awesome/fa-tag","label":{"en-US":"Timer Name"},"type":"input","opts":{"types":["str","env"]}}},{"name":"operation","type":"str","value":"start","ui":{"icon":"font-awesome/fa-cog","label":{"en-US":"Operation"},"type":"select","opts":{"opts":[{"l":{"en-US":"start"},"v":"start"},{"l":{"en-US":"stop"},"v":"stop"},{"l":{"en-US":"msg.topic"},"v":"msg.topic"},{"l":{"en-US":"msg.operation"},"v":"msg.operation"},{"l":{"en-US":"msg.payload"},"v":"msg.payload"}]}}}],"meta":{"module":"node-red-contrib-flow-performance","type":"flow-performance","version":"1.0.1","author":"Steve-Mcl","desc":"Inline flow performance measure node","keywords":"node-red performance","license":"MIT"},"color":"#DAEAAA","icon":"node-red/timer.svg","status":{"x":280,"y":160,"wires":[{"id":"7fc82258.93e36c","port":1}]}},{"id":"7fc82258.93e36c","type":"function","z":"9a693308.7ebaf","name":"do operation","func":"// @ts-ignore\nvar name = msg.perfName || env.get(\"name\");\n// @ts-ignore\nvar operation = msg.perfOperation || env.get(\"operation\");\nvar measures = global.get(\"flow_timers\") || {};\nvar measure = measures[name] || {};\n\nfunction doOp(measure, op){\n    if(operation === \"start\"){\n        measure.start = Date.now();//change to process.hrtime\n        measure.stop = null;\n        measure.durationMs = null;\n    } else if(operation === \"stop\") {\n        measure.stop = Date.now();//change to process.hrtime\n        measure.durationMs = measure.start ? measure.stop - measure.start : null;\n        msg._performance = measure;\n    }\n}\n\n\nif(operation === \"start\"){\n    doOp(measure, operation);\n} else if(operation === \"stop\") {\n    doOp(measure, operation);\n    node.send([null, { payload: { text: name + \": \" + measure.durationMs + \"ms\" }}]);\n} else if(operation === \"msg.topic\") {\n    operation = msg.topic;\n    doOp(measure, operation);\n} else if(operation === \"msg.operation\") {\n    operation = msg.operation;\n    doOp(measure, operation);\n} else if(operation === \"msg.payload\") {\n    operation = msg.payload;\n    doOp(measure, operation);\n} else {\n    return [msg, null];\n}\nmeasures[name] = measure;\nglobal.set(\"flow_timers\", measures);\n\nreturn [msg, null];","outputs":2,"noerr":0,"initialize":"","finalize":"","libs":[],"x":250,"y":100,"wires":[[],[]]},{"id":"8fa477b0.2bbac8","type":"inject","z":"df3cdacd.dc9198","name":"function","repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"function","payload":"function","payloadType":"str","x":430,"y":160,"wires":[["bee75a4f.ee4ba8"]]},{"id":"2be583a4.ba884c","type":"debug","z":"df3cdacd.dc9198","name":"","active":false,"tosidebar":true,"console":false,"tostatus":false,"complete":"false","x":930,"y":180,"wires":[]},{"id":"e5ac4683.f614f8","type":"inject","z":"df3cdacd.dc9198","name":"JSONata","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"JSONata","payload":"JSONata","payloadType":"str","x":420,"y":200,"wires":[["bee75a4f.ee4ba8"]]},{"id":"2c44f3c4.ee5efc","type":"switch","z":"df3cdacd.dc9198","name":"","property":"topic","propertyType":"msg","rules":[{"t":"eq","v":"function","vt":"str"},{"t":"eq","v":"JSONata","vt":"str"}],"checkall":"true","repair":false,"outputs":2,"x":590,"y":300,"wires":[["80b9b0b2.1dd84"],["6cb64e4a.f6365"]]},{"id":"90fd90b2.99848","type":"function","z":"df3cdacd.dc9198","name":"Native JS Sort","func":"msg.payload.sort((a,b) => {\n    if(a.age < b.age){\n        return -1;\n    }else if(a.age > b.age){\n        return 1;\n    }else{\n        return 0;\n    }\n})\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":940,"y":260,"wires":[["f6181e74.1732a"]]},{"id":"9b6c9c50.0fd5e","type":"change","z":"df3cdacd.dc9198","name":"JSONata sort","rules":[{"t":"set","p":"payload","pt":"msg","to":"payload^(age)","tot":"jsonata"}],"action":"","property":"","from":"","to":"","reg":false,"x":940,"y":340,"wires":[["617e024.a7ac9fc"]]},{"id":"e6915905.e4b498","type":"comment","z":"df3cdacd.dc9198","name":"measure time it takes for Function node VS JSONata","info":"","x":770,"y":120,"wires":[]},{"id":"bee75a4f.ee4ba8","type":"function","z":"df3cdacd.dc9198","name":"Generate a dataset","func":"var data = [];\n\nfunction randomFloat(min, max) { \n    return Math.random() * (max - min) + min; \n}\nfunction randomInt(min, max) {\n  return Math.floor(Math.random() * (max - min + 1) + min);\n}\nfunction randomBool() {\n  return Math.random() >= 0.5;\n}\n\nvar makeRow = function() {\n    return {\n        \"name\": \"Item \" + (data.length+1),\n        \"gender\": randomBool() == true ? \"male\" : \"female\",\n        \"age\": randomInt(18,75),\n        \"height\": randomInt(18,75),\n        \"lat\": randomFloat(51.0,54.9),\n        \"lon\": randomFloat(-1.8, 1.8),\n        \"friendCount\": randomInt(30,300),\n        \"employmentDuration\": randomFloat(1.0,35.9),\n        \"accessLevel\": randomInt(1,9),\n        \"canEdit\": randomBool(),\n        \"canWrite\": randomBool(),\n        \"dob\": `${randomInt(1930,1999)}-${randomInt(1,12)}-${randomInt(1,28)}`\n    }\n}\n\nfor(let i = 0; i < 1000; i++) {\n    data.push(makeRow());\n}\n\nmsg.payload = data;\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":646,"y":180,"wires":[["2be583a4.ba884c","2c44f3c4.ee5efc"]]},{"id":"80b9b0b2.1dd84","type":"subflow:9a693308.7ebaf","z":"df3cdacd.dc9198","name":"","env":[{"name":"name","value":"function","type":"str"}],"x":760,"y":260,"wires":[["90fd90b2.99848"]]},{"id":"f6181e74.1732a","type":"subflow:9a693308.7ebaf","z":"df3cdacd.dc9198","name":"","env":[{"name":"name","value":"function","type":"str"},{"name":"operation","value":"stop","type":"str"}],"x":1120,"y":260,"wires":[["189d3e26.ffd122"]]},{"id":"6cb64e4a.f6365","type":"subflow:9a693308.7ebaf","z":"df3cdacd.dc9198","name":"","env":[{"name":"name","value":"jsonata","type":"str"}],"x":760,"y":340,"wires":[["9b6c9c50.0fd5e"]]},{"id":"617e024.a7ac9fc","type":"subflow:9a693308.7ebaf","z":"df3cdacd.dc9198","name":"","env":[{"name":"name","value":"jsonata","type":"str"},{"name":"operation","value":"stop","type":"str"}],"x":1120,"y":340,"wires":[["7ce9f7fe.b33ed8"]]},{"id":"7ce9f7fe.b33ed8","type":"debug","z":"df3cdacd.dc9198","name":"JSONata","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":1280,"y":340,"wires":[]},{"id":"189d3e26.ffd122","type":"debug","z":"df3cdacd.dc9198","name":"function","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":1280,"y":260,"wires":[]}]