Umbau Phasenumschaltung für WARP 1

[MatzeTF]

On 11/5/2023 at 8:55 PM, mattsches said:

Hast du dir dein Log mal angeschaut? Darin  wimmelt es nur so vor Fehlern zu Wifi und MQTT. Und um 12:35:03,500 haut es die Kiste zusammen mit einer Exception.

Kannst du die .elf-Datei von deinem Release auch bereitstellen? Dann kann man sich die Exception mal ansehen.

On 11/5/2023 at 8:55 PM, mattsches said:

MQTT: Recv buf is 2048 bytes. meter/all_values_update requires 1786. Maybe bump MQTT_RECV_BUFFER_SIZE?

Das ist unproblematisch und bei WARP1-Firmware normal. Wegen zu wenig Speicher können wir MQTT nicht mehr als die knapp bemessenen 2k geben.

On 11/5/2023 at 8:55 PM, mattsches said:

Ich tippe eher auf einen Speicherengpass.

2023-11-05 12:34:00,581  JSON doc overflow while converting to string! Doc capacity is zero but needed 6784.

Mit deiner Vermutung liegst du wahrscheinlich genau richtig. Die Fehlermeldung bedeutet, dass kein Speicher zur Verfügung steht, um eine Config-Struktur in einen String umzuwandeln. 6784 Bytes ist aber auch echt viel. Ich weiß spontan nicht, welcher unserer Configs so riesig sein soll. Hast du zufällig in einem deiner Module eine große Config angelegt? Möglicherweise mit einem ConfArray drin, dessen maximale Anzahl von Elementen sehr groß ist, selbst wenn die in der Praxis gar nicht alle genutzt werden?

[ThomKa]

 

Vorgelagertes Skript zur Ladesteuerung:

@deepflyer911 Anbei folgende Informationen zum Nachvollziehen:

Beim Script WARP_Ladezentrale handelt es sich um das zentrale Script, hinter dem obigen Screenshot. Dieses erteilt/entzieht die Ladefreigabe und prüft dabei,

• ob ein BEV an-/abgestöpselt wurde oder ist,
• ob der gewünschte SoC_Ziel erreicht wurde,
• und ob sich zwischendurch Vorgabewerte geändert haben.

Im Script läuft ein zentrales Intervall, welches die Prüfungen wiederkehrend ausführt. Für den Fall, dass kein BEV angestöpselt ist oder der SoC_Ziel erreicht ist, wird die Intervalldauer verlängert, um den RaspberryPI nicht unnötig zu belasten. Im Fall eines Ladevorgangs erfolgt die Überprüfung dann wieder mit kürzerer Intervalldauer.

Das Script vergibt über den Datenpunkt 0_userdata.0.Warp.Ladevorgang.LV_Status die Ladefreigabe "LV_starten" oder entzieht diese "LV_stoppen". Der Datenpunkt wird von den nachgelagerten Scripts ausgelesen. Die eigentliche Ansteuerung der WARP übernehmen dann die nachfolgenden Skripte.

Angefügt findest Du dann noch die dazugehörigen Datenpunkte, alle unter dem Pfad 0_userdata.0.Warp.... Kann sein, dass da auch ungenutzte DPs drin sind. Da habe ich noch nicht komplett aufgeräumt 😉

Im nächsten Post stelle ich Dir das Script zum "EPEX laden" und zum "adhoc laden" bereit. Diese starten dann nachranging und abhängig vom DP 0_userdata.0.Warp.Ladevorgang.LV_Status.

PS: Zum Nachvollziehen des Ablaufs einfach mal die ganzen DEBUGs aktivieren. Dann zeigt sich Ablauf und Abhängigkeiten ganz schnell. 

2023-11-06_WARP_Ladezentrale_Datenpunkte.json 2023-11-06_WARP_Ladezentrale.json

bearbeitet November 6, 2023 at 11:36 von ThomKa
DEBUG-Hinweis und Überschrift ergänzt

[ThomKa]

Ladeskript für adhoc oder FAST laden:

Damit Du die Einbindung/Abhängigkeit des vorgeschalteten Scripts "WARP Ladezentrale" mit den beiden Ladefreigaben "LV_starten" / "LV_stoppen" besser einschätzen kannst, findest Du angefügt das sehr kurze Skript zum "adhoc" oder "FAST" laden.

Dieses und die anderen "nachgelagerten" Skripte steuern eigentlich nur die Höhe der verfügbaren Ladeleistung "available charging Power" (acP) zwischen "0" bis 0_userdata.0.Warp.BEV.BEV_cP_max. Die Überwachung/Festlegung des Lade-Beginns/Endes erfolgt vorgelagerten Script.

2023-11-06_WARP_adhoc_FAST_laden.json

[ThomKa]

Ladeskript für "EPEX laden":

zuerst benötigst Du die EPEX Preisdaten von heute und morgen, die ich mir jeweils gegen 13:30 über TIBBER abhole. Diese liegen dann im Format vor, wie angefügt. Die Preise liegen bei mir in den DPs 0_userdata.0.Tibber.Stundenpreise_heute   und   0_userdata.0.Tibber.Stundenpreise_morgen

Danach arbeitet das Skript "EPEX Laden" wie folgt:

• es wird direkt auf Änderungen der Vorgabewerte geprüft/reagiert
• es wird direkt auf Änderungen der Ladefreigabe geprüft/reagiert
• mit jeder Änderung der Vorgabewerte oder Ladefreigabe erfolgt
  • ein Abbruch eines laufenden Ladevorgangs,
  • eine neue Kalkulation eines neuen Ladevorgangs
  • und der Start eines neuen Ladevorgangs
• FKT2 ist die zentrale Funktion und ruft die weiteren FKTs 3-5 auf. Alle zusammen kalkulieren den Ladevorgang anhand der benötigten Energiemenge und der günstigsten EPEXpreise.
• FKT6 prüft, ob die aktuelle Stunde eine der günstigen EPEXstunden ist und übermittelt dann 0_userdata.0.Warp.BEV.BEV_cP_max an WARP. Ist es keine günstige Stunden wird "0" an WARP übergeben.

Wenn es seitens des vorgelagerten Skripts "WARP_Ladezentrale" zum Ladestatus "LV_stoppen" kommt, wird auch im Skript "EPEX laden" alles gestoppt und das Skript belastet den Raspi nicht weiter. 

Eine ausführlichere Beschreibung der DPs findest Du im ioB-Forum unter https://forum.iobroker.net/topic/68266/bev-mit-epex-börsen-strom-laden. Aber bitte nur den Abschnitt "2. Datenpunkte" betrachten. Die anderen Ausführungen passen nicht mehr zu angefügten Skript.

 

Damit hast Du alle Informationen und meinen aktuellen Stand. Die PV-Überschuss-Ansteuerung habe ich noch nicht auf das vorgelagerte Skript "WARP_Ladezentrale" umgeschrieben, also noch nicht drunter gehängt. Deshalb ist es hier nicht weiter erwähnt. Alles weitere wie immer gerne auf Rückfrage 🫡

2023-11-06_TIBBERpreise_today.json 2023-11-06_TIBBERpreise_tomorrow.json 2023-11-06_WARP_EPEX_laden.json

[deepflyer911]

danke dir @ThomKa jetzt habe ich Lesestoff :D

[mattsches]

Am 6.11.2023 um 11:07 schrieb MatzeTF:

Kannst du die .elf-Datei von deinem Release auch bereitstellen? Dann kann man sich die Exception mal ansehen.

@MatzeTF: Das .elf habe ich angehängt. Die Config-Daten von meinen Modulen sind m. E. unauffällig: phase_switcher, soc. Bei mir läuft die Firmware ohne Exception, allerdings auch ohne MQTT (ich nutze die HTTP API). ConfArrays nutze ich nicht.

@deepflyer911: Hast du denn testweise mal die Version ohne SOC-Modul probiert? In meiner Firmware ist das Debug-Modul von TF aktiv. Wie schaut es denn dort mit dem freien DRAM-Speicher aus, vor allem dem größten freien Heap-Block?

 

 

warp_firmware_2_1_5_6547f5d6.zip warp_firmware_2_1_5_6547f5d6_merged.bin

[deepflyer911]

@mattsches mit der originalen Version zeigt es mir rund 42k bis 44k freie Heap-Byte an. Größter Block 38-44k

 

mit der Version ohne SOC rund 50 bis 52 freie Byte und 47-51 größter Block

[mattsches]

Und kommt es mit der Version ohne SOC-Modul auch zu den Abbrüchen?

[MatzeTF]

On 11/6/2023 at 8:22 PM, mattsches said:

@MatzeTF: Das .elf habe ich angehängt.

Danke, aber ich hätte die .elf-Datei von deinem Release hier gebraucht, also die Datei mit Timestamp 6545e427.

[mattsches]

Am 7.11.2023 um 11:11 schrieb MatzeTF:

Danke, aber ich hätte die .elf-Datei von deinem Release hier gebraucht, also die Datei mit Timestamp 6545e427.

@MatzeTF Die .elf habe ich nicht mehr. Aber der Stand in meinem Post oben ist derselbe Commit, nur neu gebaut. Nach meinem Dafürhalten damit binär identisch zum Release auf github.

[deepflyer911]

Am 6.11.2023 um 22:14 schrieb mattsches:

Und kommt es mit der Version ohne SOC-Modul auch zu den Abbrüchen?

Bislang ohne Probleme.

[MatzeTF]

@deepflyer911 Ich habe mir gerade dein Log von Sonntag angesehen und es sieht so aus, als wäre deine Box im SoC-Modul wegen zu wenig freiem Speicher abgestürzt. MQTT verbraucht recht viel Speicher, von daher wundert mich das nicht.

Die gute Nachricht ist: Für neue Features für WARP2 und den WEM reduzieren wir gerade den Speicherverbrauch verschiedener Module. Davon wird auch die WARP1 profitieren und Abstürze wegen zu wenig freiem Speicher sollten dann seltener auftreten.

[deepflyer911]

Am 8.11.2023 um 11:34 schrieb MatzeTF:

@deepflyer911 Ich habe mir gerade dein Log von Sonntag angesehen und es sieht so aus, als wäre deine Box im SoC-Modul wegen zu wenig freiem Speicher abgestürzt. MQTT verbraucht recht viel Speicher, von daher wundert mich das nicht.

Die gute Nachricht ist: Für neue Features für WARP2 und den WEM reduzieren wir gerade den Speicherverbrauch verschiedener Module. Davon wird auch die WARP1 profitieren und Abstürze wegen zu wenig freiem Speicher sollten dann seltener auftreten.

Dann ist die Variante von @mattsches ohne SOC Modul ja genau die richtige Option 😁

[mattsches]

Ich habe eine neue Version gebaut. Basis ist weiterhin das offizielle 2.1.5 Release. Wesentlicher Fix ist das Schnell-/Spontanladen, das nun auch wieder über den Drucktaster funktioniert.

In der Version ist das SOC-Modul drin. Ich habe aber den Speicherverbrauch um ca. 8 kB reduzieren können, wenn die Ladestandsabfrage deaktiviert ist. Bzgl. größtem freien Heap-Block hat sich diese Version bei mir genauso verhalten wie ganz ohne SOC-Modul. @deepflyer911, probier' mal aus, ob die Version bei dir tut. Wenn weiterhin nicht, dann baue ich dir gerne wieder eine Variante ohne SOC-Modul.

Zum Download geht es hier lang: https://github.com/mattsches1/esp32-firmware/releases/tag/phase_switcher-2.1.5.1

[deepflyer911]

Hab die neuste Variante insatlliert. Zunächst mal ohne Probleme. Im Debug ist zu erkennen, dass sich die freien Bytes stabil über 50k bewegen. Der größte Block ist wieder bei 38-43k.

Werde es weiter beobachten und berichten.

[mattsches]

Ich hatte übrigens während meiner Versuche den Eindruck, dass ein weiterer Neustart nach dem Einspielen der Firmware eine Verbesserung bzgl. größtem freien Block brachte. Das kann aber auch Einbildung gewesen sein.

[MatzeTF]

On 11/11/2023 at 10:41 PM, mattsches said:

Ich hatte übrigens während meiner Versuche den Eindruck, dass ein weiterer Neustart nach dem Einspielen der Firmware eine Verbesserung bzgl. größtem freien Block brachte. Das kann aber auch Einbildung gewesen sein.

Die Verteilung von belegten Blöcken im Speicher ist teilweise nichtdeterministisch. Es kann passieren, dass ein belegter Block weit „hinten“ liegt und dementsprechend der größte freie Block, der typischerweise am Ende des Speichers liegt, entsprechend kleiner ist. Du kannst beliebig oft neu starten, bis du zufällig eine gute Verteilung triffst. 😉

Üblicherweise ist der größte freie Speicherblock nicht so wichtig, da z.B. bei deepflyer911s letztem Crash viele Blöcke mittlerer Größe gleichzeitig für vsprintf angefordert wurden.

[deepflyer911]

Grüße Zusammen,

 

nach dem letzten Update war heute erstmalig wieder saolarer Überschuss vorhanden und das Auto an der Wallbox. Leider klappte das Laden nicht. Nach wenigen Minuten brach die Wallbox den Ladevorgang ab. Im Webinterface stand nur EVSE hat den Ladevorgang abgebrochen. Log in der Anlage

debug-report-warp-SMq-2023-12-18T14-56-52-099.txt

[deepflyer911]

Grüße zusammen,

@mattsches gibt es eine Vermutung, was die Ursache für mein Problem sein könnte?

[mattsches]

In deinem Log steht, dass nach dem Startkommando durch die Phasenumschaltung der Charger State nur auf 2 wechselt. Das ist "Ladebereit", siehe hier: https://www.warp-charger.com/api.html#evse_state. Erwartet wird aber 3 = "Lädt", und das innerhalb 30 Sekunden nach Startkommando. Nachdem das nicht passiert, schickt die Phasenumschaltung noch zwei weitere Startkommandos ab, beide wieder im Abstand von 30 Sekunden. Dann bricht der Vorgang ab, weil die maximale Zahl von Startversuchen erreicht ist. Das Laden hat also nach allem, was ich erkennen kann, gar nicht erst begonnen, sondern der Start ging gleich schief.

Warum der Ladevorgang nicht startet, obwohl rund 10 A Ladestrom von extern freigegeben sind, kann ich nicht sagen. Der Kommunikationsablauf mit dem EVSE-Bricklet an sich funktioniert, denn weder bei mir noch bei @ThomKa gibt es dieses Problem. Ich tippe also eher auf das Zusammenspiel von (diesem) Auto und Wallbox (bzw. genauer dem EVSE-Bricklet). Oder das Auto bockt, weil erst fünf Minuten nach dem Einstecken die Ladefreigabe kam.

Ist das Verhalten denn reproduzierbar? Im Ladeprotokoll sind ja einige erfolgreiche Ladevorgänge dokumentiert. Wie hast du die denn durchgeführt?

[deepflyer911]

@mattsches die anderen sichtbaren Ladungen sind jeweils durch Schnelladungen, also manueller Start erfolgt. Da gab es einen unmittelbaren zeitlichen Zusammenhang vom Einstecken zum Ladestart.

Das du aus dem Log liest, dass überhaupt keine Ladung zustande kam erstaunt mich. Hatte es in der Weboberfläche beobachtet, und da konnte man erkennen, dass für kurze Zeit eine Ladungen erfolgte, bevor es wieder abbrach. Hatte gehofft, dass man das im Log auch erkennen kann.

[mattsches]

                  3,152  This is warp-SMq (warp-SMq), a WARP Charger Pro 22kW
                  3,163  Phase switcher: Charging initiated by EVSE but requested power is not sufficient. Requesting EVSE to stop charging.
                  5,698  Wifi connected to Mephisto, BSSID B0:F2:08:80:C0:79
                  6,215  Wifi got IP address: 192.168.178.112/24. Own MAC address: 40:F5:20:5C:93:BC
                 10,225  Phase switcher: Sending stop API request to EVSE.
                 10,480  Phase switcher: Charging stopped by EVSE, changing to standby state.
                 10,738  Charger state changed from 2 to 1
                 22,651  MQTT: Connected to broker.
                 22,652  MQTT: Recv buf is 2048 bytes. meter/all_values_update requires 1786. Maybe bump MQTT_RECV_BUFFER_SIZE?
                 22,663  MQTT: Recv buf is 2048 bytes. charge_manager/config_update requires 1553. Maybe bump MQTT_RECV_BUFFER_SIZE?
2023-12-18 14:48:48,197  NTP synchronized at 34,659!
2023-12-18 14:50:44,034  debug: HWM of task 'watchdog_task' changed: 312
2023-12-18 14:53:14,467  Wrote last uptime to flash
2023-12-18 14:53:39,810  Phase switcher: Requesting EVSE to start charging.
2023-12-18 14:53:40,066  Phase switcher: Sending start API request to EVSE.
2023-12-18 14:53:40,636  Charger state changed from 1 to 2
2023-12-18 14:53:49,919  debug: HWM of task 'watchdog_task' changed: 264
2023-12-18 14:54:10,235  Phase switcher: Sending start API request to EVSE.
2023-12-18 14:54:40,400  Phase switcher: Sending start API request to EVSE.
2023-12-18 14:55:10,568  Phase switcher: Tried to start EVSE for 3 times. Aborting.

Einen Charger state 3 sehe ich da nirgends. Laut Log ist der tatsächliche Ladevorgang (Schütz schaltet durch) also nie gestartet.

Nachdem das Schnellladen funktioniert, sehe ich am ehesten einen Zusammenhang zu den fünf Minuten Wartezeit, die das Auto möglicherweise nicht toleriert. Das kannst du checken, indem du beim nächsten PV-Überschuss mehr als fünf Minuten wartest, nachdem genügend Leistung zur Verfügung steht und dann erst das Auto ansteckst. Dann startet der Ladevorgang ja auch gleich. Dasselbe gilt natürlich für einen Neustart der Box, wie im Protokoll oben zu sehen. Da dauert es dann auch die von dir eingestellten fünf Minuten, bis die Phasenumschaltung die Ladung freigibt. Also auch bei einem Neustart bei verfügbarer Leistung erst noch warten, bis du das Auto ansteckst.

Mehr fällt mir leider nicht ein. Möglicherweise (vermutlich) würde eine CP-Trennung hier helfen, wenn wirklich der Zeitversatz das Problem ist.

[mattsches]

Ich habe ein Update auf den aktuellen TF Entwicklungsstand 2.1.90 durchgeführt: https://github.com/mattsches1/esp32-firmware/releases/tag/phase_switcher-2.1.90.1

@deepflyer911, was ich noch fragen wollte: In deinem Log ist zu sehen, dass die Wallbox erst kurz vor dem Ladeproblem neu gestartet wurde. Hattest du das gemacht? Falls nein, kommt nämlich noch ein Absturz in Frage, evtl. wieder wegen Ressourcenengpässen durch das SOC-Modul. Wobei mich das andererseits wieder wundern würde, denn das Schnellladen hat ja funktioniert, wie du sagst. Das SOC-Modul habe ich im oben verlinken Release deaktiviert, weil ich es mit dem aktuellen TF-Stand aktuell noch nicht zum Laufen bringe. Du kannst ja mal testen, ob dein Problem damit noch auftritt.

[ThomKa]

Guten Morgen zusammen. Nachdem ich artig mitgelesen habe, kann ich vielleicht etwas beitragen... Bei den letzten Ladevorgängen passierte es zwei mal, dass die Ladung (11kW EPEX) für ca 30 - 180 Sekunden startete, also die Schütze anzogen und dann der Ladevorgang beendet wurde. Am FZG erfolgte zu dieser Zeit kein Eingriff. Beheben konnte ich dies nur durch einen Neustart der WARP. 

Auch hatte ich mal die Ladestati zwecks Pushover-Information ausgewertet. Allerdings kam mir die Abfolge der Stati "durcheinander" vor. Deswegen werte ich aktuell nur noch den Fehlerstatus "4" aus. Und dieser tritt sporadisch auf. Gerade heute Nacht, wo zur 21ten Stunde und zur 1ten Stunde geladen wurde. Der ENYAQ war dazu seit ca 2020 angeschlossen. Um 2101 wurde acP auf 11000 W gesetzt, um 2201 auf 0 W, um 0101 wieder auf 11000 und um 0143 war der ZielSoC erreicht, womit acP wieder auf 0 gesetzt wurde. Um 2202 trat der Status "4" auf. 

Wenn ihr mir genauer sagt, was ich wie und wann an Logs erzeugen soll, unterstütze ich gerne mit allen Informationen. 

 

So zum Jahresausklang möchte ich mich bei Euch allen für Euer Engagement und investierte Zeit bedanken. Ich weiß dies sehr zu schätzen und bin froh, dass wir den Umbau auf @mattsches Initiative/Voraussetzungen durchgeführt haben. Sofern wir uns erst im nächsten Schaltjahr "hören", wünsche ich Euch einen tollen Jahreswechsel und alles Gute 🍀👍. Herzliche Grüße, Thomas 

bearbeitet December 30, 2023 at 14:00 von ThomKa

[mattsches]

@ThomKa, danke für die Info. Das scheint mir allerdings eine andere Situation zu sein. Dein Ladevorgang wurde nach einer Stunde planmäßig gestoppt, dabei kam kurzzeitig der Fehlerstatus. Ich habe bei mir während Schaltvorgängen auch schon sporadisch und kurzzeitige Schützfehler gesehen, allerdings kann ich die nicht reproduzieren. Und bei @deepflyer911 ist die Situation ja die, dass der Ladevorgang gar nicht erst anfängt bzw. nach seiner Beobachtung nach sehr kurzer Zeit abgebrochen wurde. Warten wir mal, wie sich die Situation mit der oben verlinkten v2.1.90 verhält.

Auch euch einen guten Rutsch und alles Gute für das kommende Jahr!