Seit Update sehr hohe Prozessorauslastung

[Michi240281]

Hallo zusammen,

ich habe am 23.8. abends ein Update gemacht. Die ganzen Tage kam mir Fhem sehr träge vor, bis ich dann soeben festgestellt habe, dass die Prozessorauslastung super hoch ist! Im Anhang mal ein Screenshot der Auswirkung durch das Update.
Und hier noch eine Auskunft von Apptime:

Code Auswählen Erweitern

                                name             function    max  count    total  average maxDly
                 tmr-Twilight_sunpos      HASH(0x16f2830)      2      1        2     2.00 70666590 HASH(My_Twilight_sunpos)
                         tmr-at_Exec      HASH(0x361b490)    130      1      130   130.00    249 HASH(Alarmanlage_aufraeumen)
                    tmr-HMLAN_clearQ      hmClearQ:HMLAN1      0      1        0     0.00     16
            tmr-HMLAN_KeepAliveCheck   keepAliveCk:HMLAN1      0      1        0     0.00      4
                  tmr-Unifi_DoUpdate      HASH(0x34af638)      2      1        2     2.00      4 HASH(Unifi_Controller)
                     Abwesend_notify          notify_Exec      4      4        4     1.00      0 HASH(Abwesend_notify); HASH(Qnap419P)
                 Abwesend_schnell_DI          DOIF_Notify      0      4        0     0.00      0

Scheinbar gibts da Probleme mit dem Twilight-Modul! Kann da jmd was zu sagen und/oder hat Ähnliches beobachtet?

Besten Dank und viele Grüße
Michi240281

[rapster]

Was sagt denn 'top' welcher Prozess soviel CPU beansprucht?

evtl. auch mal mit 'ps aux | grep [f]hem' schauen ob mehrere fhem Prozesse aktiv sind.

Fragen direkt zu Twilight würde ich in dieses Forum posten: http://forum.fhem.de/index.php/board,44.0.html

Gruß
  Claudiu

[Michi240281]

Was sagt denn 'top' welcher Prozess soviel CPU beansprucht?

evtl. auch mal mit 'ps aux | grep [f]hem' schauen ob mehrere fhem Prozesse aktiv sind.

Fragen direkt zu Twilight würde ich in dieses Forum posten: http://forum.fhem.de/index.php/board,44.0.html

Gruß
  Claudiu

Was ist "top" und was "ps aux | grep [f]hem"? Kannst du mich bitte aufschlauen?

[Posti123]

ein Linux kommandozeilenbefehl

[Michi240281]

Sooooooooo!

Mehrere Probleme erkannt:

- Verbose stand auf 4
- Logfile sehr groß geworden (200MB)
- Unifi-Modul zieht 20% CPU

@Rapster: War dann wohl doch nix mit ressourcenschonend! Alle 10 Sekunden tauchen die Readings im Eventmonitor auf und die Prozesse "mongodb" und "java" verbrauchen ca 20% CPU! Habe mal das Modul disabled, danach war Ruhe, kommt also definitiv vom Unifi-Modul! Hab jetzt erstmal des interval auf 30 Sekunden erhöht!

[rapster]

Hallo Michi,

das müssen wir hier erstmal etwas differenzieren,

das Unifi-Modul selber produziert erstmal keine erkennbare CPU-Last auf deinem System,
dieses sendet erstmal nur eine Anfrage an die Unifi-Controller-Api (das ist der Java-Prozess),

Der Java-Prozess des Unifi-Controller, versucht dann Daten aus der Datenbank zu holen (das ist der MongoDB Prozess),
und sendet diese dann an das Unifi-Modul zurück.
Erst jetzt arbeitet das Unifi-Modul weiter.

Jetzt kann es natürlich sein, dass du z.B. eine sehr langsame SD-Karte oder USB-Stick für die MongoDB verwendest,
und deshalb die CPU selbst bei einer kleiner Abfrage in der DB sehr lange warten muss, dies mögen manche Programme nicht besonders und schießen in der Zeit mit der CPU in die Höhe.

Allerdings sind ja 20% CPU generell erstmal nicht (zu)viel.
Schöne wäre es wenn du uns die Ausgabe des Shell-Kommandozeilenbefehls "uptime" zur Verfügung stellen würdest, und kurz deine Hardware (insbesondere CPU und Datenträger mitteilst)


Gruß
  Claudiu

[Michi240281]

Das ist schon klar, dass das Modul keine Auslastung "generiert", aber die Prozesse "Java" und "MongoDB" werden ja ausschließlich für das Modul benötigt und ich habe sie ja extra dafür installieren müssen. Daher zählt das natürlich insgesamt zur "Unifi-Modul-Auslastung".

Hier das Ergebnis von "uptime":

Code Auswählen Erweitern

root@raspberrypi:/home/pi# uptime
18:45:07 up 4 days,  4:42,  1 user,  load average: 0.54, 0.66, 0.55


Ich nutze einen RPi2, der ja an sich recht schnell ist! Weiß aber auch nicht genau, was die "load average" zu bedeuten hat, das sind vermutlich keine %, skaliert auf 1, oder? Ich weiß nur, dass die load vor der Inbetriebnahme des Unifi-Moduls ca bei 0.2 bis 0.3 lag und sich nun verdoppelt hat! Was sind denn "gute" und "schlechte" Werte?

Als Datenträger nutze ich einen aktuellen 32 GB USB Stick sowie eine 32GB SD-Karte mit Class 10. Also daran wirds nicht liegen....

[rapster]

deine load average sieht allerdings völlig i.O aus,

beim einem Quadcore-Prozessor (Raspi2) ist die CPU bei einer load-average von 4.00 voll ausgelastet, alles darüber ist schlecht (Sachen werden zurückgehalten), alles darunter ist OK (CPU langweilt sich).

In deinem Fall ist eine load-average von bis zu ~ 3.00 noch vollkommen im grünen Bereich, damit hättest du dann noch etwa 25% CPU-reserven, alles darunter ist Verschwendung von CPU Ressourcen 

Du kannst es dir so vorstellen, dass bei deiner momentanen average nichtmal eine Spur einer Vierspurigen Autobahn voll befahren wird, 3 Spuren sind komplett ohne Autos besetzt

P.S. Produziert bei dir das unifi-Modul evtl. ebenfalls wie das Sysmon Modul Events mehrfach? Das könnte sonst natürlich noch auf andere Probleme hindeuten....

[rapster]

Wegen der Vermutung des langsamen DB-Zugriffs, könntest du allerdings mal Probieren die DB vom USB Stick auf die SD-karte zu verschieben, oder anders rum, und beobachten ob sich dadurch was verbessert/verschlechtert.

EDIT:
und ja daran kann es klar liegen, siehe (oder probier es mal) alleine wie lange auf so einer Class 10 SD-Karte /fhem/contrib/commandref_join.pl dauert, das sind manchmal mehrere Minuten.
Wenn fhem z.B. auf einer SSD liegt ist commandref_join innerhalb von ~ 3 Sekunden fertig.
Dementsprechend dauert es natürlich auch länger bis der Java-Prozess "endlich" Daten erhält damit er weiterarbeiten kann, und der MongoDB Prozess die Daten gelesen hat um sie liefern zu können.

[rudolfkoenig]

die CPU bei einer load-average von 4.00 voll ausgelastet

Aus https://en.wikipedia.org/wiki/Load_%28computing%29#Unix-style_load_calculation

An idle computer has a load number of 0. Each process using or waiting for CPU (the ready queue or run queue) increments the load number by 1. Most UNIX systems count only processes in the running (on CPU) or runnable (waiting for CPU) states. However, Linux also includes processes in uninterruptible sleep states (usually waiting for disk activity), which can lead to markedly different results if many processes remain blocked in I/O due to a busy or stalled I/O system.

-> Eine ausgelastete Festplatte erhoeht den load, selbst wenn die CPU nichts zu tun hat.

[Michi240281]

Ich ziehe mal ein Fazit: Meine Auslastung ist noch auf recht geringem Niveau!

Hatte nur in den letzten Tagen festgestellt, dass öfter mal der Taster zum Ausschalten der Alarmanlage scheinbar nicht (sofort) den Befehl an Fhem sendet, weshalb die Alarmanlage dann weiterhin scharf ist! Ist halt so, dass ich die innerhalb 15 Sekunden deaktivieren muss, nachdem die Tür offen ist. Da kommt dann halt einiges innerhalb weniger Sekunden zusammen: Tür öffnet, iPhone loggt sich ein, Schalter werden gesetzt etc., evtl. noch ne Push die gesendet wird und dann kriegt man die Alarmanlage nicht entschärft! Das hatte ich halt vorher, als die load noch bei 0,2 war im Schnitt, nicht.

[justme1968]

-> Eine ausgelastete Festplatte erhöht den load, selbst wenn die CPU nichts zu tun hat.

was man dann sehr schön in top am sys anteil der auslastung sieht.

[rapster]

...dass öfter mal der Taster zum Ausschalten der Alarmanlage scheinbar nicht (sofort) den Befehl an Fhem sendet...und dann kriegt man die Alarmanlage nicht entschärft! Das hatte ich halt vorher, als die load noch bei 0,2 war im Schnitt, nicht.

Das hört sich eher nach einem blockierenden Fhem an.

Die Auslastung bei fremden Prozessen blockiert bei dieser load average Fhem normalerweise überhaupt nicht, resp. bekommt dies Fhem normalerweise nichtmal mit.

Kann es sein dass du in Fhem irgendwelche "system()" commands oder Perl { sleep(x) } verwendest? Oder andere Blockierende Aufrufe?

Du kannst mal mit "attr global verbose 5" & "attr global mseclog 1" deinen Alarmanlagen-Schalter loggen wenn er mal hängt, evtl. erkennt man hier dein echtes Problem...

EDIT:
Du kannst auch mal gucken was der Shell-Befehl "free" so sagt...

[Michi240281]

Nö, das nutze ich nicht!

Jo werde ich mal schauen die Tage!

Code Auswählen Erweitern

root@raspberrypi:/home/pi# free
             total       used       free     shared    buffers     cached
Mem:        948128     701308     246820          0      90820     393256
-/+ buffers/cache:     217232     730896
Swap:       102396          0     102396


SYSMON zeigt folgendes:

Code Auswählen Erweitern

Date: 01.09.2015 22:44:07
CPU temperature: 49.23 °C
CPU frequency: 950 MHz
CPU model name: ARMv7 Processor rev 5 (v7l)
BogoMIPS: 60.80
System up time: 4 days, 08 hours, 41 minutes
FHEM up time: 0 days, 00 hours, 38 minutes
Load average: 0.59 0.59 0.58
RAM: Total: 925.91 MB, Used: 209.63 MB, 22.64 %, Free: 716.27 MB
swap: Total: 100.00 MB, Used: 0.00 MB, 0.00 %, Free: 100.00 MB
Ethernet: RX: 2133.28 MB, TX: 1026.10 MB, Total: 3159.38 MB
WiFi: not available
Filesystem /boot: Total: 56 MB, Used: 20 MB, 36 %, Available: 37 MB at /boot
Root: Total: 29143 MB, Used: 4410 MB, 16 %, Available: 23507 MB at /
Filesystem /media/usbstick: Total: 30015 MB, Used: 612 MB, 3 %, Available: 27857 MB at /media/usbstick

[rapster]

Schaut alles i.O. aus.
Ja mach mal Log, dann nochmal schauen.