FHEM reagiert teilweise mehrere Sekunden nicht

[reibuehl]

Ich habe FHEM auf einem RaspberryPI installiert und habe das Problem, dass die Weboberfläche nach einem klick auf einen Link meist bis zu 45 Sekunden braucht. So jeden 4. oder 5. klick geht es dann aber ein oder zwei mal blitzschnell.
Das Verhalten scheint unabhängig von der Art der Aktion zu sein, d.h. egal ob ich nur einen Raum anzeigen will oder ein Kommando absetze und auch gleiche Aktionen gehen mal sehr schnell und mal brauchen sie bis zu 45 Sekunden.
Laut Top ist das System nicht wirklich busy - load average ist immer so zwischen 0.10 und 0.25.

Gibt es eine Möglichkeit, herauszufinden, was diese temporären Verzögerungen auslößt?

Reiner

[marvin78]

Ich hatte das Problem auf meinem Pi, als ich DBLog probiert und für die MySQl Daten die SD-Karte verwendet habe. Jetzt habe ich für die MySQl Daten und die Logdatei eine externe USB Festplatte (SSD) angeschlossen und mein Pi läuft wie geschmiert.

Nutzt du DBLog?

[thd]

Gibt es eine Möglichkeit, herauszufinden, was diese temporären Verzögerungen auslößt?

Vielleicht wäre strace hilfriech für Dich
sudo apt-get install strace
sudo strace -p $(pidof perl fhem.pl)

Gibt ein log der Kernel-Aufrufe des FHEM-Prozesses aus. Das ist aber sehr schnell sehr viel. Mit

sudo strace -p $(pidof perl fhem.pl) -o /tmp/strace.txt

Wird die Ausgabe in eine Datei /tmp/strace.txt umgeleitet.

[reibuehl]

Ich verwende nur FileLogs, kein DBLog.

Ich werde es mal mit strace probieren...

[reibuehl]

Ich hab mal strace gestartet und dann einen Link geklickt. Scheinbar verwendet das System 97% seiner Zeit für zwei "clone" aufrufe:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
96.87    0.005200        2600         2           clone
  3.13    0.000168           5        32           read
  0.00    0.000000           0        30           write
  0.00    0.000000           0         1           open
  0.00    0.000000           0         6           close
  0.00    0.000000           0         2         2 kill
  0.00    0.000000           0         2           brk
  0.00    0.000000           0        24        24 ioctl
  0.00    0.000000           0       194           gettimeofday
  0.00    0.000000           0        24        24 _llseek
  0.00    0.000000           0        52           select
  0.00    0.000000           0       119           stat64
  0.00    0.000000           0         2           getdents64
  0.00    0.000000           0        12           fcntl64
  0.00    0.000000           0        12           accept
------ ----------- ----------- --------- --------- ----------------
100.00    0.005368                   514        50 total


Das ganze scheint also wohl eher nicht mit der SD Karte zu tun zu haben, oder?

[herrmannj]

Hallo Reiner,

welche fhem version ?

vg
Jörg

[reibuehl]

Hallo Jörg,

die FHEM Version wurde zum letzten Mal gestern per update auf den neuesten Stand gebracht:

Code Auswählen Erweitern


# $Id: fhem.pl 4565 2014-01-05 22:17:37Z rudolfkoenig $
# $Id: 00_CUL.pm 4530 2014-01-02 13:56:09Z rudolfkoenig $
# $Id: 09_CUL_FHTTK.pm 4229 2013-11-15 17:29:55Z rudolfkoenig $
# $Id: 10_CUL_HM.pm 4596 2014-01-09 19:16:20Z martinp876 $
# $Id: 57_Calendar.pm 4194 2013-11-09 18:58:18Z borisneubert $
# $Id: 01_FHEMWEB.pm 4586 2014-01-07 11:48:46Z rudolfkoenig $
# $Id: 10_FS20.pm 3764 2013-08-22 07:09:38Z rudolfkoenig $
# $Id: 92_FileLog.pm 4574 2014-01-06 14:12:42Z rudolfkoenig $
# $Id: 00_HMLAN.pm 4562 2014-01-05 15:22:54Z martinp876 $
# $Id: 73_PRESENCE.pm 4342 2013-12-08 09:39:25Z markusbloch $
# $Id: 99_SUNRISE_EL.pm 4537 2014-01-03 08:28:59Z rudolfkoenig $
# $Id: 98_SVG.pm 4503 2013-12-29 18:38:50Z rudolfkoenig $
# $Id: 45_TRX.pm 3784 2013-08-24 19:04:30Z wherzig $
# $Id: 46_TRX_WEATHER.pm 3874 2013-09-08 04:26:07Z wherzig $
# $Id: 99_Utils.pm 3595 2013-08-05 05:38:48Z tobiasfaust $
# $Id: 70_WS3600.pm 4100 2013-10-23 09:22:03Z joes1 $
# $Id: 98_autocreate.pm 4234 2013-11-17 10:19:41Z rudolfkoenig $
# $Id: 98_dummy.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
# $Id: 91_eventTypes.pm 2982 2013-03-24 17:47:28Z rudolfkoenig $
# $Id: 95_holiday.pm 3602 2013-08-07 13:06:49Z rudolfkoenig $
# $Id: 91_notify.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
# $Id: 98_telnet.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $


Gruß,
Reiner.

[herrmannj]

dann kann die dieses modul bei der suche helfen http://forum.fhem.de/index.php/topic,16347.msg106295.html#msg106295.

Den verbose level hochstellen damit du im log was siehst.

vg
jörg

[reibuehl]

Ich habe das Modul geladen und sehe jetzt auch immer wieder Meldungen über mögliche freezes. Wenn ich im log nachschaue, was zur unter "possibly starting" Zeit drin steht, ist meist Einträge wie diese:

Code Auswählen Erweitern

2014.01.11 21:29:21 4: FileLog_OG_Heizung get: Input file ./log/OG_Heizung-2014.log, from:2014-01-11_00:00:00  to:2014-01-12_00:00:01
2014.01.11 21:29:24 4: FileLog_OG_Heizung get: line 1, regexp:OG_BD_Thermostat_ClimRT_tr.measured-temp\x3a, col:3, output lines:89
2014.01.11 21:29:24 4: FileLog_OG_Heizung get: line 2, regexp:OG_BD_Thermostat_ClimRT_tr.ValvePosition\x3a, col:3, output lines:89
...
2014.01.11 21:29:28 1: Perfmon: possible freeze starting at 21:29:22, delay is 6.355

Es scheint meist im Zusammenhang mit FileLog Vorgängen von einem meiner vier HM-CC-RT-DN aufzutreten...

[herrmannj]

sieht so aus. Kommt das vom laden eines plots ? Wie gross ist das filelog ?

vg
Jörg

[reibuehl]

Die Hänger scheinen unabhängig davon aufzutreten, ob ich eine Seite mit einem plot aufrufe oder nicht. Das FileLog ist im Moment 288KB groß.

[justme1968]

wenn ich das richtig sehe hast du verbose global oder zumindest für das filelog auf 4 stehen. damit schreibt es jede zeile die aus dem log gelesen wird ins fhem log. das sind dann etwa 288k auf einen schlag vor jedem plot.

damit ist zum einen deine sd karte ruck zuck voll und zum anderen dauert es auf einer relativ langsamen sd karte eine weile.

du solltest verbose im normal betrieb höchstens auf 3 stehen haben.

gruss
  andre

[herrmannj]

hmm, 300kB sind ja nicht die Welt.  Dem log nach liest er aus dem filelog - aber ob das dann wirklich die Ursache ist .

Hängt er auch wenn Du nicht per web/telnet/app etc drauf bist ?

vg
jörg

[justme1968]

sd karten sind aber zum einen nicht die schnelslten zum anderen wird concurrent das filelog zeilenweise gelesen und das fhem log geschrieben. je nach blockgrösse kann das locker 5 sekunden dauern.

zumindest wäre sehr einfach rauszufinden ob es das ist

gruss
  andre

[reibuehl]

Die Hänger sind auch bei verbose 3 aufgetreten. Verbose 5 habe ich nur heute eingefügt, da Jörg dies für das Debugging mit dem Perfmon Modul empfohlen hat.

Die Perfmon ausgaben kommen auch immer wieder mal, wenn nicht per GUI auf FHEM zugegriffen wird.