SQL-Adapter verursacht hohe CPU-Last

[Urs]

Hallo,

Vor einiger Zeit ist mir aufgefallen dass bei meinem NUC auf dem unter anderem auch IoBroker läuft plötzlich der Lüfter lauter wurde. Weitere Recherchen haben ergeben dass die Prozessorauslastung nicht wie üblich bei 5-15% sondern bei 50% lag.
Stoppte ich den sql-adapter ging auch die CPU-Last wieder runter. Neustart vom Iobroker brachte für ein paar Minuten wieder normale CPU-Werte, nach spätestens einer halben Stunde war die Auslastung bei 30-35%, nach spätestens 1 Stunde wieder auf 50%. Das war vor wenigen Wochen. Abhilfe hat damals ein löschen der Daten in der Datenbank gebracht. Vor ein paar Tagen war es wieder soweit. Wieder das gleiche Problem. In der Datenkbank (MariaDB) hat es etwa 33 MB an Daten, gut eine Halbe Million Datensätze, generiert aus ungefähr 160 Datenpunkte.
MariaDB läuft auf einer separaten Maschine unter Proxmox auf dem gleichen NUC wo auch eine Maschine mit Iobroker läuft. Die MariaDB-Maschine zeigt praktisch keine Last, ca 0.03% CPU Last und knapp 300MB von 2 GB Ram benutzt. Daher denke ich dass der Fehler irgendwo bei Iobroker liegt, hab aber keine Ahnung wie ich den weiter eingrenze.

-i5-7300U NUC, 16 GB,
-Proxmox 6.1-8
-IoBroker auf lxc Container 1, Ubuntu 18.04.4 LTS, 4GB Ram, davon knapp 2 belegt
-MariaDB auf lxc Container 2, Ubuntu 19.10, 2GB Ram, davon knapp 300MB belegt
-Js-Controller 3.1.4
-Node-JS 14.2.0 (Fehler tauchte auch unter 12.xx auf)
-NPM 6.14.5

Hat jemand eine Idee was da schief läuft? Bekanntes Problem? Hab ich irgend was falsch konfiguriert? Braucht ihr noch weitere Infos?

Vielen Dank und Gruss
Urs

PS: Hab noch was im Log gefunden:

2020-06-01 01:53:05.015  - error: sql.0 (4333) Cannot insert INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(149, 1590969182987, 102.571, 1, 10, 0);: Error: ER_DUP_ENTRY: Duplicate entry '149-1590969182987' for key 'PRIMARY' (id: web-speedy.0.Results.speeds.download_Mb)
2020-06-01 01:53:05.017  - error: sql.0 (4333) Cannot insert INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(151, 1590969182997, 28.915, 1, 10, 0);: Error: ER_DUP_ENTRY: Duplicate entry '151-1590969182997' for key 'PRIMARY' (id: web-speedy.0.Results.speeds.upload_Mb)
2020-06-01 01:53:05.024  - error: sql.0 (4333) Cannot insert INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(149, 1590969182988, 12.821375, 1, 10, 0);: Error: ER_DUP_ENTRY: Duplicate entry '149-1590969182988' for key 'PRIMARY' (id: web-speedy.0.Results.speeds.download_MB)
2020-06-01 01:53:05.025  - error: sql.0 (4333) Cannot insert INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(151, 1590969182998, 3.614375, 1, 10, 0);: Error: ER_DUP_ENTRY: Duplicate entry '151-1590969182998' for key 'PRIMARY' (id: web-speedy.0.Results.speeds.upload_MB)

Kann das die Ursache sein? Was sagt mir das genau bzw. was kann ich tun um das zu lösen?

Danke

[Glasfaser]

@Urs

Error: ER_DUP_ENTRY: Duplicate entry

Schau mal mit .... nach ,ober der SQL Adapter doppelt läuft .

ps auxww|grep io

[Urs]

@Glasfaser sagte in SQL-Adapter verursacht hohe CPU-Last:

ps auxww|grep io

iobroker 19851  0.0  3.2 1093532 138412 ?      SNl  07:31   0:06 io.vodafone-speedtest.0
iobroker 19855  0.0  3.0 1083040 126836 ?      SNl  07:31   0:06 io.vodafone-speedtest.0
iobroker 20307  0.0  1.7 808276 73624 ?        SNl  06:05   0:54 io.sql.0
iobroker 23211  0.0  0.0   4624   820 ?        S    12:44   0:00 /bin/sh -c ssh root@192.168.4.5 

SQL scheint nur einmal zu laufen.

Andere wie vodafone-speedtest, daswetter oder weatherunderground laufen aber 2 x. Grund zur Sorge?

Hat vermutlich nichts mit dem Problem zu tun, trotzdem die Frage wieso in der letzten geposteten Zeile oben root@192.168.4.5 steht? Ansonsten läuft mein LAN/WLAN auf 192.168.1.xx. Interne IP oder sowas?

Danke

[rrov1]

Hallo,
ich habe das gleiche Problem mit einem fast identischen Setup. Ursache habe ich noch keine gefunden, ich bin momentan dabei das Logging zu reduzieren, scheint, aber keinen Einfluss auf die CPU Last zu haben.
Rico

[Urs]

@Rico-Rieger Das hatte ich beim ersten mal auch versucht, hatte bei mir nichts gebracht. Erst das löschen der DB hat bei mir damals für Ruhe gesorgt. Aber das ist ja nicht Sinn und Zweck einer DB und somit eigentlich auch keine Lösung. Also wenn Du eine Lösung findest bin ich froh um jede Info.

Die doppelt laufenden Instanzen hab ich vorerst weg gebracht, sei es durch stoppen und neustarten oder neu installieren der entsprechenden Adapter. Hat das ursprüngliche Problem mit der CPU-Last aber nicht behoben.

2020-06-01 01:53:05.015  - error: sql.0 (4333) Cannot insert INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(149, 1590969182987, 102.571, 1, 10, 0);: Error: ER_DUP_ENTRY: Duplicate entry '149-1590969182987' for key 'PRIMARY' (id: web-speedy.0.Results.speeds.download_Mb)
2020-06-01 01:53:05.017  - error: sql.0 (4333) Cannot insert INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(151, 1590969182997, 28.915, 1, 10, 0);: Error: ER_DUP_ENTRY: Duplicate entry '151-1590969182997' for key 'PRIMARY' (id: web-speedy.0.Results.speeds.upload_Mb)
2020-06-01 01:53:05.024  - error: sql.0 (4333) Cannot insert INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(149, 1590969182988, 12.821375, 1, 10, 0);: Error: ER_DUP_ENTRY: Duplicate entry '149-1590969182988' for key 'PRIMARY' (id: web-speedy.0.Results.speeds.download_MB)
2020-06-01 01:53:05.025  - error: sql.0 (4333) Cannot insert INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(151, 1590969182998, 3.614375, 1, 10, 0);: Error: ER_DUP_ENTRY: Duplicate entry '151-1590969182998' for key 'PRIMARY' (id: web-speedy.0.Results.speeds.upload_MB)

Die Fehler hab ich weg gebracht indem ich nur noch die download_MB und upload_MB logge. Scheint als ob Iobroker oder MariaDB MB und Mb nicht case sensitiv behandelt und somit wegen doppelter Einträge motzt...nur eine Vermutung meinerseits.
Nachdem ich das gemacht hatte schien die CPU-Last sich für mehrere Stunden normalisiert zu haben. Freudensprünge hab ich nicht gemacht denn inzwischen ist sie leider wieder bei 30-50%.

Nun hab ich noch 4 SQL-bezogene Warnungen:

sql.0	2020-06-02 23:17:31.298	warn	(7545) No realID found for web-speedy.0.Results.speeds.download_Mb
sql.0	2020-06-02 23:17:31.298	warn	(7545) No realID found for vodafone-speedtest.0.Results.upload_Mb
sql.0	2020-06-02 23:17:31.298	warn	(7545) No realID found for proxmox.0.lxc_Iobroker-Test2.uptime
sql.0	2020-06-02 23:17:31.298	warn	(7545) No realID found for proxmox.0.lxc_Iobroker-Test2.mem_lev
sql.0	2020-06-02 23:17:31.298	warn	(7545) No realID found for proxmox.0.lxc_Iobroker-Test2.cpu

Die 3 Warnungen von Proxmox kommen wohl daher dass es die Maschine Iobroker-Test2 nicht mehr gibt und ich die Datenpunkte in Iobroker gelöscht habe ohne vorher das loggen der 3 zu stoppen. Hab versucht die 3 Datenpunkte nochmal zu erstellen und zu starten, hab die Warnungen aber so nicht weg gebracht.
Warum die ersten beiden kommen, keine Ahnung. Das loggen der beiden Punkte hab ich eigentlich deaktiviert. Aktivieren und wieder deaktivieren hat auch nicht geholfen. Vermutlich hab ich da durch das rumprobieren irgendwelche Leichen in der DB.
Wie bringe ich die weg? (Ob es das ursprüngliche Problem löst steht auf einem anderen Blatt aber einen Versuch ist es Wert)

Danke und Gruss
Urs

[Urs]

Heute hab ich einfach mal ein Backup eingespielt, datiert von kurz bevor die Auslastung laut Proxmox angestiegen ist. Ist mehrere Stunden ohne erhöhte CPU-Last gelaufen. Dann heute Abend alle Adapter aktuallisiert und die CPU Last ging wieder durch die Decke.
Einer davon in Verbindung mit dem SQL-Adapter wird der Übeltäter sein:

Hab keine Lust mehr...gute Nacht...

[Nashra]

Moin, läuft bei dir zufällig der js-controller 3.1.4?
Ich habe zwar nicht sql installiert aber auch das Problem mit extrem hoher CPU-Last.
Mal 10% und dann knallte er hoch auf 60-80%. Habe die Version 2.2.9 wieder
installiert und seitdem läuft es wesentlich ruhiger.

[Urs]

@Nashra Ja, genau, 3.1.4. Du hast nicht zufällig einen Link zur Anleitung wie man downgradet oder gar die benutzen Befehle? Ich muss doch zuerst 3.1.4 deinstallieren oder geht das downgraden auch direkt mittels npm install iobroker.js-controller@2.2.9 --production?

Danke!

[AlCalzone]

@Urs sagte in SQL-Adapter verursacht hohe CPU-Last:
direkt mittels

npm install iobroker.js-controller@2.2.9

Vorher ioBroker stoppen, Backup und den Befehl im ioBroker-Verzeichnis ausführen (/opt/iobroker auf Linux).

[Urs]

@AlCalzone
Danke.
Werde aber noch zuwarten mit downgraden, denn im Moment läuft es mit knapp 10% CPU-Last, aber gut zu wissen wie es geht falls es dann doch nötig ist.

Die im obigen Screenshot gezeigten Adapter hab ich entweder gelöscht weil sie nur zum testen waren (iquontrol, exchange rates und unify) oder nacheinander upgedated (ohne Auffälligkeiten). Bis auf einen, den Vodafone Speedcheck. Da bin ich mir noch nicht sicher ob ich den oder eher den web speedy nehmen soll, muss ich bei Gelegenheit nochmal testen.

Aber durch die ganze Testerei hab ich jetzt verschiedene hässliche Meldungen vom SQL Adapter bzw von MariaDB:

sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for web-speedy.0.Results.server.ping
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for web-speedy.0.Results.speeds.upload_MB
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for web-speedy.0.Results.speeds.download_Mb
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for web-speedy.0.Results.speeds.download_MB
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for vodafone-speedtest.0.Results.ping.packetLoss
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for vodafone-speedtest.0.Results.ping.avg
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for vodafone-speedtest.0.Results.ping.max
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for vodafone-speedtest.0.Results.ping.min
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for vodafone-speedtest.0.Results.upload_Mb
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for vodafone-speedtest.0.Results.upload_MB
sql.0	2020-06-04 03:59:59.727	warn	(3939) No realID found for vodafone-speedtest.0.Results.download_MB

Wie bekomme ich die am bessten weg?

[AxelF1977]

Moin,

ich habe/hatte das Problem auch. Der SQL Adapter beanspruchte teils 80% der CPU, echt krass.

Heute morgen habe ich ein Update auf den JS-Controller 3.1.5 und ich wer erstaut wie die CPU Last abgenommen hat. Der SQL Adapter ist jetzt noch bei ca. 3% Last

Also alle mit Problemen, updaten des JS-Controllers und gucken. Ich bin gespannt ob Ihr das bestätigen könnt.

[Nashra]

Moin, hatte die Tage ja wieder die 2.2.9 installiert womit es etwas ruhiger war
d.h. statt 60-80% waren es nur noch 40-50% CPU. Habe eben den die Neue
3.1.5 draufgehauen, mal sehen wie es jetzt läuft. Werde berichten.

[Urs]

Hallo,

Hab den JS-Controller jetz auch auf 3.1.5 hochgezogen. Keine Ahnung was dabei schief gelaufen ist aber ich hatte etliche Fehler von einigen Adaptern, so im Stil:

gree_aircon.0	2020-06-07 00:53:52.603	warn	(1358) This object will not be created in future versions. Please report this to the developer.
gree_aircon.0	2020-06-07 00:53:52.603	warn	(1358) Object gree_aircon.0.mode is invalid: obj.common.type has an invalid value (text) but has to be one of number, string, boolean, array, object, mixed, file, json

Die konnte ich alle wieder hinbiegen, nur einer noch nicht:

node-red.0	2020-06-07 13:42:11.267	info	(933) node-red exited with 6
node-red.0	2020-06-07 13:42:10.757	warn	(19769) Terminated (UNCAUGHT_EXCEPTION): Without reason
node-red.0	2020-06-07 13:42:09.756	error	at processTicksAndRejections (internal/process/task_queues.js:97:5)
node-red.0	2020-06-07 13:42:09.756	error	at runMicrotasks (<anonymous>)
node-red.0	2020-06-07 13:42:09.756	error	at /opt/iobroker/iobroker-data/node-red/node_modules/huejay/lib/Transport.js:106:15
node-red.0	2020-06-07 13:42:09.756	error	(19769) Error: Huejay: read ECONNRESET
node-red.0	2020-06-07 13:42:09.755	error	(19769) unhandled promise rejection: Huejay: read ECONNRESET
Unhandled	2020-06-07 13:42:09.753	error	promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch().

Von der Auslastung her kann es sein dass er jetzt etwas tiefer ist als vorher (bevor die extremen Auslastungen kamen), das kann ich nicht so genau sagen da ich daneben auch noch alle nicht benötigten Adapter rausgeschmissen habe. Mein NUC nuckelte jetzt die letzten paar Stunden knapp unter 10W / h, was für einen Server wo nebst Iobroker mit fast 30 Adaptern auch noch ein Pihole, eine Datenbank und noch weitere Dienste laufen nicht so schlecht ist. Prozessorauslastung bei 2-7%, alle ca 30 Sekunden kurz 15%. damit kann ich leben.

Das ursprüngliche Problem ist aber nicht gelöst, aber ich konnte die Verursacher etwas weiter eingrenzen. Sobald ich entweder den Vodafone Speedtest oder den Webspeedy aktiviere und davon Daten in die DB schreibe (4-8 Datenpunkte) geht die Auslastung durch die Decke. 30-50% dauerhaft. Stoppe ich z.B. den zuvor gestarteten Webspeedy bleibt die Auslastung bei 30% (der NUC saugt dann satte 25 W). Erst ein Neustart des SQL-Adapters bringt die Auslastung wieder runter. Wäre eine nette Spielerei gewesen die entsprechenden Internet-Geschwindigkeiten aufzuzeichnen, aber so wichtig ist es auch nicht. Hab die beiden jetzt runtergeschmissen und gut ist.

@AxelF1977 Welche Datenpunkte wertest Du bei den von Dir rot eingekreisten Graphs aus?

Hast du es schon versucht Temperaturen aus dem Proxmox zu bekommen und auszuwerten?

Danke und Gruss
Urs

[AxelF1977]

@Urs sagte in SQL-Adapter verursacht hohe CPU-Last:

Hallo,

Hab den JS-Controller jetz auch auf 3.1.5 hochgezogen. Keine Ahnung was dabei schief gelaufen ist aber ich hatte etliche Fehler von einigen Adaptern, so im Stil:

gree_aircon.0	2020-06-07 00:53:52.603	warn	(1358) This object will not be created in future versions. Please report this to the developer.
gree_aircon.0	2020-06-07 00:53:52.603	warn	(1358) Object gree_aircon.0.mode is invalid: obj.common.type has an invalid value (text) but has to be one of number, string, boolean, array, object, mixed, file, json

Die konnte ich alle wieder hinbiegen, nur einer noch nicht:

node-red.0	2020-06-07 13:42:11.267	info	(933) node-red exited with 6
node-red.0	2020-06-07 13:42:10.757	warn	(19769) Terminated (UNCAUGHT_EXCEPTION): Without reason
node-red.0	2020-06-07 13:42:09.756	error	at processTicksAndRejections (internal/process/task_queues.js:97:5)
node-red.0	2020-06-07 13:42:09.756	error	at runMicrotasks (<anonymous>)
node-red.0	2020-06-07 13:42:09.756	error	at /opt/iobroker/iobroker-data/node-red/node_modules/huejay/lib/Transport.js:106:15
node-red.0	2020-06-07 13:42:09.756	error	(19769) Error: Huejay: read ECONNRESET
node-red.0	2020-06-07 13:42:09.755	error	(19769) unhandled promise rejection: Huejay: read ECONNRESET
Unhandled	2020-06-07 13:42:09.753	error	promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch().

Von der Auslastung her kann es sein dass er jetzt etwas tiefer ist als vorher (bevor die extremen Auslastungen kamen), das kann ich nicht so genau sagen da ich daneben auch noch alle nicht benötigten Adapter rausgeschmissen habe. Mein NUC nuckelte jetzt die letzten paar Stunden knapp unter 10W / h, was für einen Server wo nebst Iobroker mit fast 30 Adaptern auch noch ein Pihole, eine Datenbank und noch weitere Dienste laufen nicht so schlecht ist. Prozessorauslastung bei 2-7%, alle ca 30 Sekunden kurz 15%. damit kann ich leben.

Das ursprüngliche Problem ist aber nicht gelöst, aber ich konnte die Verursacher etwas weiter eingrenzen. Sobald ich entweder den Vodafone Speedtest oder den Webspeedy aktiviere und davon Daten in die DB schreibe (4-8 Datenpunkte) geht die Auslastung durch die Decke. 30-50% dauerhaft. Stoppe ich z.B. den zuvor gestarteten Webspeedy bleibt die Auslastung bei 30% (der NUC saugt dann satte 25 W). Erst ein Neustart des SQL-Adapters bringt die Auslastung wieder runter. Wäre eine nette Spielerei gewesen die entsprechenden Internet-Geschwindigkeiten aufzuzeichnen, aber so wichtig ist es auch nicht. Hab die beiden jetzt runtergeschmissen und gut ist.

@AxelF1977 Welche Datenpunkte wertest Du bei den von Dir rot eingekreisten Graphs aus?

Hast du es schon versucht Temperaturen aus dem Proxmox zu bekommen und auszuwerten?

Danke und Gruss
Urs

Hi Urs,

in den beiden Fällen sind es proxmox.0.node_homeserver.cpu und proxmox.0.qemu_iobroker.cpu bei mir.

Auch nach mehr als einem Tag ist die Last bedeutend besser geworden. Für meinen Teil hat sich das Update gelohnt

[Urs]

@AxelF1977 Danke

[AxelF1977]

@Urs sagte in SQL-Adapter verursacht hohe CPU-Last:

@AxelF1977 Danke

Gerne, bin ja froh wenn ich auch mal helfen kann, und mir nicht nur geholfen wird

[Nashra]

Moin, nach dem Update auf 3.1.5 ging es stetig aufwärts mit der Last. Heute Morgen
gegen 6 Uhr ging es radikal nach unten und im Log waren auch sehr viele Fehler kurz davor.
Mal sehen ob es wieder hoch geht oder sich beruhigt hat. Achja, die Extremspitzen waren
bei mir vom Adapter "DasWetter", warum auch immer.

[AxelF1977]

@Nashra sagte in SQL-Adapter verursacht hohe CPU-Last:
Achja, die Extremspitzen waren

bei mir vom Adapter "DasWetter", warum auch immer.

Kann ich bestättigen, Das Wetter und hue-extended verursachen bei mir auch eine höhere Last aktuell. Noch vor dem Javascript Adapter, die ansich gut zu tun hat.

MySQL bleibt bei ca. 3%

[Nashra]

Nicht falsch verstehen, man sieht diese Spitzen hier sehr schlecht. Es war alles auf sehr hohem Niveau am laufen,
nur DasWetter haute noch mehr drauf. Die anderen Adapter waren auch für die hohe Last verantwortlich wie man
ja sieht. Komisch ist/war nur das es langsam angestiegen ist über ca. 24 Std. und heute Morgen dieser Einbruch
kam. Mal sehen was in den nächsten Stunden passiert.

[Urs]

Einen kontinuierlichen Anstieg wie bei Dir konnte ich nicht beobachten. Aber trotzdem komisch, denn auch bei mir ist heute Nacht was los gewesen. Allerdings etwas früher und in die andere Richtung:

Einen eindeutigen Schuldigen konnte ich bisher nicht ausmachen. Bis auf den system.host.iobroker-Live der im Moment zwischen 5 und 10% CPU Last pendelt (vermutlich normal dass der erhöht ist?) scheinen alle anderen Adapter keine übermässigen CPU-Zeiten aufzuweisen. Aber da ich die Werte bisher nicht aufgezeichnet und auch nicht wirklich angeschaut habe ist es schwierig konkrete Aussagen dazu zu machen. Im Log hab ich auf die schnelle auch nichts wirklich auffälliges gefunden.

Daswetter hat bei mir seit gestern gerade mal 0.35s cputime, ist aber auch alive = false. ist das bei euch auch so? Ist der nur alive wenn er Daten holt? Das wäre dann bei mir nur alle 30 Minuten.