Mahlzeit!
Ich habe aktuell massive Probleme mit dem Sonos-Modul. Obwohl ich heute keine Änderungen an FHEM oder dem Sonos-Setup vorgenommen habe, habe ich seit einer Stunde massive Freezes im Minutenbereich, die Apptime auf Sonos zurückführt:
name function max count total average maxDly
OG.WO.Sonos SONOS_Read 256576 16 513438 32089.88 0 HASH(OG.WO.Sonos)
Selbst nach diversen FHEM-Neustarts inkl. Killen des 00_SONOS-Prozesses tritt das Problem regelmäßig auf. Ein Log mit verbose 5 des Sonos-Moduls habe ich für den Zeitraum des letzten Freezes und stelle es gerne per PN zur Verfügung. Wegen der enthaltenden IDs möchte ich es ungern posten. Auszüge poste ich gerne, sofern Ihr mir mitteilt, wonach ich suchen muss.
Patrick
Hallo Patrick,
die Prozedur SONOS_Read ist die Hauptempfangsprozedur im Sonos-Modul im Fhem-Prozessraum. Dort landen die (alle) Aufrufe des SubProzesses an Fhem.
Wenn da irgendetwas blockiert, dann scheint etwas nicht vollständig angekommen zu sein, da die Prozedur auf ein Zeilenende für einen Befehl wartet, und erst dann diese Zeile Verarbeitet.
Kann es sein, dass bei dir Perl sich selbst seine Threads über die Netzwerkschnittstelle blockiert?
Versuch doch mal testweise (wenn du die Möglichkeit hast), den Subprozess auf einer anderen Maschine zu starten, und in Fhem dann die entsprechenden Verbindungs-Daten der neuen Position einzutragen.
Starten kannst du den SubProzess einfach durch einen direkten Perl-Aufruf:
perl 00_SONOS.pm <Port> <VerboseLevel> [MSecLog-Flag:0,1]
Port: Ein freier Port auf der lokalen Maschine, z.B. 4711
VerboseLevel: Level für die Log-Ausgabe (auf der Konsole), z.B. 4
MSecLog-Flag: 1, wenn die Log-Ausgabe Millisekunden enthalten soll, 0 oder keine Angabe für normale Ausgabe mit Sekundengenauigkeit
Vielleicht erhältst du so zumindest ein paar neue Erkenntnisse über das Problem...
Grüße
Reiner
Hallo Reiner,
danke für die schnelle Antwort.
Zitat von: Reinerlein am 01 Januar 2017, 22:10:53
die Prozedur SONOS_Read ist die Hauptempfangsprozedur im Sonos-Modul im Fhem-Prozessraum. Dort landen die (alle) Aufrufe des SubProzesses an Fhem.
Wenn da irgendetwas blockiert, dann scheint etwas nicht vollständig angekommen zu sein, da die Prozedur auf ein Zeilenende für einen Befehl wartet, und erst dann diese Zeile Verarbeitet.
Das ist natürlich insofern ärgerlich, als dass es das ganze FHEM für 4 Minuten lahmlegt und das leider mehrfach am Stück. Besteht die Möglichkeit, dort ein Timeout einzubauen?
Zitat von: Reinerlein am 01 Januar 2017, 22:10:53
Kann es sein, dass bei dir Perl sich selbst seine Threads über die Netzwerkschnittstelle blockiert?
Offenbar, wenn aus welchem Grund auch immer das Zeilenende nicht kommt. Oder verstehe ich Dich falsch?
Zitat von: Reinerlein am 01 Januar 2017, 22:10:53
Versuch doch mal testweise (wenn du die Möglichkeit hast), den Subprozess auf einer anderen Maschine zu starten, und in Fhem dann die entsprechenden Verbindungs-Daten der neuen Position einzutragen.
Starten kannst du den SubProzess einfach durch einen direkten Perl-Aufruf:
perl 00_SONOS.pm <Port> <VerboseLevel> [MSecLog-Flag:0,1]
Port: Ein freier Port auf der lokalen Maschine, z.B. 4711
VerboseLevel: Level für die Log-Ausgabe (auf der Konsole), z.B. 4
MSecLog-Flag: 1, wenn die Log-Ausgabe Millisekunden enthalten soll, 0 oder keine Angabe für normale Ausgabe mit Sekundengenauigkeit
Vielleicht erhältst du so zumindest ein paar neue Erkenntnisse über das Problem...
Mache ich morgen mal. Mir ist aber ehrlich gesagt nicht ganz wohl dabei, mit dem Produktivsystem zu experimentieren. Ggf. baue ich mir ein Testsystem auf und bei meinem Glück tritt das Problem dann nicht mehr auf... Welche Fehlerquellen möchtest Du mit dem Test ausschließen? Wäre ggf. ein vollständiger Dump der Kommunikation bei unverändertem Setup aufschlussreicher?
Kannst Du mal einen Blick auf das verbose-5-Log werfen?
Patrick
Hi Patrick,
ich möchte damit ein etwaiges Problem der Thread Implementierung ausschließen.
Threads/SubProzesse sind in Perl gelinde gesagt ziemlich doof umgesetzt, und es könnte gut sein, dass die Übertragung zwischen zwei Ports in einem einzigen Prozessraum zu Blockaden führen kann, und einfach nicht alle Zeichen in einem Rutsch übertragen werden, da sie von der Größe her vielleicht nicht in einen vorgegebenen Pufferplatz passen...
Zum Basteln an Produktivsystemen: Ich denke, es blockiert sowieso, oder? :)
Oder heißt Blockade, dass es irgendwann einfach normal weitergeht, als wäre nichts gewesen?
In der Logausgabe wären nur die letzten Zeilen vor/während der Blockade interessant, da ja alles vorher glatt durchgegangen sein muss.
Was steht denn dort so als letztes bei einer Blockade drin?
Grüße
Reiner
Hi!
Sorry, hat etwas gedauert. Lag einige Tage flach...
Zitat von: Reinerlein am 01 Januar 2017, 23:59:50
Zum Basteln an Produktivsystemen: Ich denke, es blockiert sowieso, oder? :)
Ja, aber da sehe ich nicht tatenlos zu und nehme in Kauf, dass die ganze Steuerung steht. Daher deaktiviert :)
Zitat von: Reinerlein am 01 Januar 2017, 23:59:50
Oder heißt Blockade, dass es irgendwann einfach normal weitergeht, als wäre nichts gewesen?
Ja, es ging jeweils nach ca. 4 Minuten weiter, wobei dann schon der nächte Freeze wartete. Sonst hätte ich das aufschlussreiche apptime ja nicht bekommen...
Zitat von: Reinerlein am 01 Januar 2017, 23:59:50
In der Logausgabe wären nur die letzten Zeilen vor/während der Blockade interessant, da ja alles vorher glatt durchgegangen sein muss.
Was steht denn dort so als letztes bei einer Blockade drin?
2017.01.01 20:57:54.668 5: SONOS0: Received from UPnP-Server: 'SetCurrent:TrackDuration:0:03:02'
2017.01.01 20:57:54.668 5: SONOS0: Received from UPnP-Server: 'ProcessCover:RINCON_ABC_MR:0:music/image?id=422691E95C1854F8:http://192.168.0.160:3401/'
2017.01.01 21:00:01.931 4: SONOS0: Transport-Event: Bilder-Download: SONOS_DownloadReplaceIfChanged('http://192.168.0.160:3401/music/image?id=422691E95C1854F8', './www/images/default/SONOSPLAYER/OG.WO.Sonos_Kueche_AlbumArt.ERROR');
2017.01.01 21:00:01.931 5: SONOS0: Call of SONOS_DownloadReplaceIfChanged("http://192.168.0.160:3401/music/image?id=422691E95C1854F8", "./www/images/default/SONOSPLAYER/OG.WO.Sonos_Kueche_AlbumArt.ERROR")
2017.01.01 21:02:09.163 4: SONOS0: Couldn't retrieve file "http://192.168.0.160:3401/music/image?id=422691E95C1854F8" via web. Trying to copy directly...
2017.01.01 21:02:09.163 4: SONOS0: Couldn't even copy file "http://192.168.0.160:3401/music/image?id=422691E95C1854F8" directly... exiting...
Lt. Perfmon dauerte der Freeze von 20:57:55 bis 21:02:11. Kann es sein, dass das Holen eines Covers von einem nicht mehr erreichbaren Endgerät (192.168.0.160) den Hauptprozess blockiert?
Patrick
Hi Patrick,
das ist auf jeden Fall möglich. Ich verwende LWP::Simple, das hat einen internen Timeout.
Kannst du mal vier Anpassungen durchführen, und damit testen?
Zum einen oben in der use-Zeile zu LWP::Simple folgendes Aufschreiben:
use LWP::Simple qw($ua head get);
Damit gibt es dann die Möglichkeit für eine Timeout-Angabe.
Dazu einmal nach "head(" suchen, sollte es zweimal geben, und jeweils vor dem Aufruf folgendes eintragen:
$ua->timeout(5);
dasselbe noch mal für das Suchwort "get $url", sollte einmal vorkommen...
Danke schon mal...
Grüße
Reiner
Hi!
Wir nähern uns.
Die gute Nachricht: Dank der freundlichen Unterstützung meiner besseren Hälfte lässt sich das Problem zuverlässig reproduzieren - solange in der Küche ausschließlich Robbie Williams läuft...
Die schlechte Nachricht: Aus welchem Grund auch immer scheint LWP das Timeout vollständig egal zu sein.
Habe alle Änderungen wie vorgeschlagen eingebaut (1x use, 3x timeout(5)), u. a.:
sub SONOS_DownloadReplaceIfChanged($$) {
[...]
eval {
# pr: change
$ua->timeout(5);
SONOS_Log undef, 4, 'vvvvv PR: SONOS_DownloadReplaceIfChanged... vvvvv';
$newFile = get $url;
SONOS_Log undef, 4, '^^^^^ PR: SONOS_DownloadReplaceIfChanged... ^^^^^';
Nun fallen zwei Dinge auf:
1. Der erste Freeze tritt zwischen
Received from UPnP-Server: 'ProcessCover: und SONOS_DownloadReplaceIfChanged auf[/li][/list]
2. Der Get-Aufruf in SONOS_DownloadReplaceIfChanged braucht immer noch knapp über 2 Minuten:
2017.01.08 01:59:48 4: SONOS0: vvvvv PR: SONOS_DownloadReplaceIfChanged... vvvvv
2017.01.08 02:01:55 4: SONOS0: ^^^^^ PR: SONOS_DownloadReplaceIfChanged... ^^^^^
DNS scheidet als Ursache übrigens aus, da der Request direkt an die IP-Adress geht.
Update: Wenn man sich selbst um das Timeout kümmert, dann klappt es
(bei 2.):
eval {
local $SIG{ALRM} = sub { die "alarm\n" };
alarm(10);
$newFile = get $url;
alarm(0);
};
2017.01.08 02:45:07 4: SONOS0: vvvvv PR: SONOS_DownloadReplaceIfChanged 'http://192.168.0.238:3401/music/image?id=24453AB9E643D4D1' vvvvv
2017.01.08 02:45:17 4: SONOS0: ^^^^^ PR: SONOS_DownloadReplaceIfChanged ^^^^^
:
Wenn ich den head()-Aufruf in SONOS_ImageDownloadTypeExtension() auch mit alarm() spicke, werden alle Freezes abgefangen.
Patrick
Zitat von: PatrickR am 08 Januar 2017, 02:13:55
Hi!
Wir nähern uns.
Die gute Nachricht: Dank der freundlichen Unterstützung meiner besseren Hälfte lässt sich das Problem zuverlässig reproduzieren - solange in der Küche ausschließlich Robbie Williams läuft...
Die schlechte Nachricht: Aus welchem Grund auch immer scheint LWP das Timeout vollständig egal zu sein.
Habe alle Änderungen wie vorgeschlagen eingebaut (1x use, 3x timeout(5)), u. a.:
sub SONOS_DownloadReplaceIfChanged($$) {
[...]
eval {
# pr: change
$ua->timeout(5);
SONOS_Log undef, 4, 'vvvvv PR: SONOS_DownloadReplaceIfChanged... vvvvv';
$newFile = get $url;
SONOS_Log undef, 4, '^^^^^ PR: SONOS_DownloadReplaceIfChanged... ^^^^^';
Nun fallen zwei Dinge auf:
1. Der erste Freeze tritt zwischen
Received from UPnP-Server: 'ProcessCover: und SONOS_DownloadReplaceIfChanged auf.
2. Der Get-Aufruf in SONOS_DownloadReplaceIfChanged braucht immer noch knapp über 2 Minuten:
[/list]
2017.01.08 01:59:48 4: SONOS0: vvvvv PR: SONOS_DownloadReplaceIfChanged... vvvvv
2017.01.08 02:01:55 4: SONOS0: ^^^^^ PR: SONOS_DownloadReplaceIfChanged... ^^^^^
DNS scheidet als Ursache übrigens aus, da der Request direkt an die IP-Adress geht.
Update: Wenn man sich selbst um das Timeout kümmert, dann klappt es (bei 2.):
eval {
local $SIG{ALRM} = sub { die "alarm\n" };
alarm(10);
$newFile = get $url;
alarm(0);
};
2017.01.08 02:45:07 4: SONOS0: vvvvv PR: SONOS_DownloadReplaceIfChanged 'http://192.168.0.238:3401/music/image?id=24453AB9E643D4D1' vvvvv
2017.01.08 02:45:17 4: SONOS0: ^^^^^ PR: SONOS_DownloadReplaceIfChanged ^^^^^
Update 2:
Wenn ich den head()-Aufruf in SONOS_ImageDownloadTypeExtension() auch mit alarm() spicke, werden alle Freezes abgefangen.
Patrick
Hi Patrick,
super, ich baue mal die alarm-Variante ein.
Das mit dem LWP-Timeout ist aber echt komisch... laut Doku sollte das auch Einfluß haben... na egal, Hauptsache es gibt einen Weg...
Grüße
Reiner
Hi Reiner!
Danke! Kannst Du das Timeout konfigurierbar machen oder zumindest <= 2s setzen?
Von unterwegs gesendet.
Hallo Reiner,
arbeite momentan mit einer lokalen Version zum Testen des Problems. Habe dort sämtliche get()-Aufrufe in eine Funktion ausgelagert. Interessanterweise tritt dieses Problem nun nicht mehr auf. Aber die Freezes sind weiterhin vorhanden. Warte also am besten mit dem alarm()-Patch.
Ich schaue mal weiter.
Patrick
/Edit: Auf meinem Testsystem hat SONOS_Read lt. Apptime gerade 1272861ms, also stolze 21 Minuten blockiert.
Mahlzeit!
Mal ein kleines Update zu meinen Erkenntnissen (siehe Anhang)*. Offenbar existieren zwei Probleme:
- Dauer des Timeouts in SONOS_DownloadReplaceIfChanged($$) (Habe den Request in die neue Sub SONOS_LWPGet ausgelagert.
- Weiterer Zeitverzug zwischen Received from UPnP-Server: 'ProcessCover und Call of SONOS_DownloadReplaceIfChanged
* "SONOS_Read: 6" habe ich nach dem Kommentar "# Hier könnte jetzt eine[...]" eingefügt.
Werde mal Versuchen, das 2. Problem weiter einzugrenzen.
Patrick
/Edit: OK, das Problem sind die head()s. Wer lesen kann ist klar im Vorteil...
Das sieht für mich beides mal so aus, als ob es Probleme mit dem Zugriff auf 192.168.0.238 gibt? Was ist denn das?
Und beide im Zusammenhang mit dem Cover ... ist evt. der Port 3401 blockiert ?
Mahlzeit!
@Nobby1805:
Fast. Der Host ist garnicht erreichbar, also es gibt nicht einmal eine ARP-Auflösung. Von der Erreichbarkeit geht 00_SONOS aber aus, da der Track auch von diesem Gerät (einem iPhone) gestartet wurde und es zu diesem Zeitpunkt(!) auch unter der Adresse erreichbar war.
Mein Problem ist, dass ich LWP mit Gewalt (also mit alarm()) dazu zwingen kann, früher abzubrechen. Dann habe ich aber die Qual der Wahl, ob ich den Wert "klein" wähle, d. h. <= 1000ms und riskiere, längere Requests zu früh abzuschießen oder den Wert höher wähle und damit FHEM länger blockiere. Zu allem Überfluss ruft SONOS_Read auch mehrere LWP-Funktionen auf, so dass sich die Timeouts summieren.
Eigentlich müsste man sämtliche LWP-Aufrufe mit SubProcess oder BlockingCall etc. abkoppeln (oder ggf. HTTPUtils bemühen), aber das ist voraussichtlich - müsste mich erst einlesen - nicht in 5 Minuten gemacht.
Werde daher mal schauen, ob ich den nicht erreichbaren Host schneller detektieren kann, am besten ohne weitere Abhängigkeiten hinzuzunehmen.
Patrick
Guten Abend!
So, ich bin mit den Anpassungen so weit durch und hänge die aktualisierte Datei mal an. Sämtliche get()- und head()-Aufrufe werden nun in SONOS_LWPGet und SONOS_LWPHead gekapselt und mittels alarm() an ein festes Timeout gebunden, das über das Attribut LWPTimeout einstellbar ist.
Die Lösung umgeht zwar die minutenlangen Freezes, blockiert aber je nach Zahl der Aufrufe FHEM für mehrere Sekunden.
Sie hat folgende Nachteile:
- alarm() ist nicht portabel und funktioniert lt. Doku nicht unter Windows
- Man muss abwägen, ob man eher die Gefahr eingeht, langsame Transfers zu schnell abzubrechen oder man nimmt zu lange Freezes in Kauf.
/Edit: Anhang gelöscht, siehe Folgeposting.
Vernünftigste Lösung wäre wohl, auf NonBlockingGet von HTTPUtils umstellen, was allerdings voraussetzen würde, den Ablauf zu ändern und auf Callbacks umzustellen.
Patrick
Mahlzeit!
Ich bin mit meinen Änderungen etwas über das Ziel hinaus geschossen. In GetSpeakFile() war die Änderung zu viel des Guten...
Patrick
@Reinerlein:
Gerade Deinen Patch im SVN entdeckt. Großartig. Werde das jetzt mal beobachten. Das getListsDirectlyToReadings klingt übrigens auch nach einem Feature, das ich dringend brauche. Gute Arbeit.
Patrick
Hi Patrick,
Mensch bist du aktuell :) Ich bin gerade dabei den Veröffentlichungsartikel zu schreiben, habe gerade das Wiki dazu fertig...
Grüße
Reiner