History: Restart alle paar Minuten - Downgrade geht nicht
-
Admin ist
2018-03-21 10:16:38.917 - [32minfo[39m: admin.0 starting. Version 2.0.9 in /opt/iobroker/node_modules/iobroker.admin, node: v6.13.1Controller
`2018-03-21 10:16:32.839 - [32minfo[39m: host.orangepiplus2e iobroker.js-controller version 1.2.3 js-controller starting[/code]` Habe jetzt mal nur das Nötigste am Laufen. Alles stable Versionen, von daher sollte es keinerlei Probleme haben. ~~[quote]~~ Das erste History enablen geht immer flott, bei Folgeaktionen dauert es immer lämnger. Wie oft schaltest DU das einund aus? :-) Or jetzt zum testen? ~~[quote]~~ Hatte auch schon früher ab und an ein reconnect DB, aber ohne den history Neustart. Das Reconnect weist an sich darauf hin das ggf zuviel Last auf dem System ist. Diese "States-DB" ist eine "in-memory-DB" auf Port 900x und wird vom jscontroller bereitgestellt. Darüber bekommt der Adapter Zugriff auf die States inkl. Updates und so. Ein "Reconnect" heisst dasdie Verbindung weg war und das sollte an sich nicht vorkommen. ~~[quote]~~ Wenn Du sagst, daß Dein "neuestes" System stabil läuft, dann kann ich mal eine nächtliche Neuinstallation wagen. ` ` Das "neuestes" hast Du reingemogelt ... Mein System hab ich vor 2 Jahren installiert und seitdem nur geupdatet ... Das System läuft aber auf dem Latest Repo und nicht "Stable". ~~[quote]~~ Bin immer nur unsicher welches node, npm etc mit was kompatibel ist und wie man dann das richtige zusammenbekommt. ` ` Es sei denn DU brauchst spezielle Adapter ist nodejs 4.x mit npm 3 (was da standard ist) immer noch passend. Node 6 geht auch. node 8 ist grenzwertig :-) Nodejs 4 ist noch bis April offiziell supported, dann sollte man Richtung nodejs 6 gehen. (oder halt 8) ` ` ` ` ``` ` -
Beim Einschalten von web meldet sich history und sagt etwas von "parallel requests". Hat das was zu bedeuten? `
Das sind "getHistory"-Abfragen von flot/riskshaw. "parallel requests" heisst an der Stelle das zur Verarbeiten und Sammeln der Statistikdaten mehrere Threads verwendet werden - ist aber nur zur Datenaufbereitung.
Wieviele Datenpunkte hast Du aktiv im History-Adapter?
-
Danke, ein paar hundert, HM komplett. Das aber schon lange und die Zahl hat sich in jüngster Zeit kaum erhöht.
Bin unterwegs, schaue heute Abend nach der Zahl
-
Wie geht es denn dem System so? Bedenke das "History" das ganze in JSON-Files auf die Platte legt und ggf immer das ganze File neu schreibt wenn Daten dazukommen. Das ist recht viel "I/O", was sich ggf dann in CPU-Auslastung ausdrückt.
Die Alternativen wie SQL oder InfluxDB sind ab einer gewissen Größe vorzuziehen
-
Bis vor der letzten Updaterunde ging es dem System entspannt und jetzt auch noch - wenn nicht gerade die history-enable Geschichte einsetzt oder sich gerade hochschaukelt.
CPU-Auslastung zwischen 0.05 bis 0.5 selten mehr im Normalbetrieb.
Die "reconnect DB" gab es wie gesagt früher auch ab und an aber ohne Folgeaktionen seitens history.
Zur Zahl der subscibierten items: Die HM-Adapter habe ich seinerseits alle global subscribiert. Das läuft schon lange so. Dann noch einige Werte von diversen ESP8266 über simpleApi, wenig tradfri, Xiami robovac, seit einiger Zeit ein wenig sonoff und vielleicht 15 RFLink Geräte.
Habe jetzt im Logfile die Anzahl Zeilen der history-enable events gezählt.
Beim ersten Durchlauf waren es um 7700 und beim zweiten um 11617 Zeilen.
Ich habe ersten nicht verstanden warum es so viele sind (so viele Geräte habe ich nicht) und warum die Zahl von Durchlauf zu Durchlauf schwankt.
Die History-Daten werden auf eine 32GB SSD geschoben, die via USB-Sata-Adapter angebunden ist. Ist aber schon geraume Zeit so und war bis zur letzten update session auch stabil.
Pro Tag werden normalerweise 5 bis 6 MByte history-Daten erzeugt. Das geht schon geraume Zeit so problemlos.
Mit MySQL und Influx kenne ich mich noch gar nicht aus.
Wenn mein PC läuft sind oft 20 browser Tabs mit FLOT-Diagrammen auf. Da sieht man dann nach dem Hochfahren aus dem Resume mode auch mal 70 "Connected system.user.admin" im Logfile, die der Frefox wohl im Hintergrund generiert.
-
Und das ist im echten Logfile auch alles so mit mehreren Enabled und allem ?! Oder ist da alles einmal und ok ?
-
Danke für Deine Geduld.
Aus dem Logfile (/opt/iobroker/log/iobroker.log.2018-03-20) eines Starts von gestern. Das ist das kleinste history-enable Ereignis der letzten Tage was ich auf die Schnelle finden konnte. history-log war da noch auf info.
Startet mit
!
2018-03-20 09:44:23.139 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE 2018-03-20 09:44:23.145 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL 2018-03-20 09:44:23.148 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG 2018-03-20 09:44:23.150 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_SHORT 2018-03-20 09:44:23.195 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.LEVEL 2018-03-20 09:44:23.198 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_LONG 2018-03-20 09:44:23.205 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_SHORT 2018-03-20 09:44:23.212 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.LEVEL 2018-03-20 09:44:23.220 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.PRESS_LONG 2018-03-20 09:44:23.226 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.PRESS_SHORT 2018-03-20 09:44:23.255 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.LEVEL 2018-03-20 09:44:23.269 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.PRESS_LONG 2018-03-20 09:44:23.272 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.4.PRESS_SHORT !endet mit
!
2018-03-20 09:44:31.558 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_5.SWITCH_07 2018-03-20 09:44:31.559 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_5.SWITCH_0a 2018-03-20 09:44:31.560 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_5.SWITCH_0e 2018-03-20 09:44:31.562 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterToday 2018-03-20 09:44:31.563 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterUntilMidnight 2018-03-20 09:44:31.564 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounter 2018-03-20 09:44:31.565 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-DoorClosed 2018-03-20 09:44:31.566 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_07 2018-03-20 09:44:31.568 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_0a 2018-03-20 09:44:31.569 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_0e 2018-03-20 09:44:31.570 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_07 2018-03-20 09:44:31.571 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_0e 2018-03-20 09:44:31.573 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_0a !
auf Zeite 3846, gezählt mit notepad++Also keine unmittelbaren Doppelungen und läuft rasch durch.
Habe eine Stichprobe von 10 Zeilen auf Doppelungen untersucht
Ausbeute:
! ```
2018-03-20 09:44:29.745 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.IEQ0243774.0.CONFIG_PENDING_ALARM[/code]
...
~~[code]~~2018-03-20 09:44:25.683 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.IEQ0243774.0.CONFIG_PENDING [/code] -
Und wie gesagt: Logfile hat recht. Also hast du ca. 2846 Datenpunkte im History aktiviert. Ist erstmal ok so. alles gut.
Jetzt die nächste Frage: Wie oft kommt denn diese "enabled" Arie im echteh Logfile? Sollte nur EINMALIG kommen wenn der History-Adapter gestartet wird. Danach sollte das einfach laufen.
-
Ja, so war das auch das letzte Jahr seit ich auf den OPI umgezogen bin und ich hatte logfiles von 10k bis 60k /Tag. Aber seit der letzten update-Runde startete history enable nach jedem "reconnect DB", was vorher nicht der Fall war und von diesen reconnect DB gab es auch mehr. In Abständen von ca. 10, 20, 60 Minuten. Scheint eher "zufällig" Das logfile schwoll auf 20 MB an, fast nur history enabled Einträge, history log Infostufe.
Habe gestern um 10:20 ioBroker mit den wichtigsten Adaptern gestartet und erst mal Ruhe.
Habe gestern Abend um 20:34 RFLink zugeschaltet und dort ein neues Gerät eingebaut.
Heute um 00:14 gab es wieder ein event (history log debugstufe)
!
2018-03-22 00:14:35.614 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.0.LEQ053xxxx.2.POWER, last-value=0.06, new-value=0.05, ts=1521674067985 2018-03-22 00:14:35.616 - [34mdebug[39m: history.0 value not changed hm-rpc.0.LEQ0539xxxx.2.CURRENT, last-value=0, new-value=0, ts=1521674067990 2018-03-22 00:14:35.618 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.0.LEQ053xxxx.2.VOLTAGE, last-value=232.2, new-value=232.8, ts=1521674067992 2018-03-22 00:14:35.620 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.0.LEQ053xxxx.2.FREQUENCY, last-value=49.98, new-value=49.99, ts=1521674067993 2018-03-22 00:14:36.726 - [34mdebug[39m: history.0 statesDB connected 2018-03-22 00:14:36.786 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-22 00:14:36.852 - [34mdebug[39m: history.0 statesDB connected 2018-03-22 00:14:36.892 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-22 00:14:37.083 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-22 00:14:37.109 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-22 00:14:37.221 - [34mdebug[39m: history.0 value not changed hm-rpc.1.CUX9000009.1.STATE, last-value=0, new-value=0, ts=1521674077201 2018-03-22 00:14:37.224 - [34mdebug[39m: history.0 value not changed hm-rpc.1.CUX9000007.1.STATE, last-value=3, new-value=3, ts=1521674077207 2018-03-22 00:14:37.825 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.updated 2018-03-22 00:14:37.826 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE 2018-03-22 00:14:37.828 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL 2018-03-22 00:14:37.828 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG 2018-03-22 00:14:37.829 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_SHORT 2018-03-22 00:14:37.829 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.LEVEL 2018-03-22 00:14:37.830 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_LONG 2018-03-22 00:14:37.831 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_SHORT 2018-03-22 00:14:37.831 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.LEVEL !
…...2018-03-22 00:14:51.387 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_5.SWITCH_0a 2018-03-22 00:14:51.388 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_5.SWITCH_0e 2018-03-22 00:14:51.389 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterToday 2018-03-22 00:14:51.390 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounterUntilMidnight 2018-03-22 00:14:51.391 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-doorCounter 2018-03-22 00:14:51.392 - [32minfo[39m: history.0 enabled logging of data.0.motion.Hobby-DoorClosed 2018-03-22 00:14:51.393 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_07 2018-03-22 00:14:51.394 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_0a 2018-03-22 00:14:51.394 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_6.SWITCH_0e 2018-03-22 00:14:51.395 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_07 2018-03-22 00:14:51.396 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_0e 2018-03-22 00:14:51.397 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_8.SWITCH_0a 2018-03-22 00:14:51.398 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_07 2018-03-22 00:14:51.398 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_0e 2018-03-22 00:14:51.399 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_0a 2018-03-22 00:15:56.060 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.1.CUX9002008.1.DEW_POINT, last-value=-3.1, new-value=-3.14, ts=1521674156052 2018-03-22 00:15:56.072 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.1.CUX9002008.1.ABS_HUMIDITY, last-value=3.74, new-value=3.73, ts=1521674156059 2018-03-22 00:17:37.412 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ051xxxx.1.TEMPERATURE, last-value=19.4, new-value=19.4, ts=1521674257398 2018-03-22 00:17:37.434 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ051xxxx.1.HUMIDITY, last-value=37, new-value=37, ts=1521674257421 2018-03-22 00:17:44.117 - [34mdebug[39m: history.0 value not changed hm-rpc.0.MEQ04xxxx.4.CONTROL_MODE, last-value=0, new-value=0, ts=1521674264108 2018-03-22 00:17:44.127 - [34mdebug[39m: history.0 value not changed hm-rpc.0.MEQ044xxxx.4.FAULT_REPORTING, last-value=0, new-value=0, ts=1521674264118 2018-03-22 00:17:44.139 - [34mdebug[39m: history.0 value not changed hm-rpc.0.MEQ044xxxx.4.BATTERY_STATE, last-value=2.4, new-value=2.4, ts=1521674264131 2018-03-22 00:17:44.166 - [34mdebug[39m: history.0 value not changed hm-rpc.0.MEQ044xxxx.4.VALVE_STATE, last-value=0, new-value=0, ts=1521674264137 2018-03-22 00:17:44.173 - [34mdebug[39m: history.0 value not changed hm-rpc.0.MEQ044xxxx.4.BOOST_STATE, last-value=0, new-value=0, ts=1521674264139 >! ```` -
Wenn du "ps auxww|grep history" machst kommt dann da ein Prozess oder laufen echt zwei?
-
Zur Zeit sieht es so aus:
root@orangepiplus2e:~# ps auxww|grep history root 16753 0.0 0.0 3668 756 pts/0 S+ 10:16 0:00 grep history root 28003 2.7 1.2 137476 25452 ? Sl Mar21 39:24 io.history.0 root@orangepiplus2e:~# -
Schonmal gut, nur ein Prozess. Was das log das sagt ist eeecht strange …
Am ENd ebin ich aber dabei: Finde den Grund für die Reconnect-DBs! ... Wie: keine ahnung
-
Aus meiner Sicht sind es zei Themen:
-
reconnect DB. Das habe ich schon seit Anfang des Jahres viewtopic.php?p=118988#p118988 . Bisher aber friedlich ohne sichtbare Auswirkungen.
-
Jetzt startet aber history eine Runde enable nach dieser Fehlermeldung. Die neuen histories haben dann dummerweise auch noch den letzten Datenpunkt wiederholt eingetragen, was meine Kurven von täglich (nur einmal täglich) gemessenen Werten verunstaltet. Wahrscheinlich ein gewolltes Feature, was in meiner Konstellation aber unschön ist.
Wenn ich wüsste, dass eine Neuinstallation hülfe, könnte ich eine Nachtschicht einlegen. Habe gerade Urlaub.
Wenn ich wüßte wie dem connection loss auf die Spur kommen kann würde ich natürlich auch das tun. Aber dazu reichen meine EDV-Kenntnisse nicht. Hätte nicht mal bei Windows ne Idee, geschweige den bei Linux. Wenn es keine passenden Logs oder Ereignisanzeigen gibt, wüßte ich auch nicht wo man heutzutage noch nachschauen kann. Glaube nicht, daß das an der SSD liegt, so langsam ist die auch wieder nicht - zumindest nicht an Windows.
-
-
Heute um 00:11, ebenfalss "ex nihilo"
!
hm-rpc.0.IEQ0067710.2.ADJUSTING_DATA, last-value=0, new-value=0, ts=1521760246507 2018-03-23 00:11:06.763 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ015xxxx.1.VALVE_STATE, last-value=0, new-value=0, ts=1521760246620 2018-03-23 00:11:06.765 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ015xxxx.1.ERROR, last-value=0, new-value=0, ts=1521760246629 2018-03-23 00:11:07.946 - [34mdebug[39m: history.0 statesDB connected 2018-03-23 00:11:08.129 - [34mdebug[39m: history.0 statesDB connected 2018-03-23 00:11:08.175 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-23 00:11:08.419 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-23 00:11:08.688 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-23 00:11:08.713 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-23 00:11:09.477 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.updated 2018-03-23 00:11:09.479 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE 2018-03-23 00:11:09.480 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL !
….2018-03-23 00:11:31.664 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_0a 2018-03-23 00:11:31.665 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.ElroDB_1.CHIME_1 2018-03-23 00:11:31.666 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.ElroDB_1.SWITCH_1 2018-03-23 00:11:31.666 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.Eurodomest_1.SWITCH_02 2018-03-23 00:11:31.667 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_10.SWITCH_0d 2018-03-23 00:11:31.668 - [32minfo[39m: history.0 enabled logging of data.0.leakage.Treppe 2018-03-23 00:13:36.300 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ0510473.2.ADJUSTING_COMMAND, last-value=0, new-value=0, ts=1521760416286 2018-03-23 00:13:36.323 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ0510473.2.ADJUSTING_DATA, last-value=12, new-value=12, ts=1521760416298 2018-03-23 00:13:36.415 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ0513285.1.VALVE_STATE, last-value=5, new-value=5, ts=1521760416407 >! ```` Aber schnell durchgelaufen < 1min. um 04:25 mihome adapter gesartet um 04:32 der nächste history Neustart >! ```` 2018-03-23 04:32:49.918 - [34mdebug[39m: history.0 Min-Delta ignored because no number hm-rpc.0.JEQ004xxxx.1.STATE, last-value=true, new-value=false, ts=1521775937571 2018-03-23 04:32:49.921 - [34mdebug[39m: history.0 Min-Delta ignored because no number hm-rpc.0.JEQ004xxxx.1.WORKING, last-value=true, new-value=false, ts=1521775937582 2018-03-23 04:32:49.974 - [34mdebug[39m: history.0 value not changed rflink.0.channels.SelectPlus_1.CHIME_02, last-value=1, new-value=1, ts=1521775941299 2018-03-23 04:32:50.006 - [34mdebug[39m: history.0 value not changed hm-rpc.0.MEQ0272133.2.BOOT, last-value=true, new-value=true, ts=1521775948623 2018-03-23 04:32:50.011 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.0.MEQ0272133.2.FREQUENCY, last-value=49.99, new-value=50.01, ts=1521775948637 2018-03-23 04:32:50.314 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-23 04:32:50.433 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-23 04:32:51.268 - [34mdebug[39m: history.0 statesDB connected 2018-03-23 04:32:51.320 - [34mdebug[39m: history.0 statesDB connected 2018-03-23 04:32:57.659 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ051xxxx.2.ADJUSTING_COMMAND, last-value=0, new-value=0, ts=1521775977638 2018-03-23 04:32:57.664 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ051xxxx.2.ADJUSTING_DATA, last-value=36, new-value=36, ts=1521775977648 2018-03-23 04:32:57.692 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-23 04:32:57.734 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-23 04:32:58.148 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ051xxxx.1.VALVE_STATE, last-value=14, new-value=14, ts=1521775978121 2018-03-23 04:32:58.150 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ051xxxx.1.ERROR, last-value=0, new-value=0, ts=1521775978127 2018-03-23 04:32:58.349 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.updated 2018-03-23 04:32:58.351 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE 2018-03-23 04:32:58.353 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL 2018-03-23 04:32:58.354 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG 2018-03-23 04:32:58.355 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_SHORT 2018-03-23 04:32:58.356 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.LEVEL 2018-03-23 04:32:58.356 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_LONG >! ```` ….2018-03-23 04:33:29.705 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_0e
2018-03-23 04:33:29.705 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_0a
2018-03-23 04:33:29.706 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.ElroDB_1.CHIME_1
2018-03-23 04:33:29.707 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.ElroDB_1.SWITCH_1
2018-03-23 04:33:29.708 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.Eurodomest_1.SWITCH_02
2018-03-23 04:33:29.709 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_10.SWITCH_0d
2018-03-23 04:33:29.709 - [32minfo[39m: history.0 enabled logging of data.0.leakage.Treppe
2018-03-23 04:35:30.168 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ015xxxx.1.TEMPERATURE, last-value=18.2, new-value=18.2, ts=1521776130161
2018-03-23 04:35:30.234 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ015xxxx.1.HUMIDITY, last-value=53, new-value=53, ts=1521776130166
2018-03-23 04:35:41.190 - [34mdebug[39m: history.0 value not changed hm-rpc.0.MEQ044xxxx.4.CONTROL_MODE, last-value=0, new-value=0, ts=1521776141182! ````
Durchlauf ebenfalls <1 Minute04:36 startet auch noch admin neu
!
2018-03-23 04:36:22.499 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ0067710.1.TEMPERATURE, last-value=19, new-value=19, ts=1521776182492 2018-03-23 04:36:22.506 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ006xxxx.1.HUMIDITY, last-value=51, new-value=51, ts=1521776182499 2018-03-23 04:36:23.803 - [32minfo[39m: admin.0 starting. Version 2.0.9 in /opt/iobroker/node_modules/iobroker.admin, node: v6.13.1 2018-03-23 04:36:23.901 - [32minfo[39m: admin.0 requesting all states 2018-03-23 04:36:23.908 - [32minfo[39m: admin.0 requesting all objects 2018-03-23 04:36:29.991 - [32minfo[39m: admin.0 received all states 2018-03-23 04:36:31.333 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.0.HEQ051xxxx.1.TEMPERATURE, last-value=18.1, new-value=18.2, ts=1521776191326 2018-03-23 04:36:31.342 - [34mdebug[39m: history.0 value not changed hm-rpc.0.HEQ051xxxx.1.HUMIDITY, last-value=39, new-value=39, ts=1521776191334 2018-03-23 04:36:33.298 - [32minfo[39m: admin.0 received all objects 2018-03-23 04:36:33.772 - [32minfo[39m: admin.0 http server listening on port 8081 2018-03-23 04:36:33.773 - [32minfo[39m: admin.0 Use link "http://localhost:8081" to configure. 2018-03-23 04:36:34.322 - [32minfo[39m: admin.0 Request actual repository... 2018-03-23 04:36:34.501 - [32minfo[39m: host.orangepiplus2e Update repository "default" under "http://download.iobroker.net/sources-dist.json" 2018-03-23 04:36:35.769 - [32minfo[39m: admin.0 Change log subscriber state: true 2018-03-23 04:36:35.787 - [32minfo[39m: web.0 system.adapter.admin.0: logging true 2018-03-23 04:36:35.787 - [32minfo[39m: hm-rega.0 system.adapter.admin.0: logging true 2018-03-23 04:36:35.790 - [32minfo[39m: simple-api.0 system.adapter.admin.0: logging true 2018-03-23 04:36:35.783 - [32minfo[39m: email.0 system.adapter.admin.0: logging true 2018-03-23 04:36:35.781 - [32minfo[39m: hm-rpc.0 system.adapter.admin.0: logging true 2018-03-23 04:36:35.780 - [32minfo[39m: hm-rpc.1 system.adapter.admin.0: logging true 2018-03-23 04:36:35.785 - [32minfo[39m: javascript.0 system.adapter.admin.0: logging true 2018-03-23 04:36:35.818 - [32minfo[39m: mihome-vacuum.0 system.adapter.admin.0: logging true 2018-03-23 04:36:35.820 - [32minfo[39m: history.0 system.adapter.admin.0: logging true 2018-03-23 04:36:35.809 - [32minfo[39m: rflink.0 system.adapter.admin.0: logging true 2018-03-23 04:36:36.291 - [34mdebug[39m: history.0 value not changed admin.0.info.updatesNumber, last-value=2, new-value=2, ts=1521776196285 2018-03-23 04:36:37.573 - [34mdebug[39m: history.0 value not changed admin.0.info.updatesList, last-value=flot, history, new-value=flot, history, ts=1521776197567 2018-03-23 04:36:37.687 - [32minfo[39m: admin.0 Repository received successfully. 2018-03-23 04:36:37.700 - [32minfo[39m: admin.0 system.adapter.admin.0: logging true 2018-03-23 04:36:42.547 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ006xxxx.2.ADJUSTING_COMMAND, last-value=0, new-value=0, ts=1521776202538 2018-03-23 04:36:42.576 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ006xxxx.2.ADJUSTING_DATA, last-value=0, new-value=0, ts=1521776202553 2018-03-23 04:36:42.639 - [34mdebug[39m: history.0 value not changed hm-rpc.0.IEQ015xxxx.1.VALVE_STATE, last-value=0, new-value=0, ts=1521776202633 !Und um 04:44 gleich nochmal history
! ```
2018-03-23 04:44:14.636 - [34mdebug[39m: history.0 value not changed hm-rpc.1.CUX9000009.1.STATE, last-value=0, new-value=0, ts=1521776648130 2018-03-23 04:44:14.637 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.1.CUX9000007.1.STATE, last-value=5, new-value=4, ts=1521776648148 2018-03-23 04:44:14.721 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-23 04:44:14.828 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-23 04:44:15.410 - [34mdebug[39m: history.0 statesDB connected 2018-03-23 04:44:15.470 - [34mdebug[39m: history.0 statesDB connected 2018-03-23 04:44:15.740 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-23 04:44:15.767 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-23 04:44:16.520 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.updated 2018-03-23 04:44:16.522 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE 2018-03-23 04:44:16.523 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL 2018-03-23 04:44:16.524 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG 2018-03-23 04:44:16.524 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_SHORT[/code]
....
~~[code]~~2018-03-23 04:44:44.006 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_07 2018-03-23 04:44:44.007 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_0e 2018-03-23 04:44:44.008 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_9.SWITCH_0a 2018-03-23 04:44:44.008 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.ElroDB_1.CHIME_1 2018-03-23 04:44:44.009 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.ElroDB_1.SWITCH_1 2018-03-23 04:44:44.010 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.Eurodomest_1.SWITCH_02 2018-03-23 04:44:44.011 - [32minfo[39m: history.0 enabled logging of rflink.0.channels.EV1527_10.SWITCH_0d 2018-03-23 04:44:44.012 - [32minfo[39m: history.0 enabled logging of data.0.leakage.Treppe 2018-03-23 04:45:49.683 - [34mdebug[39m: history.0 value not changed hm-rpc.1.CUX9002002.1.DEW_POINT, last-value=3.4, new-value=3.4, ts=1521776749653 2018-03-23 04:45:49.687 - [34mdebug[39m: history.0 value not changed hm-rpc.1.CUX9002002.1.ABS_HUMIDITY, last-value=5.94, new-value=5.94, ts=1521776749654 2018-03-23 04:46:01.392 - [34mdebug[39m: history.0 value not changed hm-rpc.1.CUX9001001.1.SWITCH_1H, last-value=2, new-value=2, ts=1521776761357 2018-03-23 04:46:01.396 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.1.CUX9001001.1.TIME_ON_1H, last-value=45.03, new-value=44.05, ts=1521776761359 [/code]
Durchlauf < 1min -
Also der Adapter wird nicht wirklich komplett neu gestartet, sondern durch dsas "states connected" wird die "Main"-Methode wieder aufgerufen die wieder alles neu inizialisiert.
Also Auslöser ist der States-Reconnect.
Hast Du ne Idee was zu den Urzeiten auf dem Rechner los war? Loadspitzen?
-
Vielen Dank!
Ich habe auch noch keine funktionierende Korrelation gefunden.
Lastspitzen könnten sein, wenn 20 Flot-Charts aktualisiert werden. Zumindest manchmal. Aber es gibt auch deutlich höhere Lastspitzen, die nicht zu dem Event führen und andererseits kommen die Events auch nachts oder wenn ich nicht hier bin.
Werde mal den OPi Adapter anwerfen und mitloggen. Mal sehen, ob es sich eine Korrelation ergibt.
Was hat es mit den states-reconnects auf sich?
-
AUs irgendeinem Grund verliert der history-Adapter zu dem Zeitpunkt die TCP-Verbindung zur States-DB. Die States-DB ist vom js-controller auf Port 9000 oder 9001 (weiss nimmer, eins ist States, eins Objects).
-
Also eine OS-Sache (armbian)? Bisher habe ich ja noch einen Host, den Opi unter armbian.
Und das letzte armbian-Update hat mir schon Probleme bereitet. Da konnte die SSD, auf der die History-Daten sind, nicht mehr eingebunden /angesprochen werden. Wahrscheinlich eine Treiber Geschichte. Ich habe dann einen anderen USB-SATA-Adapter genommen und es lief wieder. Der alte Adapter läuft unter Windows noch immer sehr gut. Bin kein Linux-Profi und habe das nur herausgefunden, indem ich die Serial des OPi abgehört habe. Da sah ich dann, daß irgendwas mit der SSD nicht klappte und der Bootprozess dann hängen blieb. Weil aber SSD incl. Adapter an Windows prima laufen, hats gedauert, bis ich mal den anderen Adapter getestet habe.
Aber die Schwierigkeiten mit dem history Adapter kamen erst später nach einem ioBroker Generalupdate.
-
Habe jetzt mal 2 Stresstest gemacht.
1. Dateniput oerload: Betreibe ja etliche ESPs, die über simpleAPI Daten einliefern. Habe nun bei einem ESP32 (der ESP8266 würde dabei selbst abschmieren) in der Loop über bulk Daten an den ioBroker geliefert. Jeweils ca. 1 Minute lang. Der ioBroker brauchte daraufhin mehrere Minuten, um aufzuholen. Ist aber nicht ausser Tritt gekommen, kann aber auch nicht sagen, ob er alle Daten verarbeitet hat. War auch nicht die Fragestellung. Habe das Experiment dreimal wiederholt. Kein History Neustart.
2. FLOT-Load: 24 Firefox Tabs mit FLOT Charts geöffnet. Meine alltägliche Prozedur. CPU Last ging laut armbianmonitor auf 3.6, laut OPi-Adapter auf 2.6. Das war die größte Spitze seit ich die Werte wieder mitloggen (seit heute 00:13). Kein History Neustart.
-
Hatte gerade wieder einen event ohne erkennbare Ursache. Bin nach Hause gekommen, HM-Öffnungen von Garage, Keymatic, ein paar Bewegungsmelder beim Einräumen der Einkäufe, Beim Firefox (Rechner lief durch) den Admin in focus nehmen und da wars schon da. Wahrscheinloch war das event schon vorher.
!
2018-03-24 12:31:20.515 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.1.CUX9002066.1.ABS_HUMIDITY, last-value=6.13, new-value=6.38, ts=1521891065485 2018-03-24 12:31:20.545 - [34mdebug[39m: history.0 Min-Delta reached hm-rpc.0.KEQ019xxxx.1.BRIGHTNESS, last-value=219, new-value=218, ts=1521891072585 2018-03-24 12:31:20.547 - [34mdebug[39m: history.0 Min-Delta ignored because no number hm-rpc.0.KEQ019xxxx.1.MOTION, last-value=false, new-value=true, ts=1521891072594 2018-03-24 12:31:20.549 - [34mdebug[39m: history.0 value not changed hm-rpc.0.KEQ019xxxxx.1.INSTALL_TEST, last-value=true, new-value=true, ts=1521891072599 2018-03-24 12:31:20.551 - [34mdebug[39m: history.0 value not changed hm-rpc.0.JEQ029xxxx.1.STATE, last-value=false, new-value=false, ts=1521891072707 2018-03-24 12:31:20.553 - [34mdebug[39m: history.0 value not changed hm-rpc.0.JEQ029xxxx.1.WORKING, last-value=false, new-value=false, ts=1521891072716 2018-03-24 12:31:20.758 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-24 12:31:20.860 - [33mwarn[39m: history.0 Reconnection to DB. 2018-03-24 12:31:21.513 - [34mdebug[39m: history.0 statesDB connected 2018-03-24 12:31:21.561 - [34mdebug[39m: history.0 statesDB connected 2018-03-24 12:31:22.086 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-24 12:31:22.377 - [32minfo[39m: history.0 starting. Version 1.5.3 in /opt/iobroker/node_modules/iobroker.history, node: v6.13.1 2018-03-24 12:31:22.950 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.updated 2018-03-24 12:31:22.952 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.0.INSTALL_MODE 2018-03-24 12:31:22.953 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.LEVEL 2018-03-24 12:31:22.953 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_LONG 2018-03-24 12:31:22.954 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.1.PRESS_SHORT 2018-03-24 12:31:22.955 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.LEVEL 2018-03-24 12:31:22.956 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_LONG 2018-03-24 12:31:22.957 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.2.PRESS_SHORT 2018-03-24 12:31:22.958 - [32minfo[39m: history.0 enabled logging of hm-rpc.0.BidCoS-RF.3.LEVEL !
….`2018-03-24 12:31:42.975 - [32minfo[39m: history.0 enabled logging of data.0.weather.garden.Humid-SHT31 2018-03-24 12:31:42.976 - [32minfo[39m: history.0 enabled logging of data.0.weather.garden.Humid-abs-SHT31 2018-03-24 12:31:42.977 - [32minfo[39m: history.0 enabled logging of data.0.weather.garden.DewTemp-SHT31 2018-03-24 12:32:15.411 - [34mdebug[39m: history.0 value not changed hm-rpc.0.JEQ029xxxx.1.STATE, last-value=false, new-value=false, ts=1521891135395 2018-03-24 12:32:15.459 - [34mdebug[39m: history.0 value not changed hm-rpc.0.JEQ029xxxx.1.WORKING, last-value=false, new-value=false, ts=1521891135400 2018-03-24 12:32:15.463 - [34mdebug[39m: history.0 value not changed hm-rpc.0.KEQ019xxxx.1.BRIGHTNESS, last-value=218, new-value=218, ts=1521891135403 2018-03-24 12:32:15.466 - [34md[/code]` >! Mäßige peaks bei Auslastung CPU1 von 0.22 auf 1.7 und bei der Temp von 27 auf 36°C aber mutmasslich als Folge des history enable events. >! Könnte folgende Vorwärtsstrategie aufgehen? >! - Das Problem scheint ja ein lokales zu sein. Andere haben das nicht, warum auch immer. Könnte jetzt den Rechner wechseln aber worauf? Eigentlich lief der OPi stabil und recht entspannt. Macht es Sinn History auf einen anderen Rechner auszulagern? >! - Kann noch ein, zwei Tage auf gut Glück suchen. Mehr als gut Glück wirds wohl nicht, zumindest sehe ich keine weitere Möglichkeit mit meinen Mitteln und Kenntnissen. >! - Mein ioBroker ist derzeit massiv downgegradet, das hat keine lange Zukunft. >! - Kann dann in einer Nachtschicht ioBroker neu aufsetzen. >! - Wenn dann das Problem immer noch besteht (wovon ich ausgehe), müßte ich History bei mir aufgeben. >! - Wäre Influx-DB die geeignete Vorwärtsstrategie? >! - Habe irgendwo gelesen, daß man den Datenbestand von history nach InfluxDB portieren kann. Das würde ich versuchen. >! Mein History-Datenbestand sind ca. 1.3 GByte auf einer 32GB SSD >! - Nehme an daß FLOT dann auch mit Influx-DB arbeitet, oder gibt es da andere Tools?
