RSS grows in 20–30 MB steps between event-loop ticks, and the first hours after start decide the floor — is this known?

Developers
, ,
1

Homey Pro (Early 2023) · two private apps, one simple and one complex, both affected

Summary

An app of mine is killed by Memory Warning Limit Reached every few hours. I
have instrumented it heavily and can now describe the behaviour precisely. Two
findings that I have not seen written down anywhere:
RSS grows in discrete 20–33 MB steps, and page-fault counters read
immediately before and after each loop iteration place them between two
iterations, not inside one. Most are returned within minutes; occasionally
one is not, and the floor ratchets up permanently.
The event-loop rate during the first 8–10 hours after start determines
where RSS settles. Polling every 500 ms from a cold start reaches 160 MB
in 70 minutes and gets killed. Running the first ten hours at 1500 ms and
only then switching to 500 ms settles the floor at ~100–120 MB — and after
that the interval makes no difference at all. The floor stops rising about
9 hours in, which is where the ten hours comes from.
The two are independent: the steps arrive at the same size and roughly the same
rate whatever the loop interval. What the interval changes is the floor they
land on, and therefore whether a step is survivable.
A second app on the same Homey, with unrelated code and a very different
workload, shows steps of the same shape. I have not been able to test what
would remove them from either app.
How RSS is measured here. An app cannot read its own current RSS (see
Q5 — Can an app read its own RSS? below), so a separate monitoring app polls
usage.mem for each app through homey-api every 15 seconds. All floor and step figures below come from
that. Figures called maxRSS come from process.resourceUsage() inside the
app and are high-water marks.

The apps

App 1

— energy management for a Sungrow SH10RT hybrid inverter with a
25.6 kWh battery. Modbus TCP polling, a state machine for charge/discharge,
~76 capabilities, one device, no cloud, one persistent TCP socket.

App 2

— draws a PNG chart every five minutes and uploads it over HTTP (to my internal web server on LAN) .
Reads app 1’s capabilities via homey-api. Around 3 MB of preallocated buffers
and almost no logic.

What the kill looks like

12:44:16   app starts, floor 85 MB
13:00      warm-up done, floor 97.4
13:00-21:00 drift 1.17 MB/h            floor 106.8
21:48:39   +33.0 MB, single step  ->   143.6   not returned
21:50-22:44                            145.7   flat for nearly an hour
22:44:11   loop interval 1500 -> 500 ms
22:46:56   +4.3 MB                ->   150.1
22:48:09   killed

That matches the documented behaviour — warning above 150 MB, killed after
about 50 seconds above it — so the kill itself works as designed. The question
is where the 33 MB came from.
The drift between steps is 1.17 MB/h. At that rate the run would have taken
30 hours to reach the limit on its own; it was killed after 10, one hour after a
single unreturned step.

The steps: measured over 24 hours

Eight increases of ≥8 MB, measured against actual RSS sampled every 15 seconds
by a separate monitoring app:

time        floor -> peak     +MB    outcome
08:38:29    103.8 -> 129.5   +25.7   returned after  6.0 min
09:15:35     99.2 -> 114.1   +14.9   returned after  3.0 min
12:20:51    109.5 -> 132.1   +22.6   PERMANENT
14:28:26    104.0 -> 129.2   +25.2   returned after  4.3 min
19:53:20    105.3 -> 117.3   +12.0   returned after  2.0 min
21:48:39    110.6 -> 143.6   +33.0   PERMANENT  -> killed one hour later
00:48:38    100.6 -> 121.1   +20.5   returned after  6.5 min
01:42:02    101.2 -> 128.2   +27.0   returned after  1.3 min

Six of eight are returned to the OS within minutes. Two are not, and those lift
the floor for good. Size does not predict which: 22.6 MB stayed while
27.0 MB was returned. Neither does peak_malloced_memory.
Between the steps the floor drifts 1.2 MB/h.

Where the memory is allocated

I read process.resourceUsage().minorPageFault immediately before and
immediately after each poll cycle, so an increase can be attributed to one side
or the other. Every step in the 24-hour window looks the same:

06:14   between ticks   26.6 MB   gap 1442 ms
08:38   between ticks   25.5 MB   gap 1446 ms
11:31   between ticks   24.8 MB   gap 1433 ms
13:18   between ticks   22.7 MB   gap 1455 ms
14:28   between ticks   23.5 MB   gap 1388 ms
18:42   between ticks   25.1 MB   gap 1430 ms
19:53   between ticks   30.2 MB   gap 1442 ms
21:48   between ticks   33.1 MB   gap 1456 ms
23:38   between ticks   26.6 MB   gap 1435 ms
01:41   between ticks   25.5 MB   gap 1419 ms

Always between two iterations, always across a 1388–1456 ms interval — the
configured 1500 ms less the iteration’s own run time — and always 22–33 MB. The measurements taken inside a tick in the same seconds are
1.6–3.8 MB. None of my JavaScript is running when the 25 MB arrives.
Page faults track the size exactly — in a control test, allocating a 30 MB
Buffer produced 7689 minor page faults (30.0 MB).
The gap length also identifies the loop interval, which settles a question I
expected to be asked. Of twelve measured events in that 24-hour window, eleven
happened at a 1388–1456 ms gap (the 1500 ms interval) and exactly one at 448 ms
(the 500 ms interval). The steps are therefore not a consequence of running
fast — the largest one, 33 MB, arrived nine hours into a slow-polling window.

Everything V8 reports stays flat

Over a 4-hour run RSS went from 92 to 160 MB while all V8 figures together grew
about 6 MB:
metric start after 4 h
heapUsed 18.4 MB 23.0 MB
heapTotal 23.2 MB 27.9 MB
external 3.8 MB 3.8 MB
malloced_memory 0.5 MB 0.5 MB
active libuv handles Pipe:1, Socket:4 unchanged
maxRSS 92.1 MB 160.2 MB
Handle counts never move, so it is not a handle or socket leak.

The warm-up rate decides the floor

One process, 71 hours, no restarts, two variables changed at known times.
Poll interval 1500 ms → 500 ms, while already settled

5 h before (1500 ms):  floor 121.5 MB
3 h after   (500 ms):  floor 121.5 MB      difference +0.0 MB

For comparison, from a cold start at 500 ms the first ≥5 MB step arrived after
12–16 minutes in all four runs I have, and it was 22–27 MB every time.
Cold start, same code, same hardware, same day

500 ms throughout      94 -> 160 MB in 70 minutes    -> killed
1500 ms for 8-10 h     97 -> 121 MB over ~9 hours    -> flat, ran 71 hours
   then 500 ms                  no effect at all

During warm-up the growth tracks the number of loop iterations rather than
wall-clock time: roughly 25–30 MB per 10 000 iterations at both 500 ms and
1000 ms. Halving the interval does not make an iteration cost more — it just
runs twice as many per hour, so the ceiling arrives twice as fast.
I now start the app at 1500 ms and switch to 500 ms after ten hours. It keeps
the floor around 100 MB instead of 125, which buys margin — but it does not stop
the steps, and it does not always save the app. In the run shown above the floor
had drifted to 110.6 when a 33 MB step landed, and that was enough.

Forcing garbage collection helps during warm-up, not after

Same poll interval (1500 ms, verified at 10 iterations per 15 s), same code,
same machine, same warm-up phase — the only difference is global.gc() every
30 seconds:

GC off    89.9 -> 128.7 MB in 1.7 h  = 23.3 MB/h  -> killed after 1 h 58 min
GC on     96.8 -> 109.3 MB in 1.7 h  =  7.5 MB/h  -> settled, ran for days

But GC does not reclaim a step once it has happened. In the 70 seconds
between the fatal step and the kill, five garbage collections ran and RSS did
not move a single MB. A 20 MB transient on another day took 5 minutes 16
seconds to return with GC running every 30 seconds throughout — so whatever
returns the memory operates on a minutes timescale and is not GC.

A second app shows the same pattern

App 2 does almost nothing: renders a PNG every five minutes, uploads it, reads
capabilities. Over 22 hours its floor moved 93.9 → 97.7 MB, with two transients
(+9.2 and +11.7 MB) that returned within five minutes. On another day it took
two ~10 MB steps that did not return, then sat flat for 14 hours.
Same stepping shape, completely different code. That is what makes me think
this is platform behaviour rather than something in my control logic.

Questions

Q1 — Is the warm-up effect known?
Is it known that a faster event-loop cadence during the first hours after start
leads to a permanently higher RSS floor on the 2023+ hardware? It is not
intuitive: an iteration that allocates nothing should not grow the process.
Q2 — Is there a better fix than warming up slowly?
Ten hours at a third of the control resolution is a lot to pay, and it does not
stop the steps — it only lowers the floor they land on.
Q3 — What allocates 20–33 MB between two ticks?
I do not know. What I can say is what it is not: every figure V8 reports
stays flat across a step, and the libuv handle count does not change. That
leaves memory the process obtained from the allocator without V8 accounting for
it.
If that is glibc arena behaviour, malloc_trim(0) would be the remedy, but
Node does not expose it. global.gc() is not a substitute — measured above, it
changed nothing after a step had happened. Would setting MALLOC_ARENA_MAX or
MALLOC_TRIM_THRESHOLD_ for app processes be possible, or exposing a trim call
to apps?
Q4 — Can the limit be raised for an app that needs it?
I have read on this forum that com.athom.matter is allowed roughly double —
I have not verified that myself, but if it is right the mechanism exists. My floor is ~100 MB after the workaround, but a single unreturned step
still takes it to 145 — four MB from the kill.
Q5 — Can an app read its own RSS?
Not today. /proc is not mounted in the app sandbox; confirmed at runtime:

process.memoryUsage.rss() -> ENOENT: no such file or directory,
                             uv_resident_set_memory

The only figure available in-process is getrusage(ru_maxrss), a high-water
mark that never decreases and therefore reports every transient peak as if it
were permanent. I had to write a second app that polls app.usage.mem through
homey-api just to see the real curve — and an app that wants to protect itself
has to call the REST API to look up its own memory use.
Exposing current RSS to apps would make this class of problem far easier to
diagnose, and would let an app back off on its own before it is killed.

What I have already ruled out

All buffers allocated once at onInit and written in place; no per-iteration
allocation in the poll loop.
Log strings are never built unless the line is actually emitted.
Trigger card lookups cached; TCP connections kept alive with keep-alive.
Chart rendering and all HTTP uploads moved into a separate app: ~92 kB of code
and 3 MB of buffers left app 1. The ceiling did not change.
Poll intervals tested at 500, 1000, 1500 and 2000 ms.
Forced GC tested on and off within the same process.
libuv handle count monitored continuously — constant at Pipe:1, Socket:4.

diag. showing some manual restarts with different RSS behaviours and one crash.

image
image1803×558 52.1 KB

2

Sorry I didn’t bother to read your essay (AI;DR (“AI, didn’t read”)), but the combination of “polling” and “gradually using more memory” gives off a distinct smell of a memory leak.

Things to try (perhaps you already did):

  • decrease the number of capabilities
  • decrease the polling interval significantly

Don’t try both things at the same time, start with decreasing the number of capabilities. Provided that the code that’s populating the capabilities is unlikely to leak, it could point to memory leaking from the SDK.

However, given your propensity for using AI for your post, I assume that your apps are also AI-generated, in which case all bets are off. You can ask it to do any of the things that I propose, but you won’t know for certain that it did so in a proper way unless you meticulously validate the code by hand.

3

Maybe better first fix your AI‘s writing style before letting this thing try to fix code. - Or even better: Ask some precise, focused questions, that you have written and understood yourselve.

4

Fair enough on the length — point taken.

I have two apps on the same Homey. One has 73 capabilities and
writes about 6300 values an hour. The other has 2 capabilities and writes maybe
200 an hour. Both take 10–30 MB RSS steps. Doesn’t that rule out capability
count as the cause?

On the poll interval: I’ve tested 500, 1000, 1500 and 2000 ms. The steps are the
same size at all four. Going slower than 2000 ms isn’t really an option for me —
this is load balancing a 10 kW inverter against a 16 A main fuse, so if the loop
can’t react in a couple of seconds the whole point of the app is gone.

And that’s what I keep getting stuck on. The loop doesn’t allocate anything. It
reads Modbus registers into buffers that were allocated once at startup. Why
would running that same loop more often cost more memory at all? That’s the part
I can’t make sense of, and it’s the reason I asked.

5

Perhaps. Perhaps not. :man_shrugging:t3:

This feels the same as being a car mechanic and having someone describe that their car is making a strange sound, without having brought their actual car.

In other words: without actual code we can guess all we want, but it’s probably a waste of time.

6

Tip: cache the capabilities and make the setCapability() update on a lower frequency and only update upon change:

async function updateCapability(device, capability, value) {
  try {
    const current = device.getCapabilityValue(capability);

    // --- SAFE REMOVE ---
    // Removal is allowed only when:
    // 1) the new value is null
    // 2) the current value in Homey is also null

    if (value == null && current == null) {
      if (device.hasCapability(capability)) {
        await device.removeCapability(capability);
        device.log(`🗑️ Removed capability "${capability}"`);
      }
      return;
    }

    // --- ADD IF MISSING ---
    if (!device.hasCapability(capability)) {
      try {
        await device.addCapability(capability);
        device.log(`➕ Added capability "${capability}"`);
      } catch (err) {
        if (err && (err.code === 409 || err.statusCode === 409 || (err.message && err.message.includes('capability_already_exists')))) {
          device.log(`Capability already exists: ${capability} — ignoring`);
        } else {
          throw err;
        }
      }
    }

    // --- UPDATE ---
    if (current !== value) {
      await device.setCapabilityValue(capability, value);
    }

  } catch (err) {
    if (err.message === 'device_not_found') {
      device.log(`⚠️ Skipping capability "${capability}" — device not found`);
      return;
    }
    device.error(`❌ Failed updateCapability("${capability}")`, err);
  }
}
7

That’s another thing to try: don’t update any capabilities in the polling loop, just retrieve the device data.

8

@Jeroen_Tebbens — thanks. That is already how it works here; every capability write goes through one function that skips unchanged values:

js

async _capSetM(cap, v) {
  if (!this._pollDoDisplay) return true;               // display throttle
  if (this.getCapabilityValue(cap) === v) return true;  // skip if unchanged
  ...
}

The 6300 writes/hour I quoted is what is left after that filter.

@robertklep — I ran your test. Result below.

Setup. I replaced setCapabilityValue on the device instance so every call is counted and discarded. Not a flag inside my own setter — there are 77 call sites in the file and only two go through it, so a flag there would have missed 75 of them. Modbus reads and the control logic were untouched. Poll interval 1500 ms, the same as the run I am comparing against.

Writes suppressed: 69 301 in 87 minutes (≈810/min), logged every 60 s so that “zero writes reached the device layer” is measured, not assumed.

Result: no difference.

                                    growth      outcome
previous run, writes enabled       +3.7 MB/h    -
this run, writes disabled          +5.5 MB/h    +33.9 MB permanent step at 87 min

At the moment of the step my page-fault instrumentation says:

[RSSATTR] between polls: 6290 minor faults = 24.6 MB  (gap 1474 ms)
[MEMJUMP] fsm=DAY_GRID_IDLE op=idle  heapUsed 21  heapTotal 24.9  external 4
          malloced 0.5  handles 5   state unchanged for 1637 s

24.6 MB arrived between two polls, across a 1474 ms gap, with the state machine idle for 27 minutes, three major GCs in the preceding 75 seconds, two Modbus writes in the last minute, and not one capability write in the entire process lifetime. Every V8 figure flat, handle count unchanged.

image
image1621×559 44.3 KB

So capability writes are not the cause. I am glad to have it ruled out rather than assumed — thank you for the suggestion.

That leaves the same question as before: what obtains 20–33 MB from the allocator between two event-loop iterations, while V8 accounts for none of it.

On posting the code: the device file is around 19 000 lines, and I do not think anyone wants to read that — which is the main reason it has not been uploaded. The poll loop and the memory instrumentation are the parts this question is actually about, and I am happy to post those on their own if that is useful.

9

After the test where no capability update was disabled, I turned the update on and the app ran about 2.5h into a crash.

image
image1612×571 51.1 KB

10

Step two: no Modbus interactions in the polling loop at all.

11

This is a test I carried out shortly after I first discovered the crashes (2 months ago). Modbus has no impact on this RSS issue. It was at that point that I realized that Homey does not shut down the system properly.

I have now also contacted Athom regarding that issue and reminded them that there is a four-year-old case that still remains unresolved:

12

No code base → still guessing

  • Http agent - keep alive on fetch? Vs connect / close every 1500ms
  • free/ max sockets? (Also http agent parameter)
  • Shared fs storage place vs this.homey.settings.set(key, value) ?
13

OK, now that I have given you advance notice that this is a large file (device.js), it is available for download via SwissTransfer at the following link: SwissTransfer - Send large files securely and free of charge

14

There is so much stuff layered on top of other stuff (layered on top of other stuff) that this is simply undebuggable. There could probably be a few dozen reasons why this is not working properly, and none have to do with either Node.js or Homey.

15

To clarify the current situation, the code itself is functioning exactly as intended with regard to its primary purpose and functionality. The application is performing the tasks it is designed to perform correctly.

The issue I am investigating is the seemingly “random” increases in RSS memory usage. These increases are not expected or acceptable, and they eventually cause Homey to terminate the app and restart it.

I can only hope that the issue with getting Homey to actually execute the code in onUninit() will be resolved. If that works as intended, I will be able to close the Modbus connection properly, preventing the communication from becoming stuck in the inverter. At present, this causes the inverter to remain unresponsive when the app is restarted under a different process ID.

I will have to wait for Athom’s response. Their support has told me that a developer has been assigned to investigate the problem, but it has now been almost a month without any response.

16

Spaghetti code usually does :man_shrugging:t3:

I disagree. There is so much going on in the code that it doesn’t surprise me at all.

Although I agree Athom should fix that issue before we celebrate its fourth birthday in a couple of weeks, when it comes to your app it’s just helpful to manage symptoms, not to fix the actual issue.

17

If it was raised 4 years ago, and now related again pending 1 month I would suggest not hold your breath on this.

Further looking at the code try to understand the size of the “blobs” you are writing via this.homey.settings.set() and read this.homey.settings.get().

These blobs can easily explode and eat exactly your memory (RSS).
I’ve come across this myself in my own app.

And please start splitting functions in to separate references (files) to make it readable.

Fetches on:

  • Weather
  • Prices
  • Your own url
  • Make toISOString() get it once as this is a system call (cpu hog)
18

If the communication does not get stuck, then once onUninit works as described in SDK3 and my code is able to start up properly, this is something I can live with. A restart only takes a few seconds, and if it happens on average once a day, it is merely an annoyance rather than a major problem.

Since I am, probably, the only one who will be using the app, I do not need to take the same considerations into account as I would if the app were published. In that case, one would expect the code not to be spaghetti code, and basic restart-related bugs simply cannot be present.

19

In your bug report you state that triggering on the exit event does work. Is there perhaps an option to close the Modbus connection in a synchronous way (since you can only use synchronous operations in an exit handler)?

20

When, for example, I press Ctrl+C to stop the running application, onUninit() is not executed. I see this happening repeatedly, and when the application is started again, the Modbus connection does not come back up.

I have therefore implemented a workaround in my code: I have added a boolean button to the device’s detail view. When pressed, it disconnects the Modbus connection, thereby releasing the connection between Homey and the inverter, before I press CTRL+C or restart.

Is this the functionality you have identified?