ahoy
ahoy copied to clipboard
lumapu
[Bug] Problem mit schnell volllaufender send queue bei wenigen Limits
Platform
ESP32
Assembly
I did the assebly by myself
nRF24L01+ Module
nRF24L01+ plus
Antenna
external antenna
Power Stabilization
Elko (~100uF)
Connection picture
- [ ] I will attach/upload an Image of my wiring
Version
0.8.74
Github Hash
1f0b15c
Build & Flash Method
AhoyDTU Webinstaller
Setup
Debug Serial Log output
No response
Error description
Ich habe da mal etwas unfreiwillig gefunden. Es scheint irgendwelche Probleme mit der Send Queue der DTU zu geben. In den aktuellen Version so grob ab 0.8.7x treten sehr schnell die Probleme auf das im Web log nach nur wenigen Sekunde "send queue almost full" zu sehen ist.
Also mal einen einen "netter" Stresstest gebastelt (DTU Intervall auf 5 Sekunden und alle 5 Sekunden ein Limit für alle 4 Inverter senden MQTT oder API). Aber es zeigt sehr deutlich und schnell was passiert. Wenn die Queue einmal erst fast voll ist, dann scheint die DTU ins stolpern zu kommen das sie irgendetwas wiederholt und/oder mehrfach sendet(siehe log). Das geht bei der 0.8.74 schon nach dem zweiten Sendeintervall los. Es gibt ja immer die Info im Log wie lange die DTU für einen Interval(lopp duration) gebraucht hat. Wenn die DTU strauchelt dann fehlt das für längere Zeit. Bei der 0.8.72 habe ich mal über 80 Sekunden gesehen. Was dann manchmal passiert, das die Inverter sich tot stellen und die Produktion einstellen(In alten Versionen hatte ich das nicht). Man kann sie dann mit einem "restart" wieder zum Leben erwecken und sie starten neu. Dann habe ich ein paar FW probiert weil ich meine Limit Scripte im verdacht hatte. Das Problem beginnt so grob mitte der 0.8.6x Version und wird immer schlimmer je neuer. Ich habe dann eine noch etwas ältere genommen 0.8.46 genommen. Bei der Version läuft alles bestens. Keine hängen bleiben nichts. Nur ab und an geht mal ein Limit verloren weil ich es beim Stresstest nicht prüfe ob das ACK da ist. Laut Log wird das Limit sehr Zeitnah abgearbeitet. Auch die Inverter laufen durch. Ich habe es dann nochmal ein wenig übertrieben und alle 2 Sekunden die Limits neu geschrieben. Selbst das überlebt die DTU über 5 Minuten und rennt und rennt und... Ok mal geht ein Limit verloren, aber das ist dann ja völlig Ok. Im Log sind zwei Beispiele wie schnell die DTU ins stolpern kommt. Sieht jedenfalls für mich etwas merkwürdig aus und eben die hohen Zeiten für die "loop duration".
Das andere was noch aufgefallen seit Ende der 0.8.6x aufwärts werden manchmal morgens die Inverter nicht mehr erkannt und es wird nicht kommuniziert, aber sie starten und produzieren. Packe ich dann die 0.8.46 drauf ist der fehlende Inverter sofort da. Dann wieder zurück auf die 0.8.72/73/74 und der Inverter ist wieder offline auch nach 5 Minuten noch. Wieder zurück auf die 0.8.46 und dann ist der Inverter sofort wieder Online. Manchmal hatte es auch geholfen die Frequenz bei den neueren FW Verison inder DTU für den Inverter zu ändern aber nicht immer. Was dabei auffällt, es betrifft immer nur das CMT Modul, NRF läuf immer durch ohne ein einziges Problem. Soll ich dafür ein neuen Issue aufmachen?
Ich weiß das es manchmal schwer ist alles richtig zu beschreiben. Also ruhig fragen und ich kann auch testen wenn es darum geht etwas einzukreisen.
Status zur 0.8.76: Ich hatte die heute Morgen drauf gepackt und geschaut wie die Inverter sich verhalten. Leider hat die DTU wieder zu einem HMS2000 die Kommunikation verloren obwohl der da war und auch schon Daten gesendet hatte aber nach kurzer Zeit 1-3 Minuten sagte dir DTU "keine Kommunikation mehr" der ist auch nicht wieder gekommen. Auch nicht als er schon angefangen hatte zu produzieren. Der andere HMS2000 war die ganze Zeit aber aktiv in der DTU. Also die FW wieder runter und 0.8.46 rauf und die hatte den Inverter sofort aktiv. Da ich diese Woche extrem wenig Zeit tagsüber habe, werde ich die Limits erst am Wochenende testen können.
genau in der 0.8.72 habe ich eine Begrenzung der switchCylcles eingebaut, hier mein commit log von damals:
* reduce switchChannel command for HMS (only each 5th cycle it will be send now)
-> habe es jetzt wieder rückgängig gemacht und hoffe wieder auf dem Stand 0.8.46 zu sein (in Verison 0.8.78)
Status: 0.8.78 Leider kann ich nicht bestätigen das es wieder funktioniert. Ich habe heute mal extra langsam mit dem Testen angefangen. Im 5 Sekundenabstand der DTU das Limit für die Inverter einzeln per API geschrieben nach. Um 9:35:58 ist es dann wieder da gewesen "send queue almost full" Zusätzlich dann auch eine Sekunde später "CMT TX failed, code: 2". Bei 9:36:28 ist das Kommando auch doppelt zu sehen. Aber schau besser selber.
Status 0.8.84 Das Problem mit den am Sonnenaufgang nicht erreichbaren Invertern, ist nicht mehr vorhanden.
Was noch bleibt ist das Thema "send queue almost full" nach wenigen Limits. Ich habe für euch nochmal zwei Logs erstellt wo das sehr merkwürdig im Webserial aussieht. Das andere stammt vom ioBroker(die Error im Log dienen nur zur fabrlichen Herrvorhebung beim Debugging) zum Vergleich was gesendet wurde. Dort ist nur ein Inverter aktiv. Wenn ich bei 4 Invertern die Limits sende, dann ist schon nach 2-3 neuen Werten die Meldung mit der Queue da.
Wenn ich euch irgendwie unterstützen kann mit testen, mache ich das gerne. Sonst schaue ich in den nächsten Versionen was so im Changelog steht.
Status 0.8.113 Scheinbar ist das Problem derzeit so nicht mehr vorhanden das die Queue voll läuft. Dafür zeigt sich nun ein andere merkwürdiges Problem mit den Limits.
Als Test werden alle auf 4 Inverter im Abstand von grob 100ms die Limits per API geschrieben und dann nach 30 Sekunden die nächsten Werte. Die Werte werden dabei um 0.1 inkrementiert. Doch das Ergebnis sieht etwas komisch aus. Scheinbar werden die Werte nicht immer alle Korrekt angenommen/gespeichert/???? Hier das Log dazu. Ich hoffe das Problem ist zu erkennen.
Zeile 53: 18:59:13.078 I: (#3) has accepted power limit set point 10.00 with PowerLimitControl 1
Zeile 59: 18:59:13.161 I: (#2) has accepted power limit set point 10.00 with PowerLimitControl 1
Zeile 65: 18:59:13.243 I: (#1) has accepted power limit set point 10.00 with PowerLimitControl 1
Zeile 71: 18:59:13.508 I: (#0) has accepted power limit set point 10.00 with PowerLimitControl 1
Zeile 325: 18:59:43.091 I: (#1) has accepted power limit set point 10.10 with PowerLimitControl 1
Zeile 331: 18:59:43.357 I: (#0) has accepted power limit set point 10.10 with PowerLimitControl 1
Zeile 339: 18:59:44.083 I: (#3) has accepted power limit set point 10.10 with PowerLimitControl 1
Zeile 345: 18:59:44.169 I: (#2) has accepted power limit set point 10.10 with PowerLimitControl 1
Zeile 597: 19:00:14.080 I: (#3) has accepted power limit set point 10.10 with PowerLimitControl 1
Zeile 603: 19:00:14.163 I: (#2) has accepted power limit set point 10.10 with PowerLimitControl 1
Zeile 609: 19:00:14.244 I: (#1) has accepted power limit set point 10.10 with PowerLimitControl 1
Zeile 615: 19:00:14.510 I: (#0) has accepted power limit set point 10.10 with PowerLimitControl 1
Zeile 877: 19:00:44.079 I: (#3) has accepted power limit set point 10.30 with PowerLimitControl 1
Zeile 883: 19:00:44.164 I: (#2) has accepted power limit set point 10.30 with PowerLimitControl 1
Zeile 889: 19:00:44.245 I: (#1) has accepted power limit set point 10.30 with PowerLimitControl 1
Zeile 895: 19:00:44.511 I: (#0) has accepted power limit set point 10.30 with PowerLimitControl 1
Zeile 1133: 19:01:14.079 I: (#1) has accepted power limit set point 10.30 with PowerLimitControl 1
Zeile 1139: 19:01:14.346 I: (#0) has accepted power limit set point 10.30 with PowerLimitControl 1
Zeile 1147: 19:01:15.086 I: (#3) has accepted power limit set point 10.30 with PowerLimitControl 1
Zeile 1153: 19:01:15.169 I: (#2) has accepted power limit set point 10.30 with PowerLimitControl 1
Zeile 1418: 19:01:45.080 I: (#3) has accepted power limit set point 10.50 with PowerLimitControl 1
Zeile 1424: 19:01:45.165 I: (#2) has accepted power limit set point 10.50 with PowerLimitControl 1
Zeile 1430: 19:01:45.246 I: (#1) has accepted power limit set point 10.50 with PowerLimitControl 1
Zeile 1436: 19:01:45.511 I: (#0) has accepted power limit set point 10.50 with PowerLimitControl 1
Zeile 1685: 19:02:15.081 I: (#3) has accepted power limit set point 10.60 with PowerLimitControl 1
Zeile 1691: 19:02:15.165 I: (#2) has accepted power limit set point 10.60 with PowerLimitControl 1
Zeile 1697: 19:02:15.246 I: (#1) has accepted power limit set point 10.60 with PowerLimitControl 1
Zeile 1703: 19:02:15.511 I: (#0) has accepted power limit set point 10.60 with PowerLimitControl 1
Wenn ich etwas testen machen ich das gerne. Muss nur wissen was ihr braucht.
Zudem hat der ESP aber nun viele Neustarts aber dazu kommt gleich noch ein neues Ticket.
vor paar Wochen habe ich etwas eingebaut, dass die Queue entlastet: es werden keine doppelten Einträge mehr erlaubt. Evtl. hat das ja schon zu einer Besserung geführt?
@lumapu Ich habe mir das in Ruhe angeschaut. Ja das Problem ist so nicht mehr vorhanden. Das was ich gesehen wie die Werte Übertragen wurden, geht das sicher mit 1-2 Invertern gut. Aber bei meinen 4 Stück ist MQTT für eine Nulleinspeisung nicht mehr zu gebrauchen weil dabei erheblich Verzögerungen von Limits kommt bis sie bestätigt werden. Bin mir nicht sicher woran es liegt ob das deine Änderungen sind oder mein iobroker das verursacht. Aber wenn es keinen anderen stört dann soll es so passen 😉 Ich nehme da lieber die API auch wenn es da derzeit ein kleines bisschen hakelt 😉
Ursächliches Problem gelöst, also zu damit.