...due to full buffer in FW_Notify

Begonnen von RalfP, 03 November 2018, 14:36:18

Vorheriges Thema - Nächstes Thema

RalfP

Hallo,

ich habe/hatte ein Problem mit dem Buffer für FW_Notify.

Das Symptom ist/war, das manchmal einige Status sich in Homekit nicht aktualisiert hatten und z.B. beim Schließen der Wohnungstür Homekit mich nicht informierte.
Mein Fhem hatte ich neu aufgesetzt auf einem Pi 3b+. Im Gegensatz zur vorherigen Installation, läuft jetzt auch die Homebridge auf dem selben Pi, vorher waren es zwei Separate. Die Konfiguration habe ich fast 1:1 von der alten Fheminstallation, in die Neue übernommen.
Evtl. war die Problematik auch schon vorher, nur nicht von mir so erkannt. Jetzt habe ich aber, bedingt durch die Neuinstallation, mir die Logs der Homebridge auch mal genauer angeschaut. Dabei fiel auf, dass das longpoll für die Homebridge immer mal wieder beendet wurde.

longpoll ended, reconnect in: 200msec
starting longpoll: http://127.0.0.1:8088/fhem?XHR=1&inform=type=status;addglobal=1;filter=.*;since=1541238343.655;fmt=JSON&timestamp=1541238371012
[3.11.2018, 10:46:13] [FHEM] Checking devices and attributes...
[3.11.2018, 10:46:13] [FHEM]   executing: http://127.0.0.1:8088/fhem?cmd=%7BAttrVal(%22global%22,%22userattr%22,%22%22)%7D&fwcsrf=csrf_927144399879707&XHR=1
[3.11.2018, 10:46:13] [FHEM]   executing: http://127.0.0.1:8088/fhem?cmd=jsonlist2%20TYPE=siri&fwcsrf=csrf_927144399879707&XHR=1
[3.11.2018, 10:46:13] [FHEM] siri device is siri
[3.11.2018, 10:46:13] [FHEM]   executing: http://127.0.0.1:8088/fhem?cmd=%7B$defs%7Bsiri%7D-%3E%7B%22homebridge-fhem%20version%22%7D%20=%20%220.4.5%22%7D&fwcsrf=csrf_927144399879707&XHR=1

Auf der Suche nach der Ursache fand ich heraus, dass Fhem die Verbindung kappt:

2018.11.03 10:49:47 4: Closing connection WEBHomebridge_127.0.0.1_51708 due to full buffer in FW_Notify
2018.11.03 10:49:48 4: Connection accepted from WEBHomebridge_127.0.0.1_51936
2018.11.03 10:49:48 4: WEBHomebridge_127.0.0.1_51936 GET /fhem?XHR=1&inform=type=status;addglobal=1;filter=.*;since=1541238559.362;fmt=JSON×tamp=1541238587587; BUFLEN:0
2018.11.03 10:49:48 4: Connection accepted from WEBHomebridge_127.0.0.1_51942
2018.11.03 10:49:48 4: WEBHomebridge_127.0.0.1_51942 GET /fhem?cmd=%7BAttrVal(%22global%22,%22userattr%22,%22%22)%7D&fwcsrf=csrf_927144399879707&XHR=1; BUFLEN:0
2018.11.03 10:49:48 4: WEBHomebridge: /fhem?cmd=%7BAttrVal(%22global%22,%22userattr%22,%22%22)%7D&fwcsrf=csrf_927144399879707&XHR=1 / RL:195 / text/plain; charset=UTF-8 / Content-Encoding: gzip

(habe extra ein eigenes FHEMWEB für die Homebridge definiert, um es besser im Log finden zu können, die Zeitstempel passen nicht, weil ich das verbose erst später gesetzt hatte) 

Die Verbindung wurde wieder aufgebaut, auf einem anderen Port.

Das Doofe an der Sache war aber nun, das alle Statusänderungen, die in der Zwischenzeit aufliefen, nicht mehr an die Homebridge gegeben wurden und somit mein o.g. Symptom entstand.

Als Verursacher stellte sich, in meinem Falle, Sonos heraus. Der Abbruch erfolgte fast immer, wenn ich vor allem mehrere Aktionen hintereinander mit Sonos startete. Zum Beispiel:

..in einem Notify:
WG.Sonos.dum:on
set WG.wz.Sonos AddMember WG.ku.Sonos ;
set WG.wz.Sonos AddMember WG.az.Sonos ;
set WG.wz.Sonos AddMember WG.bz.Sonos ;
set WG.ku.Sonos Volume 8 ;
set WG.ku.Sonos Mute 0 ;
set WG.az.Sonos Volume 8 ;
set WG.az.Sonos Mute 0 ;
set WG.bz.Sonos Volume 8 ;
set WG.bz.Sonos Mute 0 ;
set WG.wz.Sonos Volume 18 ;
set WG.wz.Sonos Mute 0 ;
set WG.wz.Sonos Play

(alles auf Grundeinstellung)

Dabei wurde die Verbindung immer geschlossen mit "...due to full buffer in FW_Notify" und mein Problem war da.

Bei der Suche nach FW_Notify bin ich auf https://forum.fhem.de/index.php?topic=91962.0 gestoßen. Dort wird der Zusammenhang von longpoll und FW_Notify erklärt.

Ich habe mal geloggt wie hoch length($hash->{$wbName}) in addToWritebuffer geht, ich bin auf Spitzenwerte von fast 200k gekommen, wenn das Notify für Sonos ablief, somit habe ich mir eine Grenze von 300k in der fhem.pl gegeben.

Nun ist diese Änderung hart im Code programmiert. Mit dem nächsten Update wird es mir wieder überschrieben.

Meine Frage ist nun: Wie könnte hier eine bessere Lösung aussehen?

Gruß
Ralf

rudolfkoenig

Der Schreibpuffer setzt sich aus dem TCP/IP Puffer im OS (etliche 100k, je nach OS) + mind 100k in FHEM zusammen.
"mind 100k" heisst, dass man beliebig viel Anhaengen kann, solange die im Puffer bereits vorhandenen Daten unter 100k sind.

Ich wuerde untersuchen:
- warum SONOS Aktionen so viel longpoll Daten generieren. Ich tippe auf SVG-Icons, die homebridge vermutlich eh nicht auswertet.
- warum holt homebridge die Daten nicht schnell genug ab.

Ich bin bereit was an meinen Modulen zu modifizieren, wenn das Notwendig ist. Den Puffer einfach zu vergroessern waere aus Architektur-Sicht die schlechteste Loesung.

RalfP

Hallo Rudolf,

vielen Dank für Deine Antwort. Ich habe versucht weiter zu diagnostizieren und Lösungen zu finden. Versuche in Richtung https://cromwell-intl.com/open-source/performance-tuning/tcp.html brachten keinen Erfolg. Was sich aber weiter herauskristallisierte ist Sonos.

Selbst ein einfaches  set WG.Sonos StopAll (3x Play 1 + 1x Amp) lässt den Buffer über 100k steigen und lässt alle WEB's neue Verbindungen aufbauen. Mit Homebridge hat das in erster Linie nichts zu tun, dort bemerke ich es nur als erstes. Selbst das WEB auf 8083 geht kurzzeitig offline und reconnected. Mindestens in 7 von 10 Versuchen passiert dies. Teilweise schon, wenn ich nur einen Player starte und stoppe - erstaunlicher Weise am besten am Amp reproduzierbar.

Den Tipp mit den SVG_Icons kann ich leider nicht nachvollziehen, habe so etwas bisher noch nie angefasst.

Habe schon alles mal vom Strom genommen, was ja manchmal helfen tut, in diesem aber Falle leider nicht.

Ich glaube ich müsste dies unter Multimedia mal posten, oder?

Gruß
Ralf

rudolfkoenig

Kannst du bitte deinen Puffer erhoehen, und im Browser in der JavaScript-Console das Schalten beim SONOS mitprotokollieren?

RalfP

Hallo Rudolf,

so, habe mal versucht etwas zusammenzustellen. Den Buffer hatte ich auf 300k. Habe mir aber ab einer Grenze von 100k den Inhalt von $hash->{$wbName} ins Log schreiben lassen, wie auch die length($hash->{$wbName}). Dazu das, was die Konsole aufzeichnete. So ist anhand der Zeitstempel es ein wenig erkennbar, wenn die Grenze überschritten wird.
Die Dateien habe ich angehangen.

buffer.txt + console.txt sind der Start von 4 Sonos-Player aus Fhem heraus. Bei den Beiden anderen habe ich die Gruppe aus 4 Playern über die SonosApp gestartet. Beides lässt den Buffer >100k werden.

Was ich noch probiert habe ist, bei allen 4 Devices die Events abzuschalten (event-on-change-reading = 1 event-on-update-reading = 1), wo dann der Buffer unter 100k blieb (ca. 70k) Dies wird aber auch nicht unbedingt die Lösung sein, man braucht ja doch ein paar Events, dafür nutze ich ja Fhem.
An dieser Stelle auch mein herzlichsten Dank an Dich für deine Arbeit. 

RalfP

Hallo Rudolf,

übrigens der Browser ist Safari, sofern wichtig.

Gruß
Ralf

rudolfkoenig

Zitatbuffer.txt + console.txt sind der Start von 4 Sonos-Player aus Fhem heraus.
Das erzeugt etwa 360 Events. Ich finde das ist zu viel, und das sollte im SONOS Modul geaendert werden.
Vermutlich indem die Initialisierung keine Events erzeugt, sondern nur die Readings auf den aktuellen Wert setzt.

Ich habe aber in fhem.pl die Grenze von 100k auf 1MB hochgesetzt, damit sollte erstmal dein Problem geloest sein.

RalfP

...klingt sehr gut. Ich werde mir diese Events auch nochmal anschauen und was ich mit den attr dann optimieren kann, aber den Komfort nicht groß einschränke. Mir ist es auch viel zu viel, was da generiert wird.

Vielen Dank für deine Unterstützung und Hilfe.

Gruß
Ralf