Fhem stockt immer wieder.

Caleus · 12 Januar 2019, 12:33:52

Hey Leute

also ich habe mal wieder eine frage an Euch. Ich habe leider das Problem, das mein Fhem immer wieder Aussetzer hat also in Form von Freez, habe nun mal "perfmon" und dann "apptime" laufen lassen, mir sind da erst mal, wie auf dem Bild zu sehen sind, ein Paar Einträge mit sehr Hoher ms ins Auge gesprungen, meine frage nun an Euch was kann ich machen, um das zu beheben??
Die SD-Karte hatte ich heute schon mal ausgetauscht gegen eine neue und Größere das brachte aber kein Erfolg.

Gruß Caleus

KölnSolar · 12 Januar 2019, 12:50:52

Du siehst nur ein Symptom, nicht die Ursache. Versuch es mal mit freezemon.

KernSani · 12 Januar 2019, 12:53:47

Hallo,

der Screenshot ist ein bisschen schlecht zu lesen, besser den Output in code tags posten. Statt perfmon/apptime kannst du auch mal freezemon probieren.

Kann es sein, dass deine Logfiles einfach zu groß sind? Entweder weil sie einen sehr langen Zeitraum beinhalten oder weil du einfach zu viel loggst (Stichwort event-on-change-reading)?

Kurz, weil mobil

Caleus · 12 Januar 2019, 13:04:22

Hey danke schon mal

Also so sieht nach kurzer zeit das Freezemon aus:

Code Auswählen

1 - 2019-01-12: s:12:53:09 e:12:53:14 f:5.022 d:tmr-FW_closeInactiveClients(N/A) tmr-Twilight_Midnight(myTwilight_Midnight) tmr-perfmon_ProcessTimer(N/A)
1 - 2019-01-12: s:12:58:23 e:12:58:34 f:11.041 d:no bad guy found :-(
1 - 2019-01-12: s:12:58:53 e:12:58:59 f:6.271 d:tmr-perfmon_ProcessTimer(N/A) 
1 - 2019-01-12: s:13:00:04 e:13:00:14 f:10.588 d:tmr-perfmon_ProcessTimer(N/A)

und log´s sind ja schon eigentlich alle "event-on-change-reading".

KernSani · 12 Januar 2019, 13:38:42

Perfmon bitte ausschalten wenn freezemon aktiv ist. Sonst kommt alles doppelt

Kurz, weil mobil

Caleus · 12 Januar 2019, 14:45:43

Ja ist jetzt aus, aber leider sind es immer noch recht hohe ms die im Log stehen.

Code Auswählen

1 - 2019-01-12: s:13:14:00 e:13:14:01 f:1.684 d:tmr-perfmon_ProcessTimer(N/A) 
1 - 2019-01-12: s:13:14:35 e:13:14:36 f:1.554 d:tmr-perfmon_ProcessTimer(N/A) 
1 - 2019-01-12: s:13:18:46 e:13:18:50 f:4.603 d:tmr-perfmon_ProcessTimer(N/A) tmr-Weather_GetUpdate(MyWeather) tmr-Shelly_status(Bad.Decke.Licht) 
1 - 2019-01-12: s:13:21:51 e:13:21:55 f:4.728 d:tmr-perfmon_ProcessTimer(N/A) tmr-Weather_GetUpdate(MyWeather) tmr-Shelly_status(Bad.Decke.Licht) 
1 - 2019-01-12: s:13:22:14 e:13:22:15 f:1.569 d:tmr-perfmon_ProcessTimer(N/A) 
1 - 2019-01-12: s:13:22:56 e:13:23:00 f:4.787 d:tmr-perfmon_ProcessTimer(N/A) tmr-Weather_GetUpdate(MyWeather) tmr-PRESENCE_StartLocalScan(Patrick) tmr-Shelly_status(Bad.Decke.Licht) tmr-PRESENCE_StartLocalScan(NalaBT) 
1 - 2019-01-12: s:13:27:40 e:13:27:44 f:4.574 d:tmr-perfmon_ProcessTimer(N/A) 
1 - 2019-01-12: s:13:29:27 e:13:29:31 f:4.8 d:tmr-perfmon_ProcessTimer(N/A) tmr-PRESENCE_StartLocalScan(PatrickBT) 
1 - 2019-01-12: s:13:33:02 e:13:33:06 f:4.303 d:tmr-perfmon_ProcessTimer(N/A) tmr-Weather_GetUpdate(MyWeather) tmr-Shelly_status(Bad.Decke.Licht) tmr-PRESENCE_StartLocalScan(Patrick) 
1 - 2019-01-12: s:13:37:03 e:13:37:04 f:1.94 d:tmr-perfmon_ProcessTimer(N/A) tmr-SYSMON_Update(sysmon) 
1 - 2019-01-12: s:13:40:07 e:13:40:11 f:4.664 d:tmr-perfmon_ProcessTimer(N/A) tmr-Weather_GetUpdate(MyWeather) tmr-Shelly_status(Bad.Decke.Licht) tmr-PRESENCE_StartLocalScan(Larissa) 
1 - 2019-01-12: s:13:47:12 e:13:47:14 f:2.872 d:tmr-perfmon_ProcessTimer(N/A) tmr-CometBlueBTLE::StateRequestTimer(Wohnzimmer) tmr-Weather_GetUpdate(MyWeather)
1 - 2019-01-12: s:13:53:58 e:13:54:03 f:5.285 d:tmr-Weather_GetUpdate(MyWeather) tmr-FRITZBOX_Readout_Start(N/A) 
1 - 2019-01-12: s:14:02:39 e:14:02:44 f:5.02 d:tmr-PRESENCE_StartLocalScan(PatrickBT) tmr-PRESENCE_StartLocalScan(Nala) tmr-Twilight_Midnight(myTwilight_Midnight) 
1 - 2019-01-12: s:14:08:37 e:14:08:38 f:1.239 d:tmr-PRESENCE_StartLocalScan(NalaBT) 
1 - 2019-01-12: s:14:10:23 e:14:10:27 f:4.661 d:tmr-PRESENCE_StartLocalScan(NalaBT) 
1 - 2019-01-12: s:14:13:49 e:14:13:52 f:3.359 d:tmr-SIGNALduino_KeepAlive(MYSDUINO) tmr-PRESENCE_StartLocalScan(LarissaBT) 
1 - 2019-01-12: s:14:21:27 e:14:21:32 f:5.179 d:tmr-PRESENCE_StartLocalScan(LarissaBT) 
1 - 2019-01-12: s:14:29:13 e:14:29:17 f:4.125 d:no bad guy found :-(
1 - 2019-01-12: s:14:36:48 e:14:36:52 f:4.084 d:no bad guy found :-(

Caleus

KernSani · 12 Januar 2019, 15:01:33

Der Perfmon läuft immernoch. Du musst die Datei umbenennen (so dass sie nicht mit 99 anfängt) oder aus /FHEM entfernen und einen shutdown restart machen, sonst wird perfmon immer wieder geladen

Kurz, weil mobil

Caleus · 12 Januar 2019, 15:03:16

Ich hatte sie gelöscht und ein "Shutdown restart" gemacht.

KernSani · 12 Januar 2019, 15:15:48

Das muss beim Löschen was shief gegangen sein, bitte überprüfe das nochmal. Die Einträge zeigen eindeutig, dass perfmon noch läuft:

Code Auswählen

perfmon_ProcessTimer(N/A)

KernSani · 12 Januar 2019, 15:20:05

und schonmal auf die Schnelle: Dein MyWeather device aktualisiert sich alle 3 Minuten... das ist ein bisschen arg häufig, zudem dauert es recht lange... hast du in global das Attribut dnsServer gesetzt?

Caleus · 12 Januar 2019, 15:48:27

MyWeather ist/war Yahoo und hatte ich vorhin gelöscht, und nein der dnsServer ist im Global nicht gesetzt.

Caleus

KernSani · 12 Januar 2019, 16:02:01

dnsServer zu setzen sorgt dafür, dass DNS-Aufrufe non-blocking sind, daher würde ich das empfehlen. Ist der Perfmon jetzt weg? Wie sieht das log jetzt aus?

Caleus · 12 Januar 2019, 16:24:21

ja scheint weg zu sein. auf was sollte ich denn dnsServer setzen ?

Code Auswählen

1 - 2019-01-12: s:15:13:23 e:15:13:28 f:5.039 d:tmr-Twilight_Midnight(myTwilight_Midnight) 
1 - 2019-01-12: s:15:14:28 e:15:14:33 f:5.023 d:tmr-Twilight_Midnight(myTwilight_Midnight) 
1 - 2019-01-12: s:15:15:33 e:15:15:34 f:1.182 d:tmr-Twilight_Midnight(myTwilight_Midnight) 
1 - 2019-01-12: s:15:16:54 e:15:16:55 f:1.063 d:no bad guy found :-(
1 - 2019-01-12: s:15:18:10 e:15:18:14 f:4.954 d:tmr-FW_closeInactiveClients(N/A) 
1 - 2019-01-12: s:15:23:21 e:15:23:26 f:5.078 d:no bad guy found :-(
1 - 2019-01-12: s:15:25:07 e:15:25:11 f:4.932 d:tmr-PRESENCE_StartLocalScan(LarissaBT) 
1 - 2019-01-12: s:15:31:06 e:15:31:11 f:5.719 d:tmr-PRESENCE_StartLocalScan(NalaBT) 
1 - 2019-01-12: s:15:32:48 e:15:32:53 f:5.016 d:tmr-Twilight_WeatherTimerUpdate(myTwilight_Midnight) 
1 - 2019-01-12: s:15:35:53 e:15:36:03 f:10.179 d:tmr-PRESENCE_StartLocalScan(PatrickBT) tmr-Twilight_WeatherTimerUpdate(myTwilight_Midnight) 
1 - 2019-01-12: s:15:37:06 e:15:37:07 f:1.797 d:tmr-CometBlueBTLE::StateRequestTimer(Bad) 
1 - 2019-01-12: s:15:40:29 e:15:40:33 f:4.817 d:tmr-PRESENCE_StartLocalScan(PatrickBT) 
1 - 2019-01-12: s:15:49:56 e:15:50:00 f:4.952 d:tmr-PRESENCE_StartLocalScan(PatrickBT) 
1 - 2019-01-12: s:15:53:22 e:15:53:23 f:1.254 d:no bad guy found :-(
1 - 2019-01-12: s:16:01:52 e:16:01:56 f:4.333 d:no bad guy found :-(
1 - 2019-01-12: s:16:06:58 e:16:06:59 f:1.89 d:tmr-PRESENCE_StartLocalScan(LarissaBT) 
1 - 2019-01-12: s:16:11:16 e:16:11:18 f:2.464 d:tmr-SYSMON_Update(sysmon) tmr-PRESENCE_StartLocalScan(NalaBT) 
1 - 2019-01-12: s:16:13:05 e:16:13:09 f:4.853 d:no bad guy found :-(
1 - 2019-01-12: s:16:19:55 e:16:19:59 f:4.496 d:no bad guy found :-(
1 - 2019-01-12: s:16:21:42 e:16:21:46 f:4.692 d:no bad guy found :-(

Caleus

herrmannj · 12 Januar 2019, 16:30:15

Zitat von: Caleus am 12 Januar 2019, 16:24:21
ja scheint weg zu sein. auf was sollte ich denn dnsServer setzen ?

Caleus

die ip Deiner Fritzbox (oder was auch immer)

KernSani · 12 Januar 2019, 16:43:24

Twilight scheint im Minutentakt etwas zu machen.
Für die ,,no bad guy found" bitte Attribut fm_logFile setzen und dann ins Log von freezemon schauen (auf Log in der get freeze Ansicht klicken)

Kurz, weil mobil

Caleus · 13 Januar 2019, 08:02:22

Guten Morgen

also ich habe nun mal ein paar logs aufgezeichnet und das letzte von "no bad guy found" wäre das hier

Code Auswählen


=========================================================

[Freezemon] myFreezemon: possible freeze starting at 05:31:44, delay is 1.242 possibly caused by: no bad guy found :-(

2019.01.13 05:31:43.953 4: : HTTP response code 200

2019.01.13 05:31:43.953 5: HttpUtils : Got data, length: 23

2019.01.13 05:31:43.953 5: HttpUtils response header:

HTTP/1.1 200 OK

Server: nginx/1.12.2

Date: Sun, 13 Jan 2019 04:31:43 GMT

Content-Type: application/json

Content-Length: 23

Connection: close

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, OPTIONS

Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection

Strict-Transport-Security: max-age=31536000; includeSubDomains; preload

2019.01.13 05:31:43.953 5: TelegramBot_Callback HomeBot: called from Polling

2019.01.13 05:31:43.953 5: TelegramBot_Callback HomeBot: data returned :{"ok":true,"result":[]}:

2019.01.13 05:31:43.954 5: TelegramBot_Deepencode HomeBot: encoded a String from :1: to :1:

2019.01.13 05:31:43.954 5: TelegramBot_Deepencode HomeBot: found an ARRAY

2019.01.13 05:31:43.954 5: TelegramBot_Deepencode HomeBot: found a HASH

2019.01.13 05:31:43.954 5: TelegramBot_Callback HomeBot: after encoding

2019.01.13 05:31:43.954 5: TelegramBot_Callback HomeBot: polling returned result? 0

2019.01.13 05:31:43.954 5: UpdatePoll HomeBot: number of results 0

2019.01.13 05:31:43.954 5: TelegramBot_UpdatePoll HomeBot: called 

2019.01.13 05:31:43.954 5: TelegramBot_UpdatePoll HomeBot: - Initiate non blocking polling - With callback set

2019.01.13 05:31:43.955 5: TelegramBot_readToken: Read Telegram API token from file

2019.01.13 05:31:43.956 4: TelegramBot_UpdatePoll HomeBot: initiate polling with nonblockingGet with 120s

2019.01.13 05:31:43.956 5: HttpUtils url=

2019.01.13 05:31:43.957 4: IP: api.telegram.org -> 149.154.167.220

2019.01.13 05:31:43.958 5: TelegramBot_UpdatePoll HomeBot: - Ende > next polling started

2019.01.13 05:31:43.958 4: TelegramBot_Callback HomeBot: resulted in SUCCESS from Polling

2019.01.13 05:31:43.958 5: TelegramBot_Callback HomeBot: - Ende > Control back to FHEM

--- log skips     1.283 secs.

2019.01.13 05:31:45.241 5: HttpUtils request header:

GET /bot588317852:AAEF7WqdNa97iPKMLCVu6yVrrW9gVFOzVm4/getUpdates?offset=11174092&limit=5&timeout=120 HTTP/1.0

Host: api.telegram.org

Accept-Encoding: gzip,deflate

agent: TelegramBot/1.0

User-Agent: TelegramBot/1.0

Accept: application/json

Accept-Charset: utf-8



2019.01.13 05:31:45.242 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2019.01.13 05:31:45.242 ---------------------

[Freezemon] myFreezemon: possible freeze starting at 05:31:44, delay is 1.242 possibly caused by: no bad guy found :-(

Caleus

KernSani · 13 Januar 2019, 12:07:03

Hmmm... da kann man gut sehen, dass der TelegramBot erfolgreich gepollt hat und FHEM dann erstmal ein Weilchen nichts mehr macht -zumindest keine Logeinträge mehr schreibt, d.h. es wird irgendetwas verarbeitet.
Wenn du die Catch*-Attribute noch aktivierdt, finder man möglicherweise mehr Details.
Freezemon kann leider nur Hinweise geben, wer einen Freeze verursacht hat. Das ,,warum" ist dann Handarbeit

global dnsServer hattest du gesetzt, oder?

Kurz, weil mobil

Caleus · 13 Januar 2019, 12:46:45

Ja also global dnsServer habe ich nun gestern gesetzt auf die Fritzbox IP, welche Einstellung für fm_CatchCmds
und fm_CatchFnCalls soll es den sein 0 bis 5 habe ich ?

Caleus

KernSani · 13 Januar 2019, 13:09:03

0 bedeutet inaktiv, alles größer 0 bedeautet aktiv und gibt den Loglevel an... also 3 oder so...

Kurz, weil mobil

Caleus · 13 Januar 2019, 14:22:55

so hier mal ein log mit gestztem fm_CatchCmds und fm_CatchFnCalls beides auf 5 (hoffe ich)

Code Auswählen

=========================================================

[Freezemon] myFreezemon: possible freeze starting at 14:07:51, delay is 4.376 possibly caused by: no bad guy found :-(

2019.01.13 14:07:50.048 4: : HTTP response code 200

2019.01.13 14:07:50.048 5: HttpUtils : Got data, length: 23

2019.01.13 14:07:50.048 5: HttpUtils response header:

HTTP/1.1 200 OK

Server: nginx/1.12.2

Date: Sun, 13 Jan 2019 13:07:50 GMT

Content-Type: application/json

Content-Length: 23

Connection: close

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, OPTIONS

Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection

Strict-Transport-Security: max-age=31536000; includeSubDomains; preload

2019.01.13 14:07:50.049 5: TelegramBot_Callback HomeBot: called from Polling

2019.01.13 14:07:50.049 5: TelegramBot_Callback HomeBot: data returned :{"ok":true,"result":[]}:

2019.01.13 14:07:50.049 5: TelegramBot_Deepencode HomeBot: found an ARRAY

2019.01.13 14:07:50.049 5: TelegramBot_Deepencode HomeBot: encoded a String from :1: to :1:

2019.01.13 14:07:50.049 5: TelegramBot_Deepencode HomeBot: found a HASH

2019.01.13 14:07:50.049 5: TelegramBot_Callback HomeBot: after encoding

2019.01.13 14:07:50.049 5: TelegramBot_Callback HomeBot: polling returned result? 0

2019.01.13 14:07:50.049 5: UpdatePoll HomeBot: number of results 0

2019.01.13 14:07:50.050 5: TelegramBot_UpdatePoll HomeBot: called 

2019.01.13 14:07:50.050 5: TelegramBot_UpdatePoll HomeBot: - Initiate non blocking polling - With callback set

2019.01.13 14:07:50.051 5: TelegramBot_readToken: Read Telegram API token from file

2019.01.13 14:07:50.052 4: TelegramBot_UpdatePoll HomeBot: initiate polling with nonblockingGet with 120s

2019.01.13 14:07:50.052 5: HttpUtils url=

2019.01.13 14:07:50.053 4: IP: api.telegram.org -> 149.154.167.220

2019.01.13 14:07:50.054 5: TelegramBot_UpdatePoll HomeBot: - Ende > next polling started

2019.01.13 14:07:50.054 4: TelegramBot_Callback HomeBot: resulted in SUCCESS from Polling

2019.01.13 14:07:50.054 5: TelegramBot_Callback HomeBot: - Ende > Control back to FHEM

2019.01.13 14:07:50.073 4: GHoma_d33aa0 RX: 5A A5 00 16 90 01 0A E0 35 23 D3 3A A0 FF FE 01 81 39 00 00 01 01 20 00 02 90 13 5B B5 

2019.01.13 14:07:50.080 5: rg_battery: not on any display, ignoring notify

2019.01.13 14:07:50.088 5: End notify loop for GHoma_d33aa0

--- log skips     5.287 secs.

2019.01.13 14:07:55.375 5: HttpUtils request header:

GET /bot588317852:AAEF7WqdNa97iPKMLCVu6yVrrW9gVFOzVm4/getUpdates?offset=11174092&limit=5&timeout=120 HTTP/1.0

Host: api.telegram.org

Accept-Encoding: gzip,deflate

agent: TelegramBot/1.0

User-Agent: TelegramBot/1.0

Accept: application/json

Accept-Charset: utf-8



2019.01.13 14:07:55.376 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2019.01.13 14:07:55.376 ---------------------

[Freezemon] myFreezemon: possible freeze starting at 14:07:51, delay is 4.376 possibly caused by: no bad guy found :-(

Caleus

Caleus · 31 Januar 2019, 08:19:02

Hat keiner eine Idee?