Ctrl-C is a special case, because that will only be relevant if you run the app through the CLI, which isn’t the normal running mode for an app, and you can’t test any teardown code (not even signal handlers) that way. For that, you need to properly install the app using homey app install -r (which then doesn’t provide you with any logs, though).
You can also place some placeholder images and publish it to test. Then you can install it on your own Homey and create a diagnostics report to view the logs
I’m starting my app with following command and the app is running in Homey and this way givs me logs: eg. “homey app run --remote >log/log21_173.txt 2>&1”. When Homey restarts in night hours after eg. a system update, my app is automatically restarted too and the logging continues. This is why I need to press CTRL+C to start with eg. a new app version.
Very well, but I just explained why even a working onUninit will still not be called when you stop your app using Ctrl-C.
So you probably have to live with the fact that you have to manually reset the Modbus connection while you’re debugging your app this way.
I have now done as you suggested and started the application using homey app install. It had been some time since I last tested it this way.
In my efforts to investigate the RSS memory growth, I had my internal web server running a console continuously to receive the application’s log output. With the help of AI, I have also performed extensive analyses of both the code and the logs. These analyses have repeatedly indicated that there is nothing obvious in my own code that would directly explain the continued RSS growth.
The most recent analysis came to the following conclusion:
“What remains unchanged, and has been confirmed repeatedly using different instrumentation, is that the increase occurs during the approximately 1.4-second pause between two polling cycles, with fsm=idle and op=idle — literally nothing from your own code is being logged as executing during that period.”
It has now been several hours since the installation, and the RSS has remained at a relatively low plateau (101 MB, peak max 120 MB).
When I last performed this test (Homey app install), a little over four weeks ago, I did discover an issue with eg. strings being allocated with different lengths each time they were written to the log. With the help of AI analysis, I have changed this so that the strings are now formatted to a fixed length and their memory is allocated only once during onInit(). This has now significantly reduced the rate of RSS growth, presumably by reducing repeated dynamic allocations and allowing the allocated memory to be reused more efficiently.
However, I did not expect that the logging and debugging itself would turn out to be the final culprit. The fact that the RSS is now remaining at a low plateau after a fresh installation is therefore quite interesting.
I will continue to monitor it and see whether the RSS remains stable over a longer period.
I’ve never had to “format strings to a fixed length” or “allocate them only once” in the 15 or so years that I’ve been using Node.js, even on projects that handle many (many) requests per second. It sounds like your AI is basically chasing its own tail.
Also, if the symptoms that you’re seeing are caused by either Node.js or the Homey SDK, I would expect other developers to have the same issues, and they haven’t. I have an app that handles dozens of devices and capabilities at the same time, and it has no problems.
I completely agree with this, and in fact I have been assuming this myself throughout the investigation. I have always started from the assumption that I must have done something wrong in my own code.
However, since it never occurred to me that using a debugging tool could itself potentially contribute to the problem, I may simply have been looking in the wrong places.
I made the changes I mentioned earlier and initially saw a positive development. However, I may have been misled by the fact that the random RSS increases happened to stop occurring at that particular time.
I still find it difficult to understand why something as fundamental as running a debugging tool could potentially be responsible for such significant RSS growth. Nevertheless, the recent results make me think that this is something worth investigating further.
For your information: after several hours, the RSS with homey app install has once again increased by approximately 30 MB. However, this time it appears that the garbage collector has done its job, and the memory was released again after a few minutes.
There has been no change in the FSM; it has remained constantly in the idle state. PV surplus is currently being exported to the grid.
The monitoring has continued, and the main difference with the app installed is that, during the first few hours, the baseline remains at a very stable and low level. Unfortunately, this also shows how easy it is to be misled, as RSS increases of between 20 and 30 MB can occur later on. These increases now also appear to remain until the app is restarted.
I am still inclined to believe that there is something in my own code that is not quite right. However, the fact that the AI analyses and the logs consistently indicate that the RSS growth occurs between polling cycles, when my application is not doing anything, is genuinely misleading to me. This is why I started this thread in the hope of gaining some insight into whether there is some general system-level mechanism or functionality that could affect the behaviour of my application.
I restarted the app about 13:05
If this was caused by some general system-level mechanism it would affect other apps that do similar things (many apps perform periodic polling), but AFAIK, this isn’t the case.
Also, I’m not inclined to trust your AI. If I look at the code that you posted earlier, there are many timers running, so I don’t see how it can conclude that the memory growth is happening when your app isn’t doing anything, especially since it can only perform static analysis.
Update, following up on Q3 (what allocates 20–33 MB between ticks).
I instrumented one specific occurrence down to the exact log line. Two steps, same app, ~3 hours apart, same signature both times:
I apologize that some parts of the log are written in Swedish.
Mark-Compact 21.1(23.8)->20.3(23.8) MB ... "GC in old space requested" <- V8's own --trace-gc, not my code
[INVDEV][RSS] global.gc() kord <- my periodic forced GC, fires 30s after the previous one
[INVDEV][RSSATTR] MELLAN pollar: 6405 sidor = 25.0 MB (paus 1963 ms) <- RSS step, measured in the idle gap between two polls
[INVDEV][RSS][PMJUMP] pm 5.86 -> 28.73 MB (+22.87) op=idle
Both steps land within 4–5 seconds of my own global.gc() call triggering a Mark-Compact pass that logs “GC in old space requested.” peak_malloced_memory jumps by almost exactly the step size in one case (+22.87 MB pm vs +25.0 MB RSS), barely at all in the other (+1.55 MB pm vs +26.0 MB RSS) — so it’s not a clean 1:1 every time, but the timing correlation with the forced GC call is now 2 for 2.
I don’t know if this means forcing global.gc() on a timer is provoking V8 into growing old-space (as opposed to letting it decide on its own), or if it’s coincidence and any Mark-Compact would do it, forced or not. Given the numbers in my first post (GC on = 7.5 MB/h drift vs GC off = 23.3 MB/h), I’m not going to stop forcing it — it clearly helps far more than it hurts — but this is the closest I’ve gotten to a trigger instead of just a correlation with idle time.
Also: since the first post I’ve split device.js into about a dozen smaller files by concern (poll loop, night planning, RSS diagnostics, etc.) instead of one ~15000-line file. Not a fix for this, just makes it easier for anyone who wants to actually look — link to download new zip: SwissTransfer – Sicherer und kostenloser Versand grosser Dateien
The link will be disabled at 20 sept.
