FHEM freezes over!

arthur_dent_2015 · 22 Februar 2018, 19:20:50

Hallo,
mein FHEM friert zu!

mal nen Ausschnitt aus dem aktuellen LOG:


2018.02.22 18:59:47 1: FreezeMon: myFreezemon possible freeze starting at 18:59:46, delay is 1.512 possibly caused by harmony_ping(hub2) HMUARTLGW_CheckCredits(N/A)
2018.02.22 19:00:01 1: FreezeMon: myFreezemon possible freeze starting at 19:00:00, delay is 1.053 possibly caused by DbLog_execmemcache(fhemlogDB) HttpUtils_Err(N/A)
2018.02.22 19:00:04 1: FreezeMon: myFreezemon possible freeze starting at 19:00:02, delay is 2.086 possibly caused by DOIF_TimerTrigger(heating_Sz) DOIF_TimerTrigger(LED_Wz_Fenster) PRESENCE_StartLocalScan(TX50DXW734) HMUARTLGW_CheckCredits(N/A) ENIGMA2_GetStatus(VUuno) HttpUtils_Err(N/A)
2018.02.22 19:00:06 1: FreezeMon: myFreezemon possible freeze starting at 19:00:05, delay is 1.206 possibly caused by JeeLink_HandleWriteQueue(jeelinkcross1) PRESENCE_StartLocalScan(TX49DXW604) CUL_MAX_SendQueueHandler(cm) HttpUtils_Err(N/A) HMUARTLGW_CheckCmdResp(WLAN_CUL_HM) HttpUtils_Err(N/A) watchdog_Trigger(PCA301_5_on_wd)
2018.02.22 19:00:25 4: sduino/keepalive ok, retry = 0
2018.02.22 19:01:08 1: FreezeMon: myFreezemon possible freeze starting at 19:01:06, delay is 2.399 possibly caused by at_Exec(AutoSave) HMUARTLGW_CheckCredits(N/A)
2018.02.22 19:01:25 4: sduino/KeepAlive not ok, retry = 1 -> get ping
2018.02.22 19:01:25 4: sduino/msg READ: OK
2018.02.22 19:01:26 4: sduino/HandleWriteQueue: nothing to send, stopping timer
2018.02.22 19:01:33 5: Triggering Strip3_ntfy
2018.02.22 19:01:33 4: Strip3_ntfy exec set Strip3 RGB FFFFFF
2018.02.22 19:01:33 3: Strip3 set HSV 0, 0, 100 with ramp: 0, flags: 
2018.02.22 19:01:33 1: FreezeMon: myFreezemon possible freeze starting at 19:01:32, delay is 1.787 possibly caused by DbLog_execmemcache(fhemlogDB) DOIF_SleepTrigger(LED_Wz_Fenster) HttpUtils_Err(N/A)
2018.02.22 19:01:36 1: FreezeMon: myFreezemon possible freeze starting at 19:01:35, delay is 1.303 possibly caused by ENIGMA2_GetStatus(VUuno) BlockingKill(N/A)
2018.02.22 19:01:41 1: FreezeMon: myFreezemon possible freeze starting at 19:01:39, delay is 2.013 possibly caused by PRESENCE_StartLocalScan(SGS7_WL) HMUARTLGW_CheckCredits(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A)
2018.02.22 19:01:56 3: SGS7_WL absent
2018.02.22 19:01:58 3: CALVIEW Termine - CALENDAR:Kalender triggered, updating CALVIEW Termine ...
2018.02.22 19:01:59 1: FreezeMon: myFreezemon possible freeze starting at 19:01:58, delay is 1.911 possibly caused by HTTPMOD_GetUpdate(N/A) CUL_MAX_BroadcastTime(cm) Calendar_Wakeup(Kalender)
2018.02.22 19:02:19 1: FreezeMon: myFreezemon possible freeze starting at 19:02:18, delay is 1.057 possibly caused by HMLAN_KeepAlive(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A)
2018.02.22 19:02:24 1: FreezeMon: myFreezemon possible freeze starting at 19:02:23, delay is 1.115 possibly caused by at_Exec(heartbeat) at_Exec(fhem_heartbeat) HttpUtils_Err(N/A) HttpUtils_Err(N/A)
2018.02.22 19:02:28 4: sduino/keepalive ok, retry = 0
2018.02.22 19:02:28 1: FreezeMon: myFreezemon possible freeze starting at 19:02:26, delay is 2.185 possibly caused by SYSMON_Update(Raspi) SIGNALduino_KeepAlive(sduino) SIGNALduino_KeepAlive(sduino3)
2018.02.22 19:02:30 1: FreezeMon: myFreezemon possible freeze starting at 19:02:29, delay is 1.47 possibly caused by SB_SERVER_tcb_Alive(N/A) HMUARTLGW_CheckCredits(N/A) Astro_Update(Astro)
2018.02.22 19:02:40 1: FreezeMon: myFreezemon possible freeze starting at 19:02:39, delay is 1.08 possibly caused by no bad guy found :-(
2018.02.22 19:02:42 1: FreezeMon: myFreezemon possible freeze starting at 19:02:41, delay is 1.897 possibly caused by TRAFFIC_StartUpdate(home2work)
2018.02.22 19:02:44 1: FreezeMon: myFreezemon possible freeze starting at 19:02:43, delay is 1.515 possibly caused by PRESENCE_StartLocalScan(TX49DXW604) HMLAN_KeepAlive(N/A)
2018.02.22 19:02:46 1: FreezeMon: myFreezemon possible freeze starting at 19:02:45, delay is 1.146 possibly caused by PRESENCE_StartLocalScan(TX50DXW734) HMUARTLGW_CheckCredits(N/A) HMLAN_KeepAliveCheck(N/A)
2018.02.22 19:02:54 1: FreezeMon: myFreezemon possible freeze starting at 19:02:53, delay is 1.254 possibly caused by PRESENCE_StartLocalScan(GE70)
2018.02.22 19:03:03 1: FreezeMon: myFreezemon possible freeze starting at 19:03:01, delay is 2.084 possibly caused by ENIGMA2_GetStatus(VUDuo2) HMUARTLGW_CheckCredits(N/A)
2018.02.22 19:03:13 1: FreezeMon: myFreezemon possible freeze starting at 19:03:09, delay is 4.68 possibly caused by WOL_UpdateReadings(SatServer_ping) HMLAN_KeepAlive(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A)
2018.02.22 19:03:13 1: Timeout for WOL_Ping reached, terminated process 31739
2018.02.22 19:03:13 3: BlockingCall for SatServer was aborted
2018.02.22 19:03:16 1: FreezeMon: myFreezemon possible freeze starting at 19:03:14, delay is 2.79 possibly caused by HMLAN_KeepAliveCheck(N/A) VIERA_GetStatus(Viera_Sz) HttpUtils_Err(N/A) BlockingKill(N/A) HttpUtils_Err(N/A)
2018.02.22 19:03:18 1: FreezeMon: myFreezemon possible freeze starting at 19:03:17, delay is 1.295 possibly caused by FW_closeInactiveClients(N/A) Weather_GetUpdate(WetterXXX) HttpUtils_Err(N/A)
2018.02.22 19:03:20 1: FreezeMon: myFreezemon possible freeze starting at 19:03:19, delay is 1.755 possibly caused by HMUARTLGW_CheckCredits(N/A)
2018.02.22 19:03:28 4: sduino/KeepAlive not ok, retry = 1 -> get ping
2018.02.22 19:03:28 4: sduino/msg READ: OK
2018.02.22 19:03:28 4: sduino/HandleWriteQueue: nothing to send, stopping timer
2018.02.22 19:03:35 1: FreezeMon: myFreezemon possible freeze starting at 19:03:34, delay is 1.826 possibly caused by HMLAN_KeepAlive(N/A) HMUARTLGW_CheckCredits(N/A) BlockingKill(N/A)
2018.02.22 19:03:40 1: FreezeMon: myFreezemon possible freeze starting at 19:03:36, delay is 4.531 possibly caused by HMLAN_KeepAliveCheck(N/A) DbLog_execmemcache(fhemlogDB)
2018.02.22 19:03:42 1: FreezeMon: myFreezemon possible freeze starting at 19:03:41, delay is 1.691 possibly caused by HttpUtils_Err(N/A) my_IPCAM_GetUpdate(FI9826W)
2018.02.22 19:03:44 1: FreezeMon: myFreezemon possible freeze starting at 19:03:43, delay is 1.203 possibly caused by FRITZBOX_Readout_Start(N/A)
2018.02.22 19:03:57 1: FreezeMon: myFreezemon possible freeze starting at 19:03:55, delay is 2.382 possibly caused by HttpUtils_Err(N/A) HttpUtils_Err(N/A)

Das geht hoch bis 30 Sekunden. Nach shutdown restart beruhigt es sich wieder, geht aber irgendwann wieder los. in apptime sind diese Ausreißer nicht zu sehen aber Verzögerungen bei Schaltbefehlen sind definitiv vorhanden. Könnte freezemon hier der Auslöser sein? Erst mal deaktiviert....

Gruß
Arthur

Wernieman · 22 Februar 2018, 19:26:24

Auf was für ein System .. wie sieht die Systemlast aus (CPU, IO, Speicher etc.)

arthur_dent_2015 · 22 Februar 2018, 19:46:36

Raspi 3, dümpelt normal um die 1% CPU Auslastung, kurzfristig genehmigt sich FHEM auch mal eine komplette CPU, dann 25% Auslastung. RAM in der Spitze mal 600MB belegt.

KernSani · 22 Februar 2018, 21:44:54

Ausser dem Kalender sind das alles "Dauerläufer" (Prozesse, die permanent irgendwas machen), die Freezemon da als mögliche Kandidaten identifiziert - tatsächlich sind die aber nicht schuld (daher auch nicht in apptime zu sehen). Freezemon selbst würde ich mal als Ursache ausschliessen, bleiben zwei Dinge: Externe Effekte (z.B. irgendwelche I/Os, die FHEM blocken) oder Dinge in FHEM, die nicht Timer-gesteuert ablaufen (z.B. verursacht bei mir ein Click in den SYSMON-Raum jedesmal einen Freeze, den Freezemon aber nicht identifizieren kann).
Du kannst mal PERFMON laufen lassen und schauen was der sagt. Was sind denn deine Top20 in apptime?

KernSani · 23 Februar 2018, 07:15:50

Möglichrweise auch bei dir die Ursache? https://forum.fhem.de/index.php/topic,81365.msg771169.html#msg771169

Kurz, weil mobil...

arthur_dent_2015 · 23 Februar 2018, 14:43:20

Die Symptome passen, ich geh mal zurück auf 16170.

C0mmanda · 23 Februar 2018, 19:01:52

Ich vermute dass ich das gleiche Problem habe.

Wie komme ich zurück auf eine bestimmte Version??

KernSani · 24 Februar 2018, 09:11:19

Hast du ein backup? Dann kannst du versuchen nur die fhem.pl zurück zu spielen. Das kann aber zu Nebeneffekten führen. Am besten komplettes backup zurück spielen (ggf. Fhem.cfg vorher wegsichern)

Kurz, weil mobil...

KernSani · 25 Februar 2018, 08:59:26

Das Problem wurde in oben verlinktem Beitrag identifiziert: Es liegt an apptime. Apptime deaktivieren sollte helfen. (ForceApptime in Freezemon auf 0 setzen + Neustart)

Kurz, weil mobil...

C0mmanda · 25 Februar 2018, 09:41:16

Zitat von: KernSani am 24 Februar 2018, 09:11:19
Hast du ein backup? Dann kannst du versuchen nur die fhem.pl zurück zu spielen. Das kann aber zu Nebeneffekten führen. Am besten komplettes backup zurück spielen (ggf. Fhem.cfg vorher wegsichern)

Kurz, weil mobil...

Habe Backups, die reichen dafür aber leider nicht weit genug zurück.

Hat sich bei mir allerdings auch erledigt, es lag nicht wie vermutet an Freezemon sondern scheinbar an insgesamt 8 Presence-Devices mit lan-ping.
Alle Presence-Devices umgestellt (weg von lan-ping) und es läuft seit 24Std. deutlich besser!

Danke!

grtz

KernSani · 25 Februar 2018, 10:48:55

Zitat von: C0mmanda am 25 Februar 2018, 09:41:16
Habe Backups, die reichen dafür aber leider nicht weit genug zurück.

Die problematische fhem.pl ist vom 20..02., wenn ich mich recht erinnere

Kurz, weil mobil...

ToKa · 25 Februar 2018, 10:52:15

Hallo C0mmanda,

Zitat von: C0mmanda am 25 Februar 2018, 09:41:16
Alle Presence-Devices umgestellt (weg von lan-ping) und es läuft seit 24Std. deutlich besser!

auf was hast Du diese presence-devices umgestellt? Habe davon nämlich auch einige...

Gruß
Torsten

C0mmanda · 25 Februar 2018, 19:32:14

Zitat von: ToKa am 25 Februar 2018, 10:52:15
Hallo C0mmanda,

auf was hast Du diese presence-devices umgestellt? Habe davon nämlich auch einige...

Gruß
Torsten

Da ich eine Fritzbox habe bin ich diesen Weg gegangen:
https://wiki.fhem.de/wiki/FRITZBOX#Anwesenheitserkennung_per_regelm.C3.A4.C3.9Figer_Abfrage_.C3.BCber_das_PRESENCE_Modul
Funktioniert bisher sehr gut, ich habe aber keine zeitkritischen Fälle dabei.
Es kann wohl mal 2-3min. dauern bis der Status erkannt wird. (Auch bei einem 60sec. Interval der Fritzbox).
Für mich reicht das aktuell.

grtz

ToKa · 25 Februar 2018, 20:18:45

Danke für die Rückmeldung, das passt dann bei mir leider nicht. Es hängen nicht alle Geräte an der Fritzbox.

Gruß
Torsten

vbs · 26 Februar 2018, 22:15:50

Ich hab auch das Problem: Wenn ich FHEM neu starte, dann ist erstmal alles gut und reaktionsschnell. Irgendwann passiert irgendwas und FHEM wird extrem träge. Zum Beispiel daran zu sehen, dass sämtliche Latenzen in apptime im dreistelligen Bereich liegen:

Code Auswählen

name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
 sbserver                                 SB_SERVER_Read                         474        4    1201.97   300.49     0.00     0.00 26.02. 22:08:01 HASH(sbserver)
 tmr-PRESENCE_StartLocalScan              HASH(0x53d8528)                        396        4    1037.70   259.42   230.23    59.07 26.02. 22:09:23 HASH(fl_ben)
 HMLAN0                                   HMLAN_Read                             358       19    2374.95   125.00     0.00     0.00 26.02. 22:07:56 HASH(HMLAN0)
 tmr-PRESENCE_StartLocalScan              HASH(0x6b9ac10)                        357        4     934.84   233.71    15.18     4.71 26.02. 22:08:49 HASH(sz_tabS_pres)
 tmr-PRESENCE_StartLocalScan              HASH(0x6ca5dc8)                        289        4     741.89   185.47   301.40   152.98 26.02. 22:09:12 HASH(wz_htpc)
 tmr-PRESENCE_StartLocalScan              HASH(0x6dffc08)                        276        4     862.43   215.61   450.89   152.78 26.02. 22:08:50 HASH(sz_s8_pres)
 tmr-EspLedController_Check               HASH(0x6d939f8)                        273       12    1512.50   126.04   341.30    62.93 26.02. 22:08:04 HASH(ku_lightLedFloor)
 tmr-EspLedController_Check               HASH(0x6ca4f40)                        272       12    1528.10   127.34   192.01    45.87 26.02. 22:08:03 HASH(sz_lightLedWall)
 tmr-EspLedController_Check               HASH(0x6d94f48)                        268       13    1600.75   123.13   216.13    45.35 26.02. 22:09:14 HASH(ku_lightLedCeil)
 tmr-HMLAN_KeepAlive                      keepAlive                              266        5     824.66   164.93   184.28    45.33 26.02. 22:08:38 keepAlive:HMLAN0
 tmr-PRESENCE_StartLocalScan              HASH(0x620e0d0)                        266        4     979.18   244.80   189.98    58.98 26.02. 22:09:46 HASH(wz_sub)
 tmr-DbLog_execmemcache                   HASH(0x4765938)                        255        5    1200.61   240.12     7.09     3.77 26.02. 22:08:01 HASH(benDbLog)
 tmr-FRITZBOX_Readout_Start               env_fritzbox.Readout                   250        1     250.92   250.92     2.52     2.52 26.02. 22:09:47 env_fritzbox.Readout
 tmr-KODI_Check                           HASH(0x3769878)                        247        3     496.12   165.37   218.03    74.06 26.02. 22:09:57 HASH(wz_kodi)
 tmr-PRESENCE_StartLocalScan              HASH(0x5d8bee8)                        245        3     693.81   231.27    60.60    21.68 26.02. 22:09:35 HASH(wz_base)
 tmr-SYSSTAT_GetUpdate                    HASH(0x62dd860)                        176        1     176.23   176.23     1.58     1.58 26.02. 22:09:39 HASH(fl_benStats)
 tmr-YAMAHA_AVR_GetStatus                 HASH(0x35e9c10)                        148        5     680.56   136.11     1.95     1.46 26.02. 22:09:32 HASH(wz_avr)
 tmr-ESPEasy_statusRequest                HASH(0x6dfe9c8)                        135        1     135.36   135.36   295.88   295.88 26.02. 22:08:02 HASH(sz_lightLava)
 tmr-ENIGMA2_GetStatus                    HASH(0x3625a90)                        123        3     340.01   113.34   176.79   105.96 26.02. 22:08:34 HASH(wz_dvbReceiver)
 tmr-EspLedController_Check               HASH(0x6d92cc0)                        122       12    1350.92   112.58   229.60    60.13 26.02. 22:08:34 HASH(wz_lightLedCouch)
 tmr-EspLedController_Check               HASH(0x6b2d2b0)                        120       13    1446.28   111.25   208.28    62.89 26.02. 22:09:14 HASH(wz_lightLedTv)
 tmr-SB_PLAYER_GetStatus                  HASH(0x45370a0)                        118        1     118.45   118.45     1.70     1.70 26.02. 22:08:01 HASH(bd_sb)

Darüber hinaus pendelt die CPU-Last vom perl-Prozess permanent zwischen 10 und 70%. Sollte normalerweise bei ~1% liegen:

Code Auswählen

top - 22:11:49 up 13 days, 42 min,  2 users,  load average: 0.38, 8.91, 9.75
Tasks: 201 total,   1 running, 200 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.1 us,  1.0 sy,  7.8 ni, 91.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 18867912 total,   425680 free, 14581284 used,  3860948 buff/cache
KiB Swap:  1046524 total,  1002052 free,    44472 used.  3878712 avail Mem

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 50184 fhem      32  12  377172 290720   8332 S  32.9  1.5 240:53.87 perl
    13 root      20   0       0      0      0 S   0.3  0.0   7:07.88 ksoftirqd/1
  8322 mysql     32  12 16.310g 0.013t   8084 S   0.3 74.1 652:00.09 mysqld

Alle Module auf dem neuesten Stand. Rechner ist eine VMWare mit Ubuntu 16.04 x64 auf einem i5 (Win10 Host).

Werde mal rumexperimentieren. Bin auf alle Tipps dankbar. Muss hier bald vor Ort offiziell den Notstand ausrufen