FHEM Forum

Ich habe ein Problem "mit Timeouts", dass ich hier darstellen möchte und das ich mit zwei "Hacks" in Perl "abgemildert" und schließlich tatsächlich über eine einzeilige Anpassung in 01_FHEMWEB.pm beheben konnte.

Zum Problem:
Bei der Abfrage eines SVG Plot's bekomme ich Timeouts. Log Datei ist ca. 7 MB mit ca. 140.000 Zeilen, davon etwa 26.000 Zeilen relevant.
Bei den ersten Analyse-Versuchen mit curl habe ich nach ca. 90 Sekunden trotz --max-time 3600 --speed-limit 1 --speed-time 3000 den Fehler curl: (52) Empty reply from server bekommen. Ich hatte es ursprünglich als eigenes Problem meiner Umgebung erachtet, denn mit dem Browser FireFox dauert es länger. Die Erhöhung von network.http.response.timeout auf 1800 Sekunden führt trotzdem (nach ca. 20 Minuten) auch im Browser zum Fehler Die Verbindung zum Server wurde zurückgesetzt, während die Seite geladen wurde.: Das Diagramm wird einfach nicht erzeugt.

Eine genauere Analyse mit Wireshark ergab, dass tatsächlich von *FHEM* die Verbindung abgebaut wurde. Der Browser hat das auch erkannt und die Anfrage nach ca. 2 Minuten / alle 2 Minuten einfach erneut gesendet: Vmtl. das Problem von https://heinz-otto.blogspot.com/2015/03/browser-timeout-und-fhem.html / http://forum.fhem.de/index.php/topic,28511.msg213591.html#msg213591.

Zu Timeouts habe ich nichts rechtes im Forum gefunden, im Log bei normaler Einstellung verbose=3) war auch nichts erkennbar. Mit verbose=5 taucht ein sehr unscheinbares Closing inactive connection WEB_127.0.0.1_48334 auf: Demnach wird in FW_closeInactiveClients im Modul 01_FHEMWEB.pm die Verbindung geschlossen, die eigentlich auf Daten warten würde / zu sendende Daten hat.

Es scheint also ein Problem zu geben: Wenn die Antwort zu lange dauert, wird der Socket noch vor der Rückmeldung geschlossen.

Über das Forum bin ich darauf gestoßen, dass

• evtl. schon die Werte "dünner" hätten sein sollen: Ich hatte die Werte periodisch eingerichtet, damit ich einen Anhaltspunkt habe, wenn Werte "fehlen" und diese nicht nur bei Änderung gespeichert, außerdem habe ich ein paar Werte mehr erfasst, als ich aktuell auswerte.
• evtl. DBLog besser wäre - vgl. auch jahresübergreifende Logs
• evtl. LogProxy auch noch einen Versuch wert wäre
• es auch Caching gibt - was aber hier nichts brachte, da das Diagramm nie komplett erstellt werden konnte

Auch ist mir klar, dass ein Pi Zero Leistungsgrenzen hat.

Ursprünglich habe ich versucht, die Antwortzeit zu reduzieren. Vielleicht hilft es ja mal irgendwem, daher habe ich das im nachfolgenden Teil 1 skizziert:

Lösungsteil 1:

Ich wollte das Problem der Laufzeit besser verstehen und habe mich dazu etwas im Code umgesehen. Im Modul 98-SVG.pm über SVG_getData bin ich darauf gestoßen, dass wohl FileLog_Get aus 92_FileLog.pm aufgerufen wird.

Darin ist der Zweig sichtbar, in dem ggf. eine temporäre Datei (bei Dateiwechsel mit createGluedFile=1) erzeugt wird. Das hat mich auf die folgende Idee gebracht:

Work-Around Idee:
Ich wollte prüfen, ob der Timeout verschwindet, wenn ich die Log-Daten "verkleinere": Dazu wollte ich die Daten per grep über eine (neue) temporäre Datei "vorfiltern".

Tatsächlich hat das funktioniert, die Verarbeitung war erheblich schneller. Nachteilig wäre - gerade bei kleinen Systemen mit SD oder USB-Speicher - die Schreiblast. Daher habe ich mich an einer "Abwandlung" mit Pipe versucht, die als Proof of Concept funktioniert. Allerdings habe ich für den "RESCAN"-Fall wieder die Datei geöffnet. Es ist ein bisschen ein Hack...

Work-Around:
Für das Filtern benötige ich die regulären Ausdrücke "column_specs". Ich erstelle mir daraus einen Suchstring der ein paar Sonderfälle escaped/quoted und das (mir unverständliche) \\x3a entfernt:
  my $eFun = sub {  my ($s) = @_;  $s =~ s/\\/\\\\/g; $s =~ s/\\\\x3a//g; $s =~ s/"/\\"/g; $s; };
  my $grpStr = join "|", map { $eFun->($_->{re}) } grep { defined $_->{re} } @d;

Danach lege ich den Input File Handle auf eine Pipe um:
  $ifh->close() if($ifh);
  open($ifh, "grep -E \"" . $grpStr . "\" " . $inf . " |");
  binmode($ifh, ":encoding(UTF-8)") if($ifh && $unicodeEncoding);

Falls das goto RESCAN zum Zuge kommt, schließe ich den Handle und öffne wieder die "original" Datei. Für meinen einfachen Testfall war das ausreichend (bzw. wurde nicht durchlaufen). Eine Erweiterung auf mehrere Eingabedateien (ohne "Glue" Attribut) wäre recht überschaubar.

Der Ansatz mit der externen Abhängigkeit zu grep (Plattformneutralität!) ist aber von vorn herein nicht ideal (eben "Hack").

Allerdings ist die Laufzeit damit soweit gesunken, dass ich keinen Timeout mehr hatte.

Lösungsteil 2:

Das eigentliche Problem ist, dass die Verbindung geschlossen wird, obwohl sie noch wartet / Daten zu senden hätte. Mein "Hack" hat dazu in FW_closeInactiveClients einfach die Zeitdifferenz zum letzten Zugriff von "60" auf "300" erhöht. Damit ist das Problem auch "umgangen".
Vielleicht könnte es für Fehlersuche hilfreich sein, wenn man das parametrisieren könnte.

Schließlich noch meine Lösung:

Die Verbindung wird abgebaut, wenn eigentlich Daten zurückgegeben werden sollen. Daher habe ich die LASTACCESS Zeit aktualisiert, wenn Daten in FW_addToWritebuffergeschrieben werden. Dazu habe ich in der Funktion am Ende ergänzt:
$hash->{LASTACCESS} = time();
Damit funktioniert es jetzt auch ohne die anderen Work-Arounds, selbst wenn ich mit einem Sleep die Dauer sehr ausdehne.