SubProcess.pm Datenverlust ?

[zap]

Ich habe nun HMCCU mal testweise auf die Verwendung von SubProcess.pm umgestellt. Der RPC-Server im Child-Prozess wird auch gestartet und läuft m.E. performant. Ich glaube aber, dass nicht alle Daten, die der Child an den Parent schickt dort ankommen.

Beispiel: Im Child wird bei einem bestimmten Event folgender Code ausgeführt:

Code Auswählen Erweitern


Log3 undef, 1, "HMCCU: NewDevice: received ".scalar(@$a)." device specifications";
for my $dev (@$a) {
   $hmccu_child->writeToParent ("ND|".$dev->{ADDRESS}."|".$dev->{TYPE}."\n");
}


Die Read Funktion sieht so aus:

Code Auswählen Erweitern


sub HMCCU_Read ($)
{
my ($hash) = @_;
my $name = $hash->{NAME};

my $child = $hash->{fhem}{subprocess};
my $result = $child->readFromChild ();
if(defined ($result)) {
chomp $result;
Log3 $name, 1, "HMCCU: RPC child $result";
}
return $result;
}


In der Read-Funktion protokolliere ich im Parent alle Daten, die der Child schickt. Das sieht für den o.g. Fall wie unten aus, d.h. der Child hat von der CCU 228 Device-Spezifikationen empfangen (Anzahl passt). Diese werden dann von der Read-Funktion im Parent ausgegeben, allerdings nur 9 statt 228. Was läuft da schief? Ich vermute, dass irgendwo im Select/Read Loop in FHEM die Daten verloren gehen:

Code Auswählen Erweitern


2016.03.18 13:08:10 1: HMCCU: NewDevice: received 228 device specifications
2016.03.18 13:08:10 1: HMCCU: RPC child ND|BidCoS-RF|HM-RCV-50
2016.03.18 13:08:10 1: HMCCU: RPC child ND|KEQ0161229:1|SHUTTER_CONTACT
2016.03.18 13:08:10 1: HMCCU: RPC child ND|KEQ0553611:1|SWITCH
2016.03.18 13:08:10 1: HMCCU: RPC child ND|KEQ0965669:5|CONDITION_VOLTAGE
2016.03.18 13:08:10 1: HMCCU: RPC child ND|LEQ0001975:7|SWITCH_TRANSMIT
2016.03.18 13:08:10 1: HMCCU: RPC child ND|LEQ0919881:0|MAINTENANCE
2016.03.18 13:08:10 1: HMCCU: RPC child ND|MEQ0287602|HM-Sec-SCo
2016.03.18 13:08:10 1: HMCCU: RPC child ND|MEQ0569329:3|WINDOW_SWITCH_RECEIVER
2016.03.18 13:08:10 1: HMCCU: RPC child ND|MEQ0745082:7|SWITCH_TRANSMIT


[Dr. Boris Neubert]

Was ergibt die Auswertung der Return Codes von writeToParent() und readFromChild()?

[zap]

Ich glaube, readFromChild ist die Ursache. Sysread liest max. 1024 Byte. Es wird davon ausgegangen, dass max. 1 Datagramm in den Daten enthalten ist. Bei der RPC Schnittstelle ist es aber so, dass zumindest am Anfang sehr viele kurze Datagramme kommen (die CCU schickt erst mal Infos über alle Ihre Devices/Channels).
Das bedeutet, die 1024 Byte vom sysread Puffer enthalten ca. 10 Datagramme. Da in readFromChild keine Schleife drin ist, werden alle Datagramme nach dem ersten verworfen.

[Dr. Boris Neubert]

Ok, ich sehe es. readFrom() ist in der Lage, zerbröselte Datentransfers einzusammeln, bis die in den ersten 4 Bytes angekündigte Anzahl von Bytes erreicht ist. Wenn aber pro Datentransfer mehr als 1024 Bytes gesendet werden, werden nur die ersten 1024 Bytes angenommen.

Das sollte gelöst werden, indem writeTo den Datentransfer in 1024-Byte-Blöcke zerlegt. D.h. my $buffer= $size . $msg in Zeile 198 durch eine Schleife über syswrite($fh, $buffer, 1024, $offset) versenden.

Magst Du das in SubProcess.pm einbauen und mir einen Patch schicken, wenn es funktioniert?

Viele Grüße
Boris

[zap]

mach ich. Allerdings ist das Problem etwas anders gelagert: In meinem Fall werden gar nicht per writeTo mehr als 1024 Byte geschickt. Die Datagramme sind im Gegenteil sehr kurz (< 150 Byte). Allerdings ist der RPC-Server sehr performant und feuert in kürzester Zeit >200 dieser kurzen Datagramme mit eben 200 x writeTo ab.

Beim Lesen passiert nun erstaunliches: sysread liest eben nicht 200 Einzeldatagramme sondern 1024 Byte mit 10 oder mehr Datagrammen im Block. Es braucht also in readFrom eine Logik, die diese 1024 Byte in Einzelteile zerlegt.

Ich schaue mir das nochmal genau an. Ist denke, ich werde das Test-Modul aus contrib etwas umbauen, damit ich das Verhalten simulieren kann.

[zap]

Hallo Boris,

anbei ein diff File mit meinen Änderungen an readFrom(). Ich habe fast die ganze Funktion ersetzt. Die neue Variante kommt nun mit mehreren Datagrammen pro sysread() Call klar. Die Funktion gibt nun einen String mit allen vollständigen Datagrammen eines sysread() Calls zurück. Die einzelnen Datagramme sind durch Newline getrennt, können also einfach mit split() in ein Array aufgetrennt werden.

Das hat jetzt zwar eines meiner Probleme gelöst, allerdings schlagen immer wieder readFrom() und writeTo() fehl, wenn sehr viele Daten übertragen werden sollen. In meinem Usecase werden am Anfang ca. 7 Kb Daten vom Child and den Parent geschickt. Das scheint etwas zuviel des Guten für den Select/Read Loop von FHEM zu sein. Jedenfalls schlagen in diesem Fall die select() Aufrufe sporadisch fehl. Ergebnis ist wiederum Datenverlust.

Ich glaube, in meinem Fall wird das nix mit SubProcess. Ich könnte es im Prinzip für das Starten des Child nutzen und dann weiterhin die Filequeue für die Datenübermittlung verwenden. Aber das ist schon ein ziemlicher Overhead, da ja der komplette FHEM Prozess 2x im Speicher gehalten wird. Da ist es vielleicht effektiver, wenn sich mein Modul als Child selbst forked.

[Dr. Boris Neubert]

Hallo zap,

Danke für die Analyse. Ich würde allerdings kein Diff sondern einen Patch brauchen:

Code Auswählen Erweitern

svn diff SubProcess.pm > SubProcess.pm

Ich würde gerne aus readFrom() nur ein Datagramm verarbeiten. Es müssten also die 4 Bytes Header gelesen werden und dann nochmal genau so viele, wie der Header angibt. Weitere Datagramme stehen dann an und ein select() auf den Filedescriptor sorgt dafür, dass die Routine gleich wieder aufgerufen wird. Aus ECMDDevice heraus habe ich recht viel Erfahrung gewonnen und gelernt, wie kompliziert es werden kann mit zerbröselten oder konkatenierten Datagrammen umgehen zu müssen. Zusätzliches Problem: wenn die Nutzdaten \n enthalten, funktioniert die Trennung nicht.

Ich kann mir nicht vorstellen, dass sich FHEM daran verschluckt, wenn 200 Datagramme hintereinander reinkommen (die Verarbeitung erfolgt in fhem.pl) - falls doch, sollten wir der Sache nachgehen.

Eine Warnung, wenn Du SubProcess.pm nicht nutzt: Forken und Kommunikation über Sockets zu implementieren hat eine steile Lernkurve. Ich habe mir einige Wochenenden um die Ohren geschlagen, um eine saubere wiederverwendbare Implementierung in SubProcess.pm vorzulegen.

Ich würde das gerne weiterentwickeln. Bin aber im Moment noch in anderen Aufgaben gefangen.

Viele Grüße
Boris

[zap]

Hallo Boris,

also so etwa: in readFrom()

- Lese 4 Byte Datagram Länge mit sysread()
- Lese Anzahl Datagram Länge Bytes mit sysread()
- Fallunterscheidung:
-- Wenn Datagram vollständig gelesen: return Nutzdaten
-- Sonst gelesene Daten puffern und undef zurückgeben. Beim nächsten Aufruf von ReadFn bzw. readFrom den Rest (und nur den) lesen. Wobei ich mich frage, ob dieser Fall überhaupt vorkommen kann.

Die beschriebenen Probleme treten v.a. bei writeTo() auf. Hier schlägt bei sehr vielen aufeinanderfolgenden writeTo() Aufrufen ab und zu der select() fehl, der prüft, ob der Socket beschreibbar ist.

Aber OK. Vergiss das diff erst mal. Ich versuche erst mal die oben beschriebene Variante von readFrom() umzusetzen.

Viele Grüße
Dirk

[Dr. Boris Neubert]

Hallo Dirk,

ja, genau so.

Statt stumpf 1024 Bytes zu lesen und den Überschuss in Zeile 180 wegzuwerfen, sollten zuerst 4 und dann min($size,1024) Bytes gelesen werden. Die verbleibenden Bytes vom nächsten Datagramm (4 Byte Header und Nutzdaten) stehen dann noch zum Lesen vom Filedescriptor an.

Grüße
Boris

[zap]

Habe das Lesen einzelner Datagramme jetzt mal testweise umgesetzt. Funktioniert.

Nach wie vor habe ich aber das Problem, dass bei vielen (sehr) kleinen Datagrammen der folgende Aufruf in writeTo() ein undef zurückgibt und damit der Write fehl schlägt:

Code Auswählen Erweitern


  vec($win, fileno($fh), 1)= 1;
  return undef unless select(undef, $win, undef, 0.001);


Ich habe nun mal vor dem Schreiben immer 3 Datagramme (natürlich nur die Nutzdaten) aneinander gehängt und siehe da, der Fehler tritt nicht auf. Scheint also wirklich mit der Anzahl der zu schreibenden Bytes zusammen zu hängen. Ich frage mich nur wie das sein kann. Schließlich weiß writeTo() beim select() ja noch gar nicht, wieviel ich schreiben möchte.

UPDATE: Oh, Denkfehler! Das select() ist vermutlich doch erfolgreich aber das darauf folgende syswrite() schlägt fehl.

[Dr. Boris Neubert]

Hallo,

ich bin nicht firm im File-Handling mit select. Kannst Du mal testweise den Timeout von 1ms hochdrehen:

Code Auswählen Erweitern

  return undef unless select(undef, $win, undef, 0.250);

Grüße
Boris

[zap]

Hallo Boris,

die Erhöhung des Timeouts bei Writes auf 0.25 Sekunden funktioniert so weit, d.h. es gibt keine Schreibfehler mehr. Allerdings nur, wenn ich den Child-Prozess aus dem laufenden FHEM heraus starte.

Anders sieht es aus, wenn ich FHEM neu starte. Da wird bei der Definition des IO Devices von HMCCU automatisch der Child-Prozess gestartet. Da der Boot-Vorgang von FHEM da aber noch nicht abgeschlossen ist, hagelt es wieder Write-Errors (Child -> Parent).

Mir scheint die Ursache ist, dass der FHEM-Leseloop noch nicht soweit ist, wenn der Child anfängt, Daten zu schicken.

Die Frage ist, wie man den Start des Childs timen kann, damit FHEM "fertig" ist, wenn die ersten Daten vom Child ankommen. Vermutlich müsste der Child die Daten puffern bis irgendwann mal das Select() erfolgreich ist. Das ist in meinem Fall aber sehr schwierig, da der Child in einem internen Connection-Accept-Loop hängt und nur bei neu eintreffenden Daten von der RPC-Schnittstelle diverse Callbacks aufruft, die dann wiederum die Daten an FHEM schicken.

Lösungsvorschläge zu diesem Dilemma sind willkommen.

[Dr. Boris Neubert]

Beginne mit der Verarbeitung erst, wenn FHEM initialisiert ist. Dazu musst Du auf das entsprechende Event reagieren. Im Calender-Modul habe ich das realisiert - das kannst Du abschreiben.

Viele Grüße
Boris

[zap]

Beginne mit der Verarbeitung erst, wenn FHEM initialisiert ist. Dazu musst Du auf das entsprechende Event reagieren. Im Calender-Modul habe ich das realisiert - das kannst Du abschreiben.

Viele Grüße
Boris

Danke! Ich werde Dir die Tage erst mal die Änderungen in SubProcess.pm zukommen lassen, damit das in die offizielle Distribution reinkommt. Du hast ja bereits in new() den Timeout Parameter vorgesehen. Ich habe in den Read() und Write() Funktionen den fixen Wert 0.001 durch $Timeout ersetzt. So kann sich jeder den Timeout definieren, den er braucht. Default ist dann 0.001.

Viele Grüße
Dirk

[zap]

Hallo Boris,

anbei die SVN diff von SubProcess.pm. Was sich geändert hat:

• Bei new() gibt es nun 2 neue Parameter: timeoutread und timeoutwrite. Mit diesen kann man separate Timeouts für die select() Aufrufe bei Read und Write festlegen. Wenn die Parameter fehlen, wird der Wert von timeout verwendet. Default ist der bisherige Timeout von 0.001 Sekunden.
• Die Funktion readFrom() liest nun immer genau ein Datagramm. Dabei spielt es keine Rolle, ob ein Newline am Ende steht. Es wird das Datagramm ohne Size-Header inkl. eventuellem Newline zurückgegeben. Bei Fehler undef. Der Puffer wird nicht mehr benötigt. Daher wurde der Parameter entfernt.
• Sowohl in readFrom() als auch in writeTo() habe ich das Fehler-Handling angepasst. Bei einem Fehler wird $self->{lasterror} gesetzt. Dieser Wert kann mit der neuen Funktion lasterror() ausgelesen werden.

Das Ganze läuft bei mir stabil mit timeoutread=0.01 und timeoutwrite=0.25.

Viele Grüße und frohe Ostern!
Dirk

[Dr. Boris Neubert]

Hallo Dirk,

habe es mit kleinen Korrekturen eingecheckt.

Viele Grüße
Boris

[zap]

Neuigkeiten zu SubProcess.pm:

Inzwischen verwende ich SubProcess.pm in HMCCU, um RPC-Server Prozesse zu starten. Für die Kommunikation zwischen Child- und Parent-Prozess setze ich aber nach wie vor auf File-Queues. Die direkte Kommunikation zwischen Child und Parent über Sockets funktioniert nur bis zu einem gewissen Datenaufkommen. Wird in kurzer Zeit eine große Menge Daten von einem Child- zum Parent-Prozess geschickt, schlagen irgendwann die Write-Calls fehl. Das Problem lässt sich durch Erhöhung der Timeouts etwas verzögern, jedoch nicht vermeiden. m.E. kommt ab einem bestimmten Punkt FHEM nicht mehr mit der Verarbeitung der Daten und die Übergabe an die Read-Funktion nach. Ab einem Punkt läuft dann irgendein I/O Puffer voll und weitere Daten werden ins Nirwana geschickt (so ca. ab 5 Kb auf meinem Raspi, auf schnelleren Systemen vielleicht anderer Wert).

Schade eigentlich. Sonst funktioniert SubProcess.pm einwandfrei. Habe jetzt 2 Tage lang versucht, das zum laufen zu bekommen. Letztendlich muss ich wohl akzeptieren, dass Perl für solche zeitkritischen Dinge auf schwachbrüstigen Systemen nicht geeignet ist.

Ach ja: Für die Funktion running() werde ich noch einen Patch liefern. Die arbeitet so nicht zuverlässig. Für die Prüfung, ob ein Prozess läuft, ist kill mit dem Signal 0 besser geeignet.