Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

[KernSani]

Hi Tommy,

ich hab mir die entsprechende Stelle angesehen. Eigentlich sollte es m.E. garnicht möglich sein, dass die Variable an der Stelle undefiniert ist, ich fange es jetzt aber trotzdem ab. Kommt demnächst im Update.

Etwas anderes ist mir aufgefallen (hat nichts direkt mit Freezemon zu tun) :

Code Auswählen Erweitern

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)
Ich vermute du rufst hier reduceLog auf - verwendest du noch die alte Variante? Mit der non-blocking Variante reduceLogNbl sollte dir dieser Freeze erspart bleiben...

Grüße,

Oli

[Tommy82]

Hi Tommy,

ich hab mir die entsprechende Stelle angesehen. Eigentlich sollte es m.E. garnicht möglich sein, dass die Variable an der Stelle undefiniert ist, ich fange es jetzt aber trotzdem ab. Kommt demnächst im Update.

Etwas anderes ist mir aufgefallen (hat nichts direkt mit Freezemon zu tun) :

Code Auswählen Erweitern

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)
Ich vermute du rufst hier reduceLog auf - verwendest du noch die alte Variante? Mit der non-blocking Variante reduceLogNbl sollte dir dieser Freeze erspart bleiben...

Grüße,

Oli

Hi, danke, auch für den Hinweis, ich nutzte zwar kein reduceLog, aber deleteOldDays und das in DbLog_aufrauumen, hab das dann mal auf deleteOldDaysNbl geändert, damit sollte es ja dann besser laufen.  Ich hab aber heute z.b. noch mehr solcher meldungen im Log.

Code Auswählen Erweitern

2019.01.12 01:30:12.170 1: [Freezemon] myFreezemon: possible freeze starting at 01:30:07, delay is 5.168 possibly caused by: tmr-FBAHAHTTP_Poll(FB6590) tmr-HTTPMOD_GetUpdate(N/A) tmr-HTTPMOD_GetUpdate(N/A)
2019.01.12 01:30:15.123 1: [Freezemon] myFreezemon: possible freeze starting at 01:30:14, delay is 1.121 possibly caused by: tmr-HMLAN_KeepAliveCheck(N/A)
2019.01.12 01:35:09.209 1: [Freezemon] myFreezemon: possible freeze starting at 01:35:08, delay is 1.207 possibly caused by: no bad guy found :-(
2019.01.12 01:40:09.082 1: [Freezemon] myFreezemon: possible freeze starting at 01:40:08, delay is 1.081 possibly caused by: tmr-HttpUtils_Err(N/A)
2019.01.12 05:30:01.124 1: [Freezemon] myFreezemon: possible freeze starting at 05:30:00, delay is 1.122 possibly caused by: tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-at_Exec(Weihnachtsdeko_an_am)
2019.01.12 08:30:01.175 1: [Freezemon] myFreezemon: possible freeze starting at 08:30:00, delay is 1.173 possibly caused by: tmr-at_Exec(Weihnachtsdeko_aus_am)
2019.01.12 08:50:10.013 1: [Freezemon] myFreezemon: possible freeze starting at 08:50:09, delay is 1.01 possibly caused by: tmr-PRESENCE_StartLocalScan(GalaxyS8)
2019.01.12 08:54:55.705 1: [Freezemon] myFreezemon: possible freeze starting at 08:54:41, delay is 14.703 possibly caused by: tmr-Calendar_Wakeup(AbfallA)
2019.01.12 09:10:10.089 1: [Freezemon] myFreezemon: possible freeze starting at 09:10:09, delay is 1.086 possibly caused by: no bad guy found :-(
2019.01.12 09:15:39.115 1: [Freezemon] myFreezemon: possible freeze starting at 09:15:38, delay is 1.113 possibly caused by: tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server)
2019.01.12 10:40:10.093 1: [Freezemon] myFreezemon: possible freeze starting at 10:40:09, delay is 1.091 possibly caused by: tmr-HTTPMOD_GetUpdate(N/A)
2019.01.12 10:45:10.546 1: [Freezemon] myFreezemon: possible freeze starting at 10:45:09, delay is 1.545 possibly caused by: tmr-HTTPMOD_GetUpdate(N/A)
2019.01.12 10:55:10.422 1: [Freezemon] myFreezemon: possible freeze starting at 10:55:09, delay is 1.42 possibly caused by: tmr-HTTPMOD_GetUpdate(N/A)
2019.01.12 10:57:07.169 1: [Freezemon] myFreezemon: possible freeze starting at 10:57:03, delay is 4.167 possibly caused by: tmr-BlinkCamera_PollInfo(Kameras)





[KernSani]

Ja, jetzt fängt die Arbeit an...
Im Prinzip musst (solltest) du jetzt die Freezes einzeln durchgehen und analysieren, warum die so lange brauchen. Am besten noch Attribut fm_logFile setzen, dann werden Logs erzeugt, die dir genau zeigen, was in deinem System abläuft.
Bei manchen kann man nichts machen (dann können sie auch auch auf die blacklist gepackt werden), bei anderen kann man häufig was optimieren (z.B. event-on-... Attribute setzen, logging einschränken etc...)   

[Mave]

Moin KernSani,

vielen Dank für Dein Modul.

Wie kann ich die Freezes von tmr-HttpUtils_Err(N/A) verhindern?

Vielen Dank.

Grüße Mave

[KernSani]

Moin KernSani,

vielen Dank für Dein Modul.

Wie kann ich die Freezes von tmr-HttpUtils_Err(N/A) verhindern?

Vielen Dank.

Grüße Mave

HttpUtils_Err ist meistens nicht der eigentliche Verursacher. Schau mal in die freeze-Logs, ob da ein bestimmtes Midul auffällig ist


Kurz, weil mobil

[Tommy82]

Ja, jetzt fängt die Arbeit an...
Im Prinzip musst (solltest) du jetzt die Freezes einzeln durchgehen und analysieren, warum die so lange brauchen. Am besten noch Attribut fm_logFile setzen, dann werden Logs erzeugt, die dir genau zeigen, was in deinem System abläuft.
Bei manchen kann man nichts machen (dann können sie auch auch auf die blacklist gepackt werden), bei anderen kann man häufig was optimieren (z.B. event-on-... Attribute setzen, logging einschränken etc...)

Hi,
ich hab mal das Attribut fm_logFile gesetzt, mal sehen was jetzt passiert:-)

Im anschluss daran hatte ich aber dann diese Meldung im Log

Code Auswählen Erweitern

2019.01.13 12:34:05.586 1: PERL WARNING: Use of uninitialized value $path in pattern match (m//) at ./FHEM/98_freezemon.pm line 696.
2019.01.13 12:34:05.587 1: stacktrace:
2019.01.13 12:34:05.587 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (696)
2019.01.13 12:34:05.587 1:     main::freezemon_Attr                called by fhem.pl (3610)
2019.01.13 12:34:05.588 1:     main::CallFn                        called by fhem.pl (2881)
2019.01.13 12:34:05.588 1:     main::CommandAttr                   called by fhem.pl (1218)
2019.01.13 12:34:05.588 1:     main::AnalyzeCommand                called by ./FHEM/01_FHEMWEB.pm (2600)
2019.01.13 12:34:05.589 1:     main::FW_fC                         called by ./FHEM/01_FHEMWEB.pm (877)
2019.01.13 12:34:05.589 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (548)
2019.01.13 12:34:05.589 1:     main::FW_Read                       called by fhem.pl (3610)
2019.01.13 12:34:05.589 1:     main::CallFn                        called by fhem.pl (727)
2019.01.13 12:34:05.590 1: PERL WARNING: Use of uninitialized value $path in opendir at ./FHEM/98_freezemon.pm line 697.
2019.01.13 12:34:05.590 1: stacktrace:
2019.01.13 12:34:05.590 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (697)
2019.01.13 12:34:05.591 1:     main::freezemon_Attr                called by fhem.pl (3610)
2019.01.13 12:34:05.591 1:     main::CallFn                        called by fhem.pl (2881)
2019.01.13 12:34:05.591 1:     main::CommandAttr                   called by fhem.pl (1218)
2019.01.13 12:34:05.591 1:     main::AnalyzeCommand                called by ./FHEM/01_FHEMWEB.pm (2600)
2019.01.13 12:34:05.592 1:     main::FW_fC                         called by ./FHEM/01_FHEMWEB.pm (877)
2019.01.13 12:34:05.592 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (548)
2019.01.13 12:34:05.592 1:     main::FW_Read                       called by fhem.pl (3610)
2019.01.13 12:34:05.592 1:     main::CallFn                        called by fhem.pl (727)
2019.01.13 12:34:05.593 1: PERL WARNING: Use of uninitialized value $path in concatenation (.) or string at ./FHEM/98_freezemon.pm line 702.
2019.01.13 12:34:05.593 1: stacktrace:
2019.01.13 12:34:05.594 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (702)
2019.01.13 12:34:05.594 1:     main::freezemon_Attr                called by fhem.pl (3610)
2019.01.13 12:34:05.594 1:     main::CallFn                        called by fhem.pl (2881)
2019.01.13 12:34:05.594 1:     main::CommandAttr                   called by fhem.pl (1218)
2019.01.13 12:34:05.595 1:     main::AnalyzeCommand                called by ./FHEM/01_FHEMWEB.pm (2600)
2019.01.13 12:34:05.595 1:     main::FW_fC                         called by ./FHEM/01_FHEMWEB.pm (877)
2019.01.13 12:34:05.595 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (548)
2019.01.13 12:34:05.595 1:     main::FW_Read                       called by fhem.pl (3610)
2019.01.13 12:34:05.596 1:     main::CallFn                        called by fhem.pl (727)

[Mave]

HttpUtils_Err ist meistens nicht der eigentliche Verursacher. Schau mal in die freeze-Logs, ob da ein bestimmtes Midul auffällig ist


Kurz, weil mobil

Okay, schau ich gleich Mal nach.

Kannst Du Dir erklären, wieso ich relativ regelmäßig diese Devices im Log habe: tmr-HUEDevice_GetUpdate

Vielen Dank.

[Tommy82]

Okay, schau ich gleich Mal nach.

Kannst Du Dir erklären, wieso ich relativ regelmäßig diese Devices im Log habe: tmr-HUEDevice_GetUpdate

Vielen Dank.

Das Device habe ich auch öfters drin

Hi,
ich hab mal das Attribut fm_logFile gesetzt, mal sehen was jetzt passiert:-)

Das Log ist ja releativ schnell recht groß, wie geh ich dann am besten vor?

[KernSani]

Das Log ist ja releativ schnell recht groß, wie geh ich dann am besten vor?

mit

Code Auswählen Erweitern

attr <device> fm_logFile ./log/freeze-%Y%m%d-%H%M%S.log
bekommst du ein Logfile pro Freeze - finde ich persönlich am angenehmsten. Mit fm_logKeep kannst du dann noch sagen wieviele Logfiles es maximal geben soll (freezemon löscht dann die ältesten)

HUEDevice_GetUpdate ist wahrscheinlich so ein Dingens, das im Sekundentakt läuft o.ä. und daher quasi immer als potentieller Verursacher erkannt wird. Am Besten auf fm_whitelistSub setzen (siehe Doku).

[Tommy82]

Ok versuch ich mal.
Ich habe aber immer noch Perl Warnungen im Log

Code Auswählen Erweitern

2019.01.15 06:46:52.352 1: PERL WARNING: Use of uninitialized value $FW_ME in concatenation (.) or string at ./FHEM/98_freezemon.pm line 1221.
2019.01.15 06:46:52.353 1: stacktrace:
2019.01.15 06:46:52.353 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (1221)
2019.01.15 06:46:52.354 1:     main::freezemon_logLink             called by ./FHEM/98_freezemon.pm (427)
2019.01.15 06:46:52.354 1:     main::freezemon_ProcessTimer        called by fhem.pl (3153)
2019.01.15 06:46:52.354 1:     main::HandleTimeout                 called by fhem.pl (650)

Code Auswählen Erweitern

2019.01.15 06:46:56.170 1: PERL WARNING: Use of uninitialized value $shortarg in concatenation (.) or string at ./FHEM/98_freezemon.pm line 854.
2019.01.15 06:46:56.173 1: stacktrace:
2019.01.15 06:46:56.174 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (854)
2019.01.15 06:46:56.175 1:     main::freezemon_apptime             called by ./FHEM/98_freezemon.pm (538)
2019.01.15 06:46:56.175 1:     main::freezemon_ProcessTimer        called by fhem.pl (3153)
2019.01.15 06:46:56.176 1:     main::HandleTimeout                 called by fhem.pl (650)

[KernSani]

Guten Mirgen,

@Tommy: Die erste Meldung habe ich gestern gefixt, aber noch nicht eingecheckt. Die zweite schaue ich mir heute abend nochmal an.


Kurz, weil mobil

[KernSani]

Ich kann die zweite Warnung logisch immernoch nicht nachvollziehen, habe aber nochmal etwas ein bisschen umgebaut (was das Ganze auch einen winzigen Ticken effizienter macht) und gemeinsam mit dem Fix für FW_ME eingecheckt. Morgen im Update verfügbar.

[Tommy82]

Hi,
super danke.

Jetzt aber mal noch eine grundsätzliche Frage zur Fehler suche.

Hab jetzt heute nacht diese Log meldung von freezemon

Code Auswählen Erweitern

=========================================================
[Freezemon] myFreezemon: possible freeze starting at 05:30:00, delay is 1.148 possibly caused by: tmr-at_Exec(Weihnachtsdeko_an_am)
2019.01.16 05:30:00.002 5: exec at command Weihnachtsdeko_an_am
2019.01.16 05:30:00.002 5: Cmd: >set Steckdose_aussen on<
2019.01.16 05:30:00.003 3: Cul433 IT_set: Steckdose_aussen on
2019.01.16 05:30:00.008 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:00.008 4: DbLog myDbLog -> ###              start of new Logcycle                       ###
2019.01.16 05:30:00.008 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:00.008 4: DbLog myDbLog -> number of events received: 1 for device: Steckdose_aussen
2019.01.16 05:30:00.009 4: DbLog myDbLog -> check Device: Steckdose_aussen , Event: state: on
2019.01.16 05:30:00.009 5: DbLog myDbLog -> parsed Event: Steckdose_aussen , Event: state: on
2019.01.16 05:30:00.010 4: DbLog myDbLog -> added event - Timestamp: 2019-01-16 05:30:00, Device: Steckdose_aussen, Type: IT, Event: state: on, Reading: state, Value: on, Unit:
2019.01.16 05:30:00.010 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:00.010 4: DbLog myDbLog -> ###         New database processing cycle - synchronous      ###
2019.01.16 05:30:00.010 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:00.010 4: DbLog myDbLog -> DbLogType is: Current/History
2019.01.16 05:30:00.010 4: DbLog myDbLog -> AutoCommit mode: ON, Transaction mode: ON
2019.01.16 05:30:00.020 5: DbLog myDbLog -> Primary Key used in /media/Platte/home/fhem.db.history: none
2019.01.16 05:30:00.021 5: DbLog myDbLog -> Primary Key used in /media/Platte/home/fhem.db.current: none
2019.01.16 05:30:00.021 4: DbLog myDbLog -> processing event Timestamp: 2019-01-16 05:30:00, Device: Steckdose_aussen, Type: IT, Event: state: on, Reading: state, Value: on, Unit:
2019.01.16 05:30:00.024 4: DbLog myDbLog -> 1 of 1 events inserted into table history
2019.01.16 05:30:00.029 4: DbLog myDbLog -> insert table history committed by autocommit
2019.01.16 05:30:00.034 4: DbLog myDbLog -> 1 of 1 events updated in table current
2019.01.16 05:30:00.037 4: DbLog myDbLog -> insert / update table current committed by autocommit
2019.01.16 05:30:00.038 5: DbLog myDbLog -> DbLog_Push Returncode: 0
2019.01.16 05:30:00.040 5: rd_Batterie: not on any display, ignoring notify
2019.01.16 05:30:00.040 5: rd_Batterie_Level: not on any display, ignoring notify
2019.01.16 05:30:00.046 5: End notify loop for Steckdose_aussen
2019.01.16 05:30:00.046 5: Cul433 IT_set: Type=CUL Protocol=V3
2019.01.16 05:30:00.047 5: SW: isr12
2019.01.16 05:30:00.049 5: CUL/RAW (ReadAnswer): 12

2019.01.16 05:30:00.054 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:00.054 4: DbLog myDbLog -> ###              start of new Logcycle                       ###
2019.01.16 05:30:00.054 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:00.054 4: DbLog myDbLog -> number of events received: 1 for device: Cul433
2019.01.16 05:30:00.054 4: DbLog myDbLog -> check Device: Cul433 , Event: raw: 12
2019.01.16 05:30:00.055 5: DbLog myDbLog -> parsed Event: Cul433 , Event: raw: 12
2019.01.16 05:30:00.055 4: DbLog myDbLog -> added event - Timestamp: 2019-01-16 05:30:00, Device: Cul433, Type: CUL, Event: raw: 12, Reading: raw, Value: 12, Unit:
2019.01.16 05:30:00.056 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:00.056 4: DbLog myDbLog -> ###         New database processing cycle - synchronous      ###
2019.01.16 05:30:00.056 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:00.056 4: DbLog myDbLog -> DbLogType is: Current/History
2019.01.16 05:30:00.056 4: DbLog myDbLog -> AutoCommit mode: ON, Transaction mode: ON
2019.01.16 05:30:00.066 5: DbLog myDbLog -> Primary Key used in /media/Platte/home/fhem.db.history: none
2019.01.16 05:30:00.066 5: DbLog myDbLog -> Primary Key used in /media/Platte/home/fhem.db.current: none
2019.01.16 05:30:00.066 4: DbLog myDbLog -> processing event Timestamp: 2019-01-16 05:30:00, Device: Cul433, Type: CUL, Event: raw: 12, Reading: raw, Value: 12, Unit:
2019.01.16 05:30:00.069 4: DbLog myDbLog -> 1 of 1 events inserted into table history
2019.01.16 05:30:00.078 4: DbLog myDbLog -> insert table history committed by autocommit
2019.01.16 05:30:00.084 4: DbLog myDbLog -> 1 of 1 events updated in table current
2019.01.16 05:30:00.087 4: DbLog myDbLog -> insert / update table current committed by autocommit
2019.01.16 05:30:00.088 5: DbLog myDbLog -> DbLog_Push Returncode: 0
2019.01.16 05:30:00.090 5: rd_Batterie: not on any display, ignoring notify
2019.01.16 05:30:00.090 5: rd_Batterie_Level: not on any display, ignoring notify
2019.01.16 05:30:00.094 5: End notify loop for Cul433
2019.01.16 05:30:00.094 4: IT set ITrepetition: isr12 for Cul433
2019.01.16 05:30:00.094 5: SW: is00111100110101010110011111010011
2019.01.16 05:30:01.040 5: CUL/RAW (ReadAnswer): is00111100110101010110011111010011

2019.01.16 05:30:01.047 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:01.048 4: DbLog myDbLog -> ###              start of new Logcycle                       ###
2019.01.16 05:30:01.048 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:01.048 4: DbLog myDbLog -> number of events received: 1 for device: Cul433
2019.01.16 05:30:01.048 4: DbLog myDbLog -> check Device: Cul433 , Event: raw: is00111100110101010110011111010011
2019.01.16 05:30:01.049 5: DbLog myDbLog -> parsed Event: Cul433 , Event: raw: is00111100110101010110011111010011
2019.01.16 05:30:01.049 4: DbLog myDbLog -> added event - Timestamp: 2019-01-16 05:30:01, Device: Cul433, Type: CUL, Event: raw: is00111100110101010110011111010011, Reading: raw, Value: is00111100110101010110011111010011, Unit:
2019.01.16 05:30:01.050 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:01.050 4: DbLog myDbLog -> ###         New database processing cycle - synchronous      ###
2019.01.16 05:30:01.050 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:01.050 4: DbLog myDbLog -> DbLogType is: Current/History
2019.01.16 05:30:01.050 4: DbLog myDbLog -> AutoCommit mode: ON, Transaction mode: ON
2019.01.16 05:30:01.065 5: DbLog myDbLog -> Primary Key used in /media/Platte/home/fhem.db.history: none
2019.01.16 05:30:01.065 5: DbLog myDbLog -> Primary Key used in /media/Platte/home/fhem.db.current: none
2019.01.16 05:30:01.066 4: DbLog myDbLog -> processing event Timestamp: 2019-01-16 05:30:01, Device: Cul433, Type: CUL, Event: raw: is00111100110101010110011111010011, Reading: raw, Value: is00111100110101010110011111010011, Unit:
2019.01.16 05:30:01.070 4: DbLog myDbLog -> 1 of 1 events inserted into table history
2019.01.16 05:30:01.075 4: DbLog myDbLog -> insert table history committed by autocommit
2019.01.16 05:30:01.081 4: DbLog myDbLog -> 1 of 1 events updated in table current
2019.01.16 05:30:01.084 4: DbLog myDbLog -> insert / update table current committed by autocommit
2019.01.16 05:30:01.084 5: DbLog myDbLog -> DbLog_Push Returncode: 0
2019.01.16 05:30:01.087 5: rd_Batterie: not on any display, ignoring notify
2019.01.16 05:30:01.087 5: rd_Batterie_Level: not on any display, ignoring notify
2019.01.16 05:30:01.090 5: End notify loop for Cul433
2019.01.16 05:30:01.090 5: IT_Set: GetFn(raw): message = is00111100110101010110011111010011 Antwort =   raw => is00111100110101010110011111010011
2019.01.16 05:30:01.091 4: ITSet: Answer from Cul433:   raw => is00111100110101010110011111010011
2019.01.16 05:30:01.091 5: SW: isr6
2019.01.16 05:30:01.093 5: CUL/RAW (ReadAnswer): 6

2019.01.16 05:30:01.097 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:01.098 4: DbLog myDbLog -> ###              start of new Logcycle                       ###
2019.01.16 05:30:01.098 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:01.098 4: DbLog myDbLog -> number of events received: 1 for device: Cul433
2019.01.16 05:30:01.098 4: DbLog myDbLog -> check Device: Cul433 , Event: raw: 6
2019.01.16 05:30:01.098 5: DbLog myDbLog -> parsed Event: Cul433 , Event: raw: 6
2019.01.16 05:30:01.099 4: DbLog myDbLog -> added event - Timestamp: 2019-01-16 05:30:01, Device: Cul433, Type: CUL, Event: raw: 6, Reading: raw, Value: 6, Unit:
2019.01.16 05:30:01.099 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:01.099 4: DbLog myDbLog -> ###         New database processing cycle - synchronous      ###
2019.01.16 05:30:01.099 4: DbLog myDbLog -> ################################################################
2019.01.16 05:30:01.099 4: DbLog myDbLog -> DbLogType is: Current/History
2019.01.16 05:30:01.099 4: DbLog myDbLog -> AutoCommit mode: ON, Transaction mode: ON
2019.01.16 05:30:01.110 5: DbLog myDbLog -> Primary Key used in /media/Platte/home/fhem.db.history: none
2019.01.16 05:30:01.110 5: DbLog myDbLog -> Primary Key used in /media/Platte/home/fhem.db.current: none
2019.01.16 05:30:01.110 4: DbLog myDbLog -> processing event Timestamp: 2019-01-16 05:30:01, Device: Cul433, Type: CUL, Event: raw: 6, Reading: raw, Value: 6, Unit:
2019.01.16 05:30:01.115 4: DbLog myDbLog -> 1 of 1 events inserted into table history
2019.01.16 05:30:01.118 4: DbLog myDbLog -> insert table history committed by autocommit
2019.01.16 05:30:01.125 4: DbLog myDbLog -> 1 of 1 events updated in table current
2019.01.16 05:30:01.132 4: DbLog myDbLog -> insert / update table current committed by autocommit
2019.01.16 05:30:01.133 5: DbLog myDbLog -> DbLog_Push Returncode: 0
2019.01.16 05:30:01.138 5: rd_Batterie: not on any display, ignoring notify
2019.01.16 05:30:01.138 5: rd_Batterie_Level: not on any display, ignoring notify
2019.01.16 05:30:01.143 5: End notify loop for Cul433
2019.01.16 05:30:01.143 3: IT set ITrepetition back: isr6 for Cul433
2019.01.16 05:30:01.144 5: Cmd: >sleep 10<
2019.01.16 05:30:01.144 4: sleeping for 10
2019.01.16 05:30:01.145 5: redefine at command Weihnachtsdeko_an_am as *05:30:00 set Steckdose_aussen on; sleep 10;
set Steckdose_Weihnachten_Wohnzimmer on; sleep 10;
set Steckdose_Haustuer on; sleep 10;
set Steckdose_Kueche on
2019.01.16 05:30:01.149 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2019.01.16 05:30:01.149 ---------------------
[Freezemon] myFreezemon: possible freeze starting at 05:30:00, delay is 1.148 possibly caused by: tmr-at_Exec(Weihnachtsdeko_an_am)


Ein at was nachts ausgeführt wird, aber was muss/ kann ich da jetzt machne`?

Code Auswählen Erweitern

Internals:
   COMMAND    set Steckdose_aussen on; sleep 10;
set Steckdose_Weihnachten_Wohnzimmer on; sleep 10;
set Steckdose_Haustuer on; sleep 10;
set Steckdose_Kueche on
   DEF        *05:30:00 set Steckdose_aussen on; sleep 10;
set Steckdose_Weihnachten_Wohnzimmer on; sleep 10;
set Steckdose_Haustuer on; sleep 10;
set Steckdose_Kueche on
   NAME       Weihnachtsdeko_an_am
   NR         282
   PERIODIC   yes
   RELATIVE   no
   REP        -1
   STATE      Next: 05:30:00
   TIMESPEC   05:30:00
   TRIGGERTIME 1547699400
   TRIGGERTIME_FMT 2019-01-17 05:30:00
   TYPE       at
   READINGS:
     2019-01-16 05:30:01   state           Next: 05:30:00
Attributes:
   group      Info
   room       Zentral

[KernSani]

Hi Tommy,

was ich daraus lerne: Du hast immernoch die Weihnachtsdeko hängen?

Scherz beiseite. Der Freeze ist knapp über eine Sekunde, wenn das nicht all zu häufig auftritt kann man es ignorieren. Was ich aber sehe:
* Du loggst synchron - meistens ist asynchron die bessere Variante
* Du loggst in history und current - ist das notwendig?
* Du loggst deine Steckdose??
* Du loggst auch raw events?

Warum das dann eine Sekunde dauert kann ich dir leider nicht sagen, aber insgesamt gibt es da doch einige Punkte, das logging zu reduzieren und damit die Last ein bisschen zu verringern.

Grüße,

Oli

[Tommy82]

Hi Tommy,

was ich daraus lerne: Du hast immernoch die Weihnachtsdeko hängen?

Scherz beiseite. Der Freeze ist knapp über eine Sekunde, wenn das nicht all zu häufig auftritt kann man es ignorieren. Was ich aber sehe:
* Du loggst synchron - meistens ist asynchron die bessere Variante
* Du loggst in history und current - ist das notwendig?
* Du loggst deine Steckdose??
* Du loggst auch raw events?

Warum das dann eine Sekunde dauert kann ich dir leider nicht sagen, aber insgesamt gibt es da doch einige Punkte, das logging zu reduzieren und damit die Last ein bisschen zu verringern.

Grüße,

Oli

Hi Oli,
tjaja irgendwie ende Weihnachten doch nie:-)
Das tritt in diesem fall nur 4x am Tag auf, zumindest solange Weihnachten ist damit könnte ich leben.
Zei deinen anmerkungen zum Log hab ich dann doch ein paar Fragen.

* Du loggst synchron - meistens ist asynchron die bessere Variante

Ok hab ich verstanden und umgestellt

* Du loggst in history und current - ist das notwendig?

Was würdest du empfehlen? Nur History?

* Du loggst deine Steckdose??

Was ist daran falsch?#

* Du loggst auch raw events?

brauch man wahrscheinlich nicht, allerdings hab ich gerade auch keine richtige Ahnung wie ich das deaktiviere

Ich bin beeindruckt was du alles in so einem kleinen Log siehst:-)

Heute nacht hatte ich nochmal eine Meldung zu freezemon im LOg

Code Auswählen Erweitern

2019.01.17 02:04:23.575 1: [Freezemon] myFreezemon: possible freeze starting at 02:03:02, delay is 81.564 possibly caused by: tmr-MQTT2_SERVER_keepaliveChecker(MQTT2_FHEM_Server) tmr-ENIGMA2_GetStatus(VU_Ultimo) tmr-HMLAN_KeepAlive(N/A) tmr-at_Exec(at_fp_time) tmr-ENIGMA2_GetStatus(Uno_Schlafzimmer) tmr-FW_closeInactiveClients(N/A) tmr-BlinkCamera_PollInfo(Kameras) tmr-SYSMON_Update(sysmon) tmr-WOL_UpdateReadings(WHS_2011_ping) tmr-WOL_UpdateReadings(WinServer_ping) tmr-AMAD_checkDeviceState(Android_Tablett_Wohnzimmer) tmr-FBAHAHTTP_Poll(FB6590) tmr-HTTPMOD_GetUpdate(N/A) tmr-HTTPMOD_GetUpdate(N/A) tmr-HUEBridge_GetUpdate(HUE)
2019.01.17 02:04:25.353 1: PERL WARNING: Use of uninitialized value $a[1] in exists at ./FHEM/98_freezemon.pm line 336.
2019.01.17 02:04:25.354 1: stacktrace:
2019.01.17 02:04:25.355 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (336)
2019.01.17 02:04:25.355 1:     main::freezemon_ProcessTimer        called by fhem.pl (3200)
2019.01.17 02:04:25.356 1:     main::HandleTimeout                 called by fhem.pl (656)
2019.01.17 02:04:25.356 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_freezemon.pm line 346.
2019.01.17 02:04:25.357 1: stacktrace:
2019.01.17 02:04:25.357 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (346)
2019.01.17 02:04:25.357 1:     main::freezemon_ProcessTimer        called by fhem.pl (3200)
2019.01.17 02:04:25.358 1:     main::HandleTimeout                 called by fhem.pl (656)

Danke für deine Hilfe