Hallo,
ich musste leider beobachten dass ich häufige Warnmeldungen von Perfmon
Perfmon: possible freeze starting at 22:32:44, delay is 14.503
bekomme.
Stelle ich aber verbose 5 zur besseren Recherche ein, tritt das freezing scheinbar
nicht mehr auf???
Was kann ich machen, um diese horenden freezes zu beseitigen??
Greets
Byte
Ich nehme an, dass du sie dann zwischen den vielen Meldungen bei global verbose 5 (ich nehme doch an, dass du global meinst) nicht mehr siehst. Suche mal im Browser nach Perfmon, dann sind sie sicher da. verbose hat sicher keinen Einfluss auf die Freezes.
Was du machen kannst? Herausfinden, was die Freezes verursacht. Dazu gibt es gefühlt 1000 Themen hier im Forum. apptime ist ein gutes Tool, um zu analysieren, woher die Freezes kommen. Das ganze kann man dann mit Perfmon und verbose 5 auf die entsprechenden Devices verkleinern. Zunächst würde ich aber apptime ein paar Stunden laufen lassen. Du sagst leider nichts dazu, wie oft, wie regelmäßig die Freezes auftauchen. Deshalb ist mehr Hilfe nicht möglich.
Hallo,
mit der Browsersuche hatte ich schon gearbeitet. Nun habe ich nach längerer Zeit doch Einträge gefunden.
Erstaunlich finde ich, dass zur angegebenen Start-Zeit keine Einträge vorhanden sind!
[...]
2016.08.23 11:44:40.412 5: FRITZBOX FritzRepeater: Readout_Process.1693 SET mac_XX_XX_XX_ = 'PC-XX-xx-XX-xx (WLAN, 150 / 150 Mbit/s, 42)'
2016.08.23 11:44:40.413 5: FRITZBOX FritzRepeater: Readout_Process.1693 SET box_cpuTemp = '0'
2016.08.23 11:44:40.414 5: FRITZBOX FritzRepeater: Readout_Process.1725 SET state = 'WLAN: on gWLAN: off'
2016.08.23 11:44:40.415 4: FRITZBOX FritzRepeater: Readout_Process.1743 134 values captured in 0.63 s
2016.08.23 11:44:40.416 5: Triggering FritzRepeater (1 changes)
2016.08.23 11:44:40.416 5: Starting notify loop for FritzRepeater, first event mac_XX_XX_XX_XX: PC-xx-xx-xx-xx (WLAN, 65 / 56 Mbit/s, 58)
2016.08.23 11:44:40.436 5: ZE.Batterie: not on any display, ignoring notify
2016.08.23 11:44:40.701 4: Connection closed for WEB_10.8.0.6_20137: EOF
2016.08.23 11:44:40.786 4: Connection accepted from WEB_10.8.0.6_20161
2016.08.23 11:44:40.798 4: WEB_10.8.0.6_20161 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2016-08.log; BUFLEN:0
2016.08.23 11:44:42.243 1: Perfmon: possible freeze starting at 11:44:41, delay is 1.243
[...]
2016.08.23 13:05:59.426 4: Connection accepted from telnetForBlockingFn_1471599160_127.0.0.1_47542
2016.08.23 13:05:59.430 5: Cmd: >{PRESENCE_ProcessLocalScan('MajaPresence|0|absent')}<
2016.08.23 13:05:59.433 5: PRESENCE (MajaPresence) - blocking scan result: MajaPresence|0|absent2016.08.23 13:05:59.435 4: PRESENCE (MajaPresence) - rescheduling next check in 60 seconds
2016.08.23 13:06:05.753 4: Connection closed for WEB_10.8.0.6_20161: EOF
2016.08.23 13:06:05.790 4: Connection accepted from WEB_10.8.0.6_20297
2016.08.23 13:06:05.795 4: WEB_10.8.0.6_20297 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2016-08.log; BUFLEN:0
2016.08.23 13:06:10.452 1: Perfmon: possible freeze starting at 13:06:06, delay is 4.452
Z.b. 11:44:41 findet sich kein Eintrag...
Mit apptime komme ich noch nicht so zurecht. Es zeigt an, welcher Prozess wie lange gelaufen ist?!...
Greets
Byte
Auffallend ist, dass im
apptime count all
eine Megaliste an:
[...]
tmr-BlockingKill HASH(0x451ef80) 6 1 6 6.00 3 HASH(0x451ef80)
tmr-BlockingKill HASH(0x451fba8) 5 1 5 5.00 3 HASH(0x451fba8)
tmr-BlockingKill HASH(0x451fcb0) 5 1 5 5.00 2 HASH(0x451fcb0)
tmr-BlockingKill HASH(0x4520898) 5 1 5 5.00 3 HASH(0x4520898)
tmr-BlockingKill HASH(0x4523798) 6 1 6 6.00 2 HASH(0x4523798)
tmr-BlockingKill HASH(0x4523de0) 10 1 10 10.00 3 HASH(0x4523de0)
tmr-BlockingKill HASH(0x4524140) 6 1 6 6.00 3 HASH(0x4524140)
tmr-BlockingKill HASH(0x4525c88) 6 1 6 6.00 4 HASH(0x4525c88)
tmr-BlockingKill HASH(0x4525ce8) 7 1 7 7.00 2 HASH(0x4525ce8)
tmr-BlockingKill HASH(0x4526690) 7 1 7 7.00 3 HASH(0x4526690)
tmr-BlockingKill HASH(0x4526978) 5 1 5 5.00 3 HASH(0x4526978)
tmr-BlockingKill HASH(0x4527e48) 12 1 12 12.00 11 HASH(0x4527e48)
[...] NOCH VIEL VIEL MEHR ...
vorkommt!!!! Hört sich so an als ob ein TIMER etwas blockiertes "killt"?
Hier eine Auswahl an hohen Average-Werten, sind das eigentlich Sekungen?? 2.0 = 2 Sekunden oder Millisekunden:
vccu CUL_HM_Set 1 1 1 1.00 0 HASH(vccu); vccu; ?
tmr-Twilight_sunpos HASH(0x5e1c980) 6 1 6 6.00 11 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5e2c5a8) 4 1 4 4.00 3 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5e6ef00) 5 1 5 5.00 3 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5e70a08) 4 1 4 4.00 3 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5e8a770) 5 1 5 5.00 3 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5ebe620) 4 1 4 4.00 3 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5ecef08) 5 1 5 5.00 3 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5ed1070) 5 1 5 5.00 3 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5ef01e0) 5 1 5 5.00 4 HASH(twilight_sunpos)
tmr-Twilight_sunpos HASH(0x5efc260) 4 1 4 4.00 3 HASH(twilight_sunpos)
tmr-at_Exec HASH(0x1f681e8) 25 1 25 25.00 2150 HASH(TestAliveRauchmelder)
tmr-at_Exec HASH(0x2095538) 6 1 6 6.00 4 HASH(BatteryLowPushover)
tmr-at_Exec HASH(0x244fda8) 167 1 167 167.00 4 HASH(TestAbfall)
tmr-at_Exec HASH(0x335e150) 416 1 416 416.00 419 HASH(LoescheDayTemps)
tmr-at_Exec HASH(0x33ac658) 152 1 152 152.00 3 HASH(n2_NRW_Ferien)
tmr-at_Exec HASH(0x341d288) 119 1 119 119.00 3 HASH(SetDummy1)
tmr-at_Exec HASH(0x3432298) 148 1 148 148.00 4 HASH(SetDummy2)
tmr-at_Exec HASH(0x3436b40) 155 1 155 155.00 4 HASH(sun_riseSet_timer)
tmr-at_Exec HASH(0x372bcf0) 415 1 415 415.00 3 HASH(LoescheDayWaterTemps)
tmr-at_Exec HASH(0x37b49e8) 12 1 12 12.00 93 HASH(at_TestSwitch)
tmr-at_Exec HASH(0x3cb9d90) 256 1 256 256.00 56 HASH(alarm6.disarm.T)
tmr-Twilight_WeatherTimerUpdate HASH(0x3e167f8) 29 1 29 29.00 4 HASH(twilight_weather)
tmr-Twilight_WeatherTimerUpdate HASH(0x5031c28) 29 1 29 29.00 3 HASH(twilight_weather)
tmr-Twilight_WeatherTimerUpdate HASH(0x569a2c8) 28 1 28 28.00 2 HASH(twilight_weather)
tmr-Twilight_fireEvent HASH(0x2902cc8) 55 1 55 55.00 50 HASH(twilight_ss_indoor)
tmr-Twilight_fireEvent HASH(0x3cba6f0) 69 1 69 69.00 3 HASH(twilight_sr_indoor)
tmr-Twilight_fireEvent HASH(0x4135a80) 2 1 2 2.00 45353223 HASH(twilight_sr_weather)
tmr-Twilight_fireEvent HASH(0x41aa300) 76 1 76 76.00 4 HASH(twilight_sr_astro)
tmr-Twilight_fireEvent HASH(0x4231400) 55 1 55 55.00 3 HASH(twilight_ss_naut)
tmr-Twilight_fireEvent HASH(0x44067e8) 62 1 62 62.00 2 HASH(twilight_sr)
tmr-Twilight_fireEvent HASH(0x440b888) 57 1 57 57.00 2 HASH(twilight_ss_astro)
tmr-Twilight_fireEvent HASH(0x45c62d8) 68 1 68 68.00 3 HASH(twilight_sr_civil)
tmr-Twilight_fireEvent HASH(0x463ce48) 2 1 2 2.00 43790276 HASH(twilight_sr_weather)
tmr-Twilight_fireEvent HASH(0x463d3e8) 55 1 55 55.00 2 HASH(twilight_ss)
tmr-Twilight_fireEvent HASH(0x47e6bc8) 55 1 55 55.00 3 HASH(twilight_ss_civil)
tmr-Twilight_fireEvent HASH(0x48300e0) 69 1 69 69.00 0 HASH(twilight_sr_naut)
tmr-Twilight_fireEvent HASH(0x502b190) 56 1 56 56.00 4 HASH(twilight_ss_weather)
tmr-Twilight_fireEvent HASH(0x569adc0) 68 1 68 68.00 63 HASH(twilight_sr_weather)
tmr-Calendar_Wakeup HASH(0x391c2d8) 738 1 738 738.00 3 HASH(NRW_Ferien)
tmr-DOIF_TimerTrigger REF(0x2828a38) 386 1 386 386.00 11 REF(0x2828a38)
tmr-DOIF_TimerTrigger REF(0x3c6d948) 11 1 11 11.00 3 REF(0x3c6d948)
tmr-DOIF_TimerTrigger REF(0x3c6e280) 4 1 4 4.00 3 REF(0x3c6e280)
tmr-DOIF_TimerTrigger REF(0x3f50230) 4 1 4 4.00 4 REF(0x3f50230)
tmr-DOIF_TimerTrigger REF(0x4123ec0) 289 1 289 289.00 3 REF(0x4123ec0)
tmr-DOIF_TimerTrigger REF(0x42bdbf0) 7 1 7 7.00 3 REF(0x42bdbf0)
tmr-DOIF_TimerTrigger REF(0x43afea8) 4 1 4 4.00 3 REF(0x43afea8)
tmr-DOIF_TimerTrigger REF(0x440a830) 270 1 270 270.00 10 REF(0x440a830)
tmr-DOIF_TimerTrigger REF(0x44a6a90) 89 1 89 89.00 3 REF(0x44a6a90)
tmr-DOIF_TimerTrigger REF(0x44fdb00) 76 1 76 76.00 3 REF(0x44fdb00)
tmr-DOIF_TimerTrigger REF(0x46104d8) 8 1 8 8.00 172 REF(0x46104d8)
tmr-DOIF_TimerTrigger REF(0x46587e0) 11 1 11 11.00 4 REF(0x46587e0)
tmr-DOIF_TimerTrigger REF(0x47e8290) 10 1 10 10.00 3 REF(0x47e8290)
tmr-DOIF_TimerTrigger REF(0x49bb4b8) 11 1 11 11.00 3 REF(0x49bb4b8)
tmr-FileLog_dailySwitch HASH(0x1503b28) 20 1 20 20.00 3 HASH(0x1503b28)
tmr-HTTPMOD_GetUpdate update:eq3 32 1 32 32.00 3 update:eq3
tmr-HttpUtils_Err HASH(0x5700b40) 2 1 2 2.00 3 HASH(0x5700b40)
tmr-Twilight_Midnight HASH(0x5031a60) 28 1 28 28.00 2 HASH(twilight_Midnight)
WEB_172.30.90.45_17216 FW_Read 4 1 4 4.00 0 HASH(WEB_172.30.90.45_17216)
OG_Anna_RM2 CUL_HM_Set 2 1 2 2.00 0 HASH(OG_Anna_RM2); OG_Anna_RM2; ?
OG_Linus_RM2 CUL_HM_Set 2 1 2 2.00 0 HASH(OG_Linus_RM2); OG_Linus_RM2; ?
OG_Maja_RM2 CUL_HM_Set 2 1 2 2.00 0 HASH(OG_Maja_RM2); OG_Maja_RM2; ?
OG_Schlafzimmer_RM2 CUL_HM_Set 2 1 2 2.00 0 HASH(OG_Schlafzimmer_RM2); OG_Schlafzimmer_RM2; ?
EG_Buero_RM2 CUL_HM_Set 2 1 2 2.00 0 HASH(EG_Buero_RM2); EG_Buero_RM2; ?
EG_Kueche_RM2 CUL_HM_Set 2 1 2 2.00 0 HASH(EG_Kueche_RM2); EG_Kueche_RM2; ?
EG_Wohnzimmer_RM2 CUL_HM_Set 6 1 6 6.00 0 HASH(EG_Wohnzimmer_RM2); EG_Wohnzimmer_RM2; ?
FileLog_AussenSwitch FileLog_Set 17 1 17 17.00 0 HASH(FileLog_AussenSwitch); FileLog_AussenSwitch; ?
FileLog_EG_Haustuer FileLog_Set 16 1 16 16.00 0 HASH(FileLog_EG_Haustuer); FileLog_EG_Haustuer; ?
FileLog_FB_SecureFernbedienung FileLog_Set 16 1 16 16.00 0 HASH(FileLog_FB_SecureFernbedienung); FileLog_FB_SecureFernbedienung; ?
FileLog_Garagentor FileLog_Set 16 1 16 16.00 0 HASH(FileLog_Garagentor); FileLog_Garagentor; ?
FileLog_HM_408A0A FileLog_Set 16 1 16 16.00 0 HASH(FileLog_HM_408A0A); FileLog_HM_408A0A; ?
FileLog_HandtuchHeizung FileLog_Set 18 1 18 18.00 0 HASH(FileLog_HandtuchHeizung); FileLog_HandtuchHeizung; ?
FileLog_InfoDisplay FileLog_Set 16 1 16 16.00 0 HASH(FileLog_InfoDisplay); FileLog_InfoDisplay; ?
FileLog_Markise FileLog_Set 16 1 16 16.00 0 HASH(FileLog_Markise); FileLog_Markise; ?
FileLog_Thermo_Pool FileLog_Set 16 1 16 16.00 0 HASH(FileLog_Thermo_Pool); FileLog_Thermo_Pool; ?
FileLog_Thermo_Spielhaus FileLog_Set 16 1 16 16.00 0 HASH(FileLog_Thermo_Spielhaus); FileLog_Thermo_Spielhaus; ?
FileLog_Tuergong FileLog_Set 16 1 16 16.00 0 HASH(FileLog_Tuergong); FileLog_Tuergong; ?
FileLog_Tuerklingel FileLog_Log 2 1 2 2.00 0 HASH(FileLog_Tuerklingel); HASH(Tuerklingel)
FileLog_Tuerklingel FileLog_Set 16 1 16 16.00 0 HASH(FileLog_Tuerklingel); FileLog_Tuerklingel; ?
A_HS_AL_armInt_s dummy_Set 786 1 786 786.00 0 HASH(A_HS_AL_armInt_s); A_HS_AL_armInt_s; press
FB_SecureFernbedienung CUL_HM_Set 2 2 4 2.00 0 HASH(FB_SecureFernbedienung); FB_SecureFernbedienung; ?
FileLog_Wetter_XXX FileLog_Get 37 2 72 36.00 0 HASH(FileLog_Wetter_XXX); FileLog_Wetter_XXX; CURRENT; INT; 2016-08-23_00:00:00; 2016-08-24_00:00:01; 4:wetter_XXX.temperature\x3a:1:; 4:MeinWetter.temp_c\x3a:1:
FileLog_Wetter_XXX FileLog_Set 17 2 34 17.00 0 HASH(FileLog_Wetter_XXX); FileLog_Wetter_XXX; ?
FileLog_Wetter_XXX FileLog_regexpFn 0 2 0 0.00 0
Garagentor_dummy dummy_Set 59 2 59 29.50 0 HASH(Garagentor_dummy); Garagentor_dummy; zu
HM_408A0A CUL_HM_Set 2 2 4 2.00 0 HASH(HM_408A0A); HM_408A0A; ?
NRW_Ferien Calendar_Set 30 2 30 15.00 0 HASH(NRW_Ferien); NRW_Ferien; reload
n_MP3Gong_Play notify_Exec 144 3 419 139.67 0 HASH(n_MP3Gong_Play); HASH(dummy_MP3Gong)
tmr-Calendar_Wakeup HASH(0x24b4408) 2149 3 4322 1440.67 3 HASH(Abfall_FHEM)
Tuergong_Mp3 CUL_HM_Set 136 3 398 132.67 0 HASH(Tuergong_Mp3); Tuergong_Mp3; playTone; 002; 1; 6
Tuerklingel CUL_HM_Set 2 3 6 2.00 0 HASH(Tuerklingel); Tuerklingel; ?
WEB_172.30.90.45_17213 FW_Read 4 3 12 4.00 0 HASH(WEB_172.30.90.45_17213)
Telefon FB_CALLMONITOR_Read 130 3 368 122.67 0 HASH(Telefon)
Sonnenaufgang dummy_Set 68 3 68 22.67 0 HASH(Sonnenaufgang); Sonnenaufgang; 06:00:18
Sonnenuntergang dummy_Set 68 3 68 22.67 0 HASH(Sonnenuntergang); Sonnenuntergang; 21:08:49
Garagentor CUL_HM_Set 87 3 93 31.00 0 HASH(Garagentor); Garagentor; on-for-timer; 3
FileLog_AussenSwitch FileLog_Get 41 3 55 18.33 0 HASH(FileLog_AussenSwitch); FileLog_AussenSwitch; CURRENT; INT; 2016-08-23_00:00:00; 2016-08-24_00:00:01; 4:AussenSwitch.*:0:
tmr-CUL_HM_respPendTout respPend:408A0A 141 4 148 37.00 24 respPend:408A0A
PoolDauerpumpe dummy_Set 54 5 108 21.60 0 HASH(PoolDauerpumpe); PoolDauerpumpe; ein
Tageslicht dummy_Set 66 5 120 24.00 0 HASH(Tageslicht); Tageslicht; hell
WEB_172.30.90.45_17212 FW_Read 4 5 16 3.20 0 HASH(WEB_172.30.90.45_17212)
tmr-Calendar_Wakeup HASH(0x26e3918) 29 5 119 23.80 3 HASH(Kalender_FHEM)
GarageTuer dummy_Set 91 7 358 51.14 0 HASH(GarageTuer); GarageTuer; open
RufListe FB_CALLLIST_Notify 58 6 168 28.00 0 HASH(RufListe); HASH(Telefon)
notAbfalltermine notify_Exec 1963 8 5654 706.75 0 HASH(notAbfalltermine); HASH(Abfall_FHEM)
FileLog_Thermo_Spielhaus FileLog_Get 66 9 535 59.44 0 HASH(FileLog_Thermo_Spielhaus); FileLog_Thermo_Spielhaus; CURRENT; INT; 2016-08-23_00:00:00; 2016-08-24_00:00:01; 4:Thermo_Spielhaus.temperature\x3a:0:
tmr-HTTPMOD_GetUpdate update:Pollenflug 38 10 332 33.20 4 update:Pollenflug
n_GarageTuer notify_Exec 101 11 398 36.18 0 HASH(n_GarageTuer); HASH(GarageTor
n_Telegram notify_Exec 423 15 473 31.53 0 HASH(n_Telegram); HASH(Telegram)
tmr-DOIF_SleepTrigger HASH(0x341aa08) 334 13 2034 156.46 69 HASH(do_AlarmArmedHaustuer)
AussenSwitch CUL_HM_Set 156 18 833 46.28 0 HASH(AussenSwitch); AussenSwitch; off
tmr-PRESENCE_StartLocalScan HASH(0x2c5f430) 48 1210 31131 25.73 115 HASH(AndyPresence)
tmr-PRESENCE_StartLocalScan HASH(0x2c7d6b8) 46 1210 31204 25.79 6374 HASH(MajaPresence)
tmr-PRESENCE_StartLocalScan HASH(0x30c9c90) 41 1210 31075 25.68 11052 HASH(AnnaPresence)
tmr-PRESENCE_StartLocalScan HASH(0x31c0330) 53 1210 37219 30.76 11030 HASH(KerstinPresence)
tmr-FRITZBOX_Readout_Start FritzBox.Readout 54 1212 33380 27.54 148 FritzBox.Readout
tmr-FRITZBOX_Readout_Start FritzRepeater.Readout 46 1213 33324 27.47 126 FritzRepeater.Readout
tmr-UPSPICO_Poll HASH(0x1711b70) 80 4831 241127 49.91 10405 HASH(USV)
myJeeLink JeeLink_Read 525 257164 957441 3.72 0 HASH(myJeeLink)
Du solltest dich mir apptime maxDly beschäftigen.
Die BlockingKill abfragen sind erstmal ganz normal. Es handelt sich hier lediglich um den Namen einer Routine. Die Zeiten sind viel interessanter und die sind in dem Fall zu vernachlässigen.
ZitatErstaunlich finde ich, dass zur angegebenen Start-Zeit keine Einträge vorhanden sind!
das sehe ich ganz anders. runde die ms vom log mal auf und addiere den delay zum letzten logeintrag vor der perfmon warnung.
und "erstaunlicherweise" wird beide male die selbe funktion gestartet:
2016.08.23 11:44:40.798 4: WEB_10.8.0.6_20161 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2016-08.log; BUFLEN:0
ist das zufall?
Eventuell macht es ja Sinn die Monatslogs auf Tageslogs umzustellen!?
Sag mal, hast du global verbose 5 ständig an? Das würde erklären, warum ggf. große Logfiles vorhanden sind und diese dann möglicherweise beim Laden lange blockieren.
NEIN, nur zur Analyse habe ich es jetzt auf verbose 5.
Grundsätzlich steht es auf 3.
Das Log befindet sich auch im RAM, da ich die SD meines Raspis nicht so stressen will.
Daher sind diese "freezes" vermutlich durch verbos 5 und treten im normalen Betrieb nicht auf.
Habe jetzt meine Calendar auf 35000000 Interval gestellt und aktualisiere sie Nachts einmal.
Habe gesehen, das das Calendermodul einige Sekunden brauchte.
HTTPMOD nutze ich auch in mehreren Bereichen.
Aber das läuft m.E. im Hintergrund ohne "Blocking"..
Greets
Byte