Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

[vbs]

Guck doch mal mit "dmesg -T", was der Kernel so von sich gegeben hat. Vielleicht sieht man da was. Ansonsten erstmal Prozessliste beobachten, denk ich.

Gibt noch LTTng (https://en.wikipedia.org/wiki/LTTng), aber das ist sicherlich etwas übertrieben für den Anfang.

[Pfriemler]

"dmseg -T" liefert nach dem heutigen Reboot (FHEM meldete gestern erstmals "cannot fork ...", ich vermute apptime als Mitverursacher, weil ebenfalls erstmals länger in Nutzung, und heute morgen war FHEM dann tot) nach vielen Systemmeldungen vom Neustart dann mit viel Regelmäßigkeit (timeouts alle 1-3 Minuten und die zweite Meldung alle 15-20 Minuten) Meldungen wie

Code Auswählen Erweitern

[Thu Nov 22 11:19:58 2018] Bluetooth: hci0 command 0x0419 tx timeout
[Thu Nov 22 11:22:16 2018] Transfer to device 8 endpoint 0x1 frame 994 failed - FIQ reported NYET. Data may have been lost.

Kurzes Googlen bringt das in Zusammenhang mit Bluetooth. Die PRESENCEs mit Bluetooth-Scan sind jetzt disabled - und die Meldungen kommen nicht mehr.
"top" listet perl mit user fhem zwischen 2 und 12%, CPU-Last, mit einer laufenden Websession etwa 5-10% mehr. Rufe ich dort mal ein SVG mit langem Zeitraum auf, bleibt die CPU-Last von FHEM stabil um 99.5%, bis das Diagramm fertig ist. Das sieht für mich alles unverdächtig aus, in dem Sinne dass FHEM so ziemlich der einzige Lastfresser auf dem Pi zu sein scheint.

Freezes kommen leider immer noch:

Code Auswählen Erweitern

2018.11.22 12:14:04 1: [Freezemon] freezemon: possible freeze starting at 12:13:57, delay is 7.74 possibly caused by: no bad guy found :-(
2018.11.22 12:14:22 1: [Freezemon] freezemon: possible freeze starting at 12:14:15, delay is 7.093 possibly caused by: no bad guy found :-(
2018.11.22 12:16:02 1: [Freezemon] freezemon: possible freeze starting at 12:15:55, delay is 7.544 possibly caused by: tmr-PRESENCE_StartLocalScan(VolkersEifonFB) tmr-PRESENCE_StartLocalScan(RobotronFB) tmr-HMUARTLGW_CheckCredits(N/A) tmr-HMUARTLGW_CheckCredits(N/A) tmr-PRESENCE_StartLocalScan(VolkersHandy_WLAN)
edit: Allerdings hatte ich in genau der Zeit FHEM mit den SVGs ausgelastet. Nicht dass diese Freezes eben doch irrtümlich gemeldet werden?

Ich baue jetzt einen Raspi 3 von Grund auf neu und ziehe mein FHEM anschließend dahin um...

[Wuppi68]

@Pfriemler:
sieht auf den ersten Block "normal" aus

mein Bauch sagt, dass auch Probleme mit der Stromversorgung bzw. der Temperatur vorhanden sein könnten

btw: Bei mir will ich auch für mein Zuhause 2.0 die FHEM Installation in verschiedene Instanzen splitten und via MQTT quatschen lassen

[frank]

nach meinen erfahrungen muss man mindestens 3 "auffälligkeiten" unterscheiden.

1. speicherleck in perl/fhem.(zb https://forum.fhem.de/index.php/topic,84372.0.html)
freezemon mit option apptime verstärkt den effekt enorm, zumindestens bei mir. dazu gibt es inzwischen das event "global:CANNOT_FORK", um zb einen fhem restart auszulösen.

2. freezes ohne "log skipps"
hierzu hatte ich schon riesige verbose 5 logs, in denen nach den timestamps der logeinträge bei weitem kein "platz" für ein freeze der angegebenen dauer war.

3. freezes mit "log skipps"
hier kann es zum freeze start hinweise zum auslöser des freeze geben.

"get freezemon log" hat bei mir gerade einen eigenen freeze (12s => no bad gay) ausgelöst.

[Pfriemler]

@Pfriemler: sieht auf den ersten Blick "normal" aus ...
mein Bauch sagt, dass auch Probleme mit der Stromversorgung bzw. der Temperatur vorhanden sein könnten

Temperatur laut System zwischen 42 und 45 Grad. Stromversorgung - tja, die rote LED leuchtet mit kurzen Unterbrechnungen fast ständig, trotz guter Kabel und kräftigem Netzteil (mit 5.2V Ausgangsspannung), aber das tut sie ebenfalls schon seit Jahren und als das System noch klaglos rannte. So ein Hänger wie heute früh ist neben einem vor drei Wochen der erste seit mehr als einem Jahr, ohne dass das System regelmäßig rebootet wird (schon gar nicht über eine Automatik) - ich mach nur so alle 3-4 Monate ein Speicherkartenbackup, währenddessen das System natürlich down ist. So lange liefen Raspi und auch FHEM jedenfalls bisher ohne Probs durch...

ou ... und wenn ich franks Hinweise lese ... und den Fred dazu ... ist das mit einem frischen Raspian und dem Raspi 3 mit einem Male doch keine so gute Idee ... und der WAF sinkt weiter ...

Man liest sich, danke für alles Mitgefühl bis hierher ...

[KölnSolar]

Nur kurz meine überraschende Erkenntnis:
Dank Olis Modul konnte ich die dicken Freezes(GPIO4, eigenes Modul...) eliminieren. Irgendwie wurden danach die freezes immer mehr, ohne dass ich "Schuldige" ermitteln konnte. Dann hatte ich gar Abstürze.
Ursache: nicht etwa ein Modul, sondern mein USB-Boot-Stick. Neue SD in Kombination mit aktuellstem Stretch  == kein einziger freeze(< 0,7s) diese Nacht. 
Grüße Markus

PS: Zwischen meinem letzten Raspbian und aktuellem sind syslog-messages bei undervoltage eingeführt worden !!! War für mich sehr hilfreich, denn trotz visueller Überwachung mit einem Mess-Adapter tauchten im syslog (überraschend/unerwartet) undervoltages auf.

[stanford]

[...]

Code Auswählen Erweitern


reload: Error:Modul 98_freezemon deactivated:
Global symbol "$FW_ME" requires explicit package name at ./FHEM/98_freezemon.pm line 1206, <$fh> line 17.

2018.09.13 07:50:32 0: Global symbol "$FW_ME" requires explicit package name at ./FHEM/98_freezemon.pm line 1206, <$fh> line 17.

[...]

Hatte ich gerade auch. Du musst freezemon NACH define FHEMWEB in der fhem.cfg einfügen.

[herrmannj]

Hatte ich gerade auch. Du musst freezemon NACH define FHEMWEB in der fhem.cfg einfügen.

module installiert man über das web-interface.

[Tommy82]

Hi,
ich habe nach einem Fhem Neustart folgende Meldung im Log

Code Auswählen Erweitern

2019.01.08 19:07:02.847 1: PERL WARNING: Use of uninitialized value in string ne at ./FHEM/98_freezemon.pm line 324.
2019.01.08 19:07:02.847 1: stacktrace:
2019.01.08 19:07:02.848 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (324)
2019.01.08 19:07:02.848 1:     main::freezemon_ProcessTimer        called by fhem.pl (3153)
2019.01.08 19:07:02.849 1:     main::HandleTimeout                 called by fhem.pl (650)
2019.01.08 19:07:02.850 1: [Freezemon] myFreezemon: possible freeze starting at 19:06:45, delay is 17.845 possibly caused by: no bad guy found :-(

Woher kommt das?

Danke

[KernSani]

Hi Tommy,

welche Version hast du denn im Einsatz? Scheint mir nicht ganz die aktuelle zu sein... Kannst du mal ein "list -r" des freezemons posten?

Grüße,

Oli

[Tommy82]

Hi,
hier die Ausgabe

Code Auswählen Erweitern

define myFreezemon freezemon
attr myFreezemon fm_forceApptime 1
attr myFreezemon group Info
attr myFreezemon room Zentral

setstate myFreezemon s:20:54:31 e:20:54:32 f:1.209 d:no bad guy found :-(
setstate myFreezemon 2019-01-09 20:54:32 .fm_freezes 2019-01-08: s:01:53:36 e:01:53:37 f:1.011 d:no bad guy found :-(,2019-01-08: s:02:02:00 e:02:02:23 f:23.075 d:tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-at_Exec(at_fp_time) tmr-at_Exec(DbLog_aufrauumen) ,2019-01-08: s:05:30:00 e:05:30:01 f:1.18 d:tmr-at_Exec(at_fp_time) tmr-at_Exec(Weihnachtsdeko_an_am) ,2019-01-08: s:07:03:06 e:07:03:27 f:21.919 d:tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-Calendar_Wakeup(AbfallA),2019-01-08: s:18:19:38 e:18:19:55 f:17.075 d:no bad guy found :-(,2019-01-08: s:18:29:33 e:18:29:34 f:1.039 d:tmr-CUL_HM_ActCheck(N/A) ,2019-01-08: s:18:30:00 e:18:30:01 f:1.165 d:tmr-at_Exec(Mila_Licht_1_an) tmr-at_Exec(Mila_Licht_2_an),2019-01-08: s:19:02:29 e:19:02:46 f:17.999 d:no bad guy found :-(,2019-01-08: s:19:02:47 e:19:02:48 f:1.197 d:tmr-HUEDevice_GetUpdate(HUEGroup1) tmr-HUEDevice_GetUpdate(HUEGroup0) tmr-at_Exec(at_fp_time) tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-FRITZBOX_Readout_Start(N/A) tmr-CUL_HM_procQs(N/A) tmr-HMLAN_KeepAliveCheck(N/A),2019-01-08: s:23:13:39 e:23:13:58 f:19.536 d:no bad guy found :-(,2019-01-08: s:23:16:29 e:23:16:31 f:2.78 d:tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-BlinkCamera_PollInfo(Kameras) ,2019-01-08: s:23:24:00 e:23:24:01 f:1.339 d:tmr-WOL_UpdateReadings(WinServer_ping) tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) ,2019-01-08: s:23:30:24 e:23:30:27 f:3.307 d:no bad guy found :-(,2019-01-09: s:19:15:51 e:19:15:52 f:1.862 d:no bad guy found :-(,2019-01-09: s:19:30:37 e:19:31:06 f:29.048 d:no bad guy found :-(,2019-01-09: s:20:47:55 e:20:48:17 f:22.821 d:no bad guy found :-(,2019-01-09: s:20:48:19 e:20:48:20 f:1.094 d:tmr-CUL_HM_procQs(N/A) tmr-HMLAN_KeepAliveCheck(N/A) ,2019-01-09: s:20:51:00 e:20:51:05 f:5.701 d:tmr-at_Exec(at_fp_time) ,2019-01-09: s:20:52:53 e:20:52:58 f:5.716 d:no bad guy found :-(,2019-01-09: s:20:54:31 e:20:54:32 f:1.209 d:no bad guy found :-(
setstate myFreezemon 2019-01-09 19:16:42 .lastDay 2019-01-09
setstate myFreezemon 2019-01-09 20:54:32 fcDay 6
setstate myFreezemon 2019-01-09 19:16:42 fcDayLast 17
setstate myFreezemon 2019-01-09 20:54:32 freezeDevice no bad guy found :-(
setstate myFreezemon 2019-01-09 20:54:32 freezeTime 1.209
setstate myFreezemon 2019-01-09 20:54:32 ftDay 65.589
setstate myFreezemon 2019-01-09 19:16:42 ftDayLast 121.326
setstate myFreezemon 2019-01-09 20:54:32 state s:20:54:31 e:20:54:32 f:1.209 d:no bad guy found :-(

Ist diese Version

Code Auswählen Erweitern

98_freezemon.pm      18087 2018-12-29 19:33:14Z KernSani
hab grad bei update check gesehen das es ein update gibt, ich spiel das mal ein

[KernSani]

hab grad bei update check gesehen das es ein update gibt, ich spiel das mal ein

Ich bin mir ziemlich sicher, dass das nicht helfen wird.
Ich kann die warning, die bei dir auftritt nicht ganz nachvollziehen, ich habe aber gerade eben einen Fix hochgeladen, der andere Warnings beim FHEM start behebt - vielleicht hilft der auch bei dir. Ist mit dem Update morgen verfügbar.

[Tommy82]

Hi,
ok werde das Update auch einspielen und dann mal weiter beobachten.
Danke

[Tommy82]

Guten Morgen, habe heute Morgen wieder eine Meldung im LOg

Code Auswählen Erweitern

2019.01.11 01:03:28.240 1: [Freezemon] myFreezemon: possible freeze starting at 01:03:24, delay is 4.236 possibly caused by: tmr-BlinkCamera_PollInfo(Kameras)
2019.01.11 02:02:39.500 1: [Freezemon] myFreezemon: possible freeze starting at 02:02:00, delay is 39.499 possibly caused by: tmr-at_Exec(DbLog_aufrauumen)
2019.01.11 02:02:41.519 1: [Freezemon] myFreezemon: possible freeze starting at 02:02:40, delay is 1.515 possibly caused by: tmr-WOL_UpdateReadings(WinServer_ping) tmr-at_Exec(at_fp_time) tmr-BlinkCamera_PollInfo(Kameras) tmr-SYSMON_Update(sysmon) tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-ENIGMA2_GetStatus(VU_Ultimo) tmr-ENIGMA2_GetStatus(Uno_Schlafzimmer) tmr-HMLAN_KeepAlive(N/A) tmr-HUEBridge_GetUpdate(HUE) tmr-PRESENCE_StartLocalScan(Iphone7Plus) tmr-AMAD_checkDeviceState(Android_Tablett_Wohnzimmer)
2019.01.11 02:02:41.582 1: PERL WARNING: Use of uninitialized value $shortarg in concatenation (.) or string at ./FHEM/98_freezemon.pm line 854.
2019.01.11 02:02:41.583 1: stacktrace:
2019.01.11 02:02:41.583 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (854)
2019.01.11 02:02:41.584 1:     main::freezemon_apptime             called by ./FHEM/98_freezemon.pm (538)
2019.01.11 02:02:41.584 1:     main::freezemon_ProcessTimer        called by fhem.pl (3153)
2019.01.11 02:02:41.585 1:     main::HandleTimeout                 called by fhem.pl (650)
2019.01.11 02:54:55.382 1: [Freezemon] myFreezemon: possible freeze starting at 02:54:41, delay is 14.379 possibly caused by: tmr-Calendar_Wakeup(AbfallA)

Version ist

Code Auswählen Erweitern

98_freezemon.pm      18169 2019-01-07 10:22:00Z KernSani

[KernSani]

Guten Morgen,
Du bist aber früh wach Ich schau mir das heute abend mal an... An der Stelle hab ich seit ewigen Zeiten nichts geändert...



Kurz, weil mobil