Modul zur Standardisierung nebenläufiger Prozesse

Dr. Boris Neubert · 24 Februar 2015, 20:40:41

Hallo,

wir sehen uns häufig der Anforderung ausgesetzt, länger laufende Anfragen oder Event-Schleifen in FHEM zu programmieren. Ein Beispiel findet sich in 10_OWServer.pm. Um diese Aufgabe standardisiert zu unterstützen, habe ich ein Modul SubProcess.pm entwickelt.

Code Auswählen


  my $subprocess= SubProcess->new( { onRun => \&onRun, onExit => \&onExit } );
  my $pid= $subprocess->run();

  $subprocess->wait();
  $subprocess->terminate();
  $subprocess->kill();

Im Unterschied zu BlockingCall ist das Modul leichtgewichtig und kommuniziert über Pipes oder SocketPairs in transparenter Form mit dem FHEM-Hauptprozess, da es sich wie ein externes Gerät verhält, das Informationen die select-Hauptschleife in fhem.pl einschleust. Erreicht wird dies durch die Strophe

Code Auswählen


  $hash->{FD}= $subprocess->child();
  delete($readyfnlist{"$name.$pid"});   
  $selectlist{"$name.$pid"}= $hash;

in dem Modul, welches den Subprozess losgetreten hat.

Und nun macht sich Ernüchterung breit! Sowohl mit autoflush-Pipes, forciertem flush, $|++ oder anderen Verrenkungen sowie dem ganzen statt mit Pipes mit Socketpair kommen im FHEM-Hauptprozess die Daten nur in Bündeln an, wenn von einem anderen Filedescriptor gelesen wird, oder, bei Socketpair, interessanterweise genau jede Minute ein Wert (ich schreibe 100 Werte im 3-Sekundentakt, die im Minutentakt wieder aus der Hauptschleife herauspurzeln).

Wer kann helfen?

Ich habe das Modul sowie ein Testmodul beigefügt. Definiert wird ein Testgerät mittels

Code Auswählen

define T SubProcessTester

Viele Grüße
Boris

justme1968 · 24 Februar 2015, 20:58:31

hallo boris,

vielleicht habe ich etwas falsch verstanden... nach dem

Code Auswählen

define T SubProcessTestersollte doch der parent prozess nicht blockieren oder ?

das tut er bei mir. bzw es wird kein child gestartet. ich sehe im log nur die Step... nachrichten, habe aber keinen zusätzlichen fhem prozess. nach den 100 steps beendet sich fhem komplett.

worauf bezieht sich die aussage das SubProcess leichtgewichtiger ist als BlockingCall?

zum autoflush: ich meine es muss autoflush(1) heissen.

gruss
andre

ps: ist es absicht das du das freigeben der filedescriptoren im child nicht aus BlockigCall übernommen hast? ohne wird es die probleme neustart und co. geben.

Dr. Boris Neubert · 24 Februar 2015, 21:21:30

Hallo Andre,

Zitat von: justme1968 am 24 Februar 2015, 20:58:31
vielleicht habe ich etwas falsch verstanden... nach dem
Code Auswählen Erweitern
define T SubProcessTestersollte doch der parent prozess nicht blockieren oder ?

das tut er bei mir. bzw es wird kein child gestartet. ich sehe im log nur die Step... nachrichten, habe aber keinen zusätzlichen fhem prozess. nach den 100 steps beendet sich fhem komplett.

Interessant. Verstehe ich nicht, warum er bei Dir nicht forkt sondern onRun() im Parent-Prozess ausführt. Bist Du sicher?

Bei mir (Perl 5.18.2 auf KUbuntu 14.04) sehe ich

Code Auswählen


neubert   6579  6575  0 17702 25376   1 21:01 pts/6    00:00:00 /usr/bin/perl /users/neubert/Development/Perl/fhem-code/fhem/fhem.pl /users/neubert/Development/Perl/fhem-data/fhem.conf
neubert   6581  6579  0 12705 13072   1 21:01 pts/6    00:00:00 /usr/bin/perl /users/neubert/Development/Perl/fhem-code/fhem/fhem.pl /users/neubert/Development/Perl/fhem-data/fhem.conf

Im FHEM-Log steht

Code Auswählen


...
2015.02.24 21:15:10 5: Cmd: >define T SubProcessTester<
2015.02.24 21:15:10 5: Loading /users/neubert/Development/Perl/fhem-code/fhem/FHEM/98_SubProcessTester.pm
2015.02.24 21:15:10 5: SubProcess 6734 created.
2015.02.24 21:15:10 1: RUN RUN RUN RUN...
2015.02.24 21:15:10 1: Step 0
...
2015.02.24 21:15:10 3: Converting 'attr global port 7072 global' to 'define telnetPort telnet 7072 global'
2015.02.24 21:15:10 5: Loading /users/neubert/Development/Perl/fhem-code/fhem/FHEM/98_telnet.pm
2015.02.24 21:15:10 3: telnetPort: port 7072 opened
2015.02.24 21:15:10 5: Triggering global (1 changes)
2015.02.24 21:15:10 5: Notify loop for global INITIALIZED
...
2015.02.24 21:15:10 0: Server started with 5 defined entities (version $Id: fhem.pl 8066 2015-02-22 13:33:26Z rudolfkoenig $, os linux, user neubert, pid 6733)
2015.02.24 21:15:13 1: Step 1
2015.02.24 21:15:16 1: Step 2
2015.02.24 21:15:19 1: Step 3
2015.02.24 21:15:22 1: Step 4
2015.02.24 21:15:25 1: Step 5
2015.02.24 21:15:28 1: Step 6
2015.02.24 21:15:31 1: Step 7
2015.02.24 21:15:34 1: Step 8
2015.02.24 21:15:37 1: Step 9
...
2015.02.24 21:16:07 1: Step 19
2015.02.24 21:16:09 1: DEBUG>T has data to read!
2015.02.24 21:16:09 5: T read: 0

2015.02.24 21:16:10 1: Step 20
2015.02.24 21:16:13 1: Step 21
...
2015.02.24 21:20:04 1: Step 98
2015.02.24 21:20:07 1: Step 99
2015.02.24 21:20:09 1: DEBUG>T has data to read!
2015.02.24 21:20:09 5: T read: 4

2015.02.24 21:20:10 1: EXITED!
2015.02.24 21:21:09 1: DEBUG>T has data to read!
2015.02.24 21:21:09 5: T read: 5
...

Die Funktion onRun() schreibt munter Zeile für Zeile "Step xxx" ins Log. Und ab und an kommt bei mir "DEBUG>T has data to read!" gefolgt von "T: read: xxx".

In 300 Sekunden ist das bis 100 gelaufen, während im Minutentakt die DEBUG-Meldungen weiter kommen. Woher kommt denn bitte der Minutentakt??

Ich kann mich die ganze Zeit per telnet localhost 7072 mit dem Hauptprozess verbinden und FHEM ganz normal bedienen.

Zitat
worauf bezieht sich die aussage das SubProcess leichtgewichtiger ist als BlockingCall?

BlockingCall nutzt den Telnet-Port zur Kommunikation, was etwa die Hälfte des Codes ausmacht.

shutdown restart sowie selbständiges und forciertes Beenden funktionieren ohne weiteres Zutun bei subprocess reibungslos, ein $subprocess->wait() zur rechten Zeit räumt auch Zombies weg.

Warum ich das so machen will? Ich will in einem nebenläufigen Prozess in langlaufenden Operationen meinen Rechnerpark überwachen sowie mittels des EventListeners vom VirtualBox-API meinen virtuellen Maschinen lauschen. Dazu möchte ich nicht mehr wie derzeit noch einen extra Dämon starten, zu dem sich FHEM verbindet.

Zitat
zum autoflush: ich meine es muss autoflush(1) heissen.

Hilft leider auch nicht.

Viele Grüße
Boris

justme1968 · 24 Februar 2015, 23:45:26

hallo boris,

das einzige das ich im log habe ist das hier:

Code Auswählen

2015.02.24 23:38:50 1: [21532] RUN RUN RUN RUN...
2015.02.24 23:38:50 1: [21532] Step 0
2015.02.24 23:38:53 1: [21532] Step 1
2015.02.24 23:38:56 1: [21532] Step 2

die pid ist die des geforkten child. der parent hat sich genau dann schon beendet. alle konnections sind wegen den fehlenden close auf den child prozess übergegangen und der blockiert.

ich habe gerade versucht rauszufinden wo und warum der parent prozess bei mir nicht mehr existiert. aber ich habe absolut noch keine idee.

das fehlverhalten zeigt aber zufällig genau das problem mit den fehlenden close für alle deskriptoren. das funktioniert nur so lange wie im parent alles glatt läuft. wenn der parent aus irgendeinem grund abstürzt wird das im child nicht bemerkt und ein neu starten schlägt so lange fehl wie der child prozess nicht beendet wird. das wait im parent hat hier keine auswirkungen.

gruss
andre

Dr. Boris Neubert · 25 Februar 2015, 06:43:17

Hallo Andre,

auf welcher Plattform mit welchem Kernel und Perl passiert das bei Dir?

Grüße
Boris

justme1968 · 25 Februar 2015, 10:45:24

mac os x 10.10.2 und das mit ausgelieferte perl 5.18

gruss
andre

Dr. Boris Neubert · 01 März 2015, 18:55:01

Hallo Andre,

unter MacOS X kann ich leider bei mir nicht testen.

Geht denn bei Dir überhaupt fork()? Was sagt strace (gibt's das unter MacOS?)?

Viele Grüße
Boris

justme1968 · 01 März 2015, 20:09:31

ja. fork geht natürlich. meine version der gleichen idee (forken und kommunikation per socketpair) aus dem sandbox thread funktioniert ja im prinzip genau so und hat das problem nicht. deshalb verstehe ich es ja nicht auch BlockingCall das OWServer fork funktionieren.

es gibt etwas ähnliches wie strace. ich schaue mal ob ich damit mehr rausfinde.

gruss
andre

immi · 01 März 2015, 20:26:33

boris, andre
I can confirm Andre experience on macos.

What can I see:

Code Auswählen


2015.03.01 20:07:10 1: RUN RUN RUN RUN...
2015.03.01 20:07:10 1: Step 0
2015.03.01 20:07:13 1: Step 1
2015.03.01 20:07:16 1: Step 2
2015.03.01 20:07:19 1: Step 3
2015.03.01 20:07:22 1: Step 4
2015.03.01 20:07:25 1: Step 5
2015.03.01 20:07:28 1: Step 6
2015.03.01 20:07:31 1: Step 7
2015.03.01 20:07:34 1: Step 8

From activity monitor I can see that
-the original process generate a second one
-the original process starts to consume all my memory
-when also my computer cannot deliver any memory more 60GB , the original process crashes
immi

Dr. Boris Neubert · 02 März 2015, 19:19:22

Zitat von: justme1968 am 01 März 2015, 20:09:31
ja. fork geht natürlich. meine version der gleichen idee (forken und kommunikation per socketpair) aus dem sandbox thread funktioniert ja im prinzip genau so und hat das problem nicht. deshalb verstehe ich es ja nicht auch BlockingCall das OWServer fork funktionieren.

Genau, sandbox war's, was ich als Vorbild nehmen wollte und nicht mehr gefunden habe. Habe mir den Code angesehen und glaube, dass er bis auf das Einschleusen der Ausgabe aus dem Kindprozess über das socketpair (oder die pipe) in die globale Schleife identisch ist zum SubProcess. Mysteriös...

Boris

Dr. Boris Neubert · 02 März 2015, 19:23:25

Zitat von: immi am 01 März 2015, 20:26:33
From activity monitor I can see that
-the original process generate a second one
-the original process starts to consume all my memory
-when also my computer cannot deliver any memory more 60GB , the original process crashes

That's an interesting observation. Would you mind checking if it's related to the
- insertion in the global select list (lines 152-154 in 98_SubProcessTester.pm),
- the writing to the parent (in onRun in 98_SubProcessTester.pm)
by simply removing these lines and repeat your test?

Cheers,
Boris

immi · 02 März 2015, 20:22:26

Hi Boris
by commenting out 152 to 154 --> a new process is generated and the memory is not filled out (parent and child respectively 20MB and 1 MB)
when the counter goes to 100 the second process exits

Code Auswählen


2015.03.02 20:10:11 1: RUN RUN RUN RUN...
2015.03.02 20:10:11 1: Step 0
2015.03.02 20:10:14 1: Step 1
2015.03.02 20:10:17 1: Step 2
2015.03.02 20:10:20 1: Step 3
2015.03.02 20:10:23 1: Step 4
2015.03.02 20:10:26 1: Step 5
2015.03.02 20:10:29 1: Step 6
2015.03.02 20:10:32 1: Step 7
2015.03.02 20:10:35 1: Step 8
2015.03.02 20:10:38 1: Step 9
2015.03.02 20:10:41 1: Step 10
2015.03.02 20:10:44 1: Step 11
2015.03.02 20:10:47 1: Step 12
2015.03.02 20:10:50 1: Step 13
2015.03.02 20:10:53 1: Step 14
2015.03.02 20:10:56 1: Step 15
2015.03.02 20:10:59 1: Step 16
2015.03.02 20:11:02 1: Step 17
2015.03.02 20:11:05 1: Step 18
2015.03.02 20:11:08 1: Step 19
2015.03.02 20:11:11 1: Step 20
2015.03.02 20:11:14 1: Step 21
2015.03.02 20:11:17 1: Step 22
2015.03.02 20:11:20 1: Step 23
2015.03.02 20:11:23 1: Step 24
2015.03.02 20:11:26 1: Step 25
2015.03.02 20:11:29 1: Step 26
2015.03.02 20:11:32 1: Step 27
2015.03.02 20:11:35 1: Step 28
2015.03.02 20:11:38 1: Step 29
2015.03.02 20:11:41 1: Step 30
2015.03.02 20:11:44 1: Step 31
2015.03.02 20:11:47 1: Step 32
2015.03.02 20:11:50 1: Step 33
2015.03.02 20:11:53 1: Step 34
2015.03.02 20:11:56 1: Step 35
2015.03.02 20:11:59 1: Step 36
2015.03.02 20:12:02 1: Step 37
2015.03.02 20:12:05 1: Step 38
2015.03.02 20:12:08 1: Step 39
2015.03.02 20:12:11 1: Step 40
2015.03.02 20:12:14 1: Step 41
2015.03.02 20:12:17 1: Step 42
2015.03.02 20:12:20 1: Step 43
2015.03.02 20:12:23 1: Step 44
2015.03.02 20:12:26 1: Step 45
2015.03.02 20:12:29 1: Step 46
2015.03.02 20:12:32 1: Step 47
2015.03.02 20:12:35 1: Step 48
2015.03.02 20:12:38 1: Step 49
2015.03.02 20:12:41 1: Step 50
2015.03.02 20:12:44 1: Step 51
2015.03.02 20:12:47 1: Step 52
2015.03.02 20:12:50 1: Step 53
2015.03.02 20:12:53 1: Step 54
2015.03.02 20:12:56 1: Step 55
2015.03.02 20:12:59 1: Step 56
2015.03.02 20:13:02 1: Step 57
2015.03.02 20:13:05 1: Step 58
2015.03.02 20:13:08 1: Step 59
2015.03.02 20:13:11 1: Step 60
2015.03.02 20:13:14 1: Step 61
2015.03.02 20:13:17 1: Step 62
2015.03.02 20:13:20 1: Step 63
2015.03.02 20:13:23 1: Step 64
2015.03.02 20:13:26 1: Step 65
2015.03.02 20:13:29 1: Step 66
2015.03.02 20:13:32 1: Step 67
2015.03.02 20:13:35 1: Step 68
2015.03.02 20:13:38 1: Step 69
2015.03.02 20:13:41 1: Step 70
2015.03.02 20:13:44 1: Step 71
2015.03.02 20:13:47 1: Step 72
2015.03.02 20:13:50 1: Step 73
2015.03.02 20:13:53 1: Step 74
2015.03.02 20:13:56 1: Step 75
2015.03.02 20:13:59 1: Step 76
2015.03.02 20:14:02 1: Step 77
2015.03.02 20:14:05 1: Step 78
2015.03.02 20:14:08 1: Step 79
2015.03.02 20:14:11 1: Step 80
2015.03.02 20:14:14 1: Step 81
2015.03.02 20:14:17 1: Step 82
2015.03.02 20:14:20 1: Step 83
2015.03.02 20:14:23 1: Step 84
2015.03.02 20:14:26 1: Step 85
2015.03.02 20:14:29 1: Step 86
2015.03.02 20:14:32 1: Step 87
2015.03.02 20:14:35 1: Step 88
2015.03.02 20:14:38 1: Step 89
2015.03.02 20:14:41 1: Step 90
2015.03.02 20:14:44 1: Step 91
2015.03.02 20:14:47 1: Step 92
2015.03.02 20:14:50 1: Step 93
2015.03.02 20:14:53 1: Step 94
2015.03.02 20:14:56 1: Step 95
2015.03.02 20:14:59 1: Step 96
2015.03.02 20:15:02 1: Step 97
2015.03.02 20:15:05 1: Step 98
2015.03.02 20:15:08 1: Step 99
2015.03.02 20:15:11 1: EXITED!

immi

p.s. actually, to be more precise, line 154 is the problem

Dr. Boris Neubert · 02 März 2015, 22:03:55

Thank you, immi, this helps. Will need to understand the fhem main loop to know why this happens.
bn

Dr. Boris Neubert · 07 März 2015, 23:06:46

Alright, I found the bug. I mixed up file descriptor and file handle.

I replaced the SubProcess.pm module and the 98_SubProcessTester.pm device in the first post of this thread.

The SubProcessTester devices spawns a subprocess that writes back ten times a counter variable every 5 seconds with a blocking sleep. The device updates a "step" reading from the counter and FHEM remains responsive all the time.

I would be glad if immi and Andre could test this on their MacOS box.

Kind regards
Boris

immi · 08 März 2015, 16:10:34

Hi Boris
-memory issue gone.
-fork works.
-comunication: I was not sure, therefore I added some logs

Code Auswählen


sub SubProcessTester_Read($) {
  my ($hash) = @_;
  my $name= $hash->{NAME};
  Debug "$name has data to read!";
  my $subprocess= $hash->{fhem}{subprocess};
  my ($bytes, $result);
  $bytes= sysread($subprocess->child(), $result, 1024*1024);
  if(defined($bytes)) {
    chomp $result;
    readingsSingleUpdate($hash, "step", $result, 1);
    Log3 $hash, 2, "$name: the chidl told $result";
  } else {
    Log3 $hash, 2, "$name: $!";
    $result= undef;
  }
  return $result;
}

To my opinion everythiing is fine now

Code Auswählen


2015.03.08 16:02:19 1: RUN RUN RUN RUN...
2015.03.08 16:02:19 1: DEBUG>T has data to read!
2015.03.08 16:02:19 2: T: the chidl told 0
2015.03.08 16:02:24 1: DEBUG>T has data to read!
2015.03.08 16:02:24 2: T: the chidl told 1
2015.03.08 16:02:29 1: DEBUG>T has data to read!
2015.03.08 16:02:29 2: T: the chidl told 2
2015.03.08 16:02:34 1: DEBUG>T has data to read!
2015.03.08 16:02:34 2: T: the chidl told 3
2015.03.08 16:02:39 1: DEBUG>T has data to read!
2015.03.08 16:02:39 2: T: the chidl told 4
2015.03.08 16:02:44 1: DEBUG>T has data to read!
2015.03.08 16:02:44 2: T: the chidl told 5
2015.03.08 16:02:49 1: DEBUG>T has data to read!
2015.03.08 16:02:49 2: T: the chidl told 6

good job
immi