1.9.301.1: FATAL Regulation loop needs XX seconds?

[MichaO]

Moin,

habe seit einiger Zeit wieder mal ins Debug-Log geschaut und festgestellt, dass es voll mit derartigen Meldungen ist "FATAL Regulation loop needs 14 seconds". Ich habe nun das höchste Debüt-Level eingestellt, auf die 1.9.301.1 upgedated (openWB series2 Duo), aber keine Änderung. Anbei mal ein Auszug aus dem Log:

Code: Alles auswählen

2023-05-29 18:27:01: PID: 11686: Previous regulation loop still running. Skipping. (LV0) at 35 main /var/www/html/openWB/regel.sh
10242
set-currents: setze ladung auf 6A
2023-05-29 18:26:58: PID: 10242: uberschuss 6711 wattbezug -6711 ladestatus 1 llsoll 6 pvwatt -7540 mindestuberschussphasen 1300 wattkombiniert 6711 schaltschwelle 230 (LV2) at 586 main /var/www/html/openWB/regel.sh
2023-05-29 18:26:58: PID: 10242: anzahlphasen 1 (LV1) at 585 main /var/www/html/openWB/regel.sh
2023-05-29 18:26:57: PID: 10242: Zeit zum abfragen aller Werte 6 Sekunden (LV1) at 186 main /var/www/html/openWB/regel.sh
2023-05-29 18:26:56: PID: 10242: chargestatlp1 0 chargestatlp2 0 chargestatlp3 0 (LV1) at 1274 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: plugstatlp1 1 plugstatlp2 0 plugstatlp3 0 (LV1) at 1273 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: lp1enabled 1 lp2enabled 1 lp3enabled 1 (LV1) at 1272 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: EVU 1:V/10A 2: V/8A 3: V/9A (LV1) at 1271 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: lla3 0 llv3 239.2 llas13 0 llas23  soclp1 90 soclp2 0 (LV1) at 1270 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: lla2 0 llv2 238.6 llas12 0 llas22  sofortll 16 hausverbrauch 829 wattbezug -6711 uberschuss 6711 (LV1) at 1269 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: lla1 0 llv1 239.6 llas11 0 llas21  mindestuberschuss 1300 abschaltuberschuss 0 lademodus 2 (LV1) at 1268 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: pv1watt -5877 pv2watt -1663 pvwatt -7540 ladeleistung 0 llalt 6 nachtladen 0 nachtladen 0 minimalA 6 maximalA 32 (LV1) at 1267 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: etproviderprice  etprovidermaxprice  (LV1) at 1265 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10242: speicherleistung 0 speichersoc 100 (LV1) at 1262 loadvars loadvars.sh
2023-05-29 18:26:56: PID: 10532: RET: 0 (LV2) at 16 main modules/bezug_kostalplenticoreem300haus/main.sh
2023-05-29 18:26:56: PID: 21620: legacy run server: Completed running command in 0.01s: ["bezug_kostalplenticoreem300haus.kostal_plenticore","1"]
2023-05-29 18:26:56: PID: 21620: Kostal-Plenticore: Kostal Plenticore Haus: 1
2023-05-29 18:26:56: PID: 21620: legacy run server: Received command ["bezug_kostalplenticoreem300haus.kostal_plenticore","1"]
DUo2/dev/ttyUSB0idadd106
2023-05-29 18:26:54: PID: 10477: BattLeistung: 0 (LV1) at 19 main modules/speicher_kostalplenticore/main.sh
2023-05-29 18:26:54: PID: 10477: RET: 0 (LV2) at 17 main modules/speicher_kostalplenticore/main.sh
2023-05-29 18:26:54: PID: 21620: legacy run server: Completed running command in 0.00s: ["speicher_kostalplenticore.kostal_plenticore"]
2023-05-29 18:26:54: PID: 21620: legacy run server: Received command ["speicher_kostalplenticore.kostal_plenticore"]
2023-05-29 18:26:54: PID: 21620: legacy run server: Completed running command in 0.74s: ["modules.devices.json.device","inverter","http://192.168.30.6/solar_api/v1/GetPowerFlowRealtimeData
2023-05-29 18:26:54: PID: 21620: soc.modules.common.store._api: Saving InverterState(currents=[0.0, 0.0, 0.0], dc_power=None, power=-1663.0, exported=7614320.0)

}
}
"Timestamp" : "2023-05-29T18:26:53+02:00"
},
"UserMessage" : ""
"Reason" : "",
"Code" : 0,
"Status" : {
"RequestArguments" : {},
"Head" : {
},
}
"Version" : "12"
},
"rel_SelfConsumption" : null
"rel_Autonomy" : null,
"P_PV" : 1663,
"P_Load" : null,
"P_Grid" : null,
"P_Akku" : null,
"Mode" : "produce-only",
"Meter_Location" : "unknown",
"E_Year" : 1870281.625,
"E_Total" : 7614320,
"E_Day" : 39560,
"Site" : {
},
}
"P" : 1663
"E_Year" : 1870281.625,
"E_Total" : 7614320,
"E_Day" : 39560,
"DT" : 105,
"1" : {
"Inverters" : {
"Data" : {
"Body" : {
2023-05-29 18:26:53: PID: 21620: soc.modules.common.req: Get-Response: {
2023-05-29 18:26:53: PID: 21620: requests.packages.urllib3.connectionpool: http://192.168.30.6:80 "GET /solar_api/v1/GetPowerFlowRealtimeData.fcgi HTTP/1.1" 200 904
2023-05-29 18:26:53: PID: 21620: requests.packages.urllib3.connectionpool: Starting new HTTP connection (1): 192.168.30.6:80
2023-05-29 18:26:53: PID: 21620: soc.modules.common.component_context: Update Komponenten ['Json Wechselrichter']
2023-05-29 18:26:53: PID: 21620: legacy run server: Received command ["modules.devices.json.device","inverter","http://192.168.30.6/solar_api/v1/GetPowerFlowRealtimeData
2023-05-29 18:26:53: PID: 21620: legacy run server: Completed running command in 0.45s: ["wr_plenticore.read_kostalplenticore","192.168.30.2","192.168.30.3","1","none"]
2023-05-29 18:26:53: PID: 21620: Kostal-Plenticore: WR2 Leistung = 2927PV_total = 5877
2023-05-29 18:26:53: PID: 21620: Kostal-Plenticore: WR1 Leistung = 2950PV_total = 2950
-Battery:1 -WR3:none-WR4:none-WR5:none
2023-05-29 18:26:53: PID: 21620: Kostal-Plenticore: Wechselrichter Kostal Plenticore Config - WR1:192.168.30.2 -WR2:192.168.30.3
2023-05-29 18:26:53: PID: 21620: legacy run server: Received command ["wr_plenticore.read_kostalplenticore","192.168.30.2","192.168.30.3","1","none"]
2023-05-29 18:26:51: PID: 10242: **** Regulation loop start **** (LV1) at 77 main /var/www/html/openWB/regel.sh
2023-05-29 18:26:44: PID: 8773: **** FATAL ********************************* (LV0) at 68 cleanup /var/www/html/openWB/regel.sh
2023-05-29 18:26:44: PID: 8773: **** FATAL Regulation loop needs 13 seconds (LV0) at 67 cleanup /var/www/html/openWB/regel.sh
2023-05-29 18:26:44: PID: 8773: **** FATAL ********************************* (LV0) at 66 cleanup /var/www/html/openWB/regel.sh
set-currents: setze ladung auf 12A
2023-05-29 18:26:41: PID: 10182: Previous regulation loop still running. Skipping. (LV0) at 35 main /var/www/html/openWB/regel.sh
8773
set-currents: setze ladung auf 6A
2023-05-29 18:26:38: PID: 8773: uberschuss 7119 wattbezug -7119 ladestatus 1 llsoll 6 pvwatt -7752 mindestuberschussphasen 1300 wattkombiniert 7119 schaltschwelle 230 (LV2) at 586 main /var/www/html/openWB/regel.sh
2023-05-29 18:26:38: PID: 8773: anzahlphasen 1 (LV1) at 585 main /var/www/html/openWB/regel.sh
2023-05-29 18:26:37: PID: 8773: Zeit zum abfragen aller Werte 6 Sekunden (LV1) at 186 main /var/www/html/openWB/regel.sh
2023-05-29 18:26:36: PID: 8773: chargestatlp1 0 chargestatlp2 0 chargestatlp3 0 (LV1) at 1274 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: plugstatlp1 1 plugstatlp2 0 plugstatlp3 0 (LV1) at 1273 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: lp1enabled 1 lp2enabled 1 lp3enabled 1 (LV1) at 1272 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: EVU 1:V/10A 2: V/9A 3: V/9A (LV1) at 1271 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: lla3 0 llv3 239.2 llas13 0 llas23  soclp1 90 soclp2 0 (LV1) at 1270 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: lla2 0 llv2 238.8 llas12 0 llas22  sofortll 16 hausverbrauch 633 wattbezug -7119 uberschuss 7119 (LV1) at 1269 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: lla1 0 llv1 239.6 llas11 0 llas21  mindestuberschuss 1300 abschaltuberschuss 0 lademodus 2 (LV1) at 1268 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: pv1watt -6031 pv2watt -1721 pvwatt -7752 ladeleistung 0 llalt 6 nachtladen 0 nachtladen 0 minimalA 6 maximalA 32 (LV1) at 1267 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: etproviderprice  etprovidermaxprice  (LV1) at 1265 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 8773: speicherleistung 0 speichersoc 100 (LV1) at 1262 loadvars loadvars.sh
2023-05-29 18:26:36: PID: 9063: RET: 0 (LV2) at 16 main modules/bezug_kostalplenticoreem300haus/main.sh
2023-05-29 18:26:36: PID: 21620: legacy run server: Completed running command in 0.01s: ["bezug_kostalplenticoreem300haus.kostal_plenticore","1"]
2023-05-29 18:26:36: PID: 21620: Kostal-Plenticore: Kostal Plenticore Haus: 1
2023-05-29 18:26:36: PID: 21620: legacy run server: Received command ["bezug_kostalplenticoreem300haus.kostal_plenticore","1"]
DUo2/dev/ttyUSB0idadd106
2023-05-29 18:26:34: PID: 9008: BattLeistung: 0 (LV1) at 19 main modules/speicher_kostalplenticore/main.sh
2023-05-29 18:26:34: PID: 9008: RET: 0 (LV2) at 17 main modules/speicher_kostalplenticore/main.sh
2023-05-29 18:26:34: PID: 21620: legacy run server: Completed running command in 0.00s: ["speicher_kostalplenticore.kostal_plenticore"]
2023-05-29 18:26:34: PID: 21620: legacy run server: Received command ["speicher_kostalplenticore.kostal_plenticore"]
2023-05-29 18:26:34: PID: 21620: legacy run server: Completed running command in 0.78s: ["modules.devices.json.device","inverter","http://192.168.30.6/solar_api/v1/GetPowerFlowRealtimeData
2023-05-29 18:26:34: PID: 21620: soc.modules.common.store._api: Saving InverterState(currents=[0.0, 0.0, 0.0], dc_power=None, power=-1721.0, exported=7614309.5)

}
}
"Timestamp" : "2023-05-29T18:26:33+02:00"
},
"UserMessage" : ""
"Reason" : "",
"Code" : 0,
"Status" : {
"RequestArguments" : {},
"Head" : {
},
}
"Version" : "12"
},
"rel_SelfConsumption" : null
"rel_Autonomy" : null,
"P_PV" : 1721,
"P_Load" : null,
"P_Grid" : null,
"P_Akku" : null,
"Mode" : "produce-only",
"Meter_Location" : "unknown",
"E_Year" : 1870271.875,
"E_Total" : 7614309.5,
"E_Day" : 39550,
"Site" : {
},
}
"P" : 1721
"E_Year" : 1870271.875,
"E_Total" : 7614309.5,
"E_Day" : 39550,
"DT" : 105,
"1" : {
"Inverters" : {
"Data" : {
"Body" : {
2023-05-29 18:26:33: PID: 21620: soc.modules.common.req: Get-Response: {
2023-05-29 18:26:33: PID: 21620: requests.packages.urllib3.connectionpool: http://192.168.30.6:80 "GET /solar_api/v1/GetPowerFlowRealtimeData.fcgi HTTP/1.1" 200 908
2023-05-29 18:26:33: PID: 21620: requests.packages.urllib3.connectionpool: Starting new HTTP connection (1): 192.168.30.6:80
2023-05-29 18:26:33: PID: 21620: soc.modules.common.component_context: Update Komponenten ['Json Wechselrichter']
2023-05-29 18:26:33: PID: 21620: legacy run server: Received command ["modules.devices.json.device","inverter","http://192.168.30.6/solar_api/v1/GetPowerFlowRealtimeData
2023-05-29 18:26:33: PID: 21620: legacy run server: Completed running command in 0.35s: ["wr_plenticore.read_kostalplenticore","192.168.30.2","192.168.30.3","1","none"]
2023-05-29 18:26:33: PID: 21620: Kostal-Plenticore: WR2 Leistung = 2998PV_total = 6031
2023-05-29 18:26:33: PID: 21620: Kostal-Plenticore: WR1 Leistung = 3033PV_total = 3033
-Battery:1 -WR3:none-WR4:none-WR5:none
2023-05-29 18:26:33: PID: 21620: Kostal-Plenticore: Wechselrichter Kostal Plenticore Config - WR1:192.168.30.2 -WR2:192.168.30.3
2023-05-29 18:26:33: PID: 21620: legacy run server: Received command ["wr_plenticore.read_kostalplenticore","192.168.30.2","192.168.30.3","1","none"]
2023-05-29 18:26:31: PID: 8773: **** Regulation loop start **** (LV1) at 77 main /var/www/html/openWB/regel.sh
2023-05-29 18:26:24: PID: 7302: **** FATAL ********************************* (LV0) at 68 cleanup /var/www/html/openWB/regel.sh
2023-05-29 18:26:24: PID: 7302: **** FATAL Regulation loop needs 13 seconds (LV0) at 67 cleanup /var/www/html/openWB/regel.sh
2023-05-29 18:26:24: PID: 7302: **** FATAL ********************************* (LV0) at 66 cleanup /var/www/html/openWB/regel.sh
set-currents: setze ladung auf 12A
2023-05-29 18:26:21: PID: 8711: Previous regulation loop still running. Skipping. (LV0) at 35 main /var/www/html/openWB/regel.sh
7302

Ich erkenne nicht, woran das liegen könnte. Seht ihr da was, was nicht korrekt funktioniert und diese Verzögerungen verursacht?
Gruß
Michael

[philipp123]

Da du nichts zu deiner Hardware schreibst, was hier ganz praktisch wäre, rate ich mal:
Hast du go-e und/oder Tibber im Einsatz?

[MichaO]

Also ich hab 2 Plenticore (1x mit BYD) und einen Fronius. In der Tat verwende ich Tibber, das Modul ist sogar von mir, ebenso wie das für Kostal Plenticore. Stimmt damit etwas nicht, dass Du gleich darauf kommst? Ich kann in den Logs diesbezüglich keine Fehler oder überlangen Laufzeiten feststellen. Falls es damit ein Problem gibt und das bekannt ist, wäre ich für Hinweise dankbar.

[philipp123]

viewtopic.php?p=86404#p86404

Hier gab es halt die Erkenntnis, dass es mit Tibber eng werden kann mit den 10 Sekunden.

[MichaO]

Danke für den Link. Tibber kann eigentlich nicht das Problem der Regelschleife sein. Das Preisupdate wird nicht über die Regelschleife alle 10s sondern über CRON alle 5 Minuten durchgeführt. Solange es mehr als 10 zukünftige Preis-Werte in der (internen) Preisliste gibt, macht das Tibber-Modul dann nichts, außer die interne Liste jede Stunde um den vorherigen Stundenpreis zu bereinigen. Das braucht so gut wie keine Zeit. Hierzu der Auszug aus dem Log:

Code: Alles auswählen

2023-05-30 07:00:04: Modul tibbergetprices.py: Modullaufzeit 0.055675 s
2023-05-30 07:00:04: Modul tibbergetprices.py: Publiziere Preisliste
2023-05-30 07:00:04: Modul tibbergetprices.py: Verwende Preise aus bereinigter bisheriger Preisliste
2023-05-30 07:00:04: Modul tibbergetprices.py: Ausreichend zukuenftige Preise in bisheriger Preisliste
2023-05-30 07:00:04: Modul tibbergetprices.py: Letzter Preis in bisherige Preisliste gueltig ab heute, 23:00 Uhr
2023-05-30 07:00:04: Modul tibbergetprices.py: Bisherige Preisliste hat noch 17 Eintraege
2023-05-30 07:00:04: Modul tibbergetprices.py: Es wurde 1 Preis geloescht
2023-05-30 07:00:04: Modul tibbergetprices.py: Bisherige Preisliste bereinigt
2023-05-30 07:00:04: Modul tibbergetprices.py: Bereinige bisherige Preisliste
2023-05-30 07:00:04: Modul tibbergetprices.py: Bisherige Preisliste gelesen
2023-05-30 07:00:04: Modul tibbergetprices.py: Lese bisherige Preisliste

Natürlich dauert es deutlich länger, wenn Preise angerufen werden und noch länger, wenn dann die Tibber-API nicht flott genug antwortet, was schonmal passiert. Aber es läuft ja wie gesagt außerhalb der Regelschleife.

Vielleicht kann einer der derzeitigen Entwickler aus dem openWB-Team was dazu sagen? Irgendwo her muss ja die Verzögerung der Regelschleife kommen. Ich habe gerade nochmal ins Log geschaut, heute Nacht kamen fast nur noch WARNINGS (um 8s je Durchlauf). Ich werde das beobachten und schaue mal, ab wann wieder die FATAL-Einträge los gehen. Vielleicht ist aber auch die Schleife als Bash-Skript schlichtweg zu langsam und würde als Python-Modul schneller sein? Keine Ahnung.

[balistarii]

Hallo, kann ich bestätigen.
Tritt bei meiner openWB series2 custom auch zeitweise auf.
Ich habe ebenfalls einen Kostal Plenticore mit KSEM, beide mit aktueller Firmware. Allerdings keinen Speicher.

Code: Alles auswählen

2023-05-29 14:50:02: PID: 3130: Starting OpenWB services (LV0)
2023-05-29 14:50:01: PID: 2891: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:45:03: PID: 31386: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:45:03:  Load: 0.48 0.45 0.76
2023-05-29 14:45:02: PID: 31619: Starting OpenWB services (LV0)
2023-05-29 14:45:02: PID: 31386: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:40:03: PID: 27597: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:40:02:  Load: 0.49 0.55 0.91
2023-05-29 14:40:02: PID: 27838: Starting OpenWB services (LV0)
2023-05-29 14:40:01: PID: 27597: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:35:03: PID: 23748: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:35:02:  Load: 0.67 0.94 1.15
2023-05-29 14:35:02: PID: 23982: Starting OpenWB services (LV0)
2023-05-29 14:35:01: PID: 23748: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:30:03: PID: 19963: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:30:02:  Load: 1.40 1.37 1.33
2023-05-29 14:30:02: PID: 20209: Starting OpenWB services (LV0)
2023-05-29 14:30:01: PID: 19963: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:29:20: PID: 14003: **** FATAL ********************************* (LV0)
2023-05-29 14:29:20: PID: 14003: **** FATAL Regulation loop needs 9 seconds (LV0)
2023-05-29 14:29:20: PID: 14003: **** FATAL ********************************* (LV0)
2023-05-29 14:28:49: PID: 10384: **** WARNING **** Regulation loop needs 8 seconds (LV0)
2023-05-29 14:25:03: PID: 16168: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:25:03:  Load: 1.18 1.38 1.33
2023-05-29 14:25:02: PID: 16414: Starting OpenWB services (LV0)
2023-05-29 14:25:02: PID: 16168: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:21:50: PID: 24337: **** WARNING **** Regulation loop needs 8 seconds (LV0)
2023-05-29 14:21:41: PID: 23351: **** FATAL ********************************* (LV0)
2023-05-29 14:21:41: PID: 23351: **** FATAL Regulation loop needs 9 seconds (LV0)
2023-05-29 14:21:41: PID: 23351: **** FATAL ********************************* (LV0)
2023-05-29 14:21:30: PID: 22230: **** WARNING **** Regulation loop needs 8 seconds (LV0)
2023-05-29 14:20:03: PID: 12389: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:20:02:  Load: 2.38 1.88 1.44
2023-05-29 14:20:02: PID: 12635: Starting OpenWB services (LV0)
2023-05-29 14:20:01: PID: 12389: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:15:03: PID: 8618: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:15:02:  Load: 3.17 2.10 1.37
2023-05-29 14:15:01: PID: 8855: Starting OpenWB services (LV0)
2023-05-29 14:15:01: PID: 8618: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:10:02: PID: 4822: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:10:02:  Load: 1.77 1.17 0.89
2023-05-29 14:10:01: PID: 5069: Starting OpenWB services (LV0)
2023-05-29 14:10:01: PID: 4822: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:05:03: PID: 894: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:05:03:  Load: 0.53 0.48 0.67
2023-05-29 14:05:02: PID: 1129: Starting OpenWB services (LV0)
2023-05-29 14:05:02: PID: 894: ##### cron5min.sh started ##### (LV0)
2023-05-29 14:04:19: PID: 27361: **** WARNING **** Regulation loop needs 8 seconds (LV0)
2023-05-29 14:03:39: PID: 22549: **** WARNING **** Regulation loop needs 8 seconds (LV0)
2023-05-29 14:00:03: PID: 29516: ##### cron5min.sh finished ##### (LV0)
2023-05-29 14:00:02:  Load: 0.27 0.49 0.75
2023-05-29 14:00:02: PID: 29754: Starting OpenWB services (LV0)
2023-05-29 14:00:01: PID: 29516: ##### cron5min.sh started ##### (LV0)
2023-05-29 13:58:13: PID: 16394: Modbus EVSE read CP1 issue - using previous state '1' (LV0)
2023-05-29 13:55:03: PID: 25728: ##### cron5min.sh finished ##### (LV0)
2023-05-29 13:55:03:  Load: 0.08 0.50 0.84
2023-05-29 13:55:02: PID: 25979: Starting OpenWB services (LV0)
2023-05-29 13:55:02: PID: 25728: ##### cron5min.sh started ##### (LV0)
2023-05-29 13:50:03: PID: 21966: ##### cron5min.sh finished ##### (LV0)
2023-05-29 13:50:03:  Load: 0.95 0.99 1.08
2023-05-29 13:50:02: PID: 22205: Starting OpenWB services (LV0)
2023-05-29 13:50:02: PID: 21966: ##### cron5min.sh started ##### (LV0)
2023-05-29 13:45:03: PID: 18186: ##### cron5min.sh finished ##### (LV0)

[hhoefling]

Bei dir geht hier die Zeit flöten...
...18:26:38 bis ...44 (Schleifenende)
Leider ohne weitere Log-Zeilen, dort läuft u.a U1P3 /CP und die regelalgos je nach Lademode
Die reihen Hardware abfragen brauchen nur 6 Sekunden.

[rleidner]

Ich sehe auch gelegentlich Zeiten von > 30 Sekunden.

Code: Alles auswählen

2023-05-30 10:47:34: PID: 12924: **** FATAL ********************************* (LV0) at 68 cleanup /var/www/html/openWB/regel.sh
2023-05-30 10:47:34: PID: 12924: **** FATAL Regulation loop needs 33 seconds (LV0) at 67 cleanup /var/www/html/openWB/regel.sh
2023-05-30 10:47:34: PID: 12924: **** FATAL ********************************* (LV0) at 66 cleanup /var/www/html/openWB/regel.sh
2023-05-30 10:47:34: PID: 12924: anzahlphasen 1 (LV1) at 585 main /var/www/html/openWB/regel.sh
2023-05-30 10:47:33: PID: 12924: auf 3 Phasen NurPV Automatik geaendert (LV1) at 283 u1p3pswitch u1p3p.sh
2023-05-30 10:47:31: PID: 14143: Previous regulation loop still running. Skipping. (LV0) at 35 main /var/www/html/openWB/regel.sh
12924
2023-05-30 10:47:22: PID: 14122: Previous regulation loop still running. Skipping. (LV0) at 35 main /var/www/html/openWB/regel.sh
12924
2023-05-30 10:47:12: PID: 14098: Previous regulation loop still running. Skipping. (LV0) at 35 main /var/www/html/openWB/regel.sh
12924
2023-05-30 10:47:05: PID: 12924: Nur PV Laden derzeit 1 Phasen, auf NurPV Automatik konfiguriert, aendere auf 3 Phasen da viel Überschuss vorhanden... (LV1) at 275 u1p3pswitch u1p3p.sh
2023-05-30 10:47:05: PID: 12924: Timing Umschaltung: 480 / 480 (LV1) at 17 u1p3pswitch u1p3p.sh
2023-05-30 10:47:05: PID: 12924: automatische Umschaltung aktiv (LV1) at 16 u1p3pswitch u1p3p.sh
2023-05-30 10:47:05: PID: 12924: Zeit zum abfragen aller Werte 3 Sekunden (LV1) at 186 main /var/www/html/openWB/regel.sh
2023-05-30 10:47:04: PID: 12924: chargestatlp1 0 chargestatlp2 0 chargestatlp3 0 (LV1) at 1274 loadvars loadvars.sh
2023-05-30 10:47:04: PID: 12924: plugstatlp1 0 plugstatlp2 0 plugstatlp3 0 (LV1) at 1273 loadvars loadvars.sh
2023-05-30 10:47:04: PID: 12924: lp1enabled 1 lp2enabled 1 lp3enabled 1 (LV1) at 1272 loadvars loadvars.sh
2023-05-30 10:47:04: PID: 12924: EVU 1:V/-8A 2: V/-7A 3: V/-7A (LV1) at 1271 loadvars loadvars.sh
2023-05-30 10:47:04: PID: 12924: lla3 0 llv3 237.26727294921875 llas13 0 llas23  soclp1 78 soclp2 89 (LV1) at 1270 loadvars loadvars.sh
2023-05-30 10:47:04: PID: 12924: lla2 0 llv2 238.09518432617188 llas12 0 llas22  sofortll 16 hausverbrauch 78 wattbezug -5610 uberschuss 5610 (LV1) at 1269 loadvars loadvars.sh
2023-05-30 10:47:04: PID: 12924: lla1 0 llv1 238.16587829589844 llas11 0 llas21  mindestuberschuss 1500 abschaltuberschuss -100 lademodus 2 (LV1) at 1268 loadvars loadvars.sh
2023-05-30 10:47:04: PID: 12924: pv1watt -5819 pv2watt  pvwatt -5819 ladeleistung 0 llalt 6 nachtladen 0 nachtladen 0 minimalA 6 maximalA 18 (LV1) at 1267 loadvars loadvars.sh
2023-05-30 10:47:02: PID: 12924: **** Regulation loop start **** (LV1) at 77 main /var/www/html/openWB/regel.sh

Mode ist auf PV-Laden und es ist kein Fahrzeug angesteckt.
Das scheint immer zu passieren, wenn so eine 1p3 oder 3p1 Umschaltung wie diese im Log auftaucht:

Code: Alles auswählen

2023-05-30 10:47:05: PID: 12924: Nur PV Laden derzeit 1 Phasen, auf NurPV Automatik konfiguriert, aendere auf 3 Phasen da viel Überschuss vorhanden... (LV1) at 275 u1p3pswitch u1p3p.sh

[MichaO]

Phasenumschaltung kann eine Ursache sein, aber ich habe gar keine. Leider geht aus dem Log nicht hervor, woher genau die Verzögerung kommt. Was anscheinend bei allen so ist, ist die Zeit der reinen Abfrage der Werte aus den Wechselrichtern, Akkus etc. Die liegt ja anscheinend irgendwo um 6 Sekunden.

[hhoefling]

Bei mir vergeht an der Stelle 0-1 Sekunde