Hi,
ich messe automatisiert alle 5min die Antwortzeit von FHEMWEB von meinem NAS aus mit einem "curl -w" und stelle (auch bei manueller Bedienung) fest, dass ab und an (ca. 1-2x pro Stunde) FHEMWEB bei mir sehr lange Antwortzeiten von 5s bis zu 15s hat. Auch mit global verbose 4 kann ich aus dem fhem log die Ursache nicht feststellen. Da parallele ping-Messungen vom NAS aus überhaupt keine Verzögerung zeigen, der NAS load i.O. war und andere FHEM devices zum gleichen Zeitpunkt der Verzögerung vom "curl -w" in Logfiles geschrieben haben, scheint auch der NAS, der FHEM Rapsberry 4 (8GB RAM mit SSD) oder FHEM als Prozess insgesamt nicht zu stehen/blockieren. Freezemon hat auch nicht geholfen die Ursache zu finden. Load vom Raspberry ist im Bereich von 0.4-0.5 im Durchschnitt und %CPU fhem sehe ich auch wenn ich mit top schaue nie über 50%. iostat lässt auch nicht auf irgendwelche Probleme mit io schließen...
Hat jemand ähnliche Erfahrungen und eine Idee, was die Ursache sein könnte bzw. wie man diese herausfinden und beheben kann?
Die Abarbeitung in FHEM laeuft (bis auf Ausnahmen) nicht parallel (aka es ist "single-threaded").
Wenn irgendeine Aufgabe (notify/DOIF/etc) laenger braucht, dann wartet man auf die FHEMWEB Antwort solange, bis diese Aufgabe erledigt ist.
Um die Ursache zu isolieren wuerde ich in FHEM "attr global verbose 5" aktivieren, bis die Ueberwachung ein Problem meldet, und dann im FHEM-Log die fragliche Zeit untersuchen.
Um Langläufer zu identifizieren helfen auch apptime und freezemon.
danke. Freezemon hatte ich schon probiert.
Mit verbose 5 habe ich eben eine starke Verzögerung (curl Timeout nach 15s um 18:41:47) festgestellt, nachdem der MQTT2_Client die Verbindung zu HiveMQ im Internet kurz verloren hat. Es gab dann auch einen Fehler im Modbus Device.
2025.08.30 18:38:47.155 4: authorize ...: allowed_WEBwidget_syncclient returned dont care
2025.08.30 18:40:10.519 1: ....s1.eu.hivemq.cloud:8883 disconnected, waiting to reappear (HiveMQ)
2025.08.30 18:40:11.180 1: ... Modbus Error, Message: timeout waiting for reply to fc 4 to id 2
Die Frage, ob MQTT"_Client und Modbus Ursache oder Folge der Verzögerung sind. Falls der MQTT2_Client in Verbindung mit Internetabbrüchen oder ModbusAttr in Verbindung mit Timeouts tatsächlich die Ursache ist, kann man den MQTT2_Client / ModbusAttr irgendwie so umstellen, dass er nicht fhem blockiert, wenn die Verbindung verliert?
Bei der weiteren Verzögerung war die letzte Zeile vom curl / FHEMWEB:
2025.08.30 19:10:06.908 4: WEBRegenmesser: /fhem?cmd=get+MeinRegenmesser / RL:5986 / text/html; charset=UTF-8 / / Cache-Control: no-cache, no-store, must-revalidate
2025.08.30 19:10:10.085 1: SendMessage triggered with Titel: FHEM Raspi checkfhemalivecurltime-Alarm, Message: checkfhemalivecurltime > 5s 5.86s
Kann das "must-revalidate" etwas mit der Verzögerung zu tun haben?
Zitat von: rudolfkoenig am 30 August 2025, 18:00:07Die Abarbeitung in FHEM laeuft (bis auf Ausnahmen) nicht parallel (aka es ist "single-threaded").
Wenn irgendeine Aufgabe (notify/DOIF/etc) laenger braucht, dann wartet man auf die FHEMWEB Antwort solange, bis diese Aufgabe erledigt ist.
Um die Ursache zu isolieren wuerde ich in FHEM "attr global verbose 5" aktivieren, bis die Ueberwachung ein Problem meldet, und dann im FHEM-Log die fragliche Zeit untersuchen.
Gibt es irgendweine Möglichkeit für bestimmte zeitkritische devices einen eigenen parallelen Thread zu starten?
Oder eine zweite fhem-Instanz auf dem gleichen Raspberry, die mit der ersten fhem-Instanz kommuniziert?
Zitatkann man den MQTT2_Client [...] irgendwie so umstellen, dass er nicht fhem blockiert, wenn die Verbindung verliert?
MQTT2_Client duerfte nur dann blockieren, wenn als Ziel ein Rechnername (keine IP Adresse) angegeben wurde, und "attr global dnsServer" _nicht_ gesetzt ist.
Die systemeigene DNS-Bibliothek blockiert gerne 5+ Sekunden, falls der Server nicht antwortet.
Die mit dnsServer aktvierte in FHEM implementierte DNS-Aufloesung sollte blockierungsfrei sein.
ZitatGibt es irgendweine Möglichkeit für bestimmte zeitkritische devices einen eigenen parallelen Thread zu starten?
Das ist mW nur fuer bestimmte Module implementiert (mit BlockingCal, usw), und ist nicht optional.
ZitatOder eine zweite fhem-Instanz auf dem gleichen Raspberry, die mit der ersten fhem-Instanz kommuniziert?
Das ist moeglich, es einzurichten (via FHEM2FHEM, MQTT, etc) bedeutet aber Arbeit.
Ich suche noch immer nach der Ursache für die sporadisch langen Antwortzeiten von FHEMWEB.Hier mal ein Auszug aus dem Log der Antwortzeiten von FHEMWEB vom NAS aus (mit curl -w gemessen, ins Sekunden):
2025-09-06_08:05:02 checkfhemalivecurltime curltime: 0.53
2025-09-06_08:10:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_08:15:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_08:20:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_08:25:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_08:30:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_08:35:01 checkfhemalivecurltime curltime: 0.23
2025-09-06_08:40:02 checkfhemalivecurltime curltime: 0.39
2025-09-06_08:45:04 checkfhemalivecurltime curltime: 2.08
2025-09-06_08:50:02 checkfhemalivecurltime curltime: 0.18
2025-09-06_08:55:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_09:00:03 checkfhemalivecurltime curltime: 1.53
2025-09-06_09:05:33 checkfhemalivecurltime curltime: 15.00
2025-09-06_09:10:01 checkfhemalivecurltime curltime: 0.22
2025-09-06_09:15:01 checkfhemalivecurltime curltime: 0.23
2025-09-06_09:20:01 checkfhemalivecurltime curltime: 0.21
2025-09-06_09:25:01 checkfhemalivecurltime curltime: 0.22
2025-09-06_09:30:05 checkfhemalivecurltime curltime: 3.08
2025-09-06_09:35:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_09:40:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_09:45:02 checkfhemalivecurltime curltime: 0.32
2025-09-06_09:50:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_09:55:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_10:00:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_10:05:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_10:10:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_10:15:03 checkfhemalivecurltime curltime: 1.03
2025-09-06_10:20:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_10:25:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_10:30:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_10:35:01 checkfhemalivecurltime curltime: 0.24
2025-09-06_10:40:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_10:45:01 checkfhemalivecurltime curltime: 0.21
2025-09-06_10:50:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_10:55:02 checkfhemalivecurltime curltime: 0.19
2025-09-06_11:00:01 checkfhemalivecurltime curltime: 0.29
2025-09-06_11:05:07 checkfhemalivecurltime curltime: 5.25
2025-09-06_11:10:22 checkfhemalivecurltime curltime: 15.00
2025-09-06_11:15:01 checkfhemalivecurltime curltime: 0.18
2025-09-06_11:20:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_11:25:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_11:30:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_11:35:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_11:40:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_11:45:02 checkfhemalivecurltime curltime: 0.28
2025-09-06_11:50:01 checkfhemalivecurltime curltime: 0.19
2025-09-06_11:55:02 checkfhemalivecurltime curltime: 0.18
2025-09-06_12:00:02 checkfhemalivecurltime curltime: 0.18
2025-09-06_12:05:02 checkfhemalivecurltime curltime: 0.25
2025-09-06_12:10:02 checkfhemalivecurltime curltime: 0.18
2025-09-06_12:15:07 checkfhemalivecurltime curltime: 4.73
2025-09-06_12:20:02 checkfhemalivecurltime curltime: 0.18
2025-09-06_12:25:02 checkfhemalivecurltime curltime: 0.18
2025-09-06_12:30:03 checkfhemalivecurltime curltime: 1.28
2025-09-06_12:35:52 checkfhemalivecurltime curltime: 15.00
2025-09-06_12:40:07 checkfhemalivecurltime curltime: 4.32
Parallel wurde der ping-Antwortzeit gemessen (in ms), aber die war unauffällig:
2025-09-06_09:25:01 checkfhemalivecurltime ping249: 0.10
2025-09-06_09:30:05 checkfhemalivecurltime ping249: 0.17
2025-09-06_09:35:01 checkfhemalivecurltime ping249: 0.14
2025-09-06_09:40:01 checkfhemalivecurltime ping249: 0.14
2025-09-06_09:45:02 checkfhemalivecurltime ping249: 0.17
2025-09-06_09:50:01 checkfhemalivecurltime ping249: 0.14
2025-09-06_09:55:01 checkfhemalivecurltime ping249: 0.17
2025-09-06_10:00:01 checkfhemalivecurltime ping249: 0.13
2025-09-06_10:05:01 checkfhemalivecurltime ping249: 0.13
2025-09-06_10:10:01 checkfhemalivecurltime ping249: 0.10
2025-09-06_10:15:03 checkfhemalivecurltime ping249: 0.14
2025-09-06_10:20:01 checkfhemalivecurltime ping249: 0.13
2025-09-06_10:25:01 checkfhemalivecurltime ping249: 0.14
2025-09-06_10:30:01 checkfhemalivecurltime ping249: 0.15
2025-09-06_10:35:01 checkfhemalivecurltime ping249: 0.10
2025-09-06_10:40:01 checkfhemalivecurltime ping249: 0.12
2025-09-06_10:45:01 checkfhemalivecurltime ping249: 0.11
2025-09-06_10:50:01 checkfhemalivecurltime ping249: 0.10
2025-09-06_10:55:02 checkfhemalivecurltime ping249: 0.13
2025-09-06_11:00:01 checkfhemalivecurltime ping249: 0.12
2025-09-06_11:05:07 checkfhemalivecurltime ping249: 0.20
2025-09-06_11:10:22 checkfhemalivecurltime ping249: 0.15
2025-09-06_11:15:01 checkfhemalivecurltime ping249: 0.13
2025-09-06_11:20:01 checkfhemalivecurltime ping249: 0.10
2025-09-06_11:25:01 checkfhemalivecurltime ping249: 0.16
2025-09-06_11:30:01 checkfhemalivecurltime ping249: 0.20
2025-09-06_11:35:01 checkfhemalivecurltime ping249: 0.12
2025-09-06_11:40:01 checkfhemalivecurltime ping249: 0.10
2025-09-06_11:45:02 checkfhemalivecurltime ping249: 0.17
2025-09-06_11:50:01 checkfhemalivecurltime ping249: 0.10
2025-09-06_11:55:02 checkfhemalivecurltime ping249: 0.11
2025-09-06_12:00:02 checkfhemalivecurltime ping249: 0.16
2025-09-06_12:05:02 checkfhemalivecurltime ping249: 0.15
2025-09-06_12:10:02 checkfhemalivecurltime ping249: 0.14
2025-09-06_12:15:07 checkfhemalivecurltime ping249: 0.15
2025-09-06_12:20:02 checkfhemalivecurltime ping249: 0.10
2025-09-06_12:25:02 checkfhemalivecurltime ping249: 0.11
2025-09-06_12:30:03 checkfhemalivecurltime ping249: 0.16
2025-09-06_12:35:52 checkfhemalivecurltime ping249: 0.19
2025-09-06_12:40:07 checkfhemalivecurltime ping249: 0.14
In den fhem logs mit verbose 3 ist die Ursache nicht zu finden. Ein verbose 5 würde zu sehr großen Logs führen durch die vielen Devices, mqtt und modbus readings, daher kann ich das nicht (lange) machen.
Ich versuche nun mit apptime die Ursache zu finden. Aus der Tabelle werde ich aber nicht ganz schlau.
apptime maxDly ergibt:
name function max count total average maxDly avgDly TS Max call param Max call
tmr-HMUARTLGW_CheckCredits HMUARTLGW_CheckCredits 4 30 76.10 2.54 72398.28 4828.95 06.09. 12:36:24 HMUARTLGW_CheckCredits:USR_TCP232_T2_RM_HmUART_EG
tmr-ProcessRequestQueue queue 8 411 1168.17 2.84 68112.58 466.55 06.09. 12:35:54 queue:Lambda_EU13L
tmr-watchdog_client_ProcessTimer HASH(0x559ad745a8) 17 6 76.32 12.72 68066.50 11345.07 06.09. 12:32:05 HASH(watchdog)
tmr-HMLAN_KeepAliveCheck keepAliveCk 0 18 0.81 0.04 66402.09 3745.47 06.09. 12:37:00 keepAliveCk:HMLAN1
tmr-MQTT2_SERVER_keepaliveChecker HASH(0x559c5da0e8) 0 41 4.95 0.12 66380.21 2910.00 06.09. 12:30:12 HASH(mqtt2_Server)
tmr-NUT_PollTimer pollTimer 2 40 82.62 2.07 66378.43 3022.29 06.09. 12:37:13 pollTimer:nut
tmr-HMUARTLGW_CheckCmdResp HASH(0x559ac0b138) 18884 10 33724.22 3372.42 65112.67 9098.47 06.09. 12:34:50 HASH(USR_TCP232_T2_RM_HmUART_EG)
tmr-MQTT2_CLIENT_keepalive HASH(0x559e942238) 0 3 0.62 0.21 57107.33 19036.24 06.09. 12:31:45 HASH(HiveMQ)
tmr-DOIF_TimerTrigger REF(0x55a1286620) 559 1 559.22 559.22 57080.46 57080.46 06.09. 12:35:43 REF(0x55a1286620)
tmr-HMLAN_KeepAlive keepAlive 2 25 25.77 1.03 52149.26 4081.80 06.09. 12:29:09 keepAlive:HMLAN1
tmr-DOIF_TimerTrigger REF(0x559f501e00) 30 1 30.41 30.41 46640.44 46640.44 06.09. 12:35:43 REF(0x559f501e00)
tmr-DOIF_TimerTrigger REF(0x559fddf650) 29 1 29.38 29.38 43670.95 43670.95 06.09. 12:35:43 REF(0x559fddf650)
tmr-FHEM::SSCam::wdpollcaminfo HASH(0x559732b8c8) 1 6 5.37 0.90 43589.60 7292.02 06.09. 12:32:04 HASH(SSCAM_Haustuer)
tmr-LuftdatenInfo_statusRequest HASH(0x559a386078) 1 15 13.21 0.88 41866.33 5277.70 06.09. 12:37:13 HASH(luftdateninfo)
tmr-FHEM::SSCam::wdpollcaminfo HASH(0x559a7d6390) 0 7 5.38 0.77 39642.48 7165.53 06.09. 12:32:16 HASH(SSCAM_WZ)
tmr-FHEM::SSCam::wdpollcaminfo HASH(0x559ac64be8) 0 7 5.16 0.74 39024.78 6961.92 06.09. 12:31:08 HASH(SSCAM_WZ_innen)
tmr-DOIF_TimerTrigger REF(0x55a166ba60) 206 1 206.48 206.48 31491.25 31491.25 06.09. 12:34:26 REF(0x55a166ba60)
tmr-DOIF_TimerTrigger REF(0x559f7a6668) 195 1 195.50 195.50 28719.62 28719.62 06.09. 12:34:50 REF(0x559f7a6668)
tmr-FHEM::SSCam::wdpollcaminfo HASH(0x559aa8a3e0) 1 7 6.45 0.92 26913.47 3898.13 06.09. 12:37:01 HASH(SSCAM_Essecke)
tmr-GetUpdate update 59 26 1074.71 41.33 24138.25 6293.18 06.09. 12:36:53 update:SH10rt_1_LAN
tmr-FHEM::SSCam::wdpollcaminfo HASH(0x559aa99af0) 0 6 4.85 0.81 22203.72 5616.75 06.09. 12:30:38 HASH(SSCAM_carport)
tmr-CUL_HM_motionCheck BM_HM_Kueche 22 1 22.55 22.55 21238.57 21238.57 06.09. 12:34:26 BM_HM_Kueche:motionCheck
tmr-FHEM::SSCam::wdpollcaminfo HASH(0x559aa99cf8) 1 7 6.97 1.00 17526.19 5062.53 06.09. 12:36:58 HASH(SSCAM_Kueche)
tmr-BlockingKill HASH_unnamed 8 7 9.01 1.29 17243.44 4832.38 06.09. 12:35:43 HASH(0x559e90d740)
tmr-FW_closeInactiveClients 0 28 8 215.56 26.94 17185.86 7331.50 06.09. 12:36:52 0
tmr-HUEBridge_GetUpdate HASH(0x559a7e6798) 210 8 1492.45 186.56 17184.52 7330.92 06.09. 12:34:31 HASH(HUEBridge)
tmr-OBIS_CheckNoData HASH(0x559d764550) 2 8 18.55 2.32 17183.54 7329.84 06.09. 12:33:15 HASH(MT631)
tmr-SYSMON_Update HASH(0x5595de8578) 66 8 472.48 59.06 17174.56 7330.92 06.09. 12:35:48 HASH(sysmon)
tmr-HUEBridge_GetUpdate HASH(0x559d8cba90) 40 8 294.38 36.80 17169.05 7330.82 06.09. 12:35:48 HASH(HUEBridge_OG)
tmr-FRITZBOX_Readout_Start FritzBox.Readout 25 2 51.12 25.56 17046.73 8579.48 06.09. 12:30:26 FritzBox.Readout
tmr-DENON_AVR_KeepAlive HASH(0x5598acd220) 112 2 224.46 112.23 16935.50 8468.09 06.09. 12:35:43 HASH(DENON_X1000)
tmr-FHEM::SSCam::wdpollcaminfo HASH(0x559aa8c358) 0 7 5.89 0.84 16453.65 4015.73 06.09. 12:35:48 HASH(SSCAM_Terasse)
tmr-Shelly_status HASH(0x559cbd37d8) 2 7 9.46 1.35 15365.35 4668.78 06.09. 12:34:31 HASH(Shelly3EM2)
tmr-DOIF_TimerTrigger REF(0x55a10ff5e8) 4643 1 4643.49 4643.49 13747.72 13747.72 06.09. 12:34:31 REF(0x55a10ff5e8)
tmr-Shelly_status HASH(0x559e912dc0) 1 7 8.28 1.18 13738.41 3452.62 06.09. 12:33:15 HASH(Shelly1PMmini_HZKPumpe)
tmr-DOIF_TimerTrigger REF(0x559fbb1e78) 4686 1 4686.89 4686.89 12873.85 12873.85 06.09. 12:35:48 REF(0x559fbb1e78)
tmr-BlockingStart HASH_unnamed 7 1 7.79 7.79 5667.32 5667.32 06.09. 12:35:50 HASH(0x55937a22a0)
tmr-DOIF_TimerTrigger REF(0x55a19fb100) 559 1 559.28 559.28 4789.15 4789.15 06.09. 12:28:58 REF(0x55a19fb100)
tmr-DOIF_TimerTrigger REF(0x559ff6f320) 652 1 652.85 652.85 4421.68 4421.68 06.09. 12:33:15 REF(0x559ff6f320)
tmr-Shelly_status HASH(0x559d8c7c40) 2 12 22.37 1.86 4301.30 1959.84 06.09. 12:36:19 HASH(ShellyZirku)
tmr-DOIF_TimerTrigger REF(0x55a1262888) 201 1 201.48 201.48 3919.48 3919.48 06.09. 12:31:06 REF(0x55a1262888)
Das sieht ja aus als hätten alle möglichen Devices sehr lange Delays...
Welche Einheit ist "72398" maxDly? ms?