Event loop blocking doubles exactly 2x each round until the add-on gets killed — what mechanism could do this?

I have a Node-RED instance that freezes several times a day. I instrumented the event loop and found something I can't explain: the blocking duration doubles almost exactly each round, reproducibly, across 12 independent cycles over two days.

I'm hoping someone here recognises the pattern, or can point me at a way to find which node is holding the loop.


The measurement

Added this to settings.js, above module.exports. It fires a 1-second timer and reports how late it actually ran — i.e. how long the event loop was blocked:

let __lagLast = Date.now();
setInterval(() => {
  const now = Date.now();
  const drift = now - __lagLast - 1000;
  if (drift > 30) {
    console.warn(`[lag] blocked ${drift}ms`);
  }
  __lagLast = now;
}, 1000);

Plus a memory sampler every 10 minutes:

setInterval(() => {
  const m = process.memoryUsage();
  const mb = (v) => (v / 1048576).toFixed(0);
  console.log(`[mem] rss=${mb(m.rss)}MB heap=${mb(m.heapUsed)}/${mb(m.heapTotal)}MB`);
}, 600000);

The pattern

Every cycle after a restart looks like this:

~1100ms   (startup, palette load — expected)
   ... quiet, sometimes for hours ...
~300-1300ms  →  ~3500ms  →  ~7000ms  →  ~15000ms  →  ~29000ms  →  ~60000ms  →  ~120000ms

Across 12 cycles spanning two days, same values every time:

step observations range spread
~3500ms 12 3156 – 3826 ±10%
~7000ms 12 6650 – 7351 ±5%
~15000ms 11 14447 – 15796 ±5%
~29000ms 11 28707 – 30269 ±3%
~60000ms 11 58377 – 63177 ±4%
~120000ms 3 117564 – 121399 ±2%

Ratio between consecutive steps is consistently 1.9–2.2.

Once it reaches ~120s the add-on watchdog kills the container (SIGKILL, exit 137) and the sequence resets to zero on restart. On one run I disabled the watchdog to see how far it would go — 14 consecutive doublings, no convergence:

699 → 1057 → 3257 → 6954 → 14919 → 28629 → 58013 → 115173
→ 242000 → 479712 → 957443 → 2000600 → 4031923 ms

That last one is a single 67-minute event loop block. The process was alive the whole time and eventually recovered on its own — the editor came back after a few minutes on the shorter blocks.

The timing between the early steps is irregular (anywhere from 14 minutes to 3 hours), but once a block exceeds 15s it accelerates to the end within 30 seconds to 20 minutes.

The blocking comes before the disconnect, not after

This connects to a known open issue about the HA websocket palette freezing (zachowj/node-red-contrib-home-assistant-websocket#1990), where the assumption is that a websocket disconnect triggers the freeze. My data suggests the opposite:

23:06  restart, flows started
00:27  [lag] 124ms
00:27  [lag] 449ms
00:49  [lag] 993ms
00:49  [lag] 1039ms
00:53  [lag] 3790ms
00:53  [lag] 7164ms
01:01  [lag] 15485ms      <- first block over 15s
01:01  Connection closed  <- disconnect only appears HERE

There are zero disconnects during the first five doublings. The connection only drops once a block exceeds 15 seconds, which is exactly the HA Supervisor's PING/PONG timeout — the blocked event loop simply can't answer. So the disconnect looks like a symptom, not the cause.

Memory is not it

RSS sits flat at ~180MB for hours. It spikes during an episode and is fully reclaimed afterwards:

uptime 3.3h   rss=226MB  heap=80/102MB
uptime 3.5h   rss=166MB  heap=85/90MB
uptime 3.7h   rss=171MB  heap=85/90MB
uptime 3.8h   rss=330MB  heap=157/255MB   <- during the 58s block
(next cycle)  rss=180MB  heap=77/83MB     <- fully reclaimed

Heap never gets close to the limit. Whatever runs during an episode allocates heavily and is then collected.

Environment

Host Raspberry Pi 5 (8GB), Debian 12 bookworm, HA Supervised
Storage NVMe SSD (no SD card)
Node-RED v5.0.4 (HA add-on 22.0.2)
Node.js v24.18.1
Flows 442 nodes across 10 tabs
Palette node-red-contrib-home-assistant-websocket 0.80.3, node-red-dashboard 3.6.6

Already ruled out

Tested one variable at a time over about two weeks:

  • Host resourcesvcgencmd get_throttled = 0x0 (never throttled, never under-voltage), CPU 42°C, 4.6GB RAM free, root on NVMe.
  • Flow structure — programmatic analysis of all 442 nodes: zero wire loops, zero recursion, no setInterval/setTimeout in function nodes, no repeat injects, all api-call-service nodes set to queue: none, only 3 entities both written and watched (all gated by trigger/delay).
  • Node count — disabled a whole tab (12 server-state-changed subscriptions). Freeze frequency unchanged (~9/day before and after).
  • Context storelocalfilesystem made single blocks worse (a 1.5MB global.json being reserialized on every write); reverted to memory. Doubling pattern identical either way.
  • The other side — Home Assistant's own log is completely silent at every disconnect timestamp, and HA stays fully responsive throughout. One integration blocking HA's executor was disabled; no effect on this.
  • Websocket heartbeat — enabling it made things worse (disconnects 4–9/day → 18/day). Reverted.
  • unhandledRejection handler — stops the process from exiting on rejected promises, but has no effect on the freezing.

What I'm asking

  1. What mechanism would make event-loop blocking double so precisely each round? My guess is something being registered twice as many times each cycle — listeners, subscriptions, timers — but I don't know how to confirm that from outside.

  2. Is there a way to identify which node is holding the loop, without disabling flows? Disabling tabs is disruptive (this is a live home automation setup). I know about logging.console.metrics: true — is that the best option, or is there a practical way to attach a CPU profiler to a running Node-RED instance?

Happy to run anything and report back. The lag monitor above is ten lines and makes the pattern obvious within a few hours.

Why are you so sure that it's a node that is causing this drift?

It's very hard not having seen the flows, not seeing exactly what is coming in and being acted upon, to point the finger and say "it's that node".

You can try using the message tracing facility and perhaps that will show the pathways more clearly. Provided there isn't too many messages being passed around.

What happens if nothing happens? I.e. no input, no data flow, just idling. Does this happen when NR is doing nothing because it's generally not doing anything, NR is always doing something just that nothing is acting externally upon it.

This is probably a better question to pose than which node might be broken.

What does top show?

If you have something trying to run regularly, and not enough processor time to achieve the specified rate, then requests to run it can get queued up. The result is that the queue builds up over time, getting larger and larger. So when the queue starts to build and your lag monitor task gets slotted in then it might have to wait for, say, two instances of the processor heavy event to run. By the time it next runs there may be 4 waiting in the queue, so the lag will be doubled, the next time there may be 8 in the queue and so on.

What your tests mean is that there is a task trying to run at a rate greater than can be achieved, so the queue of requests to run it gets longer and longer.

The top command may tell you more about what is going on.

Reporting back with the CPU data. Short version: it's compute-bound, and it isn't a backlog.

Method

Sampling the node-red process directly from /proc/PID/stat (utime+stime over a 5-second window, every 30 seconds) rather than top, so the figure is instantaneous rather than a lifetime average:

HZ=$(getconf CLK_TCK)
while true; do
    PID=$(pgrep -f '^node-red$' | head -1)
    T1=$(awk '{print $14+$15}' /proc/$PID/stat); sleep 5
    T2=$(awk '{print $14+$15}' /proc/$PID/stat)
    CPU=$(awk -v a=$T1 -v b=$T2 -v hz=$HZ 'BEGIN{printf "%.1f",(b-a)*100/(hz*5)}')
    RSS=$(( $(ps -p $PID -o rss=) / 1024 ))
    echo "$(date '+%H:%M:%S') cpu=${CPU}% rss=${RSS}MB"
    sleep 25
done

I also started logging the start time of each block, by subtracting the blocked duration from the timestamp (the [lag] timestamp is when the timer finally fired, i.e. when the block ended).

CPU tracks the blocks exactly — flat 1%, then flat 100%

One cycle, CPU samples interleaved with the reconstructed block boundaries:

11:12:32  cpu=0.4%   rss=224MB
11:13:02  cpu=0.6%   rss=225MB     <- block starts here (15913ms)
11:13:32  cpu=100.6% rss=290MB
                                    <- second block starts 11:13:19 (30402ms)
11:14:02  cpu=1.4%   rss=303MB     <- both blocks over
11:14:32  cpu=0.4%   rss=304MB
   ... 7 minutes of 0.4-1.0% ...
11:21:03  cpu=1.0%   rss=166MB
11:21:33  cpu=100.6% rss=226MB     <- block starts 11:21:19 (61601ms)
11:22:03  cpu=104.4% rss=310MB
11:22:33  cpu=100.4% rss=316MB     <- next block starts 11:22:26 (118371ms)
11:23:03  cpu=100.4% rss=318MB
11:23:33  cpu=100.2% rss=335MB
11:24:03  cpu=100.2% rss=351MB
11:24:33  cpu=63.4%  rss=366MB
11:25:03  cpu=100.2% rss=366MB
11:25:34  (process gone - watchdog SIGKILL)

Two things fall out of this:

1. It's real computation, not waiting. Exactly 100% of one core for the whole block. Not I/O wait, not swap (there is none in use), not a GC pause waiting on something. Something is spinning in a loop.

2. There is no ramp-up. CPU sits at 0.4–1.4% right up to the instant a block begins, jumps to 100%, and drops straight back afterwards. If a queue were gradually filling, I'd expect the process to get progressively busier between episodes as the backlog grew. It doesn't — it's completely idle between them.

The doubling survives 22 minutes of total idle

This is the part I find most telling:

10:50:25   block ends (7096ms)
           ... 22 minutes, CPU 0.6-1.4% throughout ...
11:13:02   block starts (15913ms)   <- exactly 2x the previous

If this were a backlog of pending work, 22 minutes at 1% CPU would have drained it comfortably. Instead the next block is precisely double.

So @Colin — I think your mechanism is right in shape but the doubling isn't in the queue depth. What's doubling is the thing being processed, and it persists in that doubled state while completely idle. Some structure — a collection, a set of registered handlers, a subscription list — is being iterated and coming out twice as large, then sitting there until the next trigger.

That also explains two things I couldn't account for before:

  • Why a restart resets it to zero — the structure is rebuilt from scratch.
  • Why idle time doesn't help — a data structure doesn't shrink on its own, whereas a backlog would drain.

Memory fits the same picture

RSS is stable between episodes, spikes during them, and is fully reclaimed afterwards:

before  rss=166MB
during  rss=226 -> 310 -> 366MB
after   rss=154MB  (next cycle, fresh process)

Heap never approaches the limit. Consistent with allocating heavily while walking an increasingly large collection, then releasing it.

Where that leaves the question

The question is now narrower than when I started: what would get iterated and simultaneously doubled, in a Node-RED runtime that is otherwise idle?

Nothing in my flows polls at that rate — no repeat injects, no timers in function nodes, two poll-state nodes both on 30-minute intervals. The triggering event is irregular (gaps of 3 to 50 minutes between steps), which fits "something arrives from outside and kicks off a pass over the structure" better than "something is scheduled".

I still owe the thread the idle test (@gregorius's suggestion) — all 10 tabs disabled, instance left running, see whether the doubling still appears. I've been holding off because it's a live setup, but the time-critical automations are on native HA automations now, so I can take a 3-hour window. That should settle whether this is my flows or the runtime/palette. Will report back.

If anyone has a workable recipe for attaching a CPU profiler to a running instance, now would be a great time — with CPU pinned at 100% for two minutes straight, a single sampled profile would name the function outright.

Once there is a queue that is growing then that means that the processor is not able to keep up so the processor will be at 100% on the nodejs core. Though fact that it is low before jumping to 100% does mean that it is not that you are running close to the limit most of the time and then get pushed just over it. It does suggest that something is triggering a loop of some sort.

I would ignore the fact that it is doubling and just concentrate on finding where the loop is.

Are you using MQTT? If so then use something like MQTTExplorer to see whether the loop involves MQTT.

Did you look at @gregorius' suggestion?

Otherwise I think you will just have to disable sections of your flows until you find the culprit area.

Node-RED is "just" a "simple" node.js app. :smiley:

So profiling can be done by firing up node's inspect feature.

Or, on newer versions I think, you should be able to use the --prof flag to run a detailed profile, that logs to a file that you can analyse using --prof-process