Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

[KernSani]

Nimm lieber das Attribut dann kannst mit der Funktion

Code Auswählen Erweitern


IsDisabled($name)

abfragen.

isDisabled hört auch auf state und STATE "inactive"... nutze ich schon

[Gisbert]

Hallo Oli,

ich hab heute morgen (ca. 8:25) das Modul 98_freezemon.pm upgedatet, d.h. nur dieses einzelne Modul.
Das Ergebnis war folgendes  :

Code Auswählen Erweitern

2018.04.03 08:27:48 3: freezemon defined myFreezemon freezemon
Undefined subroutine &main::isDisabled called at .//FHEM/98_freezemon.pm line 595, <$fh> line 35.
Und die Konsequenz war, dass Fhem nicht mehr erreichbar war.

Ich hab dann den RPi runtergefahren, es kam die gleiche Reaktion, wieder  :

Code Auswählen Erweitern

2018.04.03 08:42:28 3: freezemon defined myFreezemon freezemon
Undefined subroutine &main::isDisabled called at .//FHEM/98_freezemon.pm line 595, <$fh> line 35.

Nachdem ich aus dem Backup die Vorgängerversion nach Fhem geschoben habe, startet Fhem auch wieder.

Viele Grüße Gisbert

Edit:
Noch ein list meines freezemons, nachdem es wieder mit der Vorgängerversion läuft:

Code Auswählen Erweitern

Internals:
   CFGFN      ./FHEM/NetzwerkRPiPerformance.cfg
   NAME       myFreezemon
   NR         393
   NTFY_ORDER 99-myFreezemon
   STATE      Last freeze:<br/>2018-04-03 08:51:32
   TYPE       freezemon
   VERSION    0.0.18
   READINGS:
     2018-04-03 08:51:32   Zeitstempel     2018-04-03 08:51:32
     2018-04-03 08:51:32   fcDay           7
     2018-04-03 00:00:00   fcDayLast       16
     2018-04-03 08:51:32   freezeDevice    CUL_HM_respPendTout(N/A) BlockingKill(N/A)
     2018-04-03 08:51:32   freezeTime      3.746
     2018-04-03 08:51:32   ftDay           189.187
     2018-04-03 00:00:00   ftDayLast       34.387
     2018-04-03 08:51:32   state           s:08:51:29 e:08:51:32 f:3.746 d:CUL_HM_respPendTout(N/A) BlockingKill(N/A)
   helper:
     DISABLED   0
     TIMER      1522738831
     apptime    1522738832.81047-HMLAN_KeepAlive:N/A 1522738834.02203-HMUARTLGW_CheckCredits:N/A 1522738835.25623-PRESENCE_StartLocalScan:LGG6 1522738837.75537-PRESENCE_StartLocalScan:SamsungGalaxyA5 1522738838.05528-PRESENCE_StartLocalScan:MotorolaG2 1522738839.16352-PRESENCE_StartLocalScan:Honor8 1522738858.99659-SYSMON_Update:RPi.Sysmon 1522738860-DOIF_TimerTrigger:Garagentor.Alarm 1522738863.6728-at_Exec:heartbeat 1522738864.49735-CUL_HM_ActCheck:N/A 1522738868-DOIF_TimerTrigger:Klingeln 1522738868.63763-MQTT::Timer:MyBroker 1522738869.04886-HTTPMOD_GetUpdate:N/A 1522738869.05737-HTTPMOD_GetUpdate:N/A 1522738869.06152-HTTPMOD_GetUpdate:N/A 1522738869.06525-HTTPMOD_GetUpdate:N/A 1522738869.06895-HTTPMOD_GetUpdate:N/A 1522738869.07278-HTTPMOD_GetUpdate:N/A 1522738869.18854-TRAFFIC_StartUpdate:DormagenNachhause 1522738869.20379-TRAFFIC_StartUpdate:ZuhauseDormagen 1522738869.20459-TRAFFIC_StartUpdate:DormagenKoelnLuetticherStr 1522738869.2142-BlockingKill:N/A 1522738869.2403-HTTPMOD_GetUpdate:N/A 1522738869.24528-HTTPMOD_GetUpdate:N/A 1522738869.24896-HTTPMOD_GetUpdate:N/A 1522738869.2527-HTTPMOD_GetUpdate:N/A 1522738869.25657-HTTPMOD_GetUpdate:N/A 1522738869.26032-HTTPMOD_GetUpdate:N/A 1522738869.26399-HTTPMOD_GetUpdate:N/A 1522738871.18345-SIGNALduino_KeepAlive:mySIGNALduino 1522738876.60892-DOIF_SleepTrigger:Anwesenheit.Zuhause 1522738877-FW_closeInactiveClients:N/A 1522738879.02468-FRITZBOX_Readout_Start:N/A 1522738879.05074-FRITZBOX_Readout_Start:N/A 1522738898.99099-Weather_GetUpdate:Wetter.Leverkusen 1522738912.95951-DOIF_SleepTrigger:Warmwasser.Zirkulation 1522738920-DOIF_TimerTrigger:SensorAktualitaet 1522738943.16762-Buienradar_ScheduleUpdate:Buienradar 1522738968.87013-at_Exec:at.Haushaltsraum.Ventilator.on 1522738980-DOIF_TimerTrigger:SensorAktualitaet 1522738988.68285-AMADDevice_checkDeviceState:myLGG6 1522739039.80477-HttpUtils_Err:N/A 1522739100-DOIF_TimerTrigger:SensorAktualitaet 1522739118-Twilight_sunpos:myTwilight_sunpos 1522739409.26023-TRAFFIC_StartUpdate:ZuhauseDeutz 1522740058.65412-CUL_HM_complConfigTO:N/A 1522740068.95066-PROPLANTA_Start:Wetter.Proplanta 1522740092.81008-CUL_HM_qStateUpdatIfEnab:N/A 1522740600-DOIF_TimerTrigger:SensorAktualitaet 1522740660-DOIF_TimerTrigger:SensorAktualitaet 1522740720-DOIF_TimerTrigger:SensorAktualitaet 1522740780-DOIF_TimerTrigger:SensorAktualitaet 1522740840-DOIF_TimerTrigger:SensorAktualitaet 1522740900-DOIF_TimerTrigger:SensorAktualitaet 1522741878.92477-Astro_Update:myAstro 1522741884.49829-airquality_GetUpdate:Luftqualitaet 1522742395-statistics_PeriodChange:Statistik 1522742400-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522742400.19774-HourCounter_Run:N/A 1522742400.22994-HourCounter_Run:N/A 1522743658.86785-speedtest_GetUpdate:Speedtest 1522751400-DOIF_TimerTrigger:Update.FHEM 1522752300-DOIF_TimerTrigger:Update.FHEM 1522752671.18001-Calendar_Wakeup:Muelltonnen.Kalender.AVEA 1522753200-DOIF_TimerTrigger:Treppenhaus.Markisensteuerung 1522759871.793-Calendar_Wakeup:NRW.Feiertage.Kalender 1522759873.0293-Pushover_ValidateUser:Pushover.Nachricht 1522769400-DOIF_TimerTrigger:Muellabfuhr 1522773891.95-Twilight_WeatherTimerUpdate:myTwilight_weather 1522777491.95-Twilight_fireEvent:myTwilight_ss_weather 1522778106.96-Twilight_fireEvent:myTwilight_ss_indoor 1522778491.97-Twilight_fireEvent:myTwilight_ss 1522779640-DOIF_TimerTrigger:Schalter.1.Schaltzeit 1522779940-DOIF_TimerTrigger:Haustuer.Licht.Aus 1522780180-DOIF_TimerTrigger:Haustuer.Licht.Schaltzeit 1522780240-DOIF_TimerTrigger:SensorAktualitaet 1522780240-DOIF_TimerTrigger:Terrasse.Licht.Schaltzeit 1522780480-DOIF_TimerTrigger:Terrasse.Licht.Schaltzeit 1522780510-DOIF_TimerTrigger:CamWatchAlarm.on 1522780839.98-Twilight_fireEvent:myTwilight_ss_civil 1522783285.99-Twilight_fireEvent:myTwilight_ss_naut 1522783800-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522785155-DOIF_TimerTrigger:Terrasse.Licht.Schaltzeit 1522785540-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522785600-DOIF_TimerTrigger:Haushaltsraum.Lueftung 1522785600-DOIF_TimerTrigger:Treppenhaus.Markisensteuerung 1522785600-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522785660-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522785912-Twilight_fireEvent:myTwilight_ss_astro 1522786706-DOIF_TimerTrigger:Haustuer.Licht.Aus 1522787400-DOIF_TimerTrigger:Anwesenheit.Zuhause 1522787400-DOIF_TimerTrigger:Muellabfuhr 1522787401-DOIF_TimerTrigger:Anwesenheit.Zuhause 1522792801-Twilight_Midnight:myTwilight_Midnight 1522792801-FileLog_dailySwitch:N/A 1522805940-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522806000-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522807560-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522809540-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522809600-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522810258.45588-CUL_HM_statCntRfresh:N/A 1522811160-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522813500-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522814340-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522814400-DOIF_TimerTrigger:Warmwasser.Zirkulation 1522816199-DOIF_TimerTrigger:Anwesenheit.Zuhause 1522816200-DOIF_TimerTrigger:Anwesenheit.Zuhause 1522816200-DOIF_TimerTrigger:Schalter.1.Schaltzeit 1522816800-DOIF_TimerTrigger:Haustuer.Licht.Aus 1522816987-DOIF_TimerTrigger:CamWatchAlarm.on 1522817100-DOIF_TimerTrigger:Haustuer.Licht.Schaltzeit 1522817395-DOIF_TimerTrigger:SensorAktualitaet 1522817495-DOIF_TimerTrigger:Haustuer.Licht.Aus 1522817495-DOIF_TimerTrigger:Terrasse.Licht.Schaltzeit 1522818000-DOIF_TimerTrigger:Haushaltsraum.Lueftung 1522818900-DOIF_TimerTrigger:Schalter.1.Schaltzeit 1522819800-DOIF_TimerTrigger:Muellabfuhr 1522820700-DOIF_TimerTrigger:Haustuer.Licht.Schaltzeit 1522823400-DOIF_TimerTrigger:Muellabfuhr 1523337487.60984-FB_CALLLIST_deleteExpiredCalls:N/A
     fn         
     freeze     3.74677109718323
     intCount   18
     logfile    ./log/myFreezemon-2018-04-03.log
     msg        [Freezemon] myFreezemon: possible freeze starting at 08:51:29, delay is 3.746 possibly caused by: CUL_HM_respPendTout(N/A) BlockingKill(N/A)
     now        1522738292.74677
     bm:
       freezemon_Get:
         cnt        1
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        03.04. 09:00:14
         max        0.00111889839172363
         tot        0.00111889839172363
         mAr:
           HASH(0x41ce970)
           myFreezemon
           ?
       freezemon_Notify:
         cnt        589
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        03.04. 08:56:21
         max        0.0016319751739502
         tot        0.0810480117797852
         mAr:
           HASH(0x41ce970)
           HASH(0x289b1e8)
       freezemon_Set:
         cnt        3
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        03.04. 09:00:14
         max        5.69820404052734e-05
         tot        0.000139951705932617
         mAr:
           HASH(0x41ce970)
           myFreezemon
           ?
     logqueue:
       ARRAY(0x4c0dd00)
       ARRAY(0x47fd1a8)
       ARRAY(0x4a2c980)
Attributes:
   fm_forceApptime 1
   fm_log     10:1 5:2 1:3
   fm_logFile ./log/myFreezemon-%Y-%m-%d.log
   fm_logKeep 5
   group      Performance
   icon       system_fhem
   room       Mobile
   stateFormat Last freeze:<br/>Zeitstempel
   userReadings Zeitstempel {substr(ReadingsTimestamp('myFreezemon','state',''),0,19)}

[KernSani]

Arg... gestern war nicht mien Tag Das kommt wenn man mit drei Versionen gleichzeitig hantiert... Sorry, gefixte Version angehängt und eingecheckt.

[KernSani]

Wie angekündigt, habe ich Freezemon intern ein bisschen umgebaut. Die angehängte Version läuft seit ca 48 Stunden stabil in meinem Produktivsystem, ich will aber nicht ausschliessen, dass es noch das ein oder andere Problemchen gibt, daher wäre ich dankbar für Test und Feedback.
Was wurde geändert:
* ein Haufen Funktionalität, die früher in jedem Durchlauf (also jede Sekunde) ausgeführt wurde, wird jetzt nur noch im Falle eines Freezes ausgeführt. Dies sollte zu einer deutlich geringeren permanenten Systembelastung führen
* Blocking Calls (also das schreiben des verbose 5 logs in das Filesystem) werden nun mittels eine Queue-Mechanismus durchgeführt, was ebenfalls zu reduzierter Systemlast führt.
* fm_logExtraSeconds wird nicht mehr berücksichtigt
* Kombination von disable-Attribut mit set inactive/active wird analog zu anderen Modulen gehandhabt
* wrapping und unwrapping von FHEM-Funktionen sauberer implementiert

Danke!

[KölnSolar]

produktiv im Einsatz....

[MadMax-FHEM]

produktiv im Einsatz....

Dito.
Also auf meinem Testsystem...

Gruß, Joachim

[KölnSolar]

Angsthase 

Die neue Version tut seit 2 Tagen Dienst, wie es soll.

Die PID des blockingcall würde mit mit v.level 5 genügen 

Das Angebot in der Diskussion m. Boris f. ein Attr und früherem Start (bereits vor INITIALIZED) beim FHEM-Start fänd ich interessant, aber nicht notwendig(sprich Deine invest. Zeit sollte Entscheidungsgrundlage sein)
Grüße Markus

[KernSani]

Die neue Version tut seit 2 Tagen Dienst, wie es soll.

Ok, Danke für die Rückmeldung. Da auch sonst nix kam: eingecheckt...

Die PID des blockingcall würde mit mit v.level 5 genügen 

Ups, das habe ich noch korrigiert (vor dem einchecken;))

Das Angebot in der Diskussion m. Boris f. ein Attr und früherem Start (bereits vor INITIALIZED) beim FHEM-Start fänd ich interessant, aber nicht notwendig(sprich Deine invest. Zeit sollte Entscheidungsgrundlage sein)

Boris hat sich ja nichtmehr gemeldet... Sonst noch jemand Interesse?

[Navigator]

Mal eine Verständnisfrage zu Freezes. Werden eigentlich empfangene Kommandos, Ereignisse von CUL, TRX oder HMLAN erst an FHEM weitergereicht wenn dieses wieder "frei" ist oder gehen diese während des Freezes komplett verloren. Ich habe ab und an sehr kurze Phasen von Freezes von unter 2 Sekunden. Ich frage mich, was passiert wenn gerade in dieser Zeit ein Sensor meldet oder ich eine Aktion auf einem FS20 oder HM Taster ausgelöst wird.

[justme1968]

die gehen normalerweise nicht verloren da sie im seriellen buffer stehen bis sie ausgelesen werden. so lange der freeze nicht so lange dauert das der buffer voll oder über läuft geht im prinzip nichts verloren.

aber: hm erwartet das ack innerhalb einer bestimmten zeit. wenn das nicht vom io selber erzeugt wird sondern von fhem kann es folge probleme geben.

andere bidirektionale protokolle verhalten sich vermutlich ähnlich.

[Gisbert]

Hallo Oli,

ich nutze dein Modul, vielen Dank für die Bereitstellung und Unterstützung im Forum.

Über den Tag verteilt gibt es 20 bis 30 Meldungen im Freezemonitor bis max. 3 Sekunden.
Ich vermute, dass das im Rahmen des Üblichen liegt.

Der benutzte Speicher auf dem RPi3B (mit Sysmon geloggt) nimmt im Laufe einer Woche von ca. 25% auf ca. 60% zu, aktuell hab ich 48%, mehr oder wenig linear.

Code Auswählen Erweitern

2018-04-13_07:20:09 RPi.Sysmon ram: Total: 923.35 MB, Used: 443.86 MB, 48.07 %, Free: 479.49 MB
In den letzten 2-3 Wochen gab es ab ca. 60% große Probleme, die mit dem Speicher zu tun hatten und im Fhem Logfile auftauchten. Ich hab den genauen Wortlaut nicht mehr im Kopf, so ähnlich wie "Cannot fork ...".
Es half dann nur den Raspberry neu zu starten.

Hängt die zunehmende Speichernutzung mit Freezmon selbst zusammen?
Gibt es andere Ursachen?
Bevor ich Freezmon eingesetzt habe, hatte ich die "Cannot fork ..."-Meldungen noch nie gesehen. Die Speichernutzung habe ich mir allerdings damals nicht angeschaut.

Viele​ Grüße​ Gisbert​

[MadMax-FHEM]

Auf meinem Hauptsystem hab ich (aktuell) nur 1 freez knapp über einer Sek.

Freezemon sagt: Statistikmodul "Tagwechsel"...

Damit kann ich gut leben...

Beim Hauptsystem meiner Freundin ähnlich...

Mein Testsystem sieht freez-technisch aus wie deins, Gisbert...

Daher schaue ich auf dem Testsystem genau bevor es ein Modul ins Hauptsystem schafft...

Dank auch hier an FreezeMon!!

Bzgl. Speicher hab ich auch ein Wachstum aber noch nie die cannot fork Meldung...

In einem Monat in etwa 10% mehr Verbrauch...
...daher noch nicht akut...

Gruß, Joachim

[Amenophis86]

Speicherproblem: https://forum.fhem.de/index.php/topic,84372.0.html

[Paul.baumann]

Ich bekomme regelmäßig:

Code Auswählen Erweitern

1 - 2018-04-15: s:10:50:06 e:10:50:12 f:6.243 d:tmr-CUL_HM_procQs(N/A)

Hatt jemand eine Idee, wie ich diesen Timer besser eingrenzen kann?

[frank]

die funktion etscheint bei mir auch ständig, aber fälschlicher weise. nutze das logfile attr. da siehst du dann die verursacher. CUL_HM_procQs habe ich jetzt auf die whitelist gesetzt.