Anlegen von AT Befehlen dauert mehrere Sekunden

[rolf]

In meiner FHEM-Umgebung dauert das Anlegen eines AT-Befehls, z.B. per >define testat at +00:01:00 set DUMMY on< mehrere Sekunden - alles andere funktioniert wirklich rasend schnell.
Kurioserweise habe ich das Problem nur auf meiner produktiven FHEM-Umgebung mit ca. 100 angebundenen Homematic-Devices - in meiner FHEM-Testumgebung wird der gleiche Befehl im
Bruchteil einer Sekunde abgearbeitet.

Hat mir jemand einen Tip wo ich suchen muss, bzw. wie ich das Problem eingrenzen kann - meine bisherigen Versuche und Suchen nach der Fehlersuche per Verbose 5 etc. waren leider erfolglos.
Generell ist das FHEM-System bei mir auf einem Cubietruck installiert - ist wirklich super schnell - auch keine Hänger oder ähnliches - sobald jedoch ein AT-Befehl abgesetzt wird scheint FHEM
für ein paar Sekunden "geblockt" zu sein.

Für jeden Hinweis dankbar !

[rudolfkoenig]

strace -tt -p <fhem-pid> ausfuehren (evtl. als root), in FHEM at definieren, danach strace output analysieren (oder hier anhaengen).

[rolf]

Danke für die schnelle Reaktion.
Habe gerade einen strace erzeugt (ich hoffe das ich alles richtig gemacht habe...) und währende der strace lief einen AT-Befehl testat erzeugt.
Auffaellig sind wohl die permanenten gettimeofday Abfragen....

[rudolfkoenig]

Ich sehe nichts (ausser den Unmengen von gettimeofday), ich brauche eine zweite Version, mit
- "attr global verbose 5"
- "strace -tt -s1024 -o /tmp/xy -p <FHEM-PID>", und /tmp/xy hier anhaengen.

Ich wollte es bei mir nachstellen, und zu meiner ueberraschung ist auf meinem Linux gettimeofday in user-space, d.h. taucht in strace nicht auf. Auf welchem OS+Version laeuft Dein FHEM?

[rolf]

Im Anhang jetzt nochmal ein strace mit den gewuenschten Parametern - verbose 5 war gesetzt.

FHEM läuft bei mir auf dem Cubietruck mit Debian/Jessie - Image von armbian.com (Igor). Genaue Kernel-Version such ich noch raus und schreibe ich separat.

FHEM selber ist auf Level 5.7 und auf dem aktuellen Stand.

[rolf]

Kernel-Version ist:

cat /proc/Version

Linux version 4.8.4-sunxi (root@xenial) (gcc version 5.4.0 20160609 (Ubuntu/Linaro 5.4.0-6ubuntu1~16.04.1) ) #6 SMP Sun Oct 23 15:55:47 CEST 2016

[rudolfkoenig]

Im Anhang jetzt nochmal ein strace mit den gewuenschten Parametern - verbose 5 war gesetzt.

Ein so komplexes FHEM per strace zu analysieren ist nicht einfach. Was mir auffaellt:

- zwischen write ins FileLog und naechsten syscall vergeht einmal 1.66s (10:10:26.162307), das ist zu viel und klingt nach kaputte, sich zu oft schlafen legende oder ueberbelastete "Festplatte". Um sicher zu sein, dass die Zeit im syscall verbracht wird, braeuchte ich noch ein Lauf mit "strace -tt -T -o /tmp/xy -p <FHEM-PID>"

- das 3-mal hintereinender erfolgte "Ignoring TFATS34C_1" klingt komisch, ich braeuchte aber das komplette fhem.cfg, um zu sehen ob es ein Bug oder nur Konfiguration ist.

- dass HMLAN, Harmony und PRESENCE direkt nach dem define auf die Idee kommen was tun zu muessen, kann Bug sein, oder Zufall, ich kenne die Module dafuer zu wenig.

- die Version der CUNO abzufragen (per notify?) macht FHEM auch nicht schneller, auch wenn das nicht lange dauert.

[rolf]

Ich weiss wie aufwendig die Fehlersuche ist und bin an meinen Grenzen - umso mehr freue ich mich über die Schützenhilfe !

Im Anhang der strace und auch die fhem.cfg

SD-Karte hatte ich auch schon in Verdacht - hab mir über Weihnachten eine SSD gegönnt, d.h. Cubietruck bootet den Kernel über SD, mountet dann Root-FS direkt von der SSD.. Problem ist allerdings immer noch das gleiche, d.h. egal ob ich das Root-FS auf der SD-Karte oder per SSD mounte - die Verzögerungen beim Anlegen der AT-Befehle sind geblieben.

TFATS34C_1 ist irgendein Wettersensor aus der Nachbarschaft, hatte ich deshalb auf ignore gesetzt - hab ich rausgenommen.

Version der CUNOs (einer im EG, einer im OG) frag ich eigentlich nicht aktiv ab - hab se lediglich in einer structure definiert um den Zustand zu überwachen.

[rolf]

Ergänzende Info - habe gerade mein FHEM-System auf eine andere SD-Karte kopiert und dieses in meinem Ersatz-Cubietruck gebootet.
Leider bleibt das Fehlerbild mit den "langsamen define AT" erhalten, d.h. es liegt wohl nicht an der Hardware.

Um das Problem weiter einzugrenzen hab ich vor ein System komplett neu aufzusetzen - angedacht wäre als Basis Debian Jessie von armbian / Mainline 4.7.3 - oder gibt es eine bessere Empfehlung fuer den Cubietruck und FHEM ?
 

[rolf]

Habe heute Abend nochmal Jessie inkl. FHEM komplett neu installiert - Problem blieb mir leider erhalten.

Wenn ich mit top die CPU auf dem Cubietruck beobachte dümpelt die meist um 1-7% fuer den FHEM-Prozess herum - setze ich
den define AT-Befehl ab geht der FHEM-Prozess schlagartig auf 100% - sobald der define AT durch ist, bewegt sich alles wieder auf niedrigem Level....

[rudolfkoenig]

Ich habe mir erlaubt dein fhem.cfg zu loeschen, da es scheinbar sinnvolle Passwoerter enthaelt. Achtung, es wurde laut Forum vorher 4-mal heruntergeladen.

Deine fhem.cfg ist (selbst ohne FHEM/fhem_user.cfg) 30-mal groesser als meine, alle Achtung. Es enthaelt 1743 Definitionen, und 648 notifies. Ich glaube das ist fuer ein Cubie zu viel. Oder ich muss FHEM weiter optimieren

Ich habe damit angefangen (update ab morgen):

- da CUL_HM unfair spielt, und nach dem ersten Aufruf NotifyFn loescht, aber nicht NOTIFYDEV, versucht fhem.pl bei jeder Struktur-Aenderung (define, etc) 600-mal (fuer jeden deiner HM-Geraete) eine nicht-existierende Funktion aufzurufen. Ich habe das jetzt hoffentlich ohne Nebenwirkungen ausgebaut.

- viele deiner notify-regexps sind als (dev1:event1)|(dev2:event2) geschrieben, das wurde bisher vom fhem.pl-notify-Optimierer nicht erkannt (nur das gleichwertige dev1:event1|dev2:event2, ohne Klammer), und diese notifies wurden bei jedem Event aufgerufen. Die notifies haben dann gemerkt, dass es nicht passt, die Aufrufe waren aber sinnlos. Ich habe dem Optimierer jetzt "deine" Syntax auch beigebracht. Auf meinem alten Notebook mit deinem fhem.cfg dauert ein "define at" jetzt 0.12s.

- einige notify-regexps sind nach dem Muster dev.event gebaut, was nicht optimiert werden kann. Bitte diese auf dev:event umstellen. Merke: der Optimierer ist aktiv, falls bei notify/etc ein NOTIFYDEV Eintrag vorhanden ist.

Strace zeigt, dass die Platte/write nicht das Problem ist. Die Menge der notifies ist fuer ein Cubie zu viel. Wenn meine Optimierung nicht reicht, musst wohl ein HW-Upgrade in Betracht ziehen. Ein Vergleich mit einem neueren  Perl waere auch interessant zu sehen (bzw. messen).

Hast du eigentlich keine Funk-Probleme?
Gefuehlt alle 10 Sekunden werden hunderte von HM-Schalter umgelegt.

[rolf]

Erst mal vielen, vielen Dank für die ausführliche Analyse !

Zugegeben - meine fhem.cfg ist mit Sicherheit nicht gerade optimal - habe halt langsam erst dazu gelernt und nach oben ist noch viel Luft 

Funkprobeme hab ich keine - zwei über die Stockwerke verteilte HMLANDs wickeln den Funkverkehr gesteuert per vccu sauber ab - viel Verkehr entsteht wohl auch durch die zwei HM-Statusanzeigen - aber mit der Visualisierung bleiben die FHEM-Aktivitäten auch für meine besser Hälfte transparent

Nochmal recht herzlichen Danke für die Bemühungen, werde die dev.event-Notifies unter die Lupe nehmen und bin gespannt wieviel die Optimierungen
bringen. 

Noch zwei Bitten - welches Perl würde für einen Test Sinn machen ? - wäre INTEL NUC ein Ansatz in die richtige Richtung wenn es um etwas
leistungsstärkere Hardware geht ?

[rudolfkoenig]

Perl: ich wuerde 5.24 probieren, falls das fuer deine das Distribution gibt.
Hardware: Das ist kompliziert. Grob: ARM <= Intel Atom <= Intel Core (i3/i5/i7). ARM holt zwar auf, leider gibt es die schnellen ARM CPUs kaum in RPi/Cubie/etc, nur in teuren Handys. Andererseits kann sowas schnell ins Geld gehen, da kann man auch ueberlegen, ob man nicht lieber ein paar Sekunden wartet.