Höherer CPU Load durch Jarvis Prozesse

[MarkSau]

Hi.
Ich beobachte schon einige Zeit mein iobroker system und dabei ist mir aufgefallen, dass die Jarvis Prozesse so um die 3-15% CPU benutzen, obwohl kein Client aktiv ist. Was passiert da im Hintergrund?

[Zefau]

Wenn du den Adapter auf debug stellst, was sammelt sich denn da so an? jarvis aktualisiert im Hintergrund die Adapter und Skript Status sowie die Kalender.

[MarkSau]

das sehe ich im Log:

2022-09-07 20:08:03.203 - debug: jarvis.0 (35433) Redis Objects: Use Redis connection: 127.0.0.1:9001
2022-09-07 20:08:03.271 - debug: jarvis.0 (35433) Objects client ready ... initialize now
2022-09-07 20:08:03.273 - debug: jarvis.0 (35433) Objects create System PubSub Client
2022-09-07 20:08:03.274 - debug: jarvis.0 (35433) Objects create User PubSub Client
2022-09-07 20:08:03.436 - debug: jarvis.0 (35433) Objects client initialize lua scripts
2022-09-07 20:08:03.443 - debug: jarvis.0 (35433) Objects connected to redis: 127.0.0.1:9001
2022-09-07 20:08:03.506 - debug: jarvis.0 (35433) Redis States: Use Redis connection: 127.0.0.1:9000
2022-09-07 20:08:03.568 - debug: jarvis.0 (35433) States create System PubSub Client
2022-09-07 20:08:03.571 - debug: jarvis.0 (35433) States create User PubSub Client
2022-09-07 20:08:03.686 - debug: jarvis.0 (35433) States connected to redis: 127.0.0.1:9000
2022-09-07 20:08:04.383 - info: jarvis.0 (35433) starting. Version 3.1.0-alpha.37 (non-npm: Zefau/ioBroker.jarvis) in /opt/iobroker/node_modules/iobroker.jarvis, node: v16.17.0, js-controller: 4.0.23
2022-09-07 20:08:04.459 - info: jarvis.0 (35433) Found Backups for layout.
2022-09-07 20:08:04.464 - info: jarvis.0 (35433) Found Backups for styles.
2022-09-07 20:08:04.465 - info: jarvis.0 (35433) Found Backups for settings.
2022-09-07 20:08:04.470 - info: jarvis.0 (35433) Found Backups for widgets.
2022-09-07 20:08:04.478 - info: jarvis.0 (35433) Found Backups for devices.
2022-09-07 20:08:04.505 - debug: jarvis.0 (35433) Web Configuration: {"port":"8082","auth":false,"secure":false,"bind":"0.0.0.0","cache":false,"socketio":"system.adapter.socketio.0","simpleapi":true,"defaultUser":"admin","ttl":"3600","certPublic":"Priv_Public","certPrivate":"Priv_Private","certChained":"priv_chained","addUserName":false,"forceWebSockets":false,"whiteListEnabled":false,"leEnabled":false,"leUpdate":true,"leCheckPort":80,"loginBackgroundColor":"","loginBackgroundImage":false,"lePort":"80","whiteListSettings":{"default":{"user":"admin","object":{"read":true,"list":true,"write":true,"delete":true},"state":{"read":true,"list":true,"write":true,"create":true,"delete":true},"file":{"read":true,"list":true,"write":true,"create":true,"delete":true}}},"basicAuth":true,"disableExtensions":false,"disableStates":false,"disableFilesObjects":false,"leStaging":false,"defaultRedirect":"","usePureWebSockets":true,"compatibilityV2":true,"staticAssetCacheMaxAge":60,"language":""}
2022-09-07 20:08:04.517 - debug: jarvis.0 (35433) Connection: ioBroker host detected with MSNUC-IOB (IP: 192.168.0.13).
2022-09-07 20:08:04.519 - debug: jarvis.0 (35433) Connection: Using non-secure HTTP-Server
2022-09-07 20:08:04.519 - debug: jarvis.0 (35433) Connection: Using options: {}
2022-09-07 20:08:04.537 - info: jarvis.0 (35433) Connection: WebSocket opened on port 8400 using http...
2022-09-07 20:08:04.598 - info: jarvis.0 (35433) State value to set for "jarvis.0.settings.pageHomeReturn" has to be type "number" but received type "string"
2022-09-07 20:08:05.070 - debug: jarvis.0 (35433) Push update of instances..
2022-09-07 20:08:34.774 - debug: jarvis.0 (35433) Push update of scripts..

danach kommt nix mehr.

Ich habe aber mal den Jarvis Prozess mittels strace laufen lassen. Man sieht neben den "epoll_waits", die ja normal sind auch div Aktionen die Daten schreiben...Vielleicht kannst du da ja was raus lesen.

jarvis.log

[Zefau]

Wenn du den Log auf debug stellst, hast du dann auch schon um die 3-15% CPU Auslastung? Sonst lass es mal ne Weile laufen.

Aus dem epoll_waits kann ich nichts rauslesen.

[MarkSau]

Derzeit habe ich das Phänomen, das kein Client mehr verbunden ist, Jarvis.0 aber 20-28%, im Peak >50% verschlingt.
habe mal den debug ohne neustart eingestellt:

2022-09-09 15:47:04.716 - debug: jarvis.0 (40079) Refresh Adapter Instances and Script Statuses..
2022-09-09 15:47:34.716 - debug: jarvis.0 (40079) Refresh Adapter Instances and Script Statuses..
2022-09-09 15:48:04.716 - debug: jarvis.0 (40079) Refresh Adapter Instances and Script Statuses..

Kann es sein, das dies so viel verbraucht?

[MarkSau]

Habe jetzt mal alle widgets die logs, scripte, instanzen betreffen gelöscht und instanz neu gestartet.
Log zeigt aber immer noch

2022-09-09 15:59:27.321 - debug: jarvis.0 (51906) Refresh Adapter Instances and Script Statuses..
2022-09-09 15:59:57.322 - debug: jarvis.0 (51906) Refresh Adapter Instances and Script Statuses..
2022-09-09 16:00:27.322 - debug: jarvis.0 (51906) Refresh Adapter Instances and Script Statuses..
2022-09-09 16:00:57.322 - debug: jarvis.0 (51906) Refresh Adapter Instances and Script Statuses..
2022-09-09 16:01:27.323 - debug: jarvis.0 (51906) Refresh Adapter Instances and Script Statuses..
2022-09-09 16:01:57.324 - debug: jarvis.0 (51906) Refresh Adapter Instances and Script Statuses..
2022-09-09 16:02:27.324 - debug: jarvis.0 (51906) Refresh Adapter Instances and Script Statuses..
2022-09-09 16:02:27.476 - debug: jarvis.0 (51906) Push update of instances..
2022-09-09 16:02:57.329 - debug: jarvis.0 (51906) Refresh Adapter Instances and Script Statuses..

schaue morgen nochmal nach, ob die CPU wieder hoch gegangen ist. Das dauert scheinbar immer einen Tag.

[Zefau]

Wie viele Adapter und Skripte hast du denn ? Kann eigl. nicht sein. Er geht die Liste nur kurz durch um den Status aufzubereiten und an alle Clients zu verteilen, wenn diese connecten oder connected sind.

[MarkSau]

Ich habe "nur" 47 installierte Adapter und 55 Scripte. Ich nutze die Widgets jetzt aber nicht mehr.

und tatsächlich hat sich die CPU seit gestern wieder auf hohem CPU Anteil eingependelt.

[MarkSau]

Hier kann man es auch sehen. die CPU Nutzung steigt stetig an.

[Zefau]

geh mal auf die letzte Alpha bitte. Wird es damit besser?

[MarkSau]

mit der alpha 40 sieht es scheinbar besser aus ich beobachte es weiter