Sporadisch lange Antwortzeiten FHEMWEB

[FhemPiUser]

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?

[rudolfkoenig]

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.

[PatrickR]

Um Langläufer zu identifizieren helfen auch apptime und freezemon.

[FhemPiUser]

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.

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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?

[FhemPiUser]

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.

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?

[rudolfkoenig]

kann 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.

Gibt 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.

Oder 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.

[FhemPiUser]

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):

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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?