Hallo,
mein FHEM friert zu! :o >:( :(
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
Auf was für ein System .. wie sieht die Systemlast aus (CPU, IO, Speicher etc.)
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.
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?
Möglichrweise auch bei dir die Ursache? https://forum.fhem.de/index.php/topic,81365.msg771169.html#msg771169
Kurz, weil mobil...
Die Symptome passen, ich geh mal zurück auf 16170.
Ich vermute dass ich das gleiche Problem habe.
Wie komme ich zurück auf eine bestimmte Version??
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...
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...
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
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...
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
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 (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
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
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:
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:
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 :'(
Folgenden Thread gelesen?
https://forum.fhem.de/index.php/topic,81365.msg771307/topicseen.html#new (https://forum.fhem.de/index.php/topic,81365.msg771307/topicseen.html#new)
Zitat von: Wernieman am 26 Februar 2018, 23:14:49
Folgenden Thread gelesen?
https://forum.fhem.de/index.php/topic,81365.msg771307/topicseen.html#new (https://forum.fhem.de/index.php/topic,81365.msg771307/topicseen.html#new)
Hatte ich oben schonmal verlinkt... apptime abschalten (also FHEM shutdown restart - ggf. vorher bei Freezemon fm_forceApptime auf 0 setzen) sollte helfen
Danke, ja, hab ich so mit einem Auge verfolgt. Scheint wohl ziemlich im Verdacht zu stehen, die Ursache zu sein. Oder ist das schon sicher?
Ich hab jetzt meine fhem.pl erstmal auf den Stand vom 18.2. zurück gedreht. Werde das aber ~2 Tage laufen lassen müssen, um etwas sagen zu können...
@KernSani
Ja apptime abschalten hatte ich auch gelesen. Blöderweise ist apptime ja aber auch die beste Methode (die ich kenne), um die Latenzen konkret in Zahlen beobachten zu können?
Zitat von: vbs am 26 Februar 2018, 23:25:30
@KernSani
Ja apptime abschalten hatte ich auch gelesen. Blöderweise ist apptime ja aber auch die beste Methode (die ich kenne), um die Latenzen konkret in Zahlen beobachten zu können?
Ich bin überzeugt, dass es an apptime in Kombination mit der neuen Behandlung von Internal Timern liegt (Rudi hat das recht deutlich aufgezeigt). Apptime abschalten ist eine temporäre Lösung. Eine angepasste Version (zum testen) ist bereits verfügbar und wird sicherlich bald mit dem regulären Update verteilt.
Zitat von: KernSani am 26 Februar 2018, 23:33:18
Ich bin überzeugt, dass es an apptime in Kombination mit der neuen Behandlung von Internal Timern liegt (Rudi hat das recht deutlich aufgezeigt). Apptime abschalten ist eine temporäre Lösung. Eine angepasste Version (zum testen) ist bereits verfügbar und wird sicherlich bald mit dem regulären Update verteilt.
Ok klasse! Danke dass ihr euch drum kümmert!
Gesendet von meinem SM-G950F mit Tapatalk