SQL-Adapter Entprellzeit

[apollon77]

Da würde ich jetzt sagen: Debug Log bitte Da sollte man sehen können was los ist.

[Dr. Bakterius]

Änderung des Wertes von 4.5 auf 12. Wieder drei Einträge in der Datenbank innerhalb von ca. 2 Sekunden. Hier das LOG dazu:

2018-10-10 09:47:02.507 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=12, ts=1539157622502, relog=false
2018-10-10 09:47:02.708 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=12, ts=1539157622703, relog=false
2018-10-10 09:47:02.708 - debug: sql.0 value not changed maxcube.0.devices.thermostat_17b263.setpoint, last-value=12, new-value=12, ts=1539157622703
2018-10-10 09:47:02.825 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=4.5, ts=1539157622821, relog=false
2018-10-10 09:47:02.826 - debug: sql.0 Min-Delta reached maxcube.0.devices.thermostat_17b263.setpoint, last-value=12, new-value=4.5, ts=1539157622821
2018-10-10 09:47:02.826 - debug: sql.0 Datatype maxcube.0.devices.thermostat_17b263.setpoint: Currently: number, StorageType: false
2018-10-10 09:47:02.827 - debug: sql.0 Type set in Def for maxcube.0.devices.thermostat_17b263.setpoint: false
2018-10-10 09:47:02.827 - debug: sql.0 Type (from DB-Type) for maxcube.0.devices.thermostat_17b263.setpoint: 0
2018-10-10 09:47:02.828 - debug: sql.0 SELECT id FROM `iobroker`.sources WHERE name='system.adapter.maxcube.0';
2018-10-10 09:47:02.839 - debug: sql.0 INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(57, 1539157622703, 12, 1, 12, 0);
2018-10-10 09:47:02.853 - debug: sql.0 DELETE FROM `iobroker`.ts_number WHERE id=57 AND ts < 1523346420853;
2018-10-10 09:47:05.837 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=12, ts=1539157625832, relog=false
2018-10-10 09:47:05.838 - debug: sql.0 Min-Delta reached maxcube.0.devices.thermostat_17b263.setpoint, last-value=4.5, new-value=12, ts=1539157625832
2018-10-10 09:47:12.508 - debug: sql.0 Datatype maxcube.0.devices.thermostat_17b263.setpoint: Currently: number, StorageType: Number
2018-10-10 09:47:12.509 - debug: sql.0 INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(57, 1539157625832, 12, 1, 12, 0);
2018-10-10 09:47:15.838 - debug: sql.0 Datatype maxcube.0.devices.thermostat_17b263.setpoint: Currently: number, StorageType: Number
2018-10-10 09:47:15.840 - debug: sql.0 INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(57, 1539157625833, 12, 1, 12, 0);

[apollon77]

Zeig bitte mal die SQL-Konfig von dem Datenpunkt. Und bitte sagen welche sql-Version

[apollon77]

Ich glaube ich habe eine Vermuting zum Grund.

Bitte installier mal Version vom Github, dann sql instanz neu starten. Falls nochmal passiert bitte nochmal Debug log.

Konfig-Screenshot von oben bitte trotzdem schicken

[Dr. Bakterius]

Danke!

Ich habe die Github-Version (1.9.3) installiert. Nach einem ersten Test passt es jetzt - nur ein Eintrag im LOG.

2018-10-10 11:19:38.363 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=12, ts=1539163178341, relog=false
2018-10-10 11:19:38.492 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=12, ts=1539163178486, relog=false
2018-10-10 11:19:38.493 - debug: sql.0 value not changed maxcube.0.devices.thermostat_17b263.setpoint, last-value=12, new-value=12, ts=1539163178486
2018-10-10 11:19:39.129 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=4.5, ts=1539163179123, relog=false
2018-10-10 11:19:39.130 - debug: sql.0 Min-Delta reached maxcube.0.devices.thermostat_17b263.setpoint, last-value=12, new-value=4.5, ts=1539163179123
2018-10-10 11:19:39.133 - debug: sql.0 Datatype maxcube.0.devices.thermostat_17b263.setpoint: Currently: number, StorageType: false
2018-10-10 11:19:39.140 - debug: sql.0 Type set in Def for maxcube.0.devices.thermostat_17b263.setpoint: false
2018-10-10 11:19:39.141 - debug: sql.0 Type (from DB-Type) for maxcube.0.devices.thermostat_17b263.setpoint: 0
2018-10-10 11:19:39.145 - debug: sql.0 INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(57, 1539163178486, 12, 1, 12, 0);
2018-10-10 11:19:39.167 - debug: sql.0 DELETE FROM `iobroker`.ts_number WHERE id=57 AND ts < 1523351940166;
2018-10-10 11:19:40.618 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=12, ts=1539163180613, relog=false
2018-10-10 11:19:40.619 - debug: sql.0 Min-Delta reached maxcube.0.devices.thermostat_17b263.setpoint, last-value=4.5, new-value=12, ts=1539163180613

Hier noch die Konfig vom Datenpunkt:

[apollon77]

Kannst es bitte noch bissl laufen lassen und heute Abend nochmal Checken/Feedback geben? Dann mache ich update fertig

[Dr. Bakterius]

So, einige Änderungen später muss ich die Erfolgsmeldung leider zurück nehmen.

Wert	Bestätigt	Quelle		Zeit			Geändert
23.5	true		maxcube.0	2018-10-10 18:00:02.884	
23.5	true		maxcube.0	2018-10-10 18:00:00.648	
19	true		maxcube.0	2018-10-10 14:20:03.392	
4.5	true		maxcube.0	2018-10-10 11:40:07.335	
4.5	true		maxcube.0	2018-10-10 11:40:00.608	
9	true		maxcube.0	2018-10-10 11:37:58.140	
4.5	true		maxcube.0	2018-10-10 11:32:57.843	
12	true		maxcube.0	2018-10-10 11:31:53.346	
12	true		maxcube.0	2018-10-10 11:31:50.200	
4.5	true		maxcube.0	2018-10-10 11:20:03.147	
4.5	true		maxcube.0	2018-10-10 11:20:00.589	
12	true		maxcube.0	2018-10-10 11:19:38.486

Ich kann den Adapter nicht ständig auf 'debug' laufen lassen, da ich doch so einige Datenpunkte aufzeichnen lasse und so tausende Zeilen an LOG auflaufen.

[apollon77]

Das ist mir klar aber ohne log ist das eher schwierig nachzuvollziehen und ich bin ehrlich: mir fehlt gerade komplett die Zeit es versuchen irgendwie manuell nachzustellen. Wenn es bei dir regelmäßig passiert ist das (für mich) gerade der einfachere Ansatz.

Jegliche Hilfe beschleunigt damit den fix. Sonst leg ein GitHub issue an und ich schaue es an wenn ich Zeit finde.

Jetzt sieht das log aber schon etwas nachvollziehbarer aus. Ich habe eine Vermutung, aber brauche debug log um die zu bestätigen.

Gesendet vom Handy …

[Dr. Bakterius]

Ich verstehe schon, du steckst ja wirklich viel Zeit und Arbeit in das Projekt. Deswegen versuche ich auch gerne zu helfen wo ich kann.

Ich habe es nun erneut versucht und "zum Glück" gleich beim ersten Mal einen Doppeleintrag geschafft. Hier dazu das LOG:

2018-10-10 19:45:08.263 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=25, ts=1539193508255, relog=false
2018-10-10 19:45:08.453 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=25, ts=1539193508448, relog=false
2018-10-10 19:45:08.454 - debug: sql.0 value not changed maxcube.0.devices.thermostat_17b263.setpoint, last-value=25, new-value=25, ts=1539193508448
2018-10-10 19:45:09.712 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=23.5, ts=1539193509705, relog=false
2018-10-10 19:45:09.713 - debug: sql.0 Min-Delta reached maxcube.0.devices.thermostat_17b263.setpoint, last-value=25, new-value=23.5, ts=1539193509705
2018-10-10 19:45:09.714 - debug: sql.0 Datatype maxcube.0.devices.thermostat_17b263.setpoint: Currently: number, StorageType: false
2018-10-10 19:45:09.714 - debug: sql.0 Type set in Def for maxcube.0.devices.thermostat_17b263.setpoint: false
2018-10-10 19:45:09.715 - debug: sql.0 Type (from DB-Type) for maxcube.0.devices.thermostat_17b263.setpoint: 0
2018-10-10 19:45:09.715 - debug: sql.0 INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(57, 1539193508448, 25, 1, 12, 0);
2018-10-10 19:45:09.732 - debug: sql.0 DELETE FROM `iobroker`.ts_number WHERE id=57 AND ts < 1523382300731;
2018-10-10 19:45:11.200 - debug: sql.0 new value received for maxcube.0.devices.thermostat_17b263.setpoint, new-value=25, ts=1539193511195, relog=false
2018-10-10 19:45:11.201 - debug: sql.0 Min-Delta reached maxcube.0.devices.thermostat_17b263.setpoint, last-value=23.5, new-value=25, ts=1539193511195
2018-10-10 19:45:21.204 - debug: sql.0 Datatype maxcube.0.devices.thermostat_17b263.setpoint: Currently: number, StorageType: Number
2018-10-10 19:45:21.204 - debug: sql.0 INSERT INTO `iobroker`.ts_number (id, ts, val, ack, _from, q) VALUES(57, 1539193511195, 25, 1, 12, 0);

So wie ich das sehe, erfolgt ein Eintrag in die Datenbank sofort (19:45:09) und der zweite zehn Sekunden (Entprellzeit?) nachdem der Wert noch einmal ansteht (19:45:21). Eingetragen wird aber die Zeit, wo der Wert erneut gemeldet wurde - also rund 2 Sekunden nach dem ersten. Der zweite wird nicht verworfen, sondern nur verzögert geschrieben. Liege ich da richtig?

[apollon77]

Es ist wie ich vermutet habe. Hier "beisst" sich jetzt die Entprellzeit mit der Logik von "nur Änderungen loggen".

Bzw "beissen" ist falsch weil ja der "unstabile Wert" (die 23.5 in deinem Log-Fall) korrekterweise nicht geloggt wird. Also der Teil funktioniert.

Warum der stabile Wert so geloggt wird wie er es wird, liegt daran das der Adapter trotz "nur Änderungen loggen" versucht am Ende sinnvolle Werte zu haben die man für Visualisierung bzw. Berechnungen nutzen kann.

Wenn man wirklich nur Änderungen loggt und den Rest (also gleiche Werte) komplett verwirft,dann ist die formale Datenebene unvollständig weil ich nicht sehe wie lange der Wert wirklich stabil war bevor er sich geändert hat. Formal ist ja eine Treppenbewegung normal und viele Visualisierungen zeigen dann "schräge linien" an die nur die bekannten Datenpunkte verbinden, was ja aber ein falsches Bild abgibt.

Um hier als so korrekt zu arbeiten wir möglich merkt sich der Adapter intern auch den letzten "gleichen Wert" Event auch wenn er Ihn im ersten Schritt verworfen hat und wenn sich dann der Wert ändert wird dieses letzte verworfene Event verzögert geloggt, wie Du korrekt gesehen hast. So sieht man auf der Datenebene wie die "wirkliche Entwicklung" war.

In Zusammenhang mit der Entprellzeit passiert nun aktuell intern folgendes: neuer geänderter Wert kommt ist erstmal ok, triggert aber das Logging des letzten verworfenen Wertes. Das ist dann schon passiert auch wenn ggf die Änderung verworfen wird weil "instabil".

Da muss ich drüber nachdenken bzw die Umstellung ist nicht ganz so easy und kann viele nebeneffekte haben, ich muss dich also leider vertrösten und hoffe der Effekt ist für dich erstmal erträglich?!

Würdest Du mir dazu beim Adapter ein GitHub issue bitte anlegen mit Referenz hierher? Wäre super …

Ingo

[Dr. Bakterius]

Danke für die Erklärung und fürs Dranbleiben.

Issue ist eingetragen (https://github.com/ioBroker/ioBroker.sql/issues/53).

[apollon77]

Für History habe ich das in der neuen "History 2.0.0" mal gefixt weil dort das gleiche Problem besteht. Wäre es möglich im vergleich sql/history mal anzusehen und zu sagen ob es in History 2.0.0 gefixt ist?

Details: https://forum.iobroker.net/topic/54197/test-adapter-history-2-0-0