[Gelöst] Freezes in exaktem Minutenabstand - Bitte um Hilfe bei der Fehlersuche

hauwech · 22 Januar 2019, 13:07:23

Die Sortierung nach count hatte ich verwendet, weil ich minütlich Hochzählende gesucht habe.

hauwech · 22 Januar 2019, 13:20:05

Der Alarm-notify braucht aber "nur" eine halbe Sekunde. Mich würde mehr der

WEB_127.0.0.1_33816                      FW_Notify                               21      489    1477.78     3.02     0.00     0.00 22.01. 09:52:35 HASH(WEB_127.0.0.1_33816); HASH(HG_WZ_HZ_WT_Weather)

mit 3 Sekunden average stören, aber delay ist da auch 0.00.
Am Alarm-notify könnte ich auch schlecht optimieren - der wird vom Modul zusammengebaut - außer weniger Devices reinzunehmen. Das ist aber nicht im Sinne meiner Alarmanlage.

Gruß Roland

sledge · 22 Januar 2019, 13:45:59

Zitat von: hauwech am 22 Januar 2019, 13:07:23
Die Sortierung nach count hatte ich verwendet, weil ich minütlich Hochzählende gesucht habe.

Du willst aber die minütlichen mit "Auswirkungen" - daher passt das schon - ich habe ganz ohne Parameter genommen.

Wenn Du mit apptime "frisch" anfängst, dann siehst Du die Minutenkandidaten bei denen mit delay ja ganz einfach - die zählen von 1,2,3,4,5 ganz langsam hoch - eben im Minutentakt. Die anderen interessieren Dich ja erstmal nicht.

Gruß,
Tom

frank · 22 Januar 2019, 15:36:37

Code Auswählen

3.02
das sind 3 milli sekunden, nicht sekunden.

delay ist die zeit, um die die ausführung der funktion verzögert wird. als kein freeze, sondern die auswirkung zb eines freezes.

hauwech · 22 Januar 2019, 16:34:07

Ahh, Milli Sekunden... das ist gut. "Delay" habe ich jetzt auch verstanden. Ich habe derzeit ein Brett vor'm Kopp, wahrscheinlich muß ich die Suche mal einen Tag pausieren, um wieder Platz für Logik zu machen.
Ich habe vorhin nach einem "apptime clean" nochmal im Minutentakt apptime aufgerufen. Da habe ich folgendes gesehen:

Code Auswählen


                name                                     function                                max    count      total  average   maxDly   avgDly TS Max call     param Max call
nach 1 Minute:   tmr-at_Exec                              HASH(0x519c910)                        127        1     127.95   127.95     2.90     2.90 22.01. 14:21:56 HASH(a_hmlan_internals)
nach 2 Minuten: tmr-at_Exec                              HASH(0x519c910)                        127        2     255.00   127.50     3.38     3.14 22.01. 14:21:56 HASH(a_hmlan_internals)
nach 3 Minuten: tmr-at_Exec                              HASH(0x519c910)                        127        3     361.18   120.39     3.38     2.60 22.01. 14:21:56 HASH(a_hmlan_internals)
nach 4 Minuten: tmr-at_Exec                              HASH(0x519c910)                        127        4     488.28   122.07     3.38     2.72 22.01. 14:21:56 HASH(a_hmlan_internals)
nach 5 Minuten: tmr-at_Exec                              HASH(0x519c910)                        127        5     612.21   122.44     3.38     2.70 22.01. 14:21:56 HASH(a_hmlan_internals)

Den Rest habe ich weggelassen, weil die Forensoftware bei zu langen Posts den Rest abschneidet, obwohl in der Beitrags-Vorschau alles ordentlich zu sehen ist.
Der Timestamp ist exakt gleich. Heißt das, daß apptime ein und denselben Aufruf 5 mal loggt?
a_hmlan_internals wurde um 14:21:56 aufgerufen, aber um 2.9/3.38 ms verzögert?
Wenn ich den groben Zeitraum im freezemon-log anschaue, sehe ich ich keinen freeze. Das scheint also nicht der Verursacher zu sein, obwohl das der einzige "at" ist, der ein Minutenintervall hat. Wenn ich das Intervall auf 00:02:00 stelle, kommen die freezes trotzdem alle 60 Sekunden.

Code Auswählen

2019-01-22_14:21:22 myFreezemon s:14:21:20 e:14:21:22 f:2.576 d:cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_35860) 
2019-01-22_14:21:22 myFreezemon freezeTime: 2.576
2019-01-22_14:21:22 myFreezemon fcDay: 887
2019-01-22_14:21:22 myFreezemon ftDay: 2330.614
2019-01-22_14:21:22 myFreezemon freezeDevice: cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_35860) 
=========================================================
[Freezemon] myFreezemon: possible freeze starting at 14:21:20, delay is 2.576 possibly caused by: cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_35860) 
2019.01.22 14:21:19.233 4: Connection accepted from telnetPort_127.0.0.1_35860
2019.01.22 14:21:19.235 5: Cmd: >jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector<
2019.01.22 14:21:19.369 5: YAMAHA_AVR (AV_Receiver) - set AV_Receiver ?
--- log skips     2.925 secs.
2019.01.22 14:21:22.294 5: ENIGMA2 VU: called function ENIGMA2_Set()
2019.01.22 14:21:22.296 5: ENIGMA2 VUDUO: called function ENIGMA2_Set()
2019.01.22 14:21:22.406 5: GEOFANCY geofancy: called function GEOFANCY_Set()
2019.01.22 14:21:22.424 5: myFreezemon Coming with command ?
2019.01.22 14:21:22.424 5: myFreezemon leaving with Unknown argument ?, choose one of active:noArg inactive:noArg clear:noArg
2019.01.22 14:21:22.501 1: [Freezemon] myFreezemon: Long running Command detected jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector:telnetPort - 3.266186 seconds
2019.01.22 14:21:22.576 1: [Freezemon] myFreezemon: Long function call detected ReadFn:telnetPort_127.0.0.1_35860 - 3.34117 seconds
2019.01.22 14:21:22.577 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2019.01.22 14:21:22.576 ---------------------
2019.01.22 14:21:22.577 5: [Freezemon] myFreezemon logging: cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_35860)  in all mode, because telnetPort_127.0.0.1_35860 is not ignored
[Freezemon] myFreezemon: possible freeze starting at 14:21:20, delay is 2.576 possibly caused by: cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_35860) 
2019-01-22_14:22:22 myFreezemon s:14:22:20 e:14:22:22 f:2.772 d:cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_36018) 
2019-01-22_14:22:22 myFreezemon freezeTime: 2.772
2019-01-22_14:22:22 myFreezemon fcDay: 888
2019-01-22_14:22:22 myFreezemon ftDay: 2333.386
2019-01-22_14:22:22 myFreezemon freezeDevice: cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_36018) 
=========================================================
[Freezemon] myFreezemon: possible freeze starting at 14:22:20, delay is 2.772 possibly caused by: cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_36018) 
2019.01.22 14:22:19.291 4: Connection accepted from telnetPort_127.0.0.1_36018
2019.01.22 14:22:19.293 5: Cmd: >jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector<
2019.01.22 14:22:19.427 5: YAMAHA_AVR (AV_Receiver) - set AV_Receiver ?
--- log skips     3.024 secs.
2019.01.22 14:22:22.451 5: ENIGMA2 VU: called function ENIGMA2_Set()
2019.01.22 14:22:22.453 5: ENIGMA2 VUDUO: called function ENIGMA2_Set()
2019.01.22 14:22:22.577 5: GEOFANCY geofancy: called function GEOFANCY_Set()
2019.01.22 14:22:22.595 5: myFreezemon Coming with command ?
2019.01.22 14:22:22.595 5: myFreezemon leaving with Unknown argument ?, choose one of active:noArg inactive:noArg clear:noArg
2019.01.22 14:22:22.686 1: [Freezemon] myFreezemon: Long running Command detected jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector:telnetPort - 3.393913 seconds
2019.01.22 14:22:22.771 1: [Freezemon] myFreezemon: Long function call detected ReadFn:telnetPort_127.0.0.1_36018 - 3.478458 seconds
2019.01.22 14:22:22.772 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2019.01.22 14:22:22.772 ---------------------
2019.01.22 14:22:22.772 5: [Freezemon] myFreezemon logging: cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_36018)  in all mode, because telnetPort_127.0.0.1_36018 is not ignored
[Freezemon] myFreezemon: possible freeze starting at 14:22:20, delay is 2.772 possibly caused by: cmd-jsonlist2 TYPE=.*:FILTER=state=..*:FILTER=model!=CCU-FHEM:FILTER=model!=ActionDetector(telnetPort) fn-ReadFn(telnetPort_127.0.0.1_36018)

Irgendwie stehe ich auf'm Schlauch und sehe den Wald nicht mehr $:-\$

Gruß Roland

KölnSolar · 22 Januar 2019, 16:55:00

Ich mag Dich zwar nicht noch mehr verwirren und vielleicht steht es auch schon erklärt auf den 2 Seiten vorher...
Wenn ich mir das freeze log ansehe, fallen Yamaha u. Enigma ins Auge. 2 devices, die vermutlich für den Status mit einem internaltimer von 60 arbeiten und wenn die OFF sind und der call blocking ist..... $:-\$

sledge · 22 Januar 2019, 16:55:56

Zitat von: KölnSolar am 22 Januar 2019, 16:55:00
Ich mag Dich zwar nicht noch mehr verwirren und vielleicht steht es auch schon erklärt auf den 2 Seiten vorher...
Wenn ich mir das freeze log ansehe, fallen Yamaha u. Enigma ins Auge. 2 devices, die vermutlich für den Status mit einem internaltimer von 60 arbeiten und wenn die OFF sind und der call blocking ist..... $:-\$

Womit wir bei meinem Beispiel von XBMC / Kodi weiter oben im Thread wären - ähnliche Situation.

hauwech · 22 Januar 2019, 17:24:16

Yamaha und Enigma waren mir auch schon aufgefallen, die hatte ich aber schon mal eine Zeit lang disabled, ohne daß sich an den freezes was ändert.
Deswegen hatte ich weiter oben schon mal die Frage aufgeworfen, ob das Attribut "disable=1" möglicherweise nicht ausreicht, sondern vielleicht einen fhem Neustart braucht, oder das device tatsächlich gelöscht werden muß, um es vollständig kalt zu stellen. Wahrscheinlich ist das disable-handling auch modulabhängig.

Gruß Roland

KölnSolar · 22 Januar 2019, 18:13:38

ZitatWahrscheinlich ist das disable-handling auch modulabhängig.

Genau und deshalb würd ich mich nicht drauf verlassen. Lieber einfach mal ein delete(ohne save) und schlimmstenfalls machst Du nach ein Paar Minuten einen shutdown/restart und sie sind wieder da.

Wernieman · 22 Januar 2019, 18:51:56

Oder vorher mal die Config wegsichern ... (wobei Backup immer gut ist)

Otto123 · 22 Januar 2019, 19:01:15

Zitat von: Wernieman am 22 Januar 2019, 18:51:56
Oder vorher mal die Config wegsichern ... (wobei Backup immer gut ist)

Ich wiederhole mich gern, FHEM sichert beim save automatisch die alte config weg! Vorausgesetzt das letzte Update ist nicht älter als 1,5 Jahre

Trotzdem ist backup immer gut!

Wernieman · 22 Januar 2019, 20:07:46

Ich bin Konservativ ... im Zweifelsfalle lieber ein Backup zu viel als zu wenig

(wobei .. kann man Backups zu viel haben ;o) )

hauwech · 25 Januar 2019, 11:15:54

Ich taste mich langsam ran. Ich habe jetzt systematisch Räume oder Gruppen gelöscht und das Log beobachtet. Heute hatte ich den ersten Treffer.
Was habe ich gemacht:
- fhem Backup
- sicherheitshalber noch rsync von /opt/fhem auf das NAS-Spiegelverzeichnis aktualisiert
- fhem update auf den neuesten Stand (incl. fhem-Neustart)
- alle readingsGroups gelöscht (die haben bei mir alle den Präfix "rg_")
Vorher hatte ich alle 60 Sekunden 3 freezes im Log, nach dem Löschen der readingsGroups kommt nur noch 1 freeze.
Jetzt kommt der Knüller...:
Nach dem shutdown/restart von fhem sind die readingsGroups wieder da, aber es kommt trotzdem nur noch 1 freeze...
Nicht, daß ich mich nicht freue, aber ich würde das Verhalten auch gern verstehen. Ist es möglich, daß die mit dem fhem-update neu hinzugekommene UUID für jedes device an dieser Stelle etwas bewirkt? Ich habe aber nicht beachtet, ob die readingsGroups vor dem Löschen auch schon eine UUID hatten.

Gruß Roland

Otto123 · 25 Januar 2019, 11:54:17

Hallo Roland,
sag niemals nie

- aber die UUID ist nur eine Nummer im Device, die wird erzeugt gesetzt und fertig. Kann ich mir nicht vorstellen.

Im Update kann aber was anderes gewesen sein.

Gruß Otto

hauwech · 25 Januar 2019, 12:42:48

Hi Otto,
ich kann mir eigentlich auch nicht vorstellen, daß sowas an der UUID hängt, aber wenn man tagelang sucht, ohne eine vernünftige Erklärung zu finden, kommt man auf die komischsten Gedanken.
Ich frage mich nach dem Verlauf jetzt zum Beispiel: Was haben die readingGroups mit "telnetPort_127.0.0.1_xxxxx" zu tun? Wenn ich die vor dem fhem-update gelöscht hätte, wüßte ich wenigstens, ob's mit dem update zu tun hat. Aber Backup zurückspielen und nochmal probieren - und das unerklärliche Ausbleiben der freezes möglicherweise wieder einzufangen - mache ich auch nicht.

Gruß Roland