Sporadische Freezes - Analyse

bart0190 · 20 September 2020, 10:38:46

Hallo,
Ich habe ab und zu Freezes und komm nicht wirklich weiter, um den Grund zu finden.
Wahrscheinlich habe ich einen Einstellungsfehler, aber weiß auch nicht, ob die Freezes immer von der gleichen Stelle kommen bzw. wie ich richtig analysiere.

Was ich mir gedacht habe, was es sein könnte:
- watchdog_BadDusche_LED_aus_delay: hier habe ich einen Watchdog, der das Badlicht-LED-Dimmer nach einiger Zeit ausschaltet:

Code Auswählen

BadDusche_Bewegungsmelder:noMotion 00:01:35 BadDusche_Bewegungsmelder:motion set BadDusche_LED_Boden_Dimmer_Sw off

- Squeezebox an sich (hoffentlich nicht)
- Harmony Hubs (dass die sich manchmal desconnectieren ...)
- Anwesenheitsstatus über Bluetooth, der auch ein wait von 10sec dabei hat, bis es aktiv wird.

Code Auswählen

di_StatusLisa DOIF ([st_DevicesLisa] eq "absent")(set StatusLisa absent) DOELSEIF ([st_DevicesLisa] eq "present")(set StatusLisa present)

Hier werden alle 30 sec, 2 Bluetooth Devices abgefragt. Ist das zu oft?

Manchmal kommt ein Warning, was kann hier die Ursache sein?

Code Auswählen

WARNING: sleep without additional commands is deprecated and blocks FHEM

Hier einige Auszüge aus meinem log:

Code Auswählen

2020.09.01 09:25:54 3: CUL_HM set Esszimmer_Raffstore_re off
2020.09.01 10:31:04 3: CUL_HM set Kueche_6fach getConfig
2020.09.01 10:31:04 3: CUL_HM set Esszimmer_Raffstore_li on
2020.09.01 10:31:04 3: CUL_HM set Esszimmer_Raffstore_re on
2020.09.01 10:31:04 3: CUL_HM set Wohnzimmer_Raffstore_li on
2020.09.01 10:31:04 3: CUL_HM set Wohnzimmer_Raffstore_re on
2020.09.01 10:31:04 3: CUL_HM set Kueche_Raffstore on
2020.09.01 10:31:04 3: CUL_HM set Buero_Raffstore_re on
2020.09.01 10:31:04 3: CUL_HM set Buero_Raffstore_li on
2020.09.01 10:31:05 3: CUL_HM set Ankleide_Raffstore_li on
2020.09.01 10:31:05 3: CUL_HM set Ankleide_Raffstore_re on
2020.09.01 10:33:50 1: WARNING: sleep without additional commands is deprecated and blocks FHEM
2020.09.01 10:33:57 2: SB_PLAYER_Set(Ankleide_piCorePlayer): sync Wohnzimmer_SB_Player (d6:5f:84:ae:fd:3f) <- Ankleide_piCorePlayer (b8:27:eb:93:e0:22)
2020.09.01 10:33:57 1: [Freezemon] myFreezemon: possible freeze starting at 10:33:50, delay is 7.136 possibly caused by: no bad guy found :-(
2020.09.01 10:35:52 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.01 10:35:52 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.01 10:35:58 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.01 10:46:33 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered

Code Auswählen

2020.09.04 11:58:57 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.04 12:04:28 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.04 12:04:28 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.04 12:04:34 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.04 12:20:52 1: WARNING: sleep without additional commands is deprecated and blocks FHEM
2020.09.04 12:20:59 1: [Freezemon] myFreezemon: possible freeze starting at 12:20:53, delay is 6.588 possibly caused by: no bad guy found :-(
2020.09.04 12:37:00 3: CUL_HM set Tuerklingel_Mp3 playTone 10
2020.09.04 12:44:07 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.04 12:44:07 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.04 12:44:14 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.04 13:31:25 3: CUL_HM set Technikraum_KWL_Sw_04 on

Code Auswählen

2020.09.04 13:43:55 3: CUL_HM set Ankleide_Raffstore_re off
2020.09.04 13:44:00 3: CUL_HM set Technikraum_Licht_Waschbecken off
2020.09.04 13:44:04 3: CUL_HM set Esszimmer_LED_Schrank_Dimmer_Sw statusRequest
2020.09.04 13:44:31 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.04 13:44:31 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.04 13:44:37 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.04 13:48:31 1: WARNING: sleep without additional commands is deprecated and blocks FHEM
2020.09.04 13:48:38 1: [Freezemon] myFreezemon: possible freeze starting at 13:48:32, delay is 6.616 possibly caused by: no bad guy found :-(
2020.09.04 13:49:11 3: CUL_HM set TerrasseWest_Lautsprecher off
2020.09.04 13:49:13 3: CUL_HM set TerrasseWest_Lautsprecher on
2020.09.04 13:49:29 3: CUL_HM set TerrasseWest_Lautsprecher off
2020.09.04 13:49:30 3: CUL_HM set TerrasseWest_Lautsprecher on
2020.09.04 13:50:31 2: SB_PLAYER_Set(Buero_piCorePlayer): sync Wohnzimmer_SB_Player (d6:5f:84:ae:fd:3f) <- Buero_piCorePlayer (b8:27:eb:8f:f2:d2)
2020.09.04 13:52:07 3: CUL_HM set TerrasseWest_Lautsprecher off
2020.09.04 15:00:26 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered

Code Auswählen

2020.09.06 09:20:46 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.06 09:20:46 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.06 09:20:52 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.06 09:26:56 1: WARNING: sleep without additional commands is deprecated and blocks FHEM
2020.09.06 09:27:03 2: SB_PLAYER_Set(Ankleide_piCorePlayer): sync Wohnzimmer_SB_Player (d6:5f:84:ae:fd:3f) <- Ankleide_piCorePlayer (b8:27:eb:93:e0:22)
2020.09.06 09:27:03 1: [Freezemon] myFreezemon: possible freeze starting at 09:26:57, delay is 6.249 possibly caused by: no bad guy found :-(
2020.09.06 09:42:19 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.06 09:42:19 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.06 09:42:26 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.06 09:44:31 3: CUL_HM set Technikraum_KWL_Sw_04 on

Code Auswählen

2020.09.12 18:00:34 3: CUL_HM set Technikraum_KWL_Sw_04 off
2020.09.12 18:06:36 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.12 18:06:36 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.12 18:06:42 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.12 18:10:20 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.12 18:10:20 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.12 18:10:26 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.12 18:24:43 1: WARNING: sleep without additional commands is deprecated and blocks FHEM
2020.09.12 18:24:50 1: [Freezemon] myFreezemon: possible freeze starting at 18:24:44, delay is 6.666 possibly caused by: no bad guy found :-(
2020.09.12 18:39:57 3: CUL_HM set Vorraum_Licht off
2020.09.12 18:39:57 3: CUL_HM set Ankleide_Licht_Fenster off

Code Auswählen

2020.09.12 18:41:20 3: CUL_HM set Esszimmer_LED_Schrank_Dimmer_Sw statusRequest
2020.09.12 18:55:52 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.12 18:55:52 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.12 18:55:58 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.12 18:56:47 1: WARNING: sleep without additional commands is deprecated and blocks FHEM
2020.09.12 18:56:54 2: SB_PLAYER_Set(Ankleide_piCorePlayer): sync Wohnzimmer_SB_Player (d6:5f:84:ae:fd:3f) <- Ankleide_piCorePlayer (b8:27:eb:93:e0:22)
2020.09.12 18:56:54 1: [Freezemon] myFreezemon: possible freeze starting at 18:56:48, delay is 6.888 possibly caused by: no bad guy found :-(
2020.09.12 19:06:58 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.12 19:06:58 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off
2020.09.12 19:07:04 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw statusRequest
2020.09.12 19:07:48 3: CUL_HM set Kueche_Licht_Gang on

Dieser Freeze ist extrem lang und war nach dem Heimkommen und Versuch zum Einschalten der Musik (Squeezbox). Wobei ich nicht weiß, ob dieser mit den anderen zusammenhängt, da es hier das WARNING nicht gab. $:-\$

Code Auswählen

2020.09.16 17:22:57 3: CUL_HM set Ankleide_Raffstore_li on
2020.09.16 17:27:48 3: CUL_HM set Vorraum_Licht off
2020.09.16 17:27:48 3: CUL_HM set Ankleide_Licht_Fenster off
2020.09.16 17:27:48 3: CUL_HM set Ankleide_Licht_Tuer off
2020.09.16 17:27:48 3: CUL_HM set Technikraum_Licht off
2020.09.16 17:27:48 3: CUL_HM set Technikraum_Licht_Waschbecken off
2020.09.16 17:27:48 3: CUL_HM set BadBadew_Licht_Decke off
2020.09.16 17:27:48 3: CUL_HM set BadBadew_Licht_Spiegel off
2020.09.16 17:27:48 3: CUL_HM set BadDusche_Licht_Decke off
2020.09.16 17:27:48 3: CUL_HM set BadDusche_Licht_Spiegel off
2020.09.16 17:27:48 3: CUL_HM set Kueche_Licht_Gang off
2020.09.16 17:27:48 3: CUL_HM set Kueche_Licht_Herd off
2020.09.16 17:27:48 3: CUL_HM set Esszimmer_Licht off
2020.09.16 17:27:48 3: CUL_HM set Esszimmer_LED_Schrank_Dimmer_Sw off
2020.09.16 17:27:48 3: CUL_HM set Schlafzimmer_Licht off
2020.09.16 17:27:48 3: CUL_HM set Buero_Licht off
2020.09.16 17:27:48 3: CUL_HM set TerrasseSued_Licht off
2020.09.16 17:27:48 3: CUL_HM set TerrasseWest_Licht off
2020.09.16 17:27:48 3: CUL_HM set Wohnzimmer_Licht off
2020.09.16 17:27:48 3: CUL_HM set Wohnzimmer_Licht_Sofa off
2020.09.16 17:27:48 3: CUL_HM set Kueche_LED_Aktor_Sw_01_Abuelo off
2020.09.16 17:27:48 3: CUL_HM set Kueche_LED_Aktor_Sw_02_Waschbecken off
2020.09.16 17:27:48 3: CUL_HM set Kueche_LED_Aktor_Sw_03_Buegeleisen off
2020.09.16 17:27:48 3: CUL_HM set Terrasse_Markise_West on
2020.09.16 17:27:49 3: CUL_HM set Wohnzimmer_Raffstore_li off
2020.09.16 17:27:49 3: CUL_HM set Wohnzimmer_Raffstore_re off
2020.09.16 17:27:49 3: CUL_HM set Buero_Raffstore_li off
2020.09.16 17:27:49 3: CUL_HM set Buero_Raffstore_re off
2020.09.16 17:27:49 3: CUL_HM set Schlafzimmer_Raffstore_li off
2020.09.16 17:27:49 3: CUL_HM set Schlafzimmer_Raffstore_re off
2020.09.16 17:27:49 3: CUL_HM set Ankleide_Raffstore_li off
2020.09.16 17:27:49 3: CUL_HM set Ankleide_Raffstore_re off
2020.09.16 17:27:54 3: CUL_HM set Technikraum_Licht_Waschbecken off
2020.09.16 17:27:58 3: CUL_HM set Esszimmer_LED_Schrank_Dimmer_Sw statusRequest
2020.09.16 17:35:33 1: [Freezemon] myFreezemon: possible freeze starting at 17:28:35, delay is 418.291 possibly caused by: no bad guy found :-(
2020.09.16 17:36:04 2: Ankleideraum_Hub: disconnect
2020.09.16 17:36:04 2: Wohnzimmer_Hub: disconnect
2020.09.16 17:36:04 1: [Freezemon] myFreezemon: possible freeze starting at 17:35:34, delay is 30.092 possibly caused by: tmr-harmony_ping(Wohnzimmer_Hub) tmr-harmony_ping(Ankleideraum_Hub) tmr-HMLAN_KeepAlive(HM_LAN) tmr-YAMAHA_AVR_GetStatus(Wohnzimmer_YamahaRXV681_zone2) tmr-YAMAHA_AVR_GetStatus(Wohnzimmer_YamahaRXV681_main) tmr-HourCounter_Run(N/A) tmr-FReplacer_Update(kindledisplay) tmr-FW_closeInactiveClients(N/A) tmr-SB_SERVER_tcb_Alive(SqueezeBoxServer) tmr-CUL_HM_ActCheck(N/A) tmr-SB_PLAYER_GetStatus(Buero_piCorePlayer) tmr-SB_PLAYER_GetStatus(Ankleide_piCorePlayer) tmr-SB_PLAYER_GetStatus(Wohnzimmer_SB_Player) tmr-XiaomiDevice_GetUpdate(SaugerPolvito) 
2020.09.16 17:36:04 3: YAMAHA_AVR (Wohnzimmer_YamahaRXV681_main) - could not execute command on device Wohnzimmer_YamahaRXV681_main. Please turn on your device in case of deactivated network standby or check for correct hostaddress.
2020.09.16 17:36:04 3: YAMAHA_AVR (Wohnzimmer_YamahaRXV681_zone2) - could not execute command on device Wohnzimmer_YamahaRXV681_zone2. Please turn on your device in case of deactivated network standby or check for correct hostaddress.
2020.09.16 17:36:04 3: YAMAHA_AVR (Wohnzimmer_YamahaRXV681_zone2) - device Wohnzimmer_YamahaRXV681_zone2 reappeared
2020.09.16 17:36:04 3: YAMAHA_AVR (Wohnzimmer_YamahaRXV681_main) - device Wohnzimmer_YamahaRXV681_main reappeared
2020.09.16 17:36:06 3: Ankleideraum_Hub: connected
2020.09.16 17:36:06 3: Wohnzimmer_Hub: connected
2020.09.16 17:36:06 3: Ankleideraum_Hub: new config 
2020.09.16 17:36:07 3: Wohnzimmer_Hub: new config 
2020.09.16 17:38:33 3: CUL_HM set Technikraum_KWL_Sw_02 on
2020.09.16 17:38:33 3: CUL_HM set Technikraum_KWL_Sw_03 off
2020.09.16 17:38:33 3: CUL_HM set Technikraum_KWL_Sw_04 off
2020.09.16 17:47:04 3: Watchdog watchdog_BadDusche_LED_aus_delay triggered
2020.09.16 17:47:04 3: CUL_HM set BadDusche_LED_Boden_Dimmer_Sw off

Bin für jeden Hinweis dankbar.

bart

MadMax-FHEM · 20 September 2020, 10:45:32

Naja sleep without additional command ... blocks fhem: das ist ja wohl mal eindeutig!

Den würde ich mal suchen und änderm!!

Dann weiter beobachten.

Weil: nicht alles was freezemon meldet muss auch ein tatsächlicher Freeze sein. Manches sieht für freezemon auch nur so aus (evtl.)...

Bemerkst du Hänger oder ist der Aufwand "nur" weil freezemon "mosert"!?

Aber: die genannten sleeps müssen raus, weil die tatsächlich blockieren. Also entweder richtig machen: fhem-Kommando hinten dran oder raus nehmen/durch was anderes ersetzen...

Gruß, Joachim

bart0190 · 20 September 2020, 11:03:13

Danke für die schnelle Antwort.
Ja, bei dem letzten Freeze ist die Hausautomatisierung für 10min "gestanden".

Ich muss leider blöd fragen, da muss ich nur nach "Sleeps" suchen, oder sind das auch waits in den FHEM Device Attributen o.ä.? (Also nur den Befehl "Sleep")

Danke
Lg
Bart

MadMax-FHEM · 20 September 2020, 11:25:02

Die waits sollten kein Problem sein (sofern die jeweiligen Modulentwickler nichts schräg gemacht haben)...

Kommt aber drauf an von welchem/welchen Modul/Modulen du sprichst und welchen wait...

Ja, sleep in myUtils oder fhem.cfg/configDB (in defines von notify/DOIF etc.)...

Wenn das oder die draußen sind weiter schauen...

EDIT: evtl. hilft auch attr global stackTrace 1...

EDIT: und halt versuchen herauszufinden, ob verwendete/verdächtigte (z.B. von freezemon) Module non-blocking implementiert sind. Sonos z.B. war/ist (glaube ich) blocking (gewesen)...

Gruß, Joachim

bart0190 · 20 September 2020, 15:41:57

Ich glaube ich habe die (zumindest ersten) Bösewichte gefunden, die das Warning ausgelöst haben.

Ich hatte in einer frühen Phase, mit naivem Unwissen mit Kommandos in Notify's experiemtiert und diese sind leider bis jetzt geblieben - und das in meiner Squeezebox-Ansteuerung.

Beispiel, so war es:

Code Auswählen

set  noti_Wohnzimmer_Musik_an_Playlist2 notify (Kueche_6fach_Btn_05_MusikAn:LongRelease.*) {{fhem("set Wohnzimmer_Hub activity Musik")} {fhem("sleep 7")} {fhem("set Wohnzimmer_SB_Player favorites Moverse")} {fhem("set Wohnzimmer_SB_Player play")}}

So hab ich es nun korrigiert:

Code Auswählen


(Kueche_6fach_Btn_05_MusikAn:LongRelease.*) {{fhem("set Wohnzimmer_Hub activity Musik; sleep 7; set Wohnzimmer_SB_Player favorites Moverse; set Wohnzimmer_SB_Player play")}}

Das würde auch mit der WES (Wife Experience Story) zusammenpassen. "Hab versucht die Musik einzuschalten und es ging nix."
Werde noch schauen, ob ich andere finde und dann mal ne Zeit beobachten.

Vielen Dank für den Hinweis!

lg
bart

Kurt77 · 04 Oktober 2020, 21:00:11

Zitat von: MadMax-FHEM am 20 September 2020, 10:45:32
Naja sleep without additional command ... blocks fhem: das ist ja wohl mal eindeutig!

Hallo MadMax,
aber ein
"Sleep (300);"
in einer Sub kann doch nicht blockieren, weil Perl-Befehl und nicht fhem.
Ist das korrekt?

Danke und Gruß,
Kurt

MadMax-FHEM · 04 Oktober 2020, 21:10:08

Wie zu lesen: es kommt drauf an was um das sleep herum kommt, v.a. danach!
Wichtig: es muss ein fhem-sleep sein! Ansonsten blockiert es.

Klar kann und wird ein Perl-sleep (immer) oder ein fhem-sleep ohne Folge-Kommando blockieren! fhem ist single-Threadded, wenn da gewartet wird, dann "steht" fhem. Ein fhem-sleep hingegen ist ein "unsichtbares" at...

EDIT: https://forum.fhem.de/index.php/topic,114730.msg1089562.html#msg1089562

Gruß, Joachim