FHEM blockiert

ext23 · 11 Oktober 2019, 09:03:32

Ich weiß, das Thema nervt aber irgendwie stehe ich etwas auf dem Schlauch. Ich habe seit 1 Tag Probleme mit FHEM, es hängt einfach, und zwar so doll das zum HMLAN und LGW die Verbindungen auch wegbrechen. Auf der GUI merkt man es natürlich auch. Mal geht es fix, dann ein paar Sekunden später passiert nichts mehr. Ich habe schon versucht alle Module die auf Web zugreifen (Departure, Wetter etc.) zu deaktivieren. Nicht das hier irgendwo eine faule URL bei ist. Aber es hilft nichts. Ich habe auch nichts angefasst in den zwei Tagen. Switche etc. wurden alle schon neu gestartet. Also an LAN liegt es definitiv nicht, das passt alles.

Hat noch einer einen Tipp für mich wie ich das weiter eingrenzen kann? Danke!

Hier der Apptime Auszug:

Code Auswählen

active-timers: 87; max-active timers: 118; max-timer-load: 38  min-tmrHandlingTm: 0.0ms; max-tmrHandlingTm: 1892.0ms; totAvgDly: 7188.1ms

 name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
 Nextion01                                Nextion_Ready                         3002    66725 1683058.29    25.22     0.00     0.00 11.10. 03:54:05 HASH(Nextion01)
 HMLAN1                                   HMLAN_Ready                           3002      227    3651.18    16.08     0.00     0.00 10.10. 23:54:36 HASH(HMLAN1)
 CUL1                                     CUL_Read                              2030      678  116789.52   172.26     0.00     0.00 11.10. 02:16:09 HASH(CUL1)
 LGW01                                    LaCrosseGateway_Read                  2022    10092  769216.84    76.22     0.00     0.00 10.10. 23:40:22 HASH(LGW01)
 HMLAN1                                   HMLAN_Read                            2008     3872  418160.63   108.00     0.00     0.00 11.10. 04:05:02 HASH(HMLAN1)
 tmr-HMCCURPCPROC_RPCPing                 HASH(0xa271fa0)                       1561      121    2679.00    22.14 34460.67  7732.14 11.10. 04:42:19 HASH(d_rpcBidCos_RF)
 tmr-APCUPSD_PollTimer                    HASH(0x7bdcb68)                       1488      560  122282.74   218.36 25745.22  6173.80 11.10. 04:38:52 HASH(USV)
 PanStick                                 panStamp_Read                         1297     6496  382369.44    58.86     0.00     0.00 11.10. 00:11:52 HASH(PanStick)
 logdb                                    DbLog_Get                             1166       99    7854.85    79.34     0.00     0.00 10.10. 22:36:59 HASH(logdb); logdb; HISTORY; INT; 2019-10-01_00:00:00; 2019-10-31_23:59:59; ESPEasy_esp8266_espeasy03_A0:Analog; ESPEasy_esp8266_espeasy03_A4:Analog; ESPEasy_esp8266_espeasy03_A5:Analog; ESPEasy_esp8266_espeasy03_A2:Analog; ESPEasy_esp8266_espeasy03_A1:Analog; ESPEasy_esp8266_espeasy03_A3:Analog; ESPEasy_esp8266_espeasy03_A6:Analog; ESPEasy_esp8266_espeasy03_A7:Analog
 logdb                                    DbLog_Log                             1112    52061 2939892.83    56.47     0.00     0.00 11.10. 02:16:09 HASH(logdb); HASH(FS20_fd0504)
 tmr-at_Exec                              HASH(0x91b5278)                        815      124  100725.42   812.30 56713.82 11561.19 11.10. 03:32:17 HASH(Timer_ba_Temp_Steuereinheit)
 ba_Temp_Steuereinheit                    ECMDDevice_Set                         810      133  100301.73   754.15     0.00     0.00 11.10. 03:32:17 HASH(ba_Temp_Steuereinheit); ba_Temp_Steuereinheit; messen
 RPi_CUL                                  FHEM2FHEM_Read                         639      732   87984.92   120.20     0.00     0.00 11.10. 01:46:08 HASH(RPi_CUL)
 tmr-at_Exec                              HASH(0x91b3ed0)                        626      618  123519.55   199.87 63878.22  9529.27 10.10. 23:27:16 HASH(Timer_ba_Bodenfeuchtemessung)
 ba_Bodenfeuchte                          ECMDDevice_Get                         625      618  122284.06   197.87     0.00     0.00 10.10. 23:27:16 HASH(ba_Bodenfeuchte); ba_Bodenfeuchte; portvalue
 Kaltwasser_Gesamt                        WaterCalculator_Notify                 588      180   34277.51   190.43     0.00     0.00 11.10. 05:42:10 HASH(Kaltwasser_Gesamt); HASH(HM_230011_Values)
 tmr-at_Exec                              HASH(0x91b7130)                        538      618  117439.40   190.03 63977.10  9893.95 11.10. 06:16:16 HASH(Timer_Wassertonne_80)
 ba_Tonne_80                              ECMDDevice_Get                         537      623  117003.44   187.81     0.00     0.00 11.10. 06:16:16 HASH(ba_Tonne_80); ba_Tonne_80; portvalue
 tmr-sleep_WakeUpFn                       .sleep_26569                           525        1     525.59   525.59     0.27     0.27 11.10. 05:07:19 .sleep_26569
 ba_Temp_Steuereinheit                    ECMDDevice_Get                         525      124   25925.65   209.08     0.00     0.00 11.10. 05:07:19 HASH(ba_Temp_Steuereinheit); ba_Temp_Steuereinheit; temp
 EnergieverbrauchGesamt                   ElectricityCalculator_Notify           513      205   38602.93   188.31     0.00     0.00 11.10. 03:28:14 HASH(EnergieverbrauchGesamt); HASH(HM_230020_IEC_01)
 tmr-at_Exec                              HASH(0xa270d18)                        493      124    1034.55     8.34 55852.36 12910.90 10.10. 23:27:17 HASH(Timer_Flur_Pflanzen)
 fl_Pflanzen_Status                       dummy_Set                              492      123     750.29     6.10     0.00     0.00 10.10. 23:27:17 HASH(fl_Pflanzen_Status); fl_Pflanzen_Status; state; trocken
 d_rpcHmIP_RF                             HMCCURPCPROC_Read                      492      283   12875.69    45.50     0.00     0.00 10.10. 23:15:55 HASH(d_rpcHmIP_RF)
 DOIF_Pflanzen_Flur                       DOIF_Notify                            491      149     565.23     3.79     0.00     0.00 10.10. 23:27:17 HASH(DOIF_Pflanzen_Flur); HASH(fl_Pflanzen_Status)
 Warmwasser_Gesamt                        WaterCalculator_Notify                 487      180   33799.06   187.77     0.00     0.00 10.10. 23:13:40 HASH(Warmwasser_Gesamt); HASH(HM_230011_Values)
 PushNotify                               PushNotifier_Set                       485       13     486.13    37.39     0.00     0.00 10.10. 23:27:17 HASH(PushNotify); PushNotify; message; "INFO:; Blumen; im; Flur; gießen!"
 tmr-sleep_WakeUpFn                       .sleep_33334                           457        1     457.37   457.37     0.41     0.41 11.10. 07:02:19 .sleep_33334
 tmr-sleep_WakeUpFn                       .sleep_28006                           378        1     378.04   378.04     0.22     0.22 11.10. 05:32:19 .sleep_28006
 tmr-sleep_WakeUpFn                       .sleep_5184                            330        1     330.66   330.66 33449.55 33449.55 10.10. 22:38:11 .sleep_5184
 tmr-sleep_WakeUpFn                       .sleep_27446                           321        1     321.08   321.08     0.21     0.21 11.10. 05:22:19 .sleep_27446
 tmr-sleep_WakeUpFn                       .sleep_10968                           301        1     301.76   301.76     0.38     0.38 11.10. 00:17:37 .sleep_10968
 tmr-sleep_WakeUpFn                       .sleep_10135                           300        1     300.84   300.84   170.81   170.81 11.10. 00:02:19 .sleep_10135
 tmr-sleep_WakeUpFn                       .sleep_5429                            289        1     289.20   289.20 34001.64 34001.64 10.10. 22:42:53 .sleep_5429
 tmr-sleep_WakeUpFn                       .sleep_9065                            287        1     287.36   287.36     0.23     0.23 10.10. 23:42:18 .sleep_9065
 tmr-sleep_WakeUpFn                       .sleep_23461                           282        1     282.48   282.48     0.81     0.81 11.10. 04:12:42 .sleep_23461
 tmr-sleep_WakeUpFn                       .sleep_7019                            276        1     276.02   276.02   915.15   915.15 10.10. 23:07:46 .sleep_7019
 tmr-sleep_WakeUpFn                       .sleep_17100                           274        1     274.15   274.15   117.59   117.59 11.10. 02:12:23 .sleep_17100
 tmr-sleep_WakeUpFn                       .sleep_13288                           264        1     264.09   264.09 33180.18 33180.18 11.10. 01:02:59 .sleep_13288
 tmr-sleep_WakeUpFn                       .sleep_9342                            261        1     261.93   261.93   475.24   475.24 10.10. 23:47:42 .sleep_9342
 tmr-sleep_WakeUpFn                       .sleep_11661                           256        1     256.22   256.22   513.78   513.78 11.10. 00:32:43 .sleep_11661

rudolfkoenig · 11 Oktober 2019, 09:14:26

"attr global verbose 5" setzen, und bei einem Haenger pruefen, was zu dieser Zeit ins Log geschrieben wurde.

DS_Starter · 11 Oktober 2019, 09:24:04

Noch ein Hinweis aus meiner "Fachrichtung".

Code Auswählen

logdb                                    DbLog_Log                             1112    52061 2939892.83    56.47     0.00     0.00 11.10. 02:16:09 HASH(logdb); HASH(FS20_fd0504)

Solltest du DbLog _nicht_ im asynchronen Modus betrieben, schalte ihn bitte ein. Sollte das Problem dann nicht mehr auftreten, liegt es an deiner DB und du müsstest mal nachschauen warum deine DB plötzlich nicht mehr so arbeitet wie bisher.

ext23 · 11 Oktober 2019, 09:39:53

Zitat von: DS_Starter am 11 Oktober 2019, 09:24:04
Noch ein Hinweis aus meiner "Fachrichtung".

Code Auswählen Erweitern
logdb DbLog_Log 1112 52061 2939892.83 56.47 0.00 0.00 11.10. 02:16:09 HASH(logdb); HASH(FS20_fd0504)

Solltest du DbLog _nicht_ im asynchronen Modus betrieben, schalte ihn bitte ein. Sollte das Problem dann nicht mehr auftreten, liegt es an deiner DB und du müsstest mal nachschauen warum deine DB plötzlich nicht mehr so arbeitet wie bisher.

Danke, das habe ich vergessen zu frage, ob es an der DB liegen kann die stolze 8 GB hat. Aber ich sehe mit Top zumindest keinerlei Systemlast größer als 0,3% bei der DB. Generell langweilt sich der Server aber mit dem Async, mhh da schau ich mal. Das wusste ich gar nicht. Da schau ich mir direkt mal an. Danke.

DS_Starter · 11 Oktober 2019, 09:45:28

Ja, im DbLog gibt es einen "set ... configCheck". Der gibt ein paar Hinweise aus. Ein aktuelles DbLog vorausgesetzt.
8 GB sind aber normalerweise kein Problem.

ext23 · 11 Oktober 2019, 09:46:27

Zitat von: rudolfkoenig am 11 Oktober 2019, 09:14:26
"attr global verbose 5" setzen, und bei einem Haenger pruefen, was zu dieser Zeit ins Log geschrieben wurde.

Habe ich gemacht, da sind ja tausende SQL abfragen zu sehen binnen einer Sekunde, und komischerweise läuft es dann nach dem Verbose 5 auch besser. Merkwürdig, ich merke keine langen Hänger mehr.

Beispiel Auszug (wieso sind da zwei Daten?!?) Holt der da was ausm Buffer?:

Code Auswählen

2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:22:38, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:23:38, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:24:38, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:25:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:26:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:27:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:28:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:29:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:30:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:31:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:32:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:33:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:34:38, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:35:38, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:36:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:37:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:38:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:39:38, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:40:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:41:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:42:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:43:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:44:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:45:38, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:46:38, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:47:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:48:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:49:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:50:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75
2019.10.11 09:43:23 5: logdb - SQL-result -> TS: 2019-10-02 12:51:37, DEV: ESPEasy_esp8266_espeasy03_A4, RD: Analog, VAL: 1.75

/Daniel

ext23 · 11 Oktober 2019, 09:52:58

Zitat von: DS_Starter am 11 Oktober 2019, 09:45:28
Ja, im DbLog gibt es einen "set ... configCheck". Der gibt ein paar Hinweise aus. Ein aktuelles DbLog vorausgesetzt.
8 GB sind aber normalerweise kein Problem.

Danke:

Logmode of DbLog-device logdb is: synchronous
Recommendation: Switch logdb to the asynchronous logmode by setting the 'asyncMode' attribute. The advantage of this mode is to log events non-blocking.

DS_Starter · 11 Oktober 2019, 09:58:21

ZitatLogmode of DbLog-device logdb is: synchronous

Das ist auf jeden Fall eine mögliche Problemquelle. Sollte deine DB aus irgendwelchen Gründen mal nicht so zügig die Daten schreiben, d.h. loggen, bleibt dein FHEM für die Zeit hängen bis die DB fertig ist. -> Synchron.

Das betrifft nur das Schreiben. Für non-blocking Lesen was sich bei der SVG-Erstellung auswirkt, gibt es das plotfork im FHEMWEB.

LG,
Heiko

ext23 · 11 Oktober 2019, 10:10:37

Bis auf:

Encoding used by Client (connection): LATIN1
Encoding used by DB fhem: UTF8
Recommendation: Both encodings should be identical. You can adjust the usage of UTF8 connection by setting the UTF8 parameter in file './cfg/db.conf' to the right value.

Habe ich jetzt alles i.o. im dblog.

Ich beobachte das jetzt mal. Er hat aber eben schon wieder gehangen (So ca. 30 Sekunden). Ich glaube das ist noch was anderes. Mich wurmt nur das verbose 5 im log und wenn ich das mit tail -f laufen lassen geht es scheinbar.

Aber danke für den DB Tip, das ist an mir völlig vorüber gegangen. Naja einmal aktiviert schaut man sich das auch nicht mehr an. Da bekommt man Änderungen nicht mit.

/Daniel

DS_Starter · 11 Oktober 2019, 10:16:45

Zitat
Encoding used by Client (connection): LATIN1
Encoding used by DB fhem: UTF8
Recommendation: Both encodings should be identical. You can adjust the usage of UTF8 connection by setting the UTF8 parameter in file './cfg/db.conf' to the right value.

Das ist erstmal nicht kritisch. Kannst halt möglicherweise mit Umlauten ein paar seltsame Begegnungen haben.

Du kannst auch noch die Attribute showproctime und showNotifyTime im DbLog setzen. Dann siehst du Verarbeitungsgeschwindigkeit deiner DB und Geschwindigkeit des Event-Durchsatzes im DbLog (DbLog_log) im Reading notify_processing_time. Das sollte beides im ms-Bereich liegen.

Bei mir ein Beispiel:

Code Auswählen


       notify_processing_time 0.0003
       sql_processing_time 0.0255

sql_processing_time ist im asynch Betrieb nicht so wichtig, aber ein guter Hinweis wie schnell deine DB ist. Sollte auch im 10er ms-Bereich liegen.
Ich denke mit DbLog bist du jetzt save. Musst du weiter schauen...

Heiko

ext23 · 12 Oktober 2019, 09:45:27

Also danke nochmal, heute funktioniert wieder alles und ich vermute auch das Problem entdeckt zu haben. Das Departure Modul scheint ein paar Bugs zu haben. Zum einen war die URL nicht erreichbar und dort hat er vermutlich blockiert und zweitens wird das Attribut Disable von dem Modul ignoriert.

Von den Änderungen an der DB habe ich jetzt so nichts weiter mitbekommen, dennoch war es ein sehr guter Tip da einige Sachen wie die Längen der Felder falsch waren. Da FHEM bei mir auf einem recht flotten Server läuft scheint das nicht so sehr ins Gewicht zu fallen.

/Daniel