FHEM Träge / CPU Last

[Nemo0815]

Hallo zusammen,

ich habe folgendes Problem mit meiner FHEM Installation:

Die Reaktionszeiten von FHEM sind oft sehr unterschiedlich, oft reagiert es quasi sofort, ein anderes mal dauert es z.B. nach dem betätigen eines Tasters bis zu einer Minute(!) bis das Kommando dann über RF rausgesendet wird.

Gleiches gilt auch für den Webserver, manchmal reagiert er schnell, manchmal kommts sogar zum Timeout und geht dann erst nach Reload weiter, egal ob ich übers Web oder Zuhause im LAN eingeloggt bin.

Ich habe einen RPi 2 auf dem nur FHEM und Motion läuft. Motion verbrät so ca. 12-13% CPU, und FHEM (perl) schwankt so zwischen 5 und 35%, miest aber eher im unteren % Bereich.

Apptime gibt mir folgendes zurück (nach einiger Zeit):

Code Auswählen Erweitern

         name             function    max  count    total  average maxDly
      WEB_Local_192.168.178.58_39207              FW_Read  14514      1    14514 14514.00      0 HASH(WEB_Local_192.168.178.58_39207)
                               logdb            DbLog_Get   7789      6    11271  1878.50      0 HASH(logdb); logdb; HISTORY; INT; 2016-01-03_00:00:00; 2016-01-10_00:00:01; WaermepumpenZaehler:Momentanleistung; WaermepumpenZaehler:Zählerstand-Tarif-1-Bezug; WaermepumpenZaehler:Zählerstand-Tarif-2-Bezug
      WEB_Local_192.168.178.58_39200              FW_Read   5284      5    10732  2146.40      0 HASH(WEB_Local_192.168.178.58_39200)
                                 WEB              FW_Read   4012     86    18981   220.71      0 HASH(WEB)
                          SamsungTV1            STV_Ready   3817  53467    41002     0.77      0 HASH(SamsungTV1)
               tmr-IPCAM_getSnapshot      HASH(0x25cae28)   1833     14     4540   324.29    867 HASH(IRULUCam)
      WEB_Local_192.168.178.58_39194              FW_Read    934      5     1833   366.60      0 HASH(WEB_Local_192.168.178.58_39194)
                 tmr-I2C_BMP180_Poll      HASH(0x1fe8e38)    252      3      487   162.33    715 HASH(BMP085)
            WEB_212.77.163.110_31176              FW_Read    251     20      427    21.35      0 HASH(WEB_212.77.163.110_31176)
                             RPi_I2C         RPII2C_Write    198     12      383    31.92      0 HASH(RPi_I2C); HASH(0x2655708)
                              BMP085    I2C_BMP180_I2CRec    192     12      331    27.58      0 HASH(BMP085); HASH(0x2655708)
                    HausstromZaehler          SMLUSB_Read    169  12326     3360     0.27      0 HASH(HausstromZaehler)
                               fbaha           FBAHA_Read    160     12      956    79.67      0 HASH(fbaha)
                           Hausstrom readingsGroup_Notify    151    591     5327     9.01      0 HASH(Hausstrom); HASH(SystemMonitor)
                  LuftdruckAenderung          notify_Exec    148      2      250   125.00      0 HASH(LuftdruckAenderung); HASH(BMP085)
                   TemperaturesGroup readingsGroup_Notify    146    591     4691     7.94      0 HASH(TemperaturesGroup); HASH(SystemMonitor)
                             nanoCUL             CUL_Read    139     28      975    34.82      0 HASH(nanoCUL)
                         tmr-at_Exec      HASH(0x1ab0218)    137      3      386   128.67   4073 HASH(VitocalAnDummies)
                   tmr-SYSMON_Update      HASH(0x1794b20)    130     13     1289    99.15   5093 HASH(SystemMonitor)
                 WaermepumpenZaehler          SMLUSB_Read    128  39993     3356     0.08      0 HASH(WaermepumpenZaehler)
                         tmr-at_Exec      HASH(0x225fae8)     82    160     5612    35.08  14026 HASH(RegenReset)

Sind das normale Werte, oder deutet das auf eine falsche Konfiguration hin?

Im Log hab ich gelegentlich ein paar Perl warnings, z.B. auch bei apptime:

Code Auswählen Erweitern

2016.01.08 15:41:06 1: PERL WARNING: Subroutine HandleTimeout redefined at ./FHEM/98_apptime.pm line 24.
2016.01.08 15:41:06 1: PERL WARNING: Subroutine CallFn redefined at ./FHEM/98_apptime.pm line 58.
2016.01.08 15:41:40 1: PERL WARNING: Use of uninitialized value in join or string at ./FHEM/98_apptime.pm line 150.

Sonst fällt mir aber nichts auf, irgendeine Idee?

[Nemo0815]

Gerade nochmal gecheckt, einfach auf eine Objekt in der Webansicht geklickt, Browser (Chrome) fängt an zu laden, dauer etwa 2 Minuten bis sich die Seite mit der Detailansicht zeigt (im LAN!).

Dabei CPU Last in top 100% , belegt durch FHEM. Geht danach auch nicht sofort runter, sondern erst Minuten später wieder bzw. nach (FHEM-) Neustart.

apptime:

Code Auswählen Erweitern

name             function    max  count    total  average maxDly
                          SamsungTV1            STV_Ready   3003   2429     3004     1.24      0 HASH(SamsungTV1)
      WEB_Local_192.168.178.58_48836              FW_Read   1047      7     1265   180.71      0 HASH(WEB_Local_192.168.178.58_48836)
                             nanoCUL             CUL_Read    259      6      322    53.67      0 HASH(nanoCUL)
                         Regensensor      RPI_GPIO_Except    177   1833    65832    35.91      0 HASH(Regensensor)
               tmr-IPCAM_getSnapshot      HASH(0x2031958)    158      2      303   151.50     27 HASH(IRULUCam)
                  JemandZuhauseCheck          notify_Exec    135   3923     1480     0.38      0 HASH(JemandZuhauseCheck); HASH(Handy2)
                               logdb            DbLog_Log    135   3923     4738     1.21      0 HASH(logdb); HASH(Regensensor)
                               fbaha           FBAHA_Read    102      1      102   102.00      0 HASH(fbaha)
      WEB_Local_192.168.178.32_51026              FW_Read     82      8       94    11.75      0 HASH(WEB_Local_192.168.178.32_51026)
                 WaermepumpenZaehler          SMLUSB_Read     68    956      306     0.32      0 HASH(WaermepumpenZaehler)
                        RegenCounter          notify_Exec     67   1255    34655    27.61      0 HASH(RegenCounter); HASH(Regensensor)
      WEB_Local_192.168.178.32_51027              FW_Read     62     11       83     7.55      0 HASH(WEB_Local_192.168.178.32_51027)
                    HausstromZaehler          SMLUSB_Read     47    554      275     0.50      0 HASH(HausstromZaehler)
                       JemandZuhause            dummy_Set     40     34     1138    33.47      0 HASH(JemandZuhause); JemandZuhause; true
      WEB_Local_192.168.178.58_48842              FW_Read     38      1       38    38.00      0 HASH(WEB_Local_192.168.178.58_48842)
                         tmr-at_Exec      HASH(0x1cc4a30)     35     17      423    24.88    640 HASH(RegenReset)
         tmr-PRESENCE_StartLocalScan      HASH(0x21aaf50)     33      4       73    18.25   1272 HASH(Handy2_Presence)
                   tmr-SYSMON_Update      HASH(0x11f9e28)     31      2       61    30.50     38 HASH(SystemMonitor)
                         tmr-at_Exec      HASH(0x1a493c0)     31      2       59    29.50     43 HASH(RASPI.WatchdogCounter)
                     RegenTropfenCnt            dummy_Set     30   2527    26859    10.63      0 HASH(RegenTropfenCnt); RegenTropfenCnt; 130022
                 tmr-SISPM_GetStatus      HASH(0x2175868)     26      3       71    23.67     41 HASH(mySISPM)

und das zugehörige top:

[Nemo0815]

3 Stunden später:

Code Auswählen Erweitern

name             function    max  count    total  average maxDly
                          SamsungTV1            STV_Ready   8322 632712   299113     0.47      0 HASH(SamsungTV1)
      WEB_Local_192.168.178.58_49271              FW_Read   5636     17     8213   483.12      0 HASH(WEB_Local_192.168.178.58_49271)
               tmr-IPCAM_getSnapshot      HASH(0x2031958)   4011    105    29734   283.18 194877 HASH(IRULUCam)
                         Regensensor      RPI_GPIO_Except   2450  17689   606300    34.28      0 HASH(Regensensor)
                               logdb            DbLog_Log   2410  44121    61566     1.40      0 HASH(logdb); HASH(Regensensor)
      WEB_Local_192.168.178.58_49285              FW_Read    950      4     1182   295.50      0 HASH(WEB_Local_192.168.178.58_49285)
                  JemandZuhauseCheck          notify_Exec    840  44121   108595     2.46      0 HASH(JemandZuhauseCheck); HASH(Handy2)
                       JemandZuhause            dummy_Set    698   2167    89578    41.34      0 HASH(JemandZuhause); JemandZuhause; true
                    HausstromZaehler          SMLUSB_Read    624 113623    21903     0.19      0 HASH(HausstromZaehler)
                             nanoCUL             CUL_Read    559    196     3810    19.44      0 HASH(nanoCUL)
                       Heizraum_Tuer      RPI_GPIO_Except    253      1      253   253.00      0 HASH(Heizraum_Tuer)
                 tmr-I2C_BMP180_Poll      HASH(0x1a4dcf8)    226     20     2784   139.20  25183 HASH(BMP085)
                         tmr-at_Exec      HASH(0x15152b0)    218     21     2224   105.90  50635 HASH(VitocalAnDummies)
                 WaermepumpenZaehler          SMLUSB_Read    203 507783    22623     0.04      0 HASH(WaermepumpenZaehler)
                               fbaha           FBAHA_Read    193     88     5346    60.75      0 HASH(fbaha)
                             RPi_I2C         RPII2C_Write    182     80     2109    26.36      0 HASH(RPi_I2C); HASH(0x2b36058)
                              BMP085    I2C_BMP180_I2CRec    178     80     1845    23.06      0 HASH(BMP085); HASH(0x2b36058)
                  LuftdruckAenderung          notify_Exec    155     17     1488    87.53      0 HASH(LuftdruckAenderung); HASH(BMP085)
                       Sammelmeldung            dummy_Set    133     28      544    19.43      0 HASH(Sammelmeldung); Sammelmeldung; off
                         tmr-at_Exec      HASH(0x1cc4a30)    105   1256    43220    34.41 368847 HASH(RegenReset)
                   tmr-SYSMON_Update      HASH(0x11f9e28)     87     96     4844    50.46 193056 HASH(SystemMonitor)


Ich würde mal sagen das STV Modul ist "leicht" buggy...
Mir ist schon vor längerer Zeit aufgeallen dass es z.B. nicht richtig auf Events reagiert, bzw. Events daraus nicht richtig funktionieren (z.B. STVDevice:reading führt nicht zu einem Event, nur STV alleine triggert!)

Ist das -Modul vielleicht anders implementiert (Polling statt events, was zu höhere CPU Last führ?)?

[Prof. Dr. Peter Henning]

Nix "Buggy". Sondern wartet auf response vom (wahrscheinlich ausgeschalteten) Fernseher 

LG

pah

[Nemo0815]

Und diese hohe Aufrufanzahl geht nicht zu Lasten der CPU? Irgendwas hat sich geändert, bis vor kurzem war motion mein CPU "Fresser" mit so 12% CPU Last, jetzt ist das System quasi durch FHEM ausgelastet

[Puschel74]

Bei mir bremst STV das System nicht aus - und der Fernseher ist zur Zeit aus.

Was ich aber nicht ganz verstehe:

bis vor kurzem war motion mein CPU "Fresser" mit so 12% CPU Last, jetzt ist das System quasi durch FHEM ausgelastet

motion ist nicht FHEM?
was ist motion dann?

[Nemo0815]

Bei mir bremst STV das System nicht aus - und der Fernseher ist zur Zeit aus.

Was ich aber nicht ganz verstehe:motion ist nicht FHEM?
was ist motion dann?

Motion ist ein Software motion detector für USB Webcams, die hängt am Raspi...

[Puschel74]

Motion ist ein Software motion detector für USB Webcams, die hängt am Raspi...

Ok, danke für die Erklärung.

[Prof. Dr. Peter Henning]

Bitte zu beachten, dass Ausführungszeit und CPU-Last zwei verschiedene Sachen sind. apptime misst die Ausführungszeit - und die kann durchaus hoch sein, wenn ein Modul auf irgendetwas wartet und dabei FHEM blockiert.

LG

pah

[Nemo0815]

Was habt ihr denn für CPU Auslastungen in "top" für FHEM (perl)?

Ich finde 30%+ etwas hoch, und noch dazu schwankt die Last sehr stark, bzw. hält sich manchmal auch bei 99%, ich sehe aber nicht was dafür verantwortlich sein sollte 

[Otto123]

hast Du 99% auf allen 4 Kernen?
Also bei mir liegt die normale Last bei ein paar Prozent, wenn ich per Web drauf zugreife Plots anschaue usw. geht sie etwas hoch.

Wenn sie dauerhaft hoch ist, hat bei mir bisher ein kompletter Neustart (nicht nur FHEM) geholfen. Das hatte ich bisher genau zweimal. Jedesmal war eine Art "Absturz" von FHEM die Ursache, d.h. FHEM lief plötzlich scheinbar nicht mehr und ich habe es einfach neu gestartet. Dann habe ich später gemerkt das ein Topf auf 100% läuft. Am System selbst hat man dabei aber wenig gemerkt.
An andere Stelle hier im Forum ist beschrieben, dass dies auftritt wenn beim Start von FHEM die Systemzeit noch nicht stimmt (fehlende Hardware Uhr) und man darauf achten soll, dass FHEM nach ntp startet.

Ein zweiter Hinweis: Schau mal eine Weile dem Eventmonitor zu. Das zeigt einem manchmal, wenn man selbst Mist gebaut hat mit Schleifen usw. Aber das dadurch 100% CPU auftraten hatte ich auch noch nicht, FHEM träge schon eher.

Gruß Otto

[frank]

Motion ist ein Software motion detector für USB Webcams, die hängt am Raspi...

das würde ich doch testweise mal abschalten.

[Prof. Dr. Peter Henning]

Finger in den Wind gehalten: Limitierender Faktor ist möglicherweise nicht die CPU-Last, sondern die maximale Speicherbandbreite.

LG

pah

[Nemo0815]

Es hatte je früher normal funktoiniert, irgendwas muss sich geändert haben. Im Eventmonitor sehe ich nicht besonders viele Events, sieht ganz normal aus:


Hier mal Pro CPU:

Code Auswählen Erweitern

top - 10:51:38 up 2 days,  1:07,  1 user,  load average: 0,34, 0,47, 0,53                                                                                           
Tasks: 114 total,   2 running, 112 sleeping,   0 stopped,   0 zombie                                                                                               
%Cpu0  : 26,7 us,  1,9 sy,  0,0 ni, 68,2 id,  0,0 wa,  0,0 hi,  3,1 si,  0,0 st                                                                                     
%Cpu1  :  0,0 us,  0,0 sy,  0,0 ni,100,0 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st                                                                                     
%Cpu2  : 11,4 us,  0,7 sy,  0,0 ni, 88,0 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st                                                                                     
%Cpu3  :  0,0 us,  0,0 sy,  0,0 ni,100,0 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st                                                                                     
KiB Mem:    948152 total,   813336 used,   134816 free,    73888 buffers                                                                                           
KiB Swap:   102396 total,        0 used,   102396 free,   443944 cached

FHEM (perl) ist dabei ganz oben mit über 30%...

[Otto123]

Und stimmt die Systemzeit?
Welches System hast du?
Ist ntp konfiguriert?

Gruß Otto