FHEM Blockiert und Meldung "Alarm clock" im Log

[bismosa]

Hallo!

Ich habe seit ein paar Tagen das Problem, das mein FHEM wohl gelegentlich blockiert.
Da ich gerade sehr viel ändere, möchte ich einen Fehler auf meiner Seite (z.B. ein DOIF das es schafft mein FHEM zu blockieren) nicht ausschließen. Aber seltsam ist das Verhalten.
Ich habe gerade recht viele Chrome-Tabs mit FHEM geöffnet (12-14 Stück). Diese fangen an sich aufzuhängen und mein Chrome erzeugt eine CPU-Last von 100% auf meinem Laptop (nicht das System auf dem FHEM läuft).
Mein Log sieht dann so aus:

Code Auswählen Erweitern

2025.05.04 16:17:22 2: FULLY: [fully] Error during request http://192.168.183.58:2323/?cmd=screenOn&password=fully1234&type=json. 192.168.183.58: Verbindungsaufbau abgelehnt (111)
Alarm clock
Alarm clock
Alarm clock
Alarm clock
Alarm clock
Alarm clock
Alarm clock
2025.05.04 16:25:14 1: [Freezemon] freezemon: possible freeze starting at 16:21:20, delay is 234.598 possibly caused by: no bad guy found :-(
2025.05.04 16:25:14 3: MQTT2_FHEM_Server: MQTT2_FHEM_Server_127.0.0.1_56980/myBrokerIO left us (keepalive check)
2025.05.04 16:25:14 3: MQTT2_FHEM_Server: MQTT2_FHEM_Server_127.0.0.1_43248/zigbee_pi left us (keepalive check)
2025.05.04 16:25:14 3: MQTT2_FHEM_Server: MQTT2_FHEM_Server_127.0.0.1_41465 left us (keepalive check)
Die Meldungen von FULLY sind häufiger. Haben hiermit nichts zu tun. Nur um den zeitlichen Ablauf zu beschreiben.

Starte ich Chrome neu, beruhigt sich wieder alles. Aber ob das damit zusammenhängt kann ich nicht sagen. Ich kann auch Chrome in dem Fall nicht mehr bedienen.

Woher stammt die Meldung "Alarm clock"? Ich konnte nichts in diesem Zusammenhang entdecken. Ist doch sicherlich nichts von FHEM?

Gruß
Bismosa

[Otto123]

Hallo Bismosa,

Woher stammt die Meldung "Alarm clock"? Ich konnte nichts in diesem Zusammenhang entdecken. Ist doch sicherlich nichts von FHEM?

das ist eine Meldung aus dem stdout von FHEM. Also eine Meldung die ein Programm - welches Du/FHEM startet - in den stdout schreibt. Häufig shell Befehle /Scripts, die aber auch in Modulen gestartet  werden könnten.

Gruß Otto

[rudolfkoenig]

Diese fangen an sich aufzuhängen und mein Chrome erzeugt eine CPU-Last von 100% auf meinem Laptop

Was sieht man in der JavaScript-Console des Browsers?

[bismosa]

Hallo!

Was sieht man in der JavaScript-Console des Browsers?

Leider gar nichts mehr, da Chrome so ausgelastet war, das nichts mehr lief 

Kann das denn überhaupt damit zusammenhängen? Oder war das eher ein Zufall?

Werde das beim nächsten Mal nochmal versuchen, ob ich da was finde. Da es nur 1-2x pro Tag auftaucht ist das aber etwas schwieriger abzupassen.

[bismosa]

Hallo,

nur ein kleines Update:
Der Browser auf meinem Laptop hat damit nichts zu tun. Die Meldung ist auch aufgetreten, während dieser abgeschaltet war.
Auch haben meine letzten Änderungen in FHEM wohl nichts damit zu tun, da ich auch einen Eintrag im Dezember im Log gefunden habe.
Um den ganzen auf die Schliche zu kommen, lasse ich FHEM derzeit mit Verbose 4 laufen. Jetzt ist es heute (endlich) wieder 2x vorgekommen...aber im Log ist nichts auffälliges in die Richtung. Entweder ist im entsprechenden Modul ein anderer Verbose eingestellt oder 4 reicht nicht.
Bei Verbose 5 kommen bei mir so viele Daten zusammen, das mein Speicherplatz auf dem System schnell knapp werden würde. Nun habe ich heute erst entdeckt, das Freezemon da ein eigenes Log integriert hat, das Verbose 5 loggt, wenn es einen Freeze gibt. Spannend. Bin mal gespannt, was dabei herauskommt.

Unabhängig davon habe ich aber gefunden, warum ich so oft einen freeze habe. Ich habe bei der Neueinrichtung von FHEM letztes Jahr vergessen das Attribut "longpoll websocket" zu setzen    Jedes Mal, wenn mein Tablet mit FTUI3 die Daten anfordert, habe ich einen Freeze von > 1 sek. (aber nicht so lange, wie bei den "Alarm clock" Meldungen.
Geändert habe ich es jetzt aber aus testgründen noch nicht.

Ich bin also noch dran...

Gruß
Bismosa

[rudolfkoenig]

Ich habe bei der Neueinrichtung von FHEM letztes Jahr vergessen das Attribut "longpoll websocket" zu setzen 

longpoll ist per Voreinstellung websocket fuer Chrome, und 1 (d.h. echtes Longpoll) sonst.
Eine Auswirkung auf die Performance in FHEM kann ich mir (noch) nicht vorstellen.

[bismosa]

Hallo!

Eine Auswirkung auf die Performance in FHEM kann ich mir (noch) nicht vorstellen.

Stimmt. Lief auch vorher auf Longpoll. Die Einstellung hatte keine Auswirkungen.

Ich habe mich jetzt lange nicht hier gemeldet, da ich eigentlich noch nicht weiter gekommen bin. Die Meldung "Alarm clock" taucht immer noch gelegentlich im Log auf.
Ich lasse mittlerweile mein FHEM-Log auf Verbose 3 laufen (anders ist die Datenmenge so groß, das ich das kaum händeln kann) und lasse im Fehlerfall von Freezemon die entsprechende Zeit (+5 sek. Verbose 5) loggen.
Immer wenn die Meldung auftaucht ist mein FHEM auch lange Zeit blockiert. Hier mal ein Beispiel von heute:
FHEM-Log:

Code Auswählen Erweitern

2025.05.18 13:06:40 1: [Freezemon] freezemon: Long function call detected ReadFn:WEBtablet_192.168.183.31_53931 - 1.436135 seconds
Alarm clock
Alarm clock
2025.05.18 13:12:41 1: [Freezemon] freezemon: Long function call detected ReadFn:WEBtablet_192.168.183.31_53932 - 70.75774 seconds
Die "Freezes" von ca. 1,5-2 sek. entstehen immer, wenn mein FTUI3-Tablet aufwacht. Dann werden sehr viele Daten per jsonlist2 abgefragt.
Da ich da mittlerweile auch schon viele Daten "benötige", habe ich wohl kaum eine chance die Zeiten zu kürzen.

Freezemon-Log:

Code Auswählen Erweitern

[Freezemon] freezemon: possible freeze starting at 13:11:31, delay is 70.583 possibly caused by: fn-ReadFn(WEBtablet_192.168.183.31_53932) tmr-DbLog_execMemCacheAsync(logdb) tmr-DbLog_execMemCacheAsync(logdb)
2025.05.18 13:11:29.006 4:  MQTT2_FHEM_Server_127.0.0.1_39064 myBrokerIO PUBLISH FHEMIO/MqttGenericBridge2/Firmata_OUT/value:on
2025.05.18 13:11:29.006 5:  MQTT2_FHEM_Server_127.0.0.1_39064 myBrokerIO => FHEMIO/MqttGenericBridge2/Firmata_OUT/value:on
2025.05.18 13:11:29.010 5: MQTT_GENERIC_BRIDGE: [mqttGeneric] Parse (MQTT2_SERVER : 'MQTT2_FHEM_Server'): Msg: FHEMIO/MqttGenericBridge2/Firmata_OUT/value => on
2025.05.18 13:11:29.010 4: MQTT2_DEVICE_Parse: MQTT2_mgb2_Firmata_OUT FHEMIO/MqttGenericBridge2/Firmata_OUT/value => value
2025.05.18 13:11:29.011 4: logdb - check Device: MQTT2_mgb2_Firmata_OUT , Event: value: on
2025.05.18 13:11:29.011 5: logdb - parsed Event: MQTT2_mgb2_Firmata_OUT , Event: value: on
2025.05.18 13:11:29.012 4: logdb - added event - Timestamp: 2025-05-18 13:11:29, Device: MQTT2_mgb2_Firmata_OUT, Type: MQTT2_DEVICE, Event: value: on, Reading: value, Value: on, Unit:
2025.05.18 13:11:29.013 5: End notify loop for MQTT2_mgb2_Firmata_OUT
2025.05.18 13:11:29.952 5: SMAEM SunnyHomeManager - received 608 bytes from "3017575707" but interval 15s isn't expired.
2025.05.18 13:11:29.978 4: logdb - check Device: MQTT2_FHEM_Server , Event: nrclients: 2
2025.05.18 13:11:29.978 5: logdb - parsed Event: MQTT2_FHEM_Server , Event: nrclients: 2
2025.05.18 13:11:29.978 4: logdb - added event - Timestamp: 2025-05-18 13:11:29, Device: MQTT2_FHEM_Server, Type: MQTT2_SERVER, Event: nrclients: 2, Reading: nrclients, Value: 2, Unit:
2025.05.18 13:11:29.979 5: End notify loop for MQTT2_FHEM_Server
2025.05.18 13:11:29.979 4: Connection closed for MQTT2_FHEM_Server_127.0.0.1_38353: Connection reset by peer
2025.05.18 13:11:29.979 4: Connection accepted from MQTT2_FHEM_Server_127.0.0.1_50101
2025.05.18 13:11:29.981 4: logdb - check Device: MQTT2_FHEM_Server , Event: nrclients: 3
2025.05.18 13:11:29.981 5: logdb - parsed Event: MQTT2_FHEM_Server , Event: nrclients: 3
2025.05.18 13:11:29.981 4: logdb - added event - Timestamp: 2025-05-18 13:11:29, Device: MQTT2_FHEM_Server, Type: MQTT2_SERVER, Event: nrclients: 3, Reading: nrclients, Value: 3, Unit:
2025.05.18 13:11:29.981 5: End notify loop for MQTT2_FHEM_Server
2025.05.18 13:11:29.982 4:  MQTT2_FHEM_Server_127.0.0.1_50101 cid: CONNECT V:4 keepAlive:60
2025.05.18 13:11:30.009 4:  MQTT2_FHEM_Server_127.0.0.1_39064 myBrokerIO PUBLISH FHEMIO/MqttGenericBridge2/Firmata_OUT/value:off
2025.05.18 13:11:30.010 5:  MQTT2_FHEM_Server_127.0.0.1_39064 myBrokerIO => FHEMIO/MqttGenericBridge2/Firmata_OUT/value:off
2025.05.18 13:11:30.014 5: MQTT_GENERIC_BRIDGE: [mqttGeneric] Parse (MQTT2_SERVER : 'MQTT2_FHEM_Server'): Msg: FHEMIO/MqttGenericBridge2/Firmata_OUT/value => off
2025.05.18 13:11:30.014 4: MQTT2_DEVICE_Parse: MQTT2_mgb2_Firmata_OUT FHEMIO/MqttGenericBridge2/Firmata_OUT/value => value
2025.05.18 13:11:30.015 4: logdb - check Device: MQTT2_mgb2_Firmata_OUT , Event: value: off
2025.05.18 13:11:30.016 5: logdb - parsed Event: MQTT2_mgb2_Firmata_OUT , Event: value: off
2025.05.18 13:11:30.016 4: logdb - added event - Timestamp: 2025-05-18 13:11:30, Device: MQTT2_mgb2_Firmata_OUT, Type: MQTT2_DEVICE, Event: value: off, Reading: value, Value: off, Unit:
2025.05.18 13:11:30.017 5: End notify loop for MQTT2_mgb2_Firmata_OUT
2025.05.18 13:11:30.043 4: logdb - check Device: logdb , Event: CacheOverflowLastNum: 0
2025.05.18 13:11:30.043 5: logdb - parsed Event: logdb , Event: CacheOverflowLastNum: 0
2025.05.18 13:11:30.044 4: logdb - added event - Timestamp: 2025-05-18 13:11:30, Device: logdb, Type: DBLOG, Event: CacheOverflowLastNum: 0, Reading: CacheOverflowLastNum, Value: 0, Unit:
2025.05.18 13:11:30.045 5: End notify loop for logdb
2025.05.18 13:11:30.076 4: Connection accepted from telnetPort_127.0.0.1_52774
2025.05.18 13:11:30.076 5: Cmd: >setreading PV_Realtime_Val Bezug_W 0<
2025.05.18 13:11:30.077 5: Cmd: >setreading PV_Realtime_Val Einspeisung_W 2241<
2025.05.18 13:11:30.081 5: End notify loop for PV_Realtime_Val
2025.05.18 13:11:30.081 5: Cmd: >setreading PV_Realtime_Val PV_Grid_Leistung_W 4513<
2025.05.18 13:11:30.084 5: End notify loop for PV_Realtime_Val
2025.05.18 13:11:30.084 5: Cmd: >setreading PV_Realtime_Val PV_Leistung_W 4513<
2025.05.18 13:11:30.087 5: End notify loop for PV_Realtime_Val
2025.05.18 13:11:30.087 5: Cmd: ><
--- log skips    71.283 secs.
2025.05.18 13:12:41.371 1: [Freezemon] freezemon: Long function call detected ReadFn:WEBtablet_192.168.183.31_53932 - 70.75774 seconds
2025.05.18 13:12:41.372 5: [Astro] No horizon attribute defined, using 0.0° for morning and evening
2025.05.18 13:12:41.372 5: [FHEM::Astro::GMSTRiseSet] Parameters 0.960912496931518 0.341418505426556 0.154185405540785 0.924045635646014 -0.314159265358979 give complex angle
2025.05.18 13:12:41.372 5: [FHEM::Astro::GMSTRiseSet] Parameters 0.978302320687031 0.345199140812018 0.154185405540785 0.924045635646014 -0.314159265358979 give complex angle
2025.05.18 13:12:41.372 4: [FHEM::Astro::SunRise] no solution possible for astronomical twilight - maybe the sun never sets below -18 degrees?
2025.05.18 13:12:41.373 5: Compute sunrise/sunset for latitude 52.943915 , longitude 8.834173
2025.05.18 13:12:41.374 5: Compute sunrise/sunset for latitude 52.943915 , longitude 8.834173
2025.05.18 13:12:41.374 5: Compute sunrise/sunset for latitude 52.943915 , longitude 8.834173
2025.05.18 13:12:41.374 5: Compute sunrise/sunset for latitude 52.943915 , longitude 8.834173
2025.05.18 13:12:41.381 5: [Astro] No horizon attribute defined, using 0.0° for morning and evening
2025.05.18 13:12:41.382 5: [FHEM::Astro::GMSTRiseSet] Parameters 0.978302320687031 0.345199140812018 0.154185405540785 0.924045635646014 -0.314159265358979 give complex angle
2025.05.18 13:12:41.382 5: [FHEM::Astro::GMSTRiseSet] Parameters 0.995731511586462 0.348881690141415 0.154185405540785 0.924045635646014 -0.314159265358979 give complex angle
2025.05.18 13:12:41.382 4: [FHEM::Astro::SunRise] no solution possible for astronomical twilight - maybe the sun never sets below -18 degrees?
2025.05.18 13:12:41.383 5: [Astro] No horizon attribute defined, using 0.0° for morning and evening
2025.05.18 13:12:41.448 2: SF - switching Consumer 'MQTT2_zigbee_plug_Klimaanlage' to 'on', command: "set MQTT2_zigbee_plug_Klimaanlage on", cause: existing surplus
2025.05.18 13:12:41.448 3: MQTT2_DEVICE set MQTT2_zigbee_plug_Klimaanlage on
2025.05.18 13:12:41.448 5: MQTT2_FHEM_Server: PUBLISH zigbee2mqtt/0x3425b4fffeb5ec85/set {"state":"ON"}
2025.05.18 13:12:41.448 5:  MQTT2_FHEM_Server_127.0.0.1_39064 myBrokerIO => zigbee2mqtt/0x3425b4fffeb5ec85/set:{"state":"ON"}
2025.05.18 13:12:41.448 5:  MQTT2_FHEM_Server_127.0.0.1_33380 zigbee_pi => zigbee2mqtt/0x3425b4fffeb5ec85/set:{"state":"ON"}
2025.05.18 13:12:41.452 5: End notify loop for MQTT2_zigbee_plug_Klimaanlage
2025.05.18 13:12:41.512 5: End notify loop for SF
2025.05.18 13:12:41.583 5: End notify loop for SF
2025.05.18 13:12:41.583 5: [Freezemon] freezemon: ----------- Starting Freeze handling at 2025.05.18 13:12:41.583 ---------------------
2025.05.18 13:12:41.584 5: [Freezemon] freezemon: purging log entries before 2025.05.18 13:11:25.000.
[Freezemon] freezemon: possible freeze starting at 13:11:31, delay is 70.583 possibly caused by: fn-ReadFn(WEBtablet_192.168.183.31_53932) tmr-DbLog_execMemCacheAsync(logdb) tmr-DbLog_execMemCacheAsync(logdb)
Allerdings konnte ich bisher nichts ungewöhnliches finden. Alle aufgeführten Sachen laufen den ganzen Tag sonst Störungsfrei. Ungewöhnlich war vielleicht, das gerade die "MQTT2_zigbee_plug_Klimaanlage" geschaltet wurde. Aber das war erst nach dem Blockieren und klappt zumindest manuell ohne Probleme.
Ich werde weiter nach dem Verursacher Ausschau halten müssen. Ich habe jetzt schon mal zwei DOIF von mir angepasst, die FHEM leicht blockiert haben (etwas über eine Sekunde).

Gruß
Bismosa