GELÖST: Filedescriptor ermitteln, Hänger finden

[Dr. Boris Neubert]

Hallo,

ich leide darunter, daß FHEM massiv lahmt (= hohe Latenz), sei es in der Konsole oder im Webinterface. Ich schaue mir an, wo die Zeit verplempert wird:

Code Auswählen Erweitern


strace -p PIDvonFHEM -ttTr -o strace.log
tail -f strace.log | grep -v '<0.'


zeigt mir alle Systemaufrufe an, die eine Sekunde oder länger laufen:

Code Auswählen Erweitern


     0.002098 select(56, NULL, [48], NULL, {2, 0}) = 0 (Timeout) <2.002416>
     0.002434 select(56, NULL, [48], NULL, {2, 0}) = 0 (Timeout) <2.002430>
     0.001868 select(112, NULL, [104], NULL, {2, 0}) = 0 (Timeout) <2.002391>
     0.002227 select(112, NULL, [104], NULL, {2, 0}) = 0 (Timeout) <2.002367>
     0.002046 select(112, NULL, [104], NULL, {2, 0}) = 0 (Timeout) <2.002390>
     0.002078 select(112, NULL, [104], NULL, {2, 0}) = 0 (Timeout) <2.002445>
     0.002014 select(112, NULL, [104], NULL, {2, 0}) = 0 (Timeout) <2.002559>
     0.002612 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 102180) = 102180 <54.044077>
     0.002187 select(112, NULL, [104], NULL, {2, 0}) = 0 (Timeout) <2.002428>
     0.002205 select(112, NULL, [104], NULL, {2, 0}) = 0 (Timeout) <2.002372>
     0.002366 select(56, NULL, [48], NULL, {2, 0}) = 0 (Timeout) <2.010422>
     0.002065 select(56, NULL, [48], NULL, {2, 0}) = 0 (Timeout) <2.002398>
     0.002128 select(56, NULL, [48], NULL, {2, 0}) = 0 (Timeout) <2.002445>
     0.002514 select(56, NULL, [48], NULL, {2, 0}) = 0 (Timeout) <2.001521>


Ich sehe zum einen, daß Webseiten teilweise mit enormer Verzögerung auf Filedescriptor 101 ausgeliefert werden. Ich sehe aber auch Timeouts auf Filedescriptor 112, 104 und 56.

Wir kann ich herausfinden, welche Geräte diese Filedescriptoren nutzen?

Code Auswählen Erweitern


{ foreach my $key (keys %defs) { if(defined($defs{$key}{FD})) { print $key . ": " . $defs{$key}{FD} . "\n" } } }


zeigt mir nämlich nur

Code Auswählen Erweitern


CUN: 13
webserver1: 9
CUL: 11
FHEMWEB:192.168.31.77:63387: 102
webserver2: 10
FHEMWEB:192.168.31.77:63388: 48
AVRNETIO: 8
AVRNETIO2: 73
telnetPort: 6
CM11: 5
telnet:192.168.31.8:38219: 103


Viele Grüße
Boris

[Dr. Boris Neubert]

Nachtrag: sind ein paar echt brutale Hänger bei der Auslieferung von Webseiten (FrameRSS und FHEMWEB) dabei:

0.002589 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 88692) = 88692 <1.714188>
     0.002076 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 79879) = 79879 <1.738280>
     0.003186 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 81867) = 81867 <1.764206>
     0.002509 write(109, "HTTP/1.1 200 OK\r\nContent-Length:"..., 105973) = 105973 <84.137766>
     0.002689 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 99770) = 99770 <6.899401>
     0.002919 write(104, "HTTP/1.1 200 OK\r\nContent-Length:"..., 96973) = 96973 <27.119286>
     0.002542 write(104, "HTTP/1.1 200 OK\r\nContent-Length:"..., 88323) = 88323 <3.436835>
     0.002612 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 102180) = 102180 <54.044077>
     0.002693 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 123493) = 115340 <215.715080>
     0.002375 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 90038) = 90038 <3.523256>
     0.002761 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 97635) = 97635 <3.529304>
     0.003286 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 87495) = 87495 <1.778362>
     0.002863 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 103568) = 103568 <3.453248>
     0.003235 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 87373) = 87373 <1.753771>
     0.002995 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 97628) = 97628 <6.928968>
     0.003015 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 108286) = 108286 <54.128013>
     0.002224 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 78067) = 78067 <1.586538>
     0.002464 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 79206) = 79206 <3.374005>
     0.003402 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 96306) = 96306 <27.030293>
     0.002991 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 75035) = 75035 <1.580664>
     0.003166 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 81018) = 81018 <3.365794>
     0.002855 write(104, "HTTP/1.1 200 OK\r\nContent-Length:"..., 118925) = 115340 <215.799736>
     0.002994 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 70229) = 70229 <1.593429>
     0.008100 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 82553) = 82553 <1.767228>
     0.003313 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 109786) = 108040 <215.614713>
     0.003175 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 113540) = 108040 <215.768233>
     0.002408 write(48, "HTTP/1.1 200 OK\r\nContent-Length:"..., 94402) = 94402 <3.348065>
     0.002429 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 87943) = 87943 <6.713682>
     0.002581 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 72364) = 72364 <1.571730>
     0.003755 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 96269) = 96269 <26.989210>
     0.003356 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 105730) = 105730 <84.028372>
     0.002711 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 75354) = 75354 <1.629314>
     0.003589 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 101042) = 101042 <26.957112>
     0.003029 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 92373) = 92373 <13.653338>
     0.002334 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 78908) = 78908 <3.353236>
     0.002819 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 75584) = 75584 <1.601431>
     0.002867 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 69004) = 69004 <1.593891>
     0.002515 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 95325) = 95325 <28.346216>
     0.002821 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 68377) = 68377 <1.592705>
     0.002426 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 76339) = 76339 <1.579382>
     0.005229 write(103, "HTTP/1.1 200 OK\r\nContent-Length:"..., 153256) = 118260 <226.163602>
     0.003552 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 82243) = 82243 <3.298644>
     0.002570 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 76577) = 76577 <1.586969>
     0.003103 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 136770) = 115340 <215.911152>
     0.002784 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 92964) = 92964 <1.747179>
     0.003155 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 68128) = 68128 <1.579645>
     0.002422 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 90649) = 90649 <3.328377>
     0.002552 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 83324) = 83324 <3.338918>
     0.002617 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 80269) = 80269 <1.630688>
     0.003984 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 127214) = 108040 <215.639109>
     0.002411 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 73765) = 73765 <1.581534>
     0.003044 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 91687) = 91687 <3.353827>
     0.002540 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 94898) = 94898 <13.716811>
     0.002716 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 67798) = 67798 <1.568239>
     0.002913 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 75486) = 75486 <1.597398>
     0.002960 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 104625) = 104625 <27.036636>
     0.003755 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 73458) = 73458 <1.580050>
     0.015446 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 70622) = 70622 <1.579651>
     0.003540 write(103, "HTTP/1.1 200 OK\r\nContent-Length:"..., 84468) = 84468 <1.764102>
     0.003511 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 74486) = 74486 <1.608765>
     0.002541 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 94695) = 94695 <27.026100>
     0.003782 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 78208) = 78208 <1.611226>
     0.003030 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 124006) = 110960 <215.838667>
     0.003444 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 104388) = 104388 <27.121871>
     0.002865 write(73, "HTTP/1.1 200 OK\r\nContent-Length:"..., 88479) = 88479 <13.538930>
     0.003925 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 81063) = 81063 <3.308891>
     0.002450 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 96867) = 96867 <27.052190>
     0.002567 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 113023) = 113023 <84.031215>
     0.016239 write(101, "HTTP/1.1 200 OK\r\nContent-Length:"..., 68198) = 68198 <1.589537>
     0.004664 write(102, "HTTP/1.1 200 OK\r\nContent-Length:"..., 116984) = 108040 <215.538014>


...und ich habe keine Ideen mehr, wie ich nach der Ursache forschen soll.

[rudolfkoenig]

Die FD muesste man mit list .* FD ausgeben koennen. Oder in /proc/fhem-pid/fd nachschauen, falls es linux ist.

[Dr. Boris Neubert]

Danke Rudi.  Habe es dokumentiert: http://www.fhemwiki.de/wiki/Strace_verwenden

Code Auswählen Erweitern


17:16:08.968221 select(80, NULL, [73], NULL, {2, 0}) = 0 (Timeout) <2.003022>
17:16:11.013502 select(80, NULL, [73], NULL, {2, 0}) = 0 (Timeout) <2.002830>
17:16:13.058697 select(80, NULL, [73], NULL, {2, 0}) = 0 (Timeout) <2.002915>
17:16:15.099396 select(80, NULL, [73], NULL, {2, 0}) = 0 (Timeout) <2.002943>
17:16:17.140573 select(80, NULL, [73], NULL, {2, 0}) = 0 (Timeout) <2.003109>


zeigt also den Versuch, auf FD 73 zu schreiben. Das ist

Code Auswählen Erweitern


lrwx------ 1 root root 64 Jul 21 16:54 73 -> socket:[516488]


und

Code Auswählen Erweitern


lsof | grep 516488


gibt

Code Auswählen Erweitern


perl      14795             fhem   73u     IPv4     516488      0t0        TCP raspi:8083->frame:33184 (ESTABLISHED)


Aha, FHEM kann also nicht per RSS-Extension von FHEMWEB via HTML an den WLAN-Bilderrahmen liefern.

Das liegt daran, daß die HTML-Verbindung klemmt. Man sieht das auch mit

Code Auswählen Erweitern


list .* FD
[code]

auf der Kommandozeile von FHEM:

[code]
...
FHEMWEB:192.168.31.77:33169 104
FHEMWEB:192.168.31.77:33170 73
FHEMWEB:192.168.31.77:33171 102
FHEMWEB:192.168.31.77:33172 105
...

Es sind vier Verbindungen zum Frame (192.168.31.77) offen.

Vermutung: die Verbindung zum Bilderrahmen ist durcheinander und es liegt an der Geschichte mit dem unsauberen Beenden von HTTP-Verbindungen. Vor einigen Monaten ging das noch. Ich kann mich aber nicht daran erinnern, ob und was in FHEMWEB geändert wurde, daß die Verbindung nicht mehr stabil ist.

Viele Grüße
Boris

[rudolfkoenig]

Kannst du versuchen das close... FHEMWEB Attribut zu setzen? Sorry, bin unterwegs ohne Quellen.

[Dr. Boris Neubert]

Kannst du versuchen das close... FHEMWEB Attribut zu setzen? Sorry, bin unterwegs ohne Quellen.

Danke für den Hinweis. closeConn behebt die Hänger bei der Auslieferung des Bildes ans den WLAN-Bilderrahmen per FHEMWEB via RSS nicht.

16:34:53.145970 select(112, [4 5 7 8 9 10 12 47 72 99 100 103 104], NULL, NULL, {1, 887938}) = 1 (in [72], left {1, 887868}) <0.001201>
16:34:56.716484 select(112, [4 5 7 8 9 10 12 47 72 99 100 103 104], [72], NULL, {6, 353157}) = 1 (out [72], left {6, 353093}) <0.001146>
16:34:56.721025 write(72, "HTTP/1.1 200 OK\r\nContent-Length:"..., 117466) = 108040 <215.669481>

Allerdings gibt es keine mehrfachen offenen Verbindungen mehr zum Bilderrahmen.

Ich hatte vor einiger Zeit mal einen Patch vorgeschlagen, der die Auslieferung sämtlicher Daten von FHEMWEB in einen Subprozess auslagert (analog plotforkSVG für Grafiken). Damit würden dann alle Webseiten grundsätzlich asynchron ausgeliefert. Was hältst Du davon?

Viele Grüße
Boris

[Dr. Boris Neubert]

ich leide darunter, daß FHEM massiv lahmt (= hohe Latenz), sei es in der Konsole oder im Webinterface. Ich schaue mir an, wo die Zeit verplempert wird:

Code Auswählen Erweitern


     0.002098 select(56, NULL, [48], NULL, {2, 0}) = 0 (Timeout) <2.002416>


For the records: die 2-Sekunden-Hänger kommen von ICMP-Pings auf augeschaltete Rechner. Mit den Pings stelle ich fest, welche Rechner im lokalen Netz erreichbar sind.

Ich habe das jetzt auf SYN/ACK-Pings umgestellt, mit denen ich alle 10 Rechner auf einmal mit einstellbaren sehr kurzen Timeout überprüfe. Und siehe da: ich habe wieder eine hohe Schwuppdizität im FHEMWEB.

Viele Grüße
Boris

[rudolfkoenig]

Was hältst du davon?

Immer noch wenig, weil ein set dann im Kind-Prozess den Status setzt. Und wir haben immer noch Probleme im geforkten Prozess mit db & co.

[Dr. Boris Neubert]

Uh, hinter

Code Auswählen Erweitern


  my $cacheable = FW_answerCall($arg);
  return if($cacheable == -1); # Longpoll / inform


kommt doch nichts mehr außer der Rückgabe von FW_RET auf den Socket. Oder übersehe ich da was?


Grüße
Boris

[justme1968]

ich glaboris meint nicht fhemweb komplett in einen prozess zu stecken sondern nur das ausliefern der kompletten seite. also jedes mal neu zu forken.

aber auch dabei bleiben glaube ich noch ein paar globals die nicht so einfach zurück gegeben können. z.b. dir liste der devices die gerade angezeigt wird und für die dann longpoll gesendet werden muss.

gruss
  andre

[Dr. Boris Neubert]

Hallo,

ja, Andre, Du hast wiedergegeben, was ich sagen will.

ich habe gerade noch folgendes versucht: in TcpServerUtils.pm die Option Timeout => 5 den Optionen hinzugefügt. Das funktioniert aber nicht, wobei es auch Berichte im Internet gibt, daß das nicht funktioniert.

Alternativ könnten wir in MAIN, wo der WriteBuffer geschrieben wird, das SysWrite mit einem gerätespezifischen Alarm (siehe http://perldoc.perl.org/functions/alarm.html) umgeben (neues allgemeines Attribut writeTimeout), der bei Hängern das syswrite beendet.

Grüße
Boris

[rudolfkoenig]

Ich habe fuer FHEMWEB das alarmTimeout Attribut testweise eingebaut, zunaechst ohne Doku. Falls gesetzt und nicht 0 (z.Bsp "attr WEB alarmTimeout 5"), spezifiziert das alarm Argument for dem syswrite. Boris, koenntest Du bitte pruefen ob, das dein Problem loest?
Evtl. loest es noch das Problem hier auch.

[Dr. Boris Neubert]

Hallo,

Blitzschlag hat am Sonntag meine halbe Netzwerkinfrastruktur und Hausautomation geschrottet. Melde mich wieder, wenn die Reservegeräte angekommen und in Betrieb sind.

Grüße
Boris

[Dr. Boris Neubert]

Hallo Rudi,

ich habe jetzt alarmTimeout mit der Mindestdauer von einer Sekunde auf meiner FHEMWEB-Instanz aktiviert und sehe mir im Browser den RSS-Feed (02_RSS-Plugin) an, der auch zu meinem Bilderrahmen bzw. jetzt Tablet mit WebViewControl geht. Der RSS-Feed ist eine sich alle 15 Sekunden refreshende HTML-Datei mit eingebetteter Grafik, die bei jedem Aufruf on-the-fly erstellt wird

Ergebnis:
1) Ich bekomme keine Meldungen "ALARM signal, blocking write?" im Log. Das bedeutet also, dass der syswrite auf den Socket innerhalb 1 Sekunde die Daten an den Client loswird.
2) apptime zeigt mir, dass in mehreren Verbindungen von meinem Browser aus im Durchschnitt 1 bis 3 Sekunden und in der Spitze 10 bis 28 Sekunden in FW_Read verbracht werden.

Fazit: die Hänger entstehen durch die Zeit, die für die Zusammenstellung des RSS-Feeds benötigt wird.

Ich komme daher auf meinen Vorschlag zurück, in FW_Read die gesamte Auslieferung der Seite zu forken, wenn ein Attribut alwaysFork an der FHEMWEB-Instanz gesetzt ist (analog plotfork für die SVG-Elemente). Dadurch bleibt die Schwuppdizität von FHEM erhalten, selbst wenn es beim Seitenaufbau auf einer anderen Verbindung gerade länger dauert.

Viele Grüße
Boris

[Dr. Boris Neubert]

Hallo,

habe den hinteren Teil des Threads als "Forkable FHEMWEB Extensions" abgetrennt.

Viele Grüße
Boris