Device Watcher makes 100% CPU load of js-controller

[Roellen]

Describe the bug
I Installed Device watcher, then CPU load always goes 100% of the js-controller and the hole ioBroker system was un-usable. Needed help of another developer to find that device watcher was the problem.

Versions:

• Adapter version: v2.9.6
• JS-Controller version: 5.0.17
• Node version: 18.19.0
• Operating system: Debian 11 Bulls Eye

Additional context
Not sure what causes the problem. I can give teamviewer access to my old system where the problem happens in case someone wants to check the problem. Other then that... if no one else has the problem, it might be my own fault. Who knows. It seems that the problem happens after installing the new JS controller version.

[splizz1st]

I have the same issue with my installation:

maybe the log can help: iobroker.2023-12-29.log.gz

[Roellen]

I think I made the problem myselfs by hitting all buttons so that EVERYTHING is beeing „watched“. Well… at the same time I tried to update nodejs, which went wrong. So I thought THIS was the problem and I never tried to stop all instances and start them one after each other to see if any instance makes this problem.

It seems that device watcher can check A LOT datapoints and that seems to stress the js controller. Funny thing is, the device watcher instance itselfs just has very low cpu usage. So… not that easy to find the problem.

I failed to find it, only one of the developers found my problem in the end.

Actually I installed home assistant to see if my devices are working ok. Worked fine.

But now ioBroker works fine again. Database has been changed to Redis, and that lowers cpu usage also as I have more then 200.000 datapoints.

[ciddi89]

Ich antworte mal auf deutsch, denke das ist am einfachsten. :)

Ist natürlich Mist und ich versuche Code mäßig da was zu machen. Nichts desto trotz denke ich das indirekt ein anderer Adapter dafür verantwortlich ist und der device watcher nur der Auslöser ist weil er die states abonniert. Daher hat der watcher selber eine geringe CPU Last und der js-Controller geht hoch. Das heißt das sich wohl möglich einige Datenpunkte die der watcher abonniert hat ständig ändern, ist meine Theorie kann mich aber auch irren. Vielleicht kann man, um das herauszufinden, das selbe im device watcher machen wie mit den Instanzen. Ein Adapter nach dem nächsten abonnieren um den Übeltäter zu finden. Der watcher abonniert auch nur die Datenpunkte die er wirklich braucht und die auch verfügbar sind.

Ich werde aber mal andere Adapter angucken, wie die das handhaben. Im discord war das Problem wohl schon im Gespräch. Werde auf jeden Fall die Tage nach einer Lösung schauen und versuchen diese umzusetzen. Hab schon eine Idee.

[splizz1st]

Ich vermute das es bei mir am Shelly-Adapter liegt. Wenn ich z.B. meinen Router neustarte, kriege ich viele Fehler vom Shelly-Adapter. Daraufhin reagiert vermutlich der device-watcher und es landet in einer Endlosschleife. Ich kriege das Problem nur durch einen Neustart meiner Proxmox-VM gelöst.

Danke dir für deine Arbeit!

[Roellen]

Interessant. Weil... den Shelly adapter hatte ich auch in Verdacht als ICH das Problem hatte. Ich hatte schon ein Issue beim Shellyadapter aufgemacht, dann aber wieder gelöscht, weil's doch nicht daran lag. Bzw.. vermutlich lag es indirekt am Shelly Adapter, weil der Device Watcher vielleicht "zu viel/oft" die Datenpunkte vom Shelly Adapter abfragt.

[ciddi89]

hmm okay werde ich mal im Hinterkopf behalten und vielleichten müssen wir das mal testen um es auszuschließen. Gerade bin ich dabei die Funktionen im watcher so umzuschreiben das er bei den state changes nicht mehr so loop lastig ist und wenn möglich Schleifen zu vermeiden. Vielleicht hilft das auch schon.

[ciddi89]

Soo hab das handling nun mit v2.9.12 geändert. Kann aber nicht garantieren das es auch was gebracht hat. Und kann vielleicht auch neue Fehler bringen. Leider hat mein Testsystem nicht so viel Auswahl an Instanzen und Geräten um es bestmöglich zu testen.

Was mir aber aufgefallen ist: Ich habe gerade auf mein System auch den js-controller über die Weboberfläche aktualisiert. Das mochte der device-watcher aber definitiv nicht, da er die Verbindung über die abonnierten Objekte und States verliert. Dadurch ging auch bei mir die CPU und der Ram extrem hoch. Und es gab diverse Warnungen darüber im Log. Aber nach einem Neustart des Adapters war wieder alles okay. Nur falls andere das Problem dann auch haben. Weiss auch noch nicht wie ich so einen Fall behandeln soll. Kommt ja nun nicht oft vor. Werde mir aber Gedanken darüber machen. :)

// EDIT:

Okay ich muss wohl doch noch mal gucken was da genau los ist. Wenn man eine Instanz mit vielen Geräten einschaltet. (In meinem Fall Zigbee2MQTT) Dann geht auch bei mir wieder alles hoch und hält sich so bei 55-75% CPU Last. Startet man Device Watcher neu ist wieder alles normal. Hm wirklich komisch da das vor dem js-controller Update nicht so war. Zumindest bei mir.

[arteck]

jo hier auch.. update auf 2.9.12 gehen die io hoch.. beendest du den adapter ordentlich.. ?? die io stiegen erst nach dem adapter update.. musste den per hand stoppen..

die 2.9.11 läuft aber.. wobei ich nur zwave und zigbee überwache

[mctom]

Hallo zusammen,

vielleicht hilft es bei der Analyse. Ich habe auch mit der 2.9.12 Probleme. Downgrade auf 2.9.11 bringt wieder alles in Ordnung. Folgendes habe ich im Log gefunden, vielleicht hilft das:

2024-01-03 11:17:48.328 - error: host.ioBroker Caught by controller[0]: <--- Last few GCs --->
--
2024-01-03 11:17:48.328 - error: host.ioBroker Caught by controller[0]: [1602:0x580a5e0] 187355 ms: Scavenge (reduce) 2042.0 (2083.0) -> 2042.0 (2083.8) MB, 4.4 / 0.0 ms (average mu = 0.301, current mu = 0.314) allocation failure;
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[0]: [1602:0x580a5e0] 187413 ms: Scavenge (reduce) 2042.9 (2083.8) -> 2043.0 (2084.0) MB, 5.6 / 0.0 ms (average mu = 0.301, current mu = 0.314) allocation failure;
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[0]: [1602:0x580a5e0] 187421 ms: Scavenge (reduce) 2043.0 (2084.0) -> 2043.0 (2084.8) MB, 4.7 / 0.0 ms (average mu = 0.301, current mu = 0.314) allocation failure;
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[0]: <--- JS stacktrace --->
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[0]: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[1]: 1: 0xb85bc0 node::Abort() [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[2]: 2: 0xa94834 [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[3]: 3: 0xd66d10 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[4]: 4: 0xd670b7 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[5]: 5: 0xf447c5 [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[6]: 6: 0xf456c8 v8::internal::Heap::RecomputeLimits(v8::internal::GarbageCollector) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[7]: 7: 0xf55bd3 [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[8]: 8: 0xf56a48 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[9]: 9: 0xf313ae v8::internal::HeapAllocator::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[10]: 10: 0xf32777 v8::internal::HeapAllocator::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[11]: 11: 0xf12cc0 v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[12]: 12: 0xf0a734 v8::internal::FactoryBase::AllocateRawWithImmortalMap(int, v8::internal::AllocationType, v8::internal::Map, v8::internal::AllocationAlignment) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[13]: 13: 0xf0c9e8 v8::internal::FactoryBase::NewRawOneByteString(int, v8::internal::AllocationType) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[14]: 14: 0xf15fad v8::internal::Factory::NewStringFromUtf8(v8::base::Vector const&, v8::internal::AllocationType) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[15]: 15: 0xd75dc3 v8::String::NewFromUtf8(v8::Isolate*, char const*, v8::NewStringType, int) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[16]: 16: 0xc6f629 node::StringBytes::Encode(v8::Isolate*, char const*, unsigned long, node::encoding, v8::Local*) [io.device-watcher.0]
2024-01-03 11:17:48.329 - error: host.ioBroker Caught by controller[17]: 17: 0xb5aaca [io.device-watcher.0]
2024-01-03 11:17:48.330 - error: host.ioBroker Caught by controller[18]: 18: 0x168b3af [io.device-watcher.0]
2024-01-03 11:17:48.330 - warn: host.ioBroker instance system.adapter.device-watcher.0 terminated due to SIGABRT
2024-01-03 11:17:48.330 - info: host.ioBroker instance system.adapter.device-watcher.0 terminated with code null ()
2024-01-03 11:17:48.330 - info: host.ioBroker Restart adapter system.adapter.device-watcher.0 because enabled

[ciddi89]

okay habe nun den Fehler gefunden wegen der hohen CPU last und mit der neusten Version v2.9.13 sollte wieder alles wie gewohnt laufen. Ursache war das bei einem ObjectChange die main function haufenweise ausgeführt worden ist. Komisch das es vorher noch nie aufgefallen ist, da es schon länger falsch dort drin steht. Alle anderen Fehler min 2.9.12 sollten auch wieder weg sein.

[Horgul123]

@ciddi89 Danke für den Fix! Wollte grad ein Issue aufmachen, weil iobroker Amok lief :P

[Horgul123]

Zu früh gefreut.... 2.9.13 frisst aktuell 75% CPU :( Beruhigt sich auch nicht... Und auch wenn ich die Instant stoppe (via Admin) läuft der Prozess weiter.... Irgendwas stimmt da noch nicht.....

[splizz1st]

Das hatte ich heute auch. Der Adapter sorgte auch nach Deaktivierung für hohe CPU.

[Horgul123]

ein "kill -9 " hat ihn "entsorgt.....

[ciddi89]

hmm vielleicht von der 2.9.12 version noch nicht richtig beendet? vielleicht komplett killen und dann die neue version neu starten. Bei mir macht er derzeit was er soll

[Horgul123]

Nö. Geht sofort wieder auf 75% CPU Verbrauch :(

[ciddi89]

verstehe ich nicht. hast mal n log?

[Horgul123]

Müsst ich morgen machen. Muss gleich weg... Was genau brauchst Du?

[Ilovegym66]

2.9.13 bei mir gibts keine Fehler im Log, aber hat schon 4GB Ram im beschlag... wieder zurueck auf 2.9.11.

[ciddi89]

Am besten Adapter auf debug stellen um zu sehen ob er irgendwas mehrfach ausführt oder irgendwo drin hängen bleibt.

Interessant. Bei mir dümpelt er zwischen 80-90 rum. Werde das subscribe der states wieder auf einzelnd stellen so wie es von Anfang an war vielleicht ändert sich das Verhalten dann wieder. Melde mich dann nochmal und vielleicht kann dann einer vorab die GitHub Version testen bevor ich wieder eine Version veröffentliche.

Die 2.9.12 habe ich auf npm wieder rausgenommen. War erschrocken wieviele auf latest rumdümpeln und nicht stable laut den install zahlen. 😂

[ciddi89]

hab nun die GitHub version angepasst und wieder umgestellt auf einzelsubscribe. Wenn einer testen mag. Wenn der Fehler dann weiterhin auftaucht könnte man zumindest dies ausschliessen. Soviel große unterschiede gibt es dann aber auch nicht mehr zur vorherigen Version.

[Horgul123]

Sieht gut aus! Pendelt sich bei mir so auf 4% ein. Damit ist der Fehler wohl eingegrenzt :)

[arteck]

2.9.13 nimmt sich genauso viel CPU wie die .12 ..

zurück auf die .11

[ciddi89]

Über GitHub link installiert?

[arteck]

ne jetzt aber

wobei .. guck dir mal das beenden des adapter an

[ciddi89]

Ja sollte noch von der alten Version sein. Oder nicht?

[arteck]

jo hast recht.. sieht gut aus mit der GIT version

[ciddi89]

Ok danke für die Rückmeldung 👍🏻

[ciddi89]

Wie sieht die Situation beim issue Ersteller aus mit der Version 2.9.14? Immer noch Probleme mit der CPU? @Roellen

[Roellen]

Weis nicht. Moritz hatte das Problem bei mir über Teamviewer einsgeschränkt und dann hatten wir den Adapter gelöscht. Soll ich den Adapter nochmal installieren um dann zu gucken ob alles normal laufen würde?

[ciddi89]

@Roellen wäre nett, aber kein Muss. Dann wüsste man wenigstens ob das was gebracht hat und ich kann das Thema schließen. Aber wenn dir das zu riskant ist dann lieber nicht.

[Roellen]

Ok, hab's installiert (2.9.14). Leben muss ja weiter gehen. :-)

Ich habe die Sachen die ich so habe angehakt (wie damals mit 100% CPU last auch) aber jetzt bleibt die CPU Last überwiegend bei 0,4%. (was auch vor der Adapterinstallation so war).

Sieht also alles sehr gut aus jetzt!

Allerdings benutze ich inzwischen auch Redis als Datenbank. (was bei vielen Datenpunkten generell besser performen soll. (ich hab 200.000 Objekte bei mir)

[ciddi89]

Okay super dann kann ich das ja erstmal schliessen. Falls doch noch wieder was sein sollte dann einfach melden. ;)