rdmtc / RedMatic

Node-RED packaged as Addon for the Homematic CCU3 and RaspberryMatic 🤹‍♂️
Apache License 2.0
535 stars 47 forks source link

JavaScript heap out of memory wenn Context-Storage file statt memory #325

Open Subnum12 opened 4 years ago

Subnum12 commented 4 years ago

Wenn Context Storage auf memory gesetzt ist läuft alles bestes: grafik Wenn Context Storage auf file gesetzt ist: grafik

anbei der Log:

18:11:07 ccu3 daemon.info node-red[15951]: Welcome to Node-RED
18:11:07 ccu3 daemon.info node-red[15951]: ===================
18:11:07 ccu3 daemon.info node-red[15951]: Node-RED version: v1.0.4
18:11:07 ccu3 daemon.info node-red[15951]: Node.js  version: v10.19.0
18:11:07 ccu3 daemon.info node-red[15951]: Linux 4.19.97-v7l+ arm LE
18:11:07 ccu3 daemon.err node-red: (node:15951) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
18:11:08 ccu3 daemon.info node-red[15951]: Loading palette nodes
18:11:10 ccu3 daemon.info node-red[15951]: Dashboard version 2.19.4 started at /addons/red/ui
18:11:10 ccu3 daemon.info node-red[15951]: node-red-contrib-ccu version: 3.1.4
18:11:10 ccu3 daemon.info node-red[15951]: Settings file  : /usr/local/addons/redmatic/lib/settings.js
18:11:10 ccu3 daemon.info node-red[15951]: Context store  : 'default' [module=localfilesystem]
18:11:10 ccu3 daemon.info node-red[15951]: Context store  : 'memory' [module=memory]
18:11:17 ccu3 daemon.info node-red[15951]: User directory : /usr/local/addons/redmatic/var
18:11:17 ccu3 daemon.warn node-red[15951]: Projects disabled : editorTheme.projects.enabled=false
18:11:17 ccu3 daemon.info node-red[15951]: Flows file     : /usr/local/addons/redmatic/var/flows.json
18:11:17 ccu3 daemon.info node-red[15951]: Server now running at http://127.0.0.1:1880/addons/red/
18:11:17 ccu3 daemon.info node-red[15951]: Starting flows
18:11:17 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] local connection on ccu >= v3.41 detected
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] paramsets loaded from /usr/local/addons/redmatic/var/paramsets.json
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] metadata loaded from /usr/local/addons/redmatic/var/ccu_localhost.json
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] regadata loaded from /usr/local/addons/redmatic/var/ccu_rega_localhost.json
18:11:18 ccu3 daemon.info node-red[15951]: Started flows
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] values saved to /usr/local/addons/redmatic/var/ccu_values_localhost.json
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] Interfaces: ReGaHSS, BidCos-RF, HmIP-RF, VirtualDevices
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] Interface ReGaHSS connected
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] init BidCos-RF binrpc://127.0.0.1:2047 nr_AKHydZ_BidCos-RF
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] init HmIP-RF http://127.0.0.1:2048 nr_D24DjW_HmIP-RF
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] init VirtualDevices http://127.0.0.1:2048 nr_D24DjW_VirtualDevices
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] binrpc server listening on binrpc://127.0.0.1:2047
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] xmlrpc server listening on http://127.0.0.1:2048
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] Interface BidCos-RF binrpc port 32001 connected
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] Interface VirtualDevices http port 39292 connected
18:11:18 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] Interface HmIP-RF http port 32010 connected
18:11:19 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] metadata saved to /usr/local/addons/redmatic/var/ccu_localhost.json
18:11:19 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] regadata saved to /usr/local/addons/redmatic/var/ccu_rega_localhost.json
18:18:06 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] Interface BidCos-RF disconnected
18:18:06 ccu3 daemon.warn node-red[15951]: [ccu-connection:localhost] ping timeout BidCos-RF 216
18:18:06 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] init BidCos-RF binrpc://127.0.0.1:2047 nr_AKHydZ_BidCos-RF
18:18:06 ccu3 daemon.info node-red[15951]: [ccu-connection:localhost] Interface BidCos-RF binrpc port 32001 connected
18:18:12 ccu3 daemon.err node-red[15951]: [ccu-connection:localhost]     < BidCos-RF init Error: response timeout
18:18:12 ccu3 daemon.err node-red[15951]: [ccu-connection:localhost] response timeout
18:18:13 ccu3 daemon.err node-red: <--- Last few GCs --->
18:18:13 ccu3 daemon.err node-red: [15951:0x2b1a298]   426893 ms: Mark-sweep 516.7 (541.4) -> 516.7 (541.4) MB, 127.1 / 0.0 ms  (average mu = 0.885, current mu = 0.001) last resort GC in old space requested
18:18:13 ccu3 daemon.err node-red: [15951:0x2b1a298]   427029 ms: Mark-sweep 516.7 (541.4) -> 516.7 (541.4) MB, 136.3 / 0.0 ms  (average mu = 0.796, current mu = 0.001) last resort GC in old space requested
18:18:13 ccu3 daemon.err node-red: <--- JS stacktrace --->
18:18:13 ccu3 daemon.err node-red: ==== JS stack trace =========================================
18:18:13 ccu3 daemon.err node-red:     0: ExitFrame [pc: 0x56feae9c]
18:18:13 ccu3 daemon.err node-red: Security context: 0x3cf92705 <JSObject>
18:18:13 ccu3 daemon.err node-red:     1: byteLength(aka byteLength) [0x4952f0dd] [buffer.js:531] [bytecode=0x3c2d828d offset=204](this=0x2838438d <undefined>,string=0xaa640541 <Very long string[229460545]>,encoding=0x3cfa3dd9 <String[4]: utf8>)
18:18:13 ccu3 daemon.err node-red:     2: arguments adaptor frame: 3->2
18:18:13 ccu3 daemon.err node-red:     3: fromString(aka fromString) [0x49539a81] [buffer.js:342] [bytecode=0x3c2d4325 offset=74](this=0x2838438d <undefine...
18:18:13 ccu3 daemon.err node-red: FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
18:18:13 ccu3 daemon.err node-red: Node-RED exited with non-zero exit status 134

Eigentlich sollte das keinen Unterschied machen wo die Daten liegen (memory/file). Anscheinend werden jedoch von Bausteinen teilweise erheblich mehr Daten im Filesystem gespeichert als im RAM. Das sollte zumindest insofern konfigurierbar sein, dass es nicht zum "heap out of memory" führt.

Hat #324 villeicht was zu tun?

hobbyquaker commented 4 years ago

Spontan: keine Ahnung. Möglicherweise entsteht der erhöhte Speicherbedarf bei File Storage daraus dass der Context dann nach JSON serialisiert werden muss. Dein Context scheint recht "riesig" zu sein, vielleicht wäre er hier besser die Daten anderswo (SQLite oder externe DB, Redis o.Ä.) abzulegen. Was hältst Du denn so für Daten im Context?

Subnum12 commented 4 years ago

Habe festgestellt es betrifft primär einen Baustein Dieser protokolliert wohl intern Daten (ohne das das konfigurierbar wäre oder dokumentiert ist).

Wie auch immer, anscheinend werden die Daten im RAM wohl wesentlich effizienter gespeichert als das nach dem serialisieren nach JSON der Fall ist.

Beispiel (tatsächlich ist das File mit allen logs >200MB):

{
    "values": {
        "currentTemp": 22.88,
        "targetValue": 22,
        "isUserCustom": true,
        "currentSchedule": {
            "temp": 19,
            "day": "Thursday",
            "time": "16:30"
        },
        "nextSchedule": {
            "temp": 19,
            "day": "Thursday",
            "time": "23:59"
        },
        "currentHeaterStatus": "off",
        "userTargetValue": 22,
        "time": "3/5/2020, 8:31:48 PM"
    },
    "logs": [
        {
            "currentTemp": 22.88,
            "targetValue": 15,
            "isUserCustom": true,
            "currentSchedule": {
                "temp": 19,
                "day": "Thursday",
                "time": "16:30"
            },
            "nextSchedule": {
                "temp": 19,
                "day": "Thursday",
                "time": "23:59"
            },
            "currentHeaterStatus": "off",
            "userTargetValue": 15,
            "time": "3/5/2020, 8:31:44 PM"
        },
        {
            "currentTemp": 22.88,
            "targetValue": 22,
            "isUserCustom": true,
            "currentSchedule": {
                "temp": 19,
                "day": "Thursday",
                "time": "16:30"
            },
            "nextSchedule": {
                "temp": 19,
                "day": "Thursday",
                "time": "23:59"
            },
            "currentHeaterStatus": "off",
            "userTargetValue": 22,
            "time": "3/5/2020, 8:31:48 PM"
        }
    ]
}
hobbyquaker commented 4 years ago

Da würde ich vorschlagen mal ein Issue bei node-red-contrib-heater-controller aufzumachen. Aus meiner Sicht ist es nicht wirklich akzeptabel dass Nodes den Context mit solchen Datenmengen befüllen und soviel RAM belegen.

Subnum12 commented 4 years ago

ja klar, das ist dort auch bereits behoben...

Dennoch zeigt das ein Problem mit dem File Storage auf, denn im RAM führt das nicht zum crash sondern die Daten werden beschränkt. Das ist beim speichern im File Storage wohl nicht der Fall, bzw. aufgrund der größeren Ressourcennutzung wenn die Daten nach JSON serialisiert werden reicht die Beschränkung die im RAM passiert nicht aus.

hobbyquaker commented 4 years ago

denn im RAM führt das nicht zum crash sondern die Daten werden beschränkt.

Mir ist keine Beschränkung der Context-Größe bekannt, woher nimmst Du diese Info? Am besten mal im Node-RED Discourse/Slack/Issuetracker nachfragen.