Hallo zusammen,
ich beschäftige mich recht intensiv mit der Verwendung von Blocking.pm und bastele gerade am DbLog um zumindest die Log-Funktion non-blocking zu gestalten. Klappt auch schon prima.
Jetzt habe ich mal $hash->{HELPER}{RUNNING_PID}{pid} mitgeloggt / ausgegeben. DbLog_Push ist die Blocking-Funktion und DbLog_PushDone die Rückkehrfunktion.
Es funktioniert alles einwandfrei ... kein Fehler.
Nur hätte ich gern gewußt was es mit der PID "DEAD:<pid>" auf sich hat, was immer mal wieder auftritt.
Die Funktion an sich wird einwandfrei ausgeführt. Ich kann es nur nicht einordnen.
2016.12.15 22:21:53.092 4: DbRep LogDB -> Start DbLog_Push with PID: DEAD:3252
2016.12.15 22:21:53.134 4: DbRep LogDB -> DbLog_Push finished
2016.12.15 22:21:53.143 4: DbRep LogDB -> Start DbLog_Push with PID: 3254
2016.12.15 22:21:53.168 4: DbLog LogDB -> Start DbLog_PushDone
2016.12.15 22:21:53.169 4: DbLog LogDB -> DbLog_PushDone PID: DEAD:3252 finished
2016.12.15 22:21:53.206 4: DbRep LogDB -> DbLog_Push finished
2016.12.15 22:21:53.211 4: DbLog LogDB -> Start DbLog_PushDone
2016.12.15 22:21:53.212 4: DbLog LogDB -> DbLog_PushDone PID: 3254 finished
Weiß jemand wie man das interpretieren kann ?
Grüße
Heiko
ZitatWeiß jemand wie man das interpretieren kann ?
In Blocking.pm steht:
...
if(!kill(0, $h->{pid})) {
$h->{pid} = "DEAD:$h->{pid}";
...d.h. wenn kill meint, dem Prozess kann man kein Signal zustellen, dann ist Blocking.pm der Ansicht, der Prozess ist beendet.
Hallo Rudi,
danke für die Antwort ... soweit ist mir das auch klar.
Was mir etwas unerklärlich ist, wieso in ca. 10-20% der BlockungCall-Aufrufe die zurück gelieferte PID bereits als "DEAD" ("Start DbLog_Push with PID: DEAD:3252") gekennzeichnet ist. Wie gesagt, die Funktion wird trotzdem ordnungsgemäß durchgeführt und ist insofern auch nur eine Info.
Mir war es nur aufgefallen weil ich im Entwicklungsprozess mal zufällig die zurück gelieferten PID's ($hash->{HELPER}{RUNNING_PID}{pid}) mitgeloggt habe um zu schauen wie die einzelnen Starts und Abarbeitungen der Prozesse zusammenpassen.
Grüße
Heiko
In diesem Fall ist vermutlich was falsch. Kanst du mir Testcode zur Verfuegung stellen?
Ist dein Testplattform der aus dem Signature?
Hallo Rudi,
gebe dir gerne noch ein paar Infos.
Meine Testmaschine ist eine virtuelle Debian:
Linux fhemtest 3.16.0-4-amd64 #1 SMP Debian 3.16.36-1+deb8u2 (2016-10-19) x86_64 GNU/Linux
Die relevanten Subroutinen an denen ich gerade arbeite sehen so aus:
##################################################################################################################
#
# Hauptroutine zum Loggen. Wird bei jedem Eventchange
# aufgerufen
#
##################################################################################################################
sub DbLog_Log($$) {
# Log is my entry, Dev is the entry of the changed device
my ($hash, $dev) = @_;
my $name = $hash->{NAME};
Log3 $hash->{NAME}, 5, "Notify from Device: ".$dev->{NAME}." recieved";
return if(IsDisabled($name) || $init_done != 1);
# name and type required for parsing
my $n= $dev->{NAME};
my $t= uc($dev->{TYPE});
# timestamp in SQL format YYYY-MM-DD hh:mm:ss
#my ($sec,$min,$hr,$day,$mon,$yr,$wday,$yday,$isdst)= localtime(time);
#my $ts= sprintf("%04d-%02d-%02d %02d:%02d:%02d", $yr+1900,$mon+1,$day,$hr,$min,$sec);
my $re = $hash->{REGEXP};
my $max = int(@{$dev->{CHANGED}});
my $ts_0 = TimeNow();
my $now = gettimeofday(); # get timestamp in seconds since epoch
my $DbLogExclude = AttrVal($dev->{NAME}, "DbLogExclude", undef);
my $DbLogInclude = AttrVal($dev->{NAME}, "DbLogInclude",undef);
my $DbLogSelectionMode=AttrVal($hash->{NAME},"DbLogSelectionMode","Exclude");
my $DbLogType = AttrVal($hash->{NAME}, "DbLogType", "Current/History");
for (my $i = 0; $i < $max; $i++) {
my $s = $dev->{CHANGED}[$i];
$s = "" if(!defined($s));
if($n =~ m/^$re$/ || "$n:$s" =~ m/^$re$/ || $DbLogSelectionMode eq 'Include') {
my $ts = $ts_0;
$ts = $dev->{CHANGETIME}[$i] if(defined($dev->{CHANGETIME}[$i]));
# $ts is in SQL format YYYY-MM-DD hh:mm:ss
my @r= DbLog_ParseEvent($n, $t, $s);
my $reading= $r[0];
my $value= $r[1];
my $unit= $r[2];
if(!defined $reading) { $reading= ""; }
if(!defined $value) { $value= ""; }
if(!defined $unit || $unit eq "") {
$unit = AttrVal("$n", "unit", "");
}
#Je nach DBLogSelectionMode muss das vorgegebene Ergebnis der Include-, bzw. Exclude-Pruefung
#entsprechend unterschiedlich vorbelegt sein.
#keine Readings loggen die in DbLogExclude explizit ausgeschlossen sind
my $DoIt = 0;
$DoIt = 1 if($DbLogSelectionMode =~ m/Exclude/ );
if($DbLogExclude && $DbLogSelectionMode =~ m/Exclude/) {
# Bsp: "(temperature|humidity):300 battery:3600"
my @v1 = split(/,/, $DbLogExclude);
for (my $i=0; $i<int(@v1); $i++) {
my @v2 = split(/:/, $v1[$i]);
$DoIt = 0 if(!$v2[1] && $reading =~ m/^$v2[0]$/); #Reading matcht auf Regexp, kein MinIntervall angegeben
if(($v2[1] && $reading =~ m/^$v2[0]$/) && ($v2[1] =~ m/^(\d+)$/)) {
#Regexp matcht und MinIntervall ist angegeben
my $lt = $defs{$dev->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{TIME};
my $lv = $defs{$dev->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{VALUE};
$lt = 0 if(!$lt);
$lv = "" if(!$lv);
if(($now-$lt < $v2[1]) && ($lv eq $value)) {
# innerhalb MinIntervall und LastValue=Value
$DoIt = 0;
}
}
}
}
#Hier ggf. zusaetlich noch dbLogInclude pruefen, falls bereits durch DbLogExclude ausgeschlossen
#Im Endeffekt genau die gleiche Pruefung, wie fuer DBLogExclude, lediglich mit umgegkehrtem Ergebnis.
if($DoIt == 0) {
if($DbLogInclude && ($DbLogSelectionMode =~ m/Include/)) {
my @v1 = split(/,/, $DbLogInclude);
for (my $i=0; $i<int(@v1); $i++) {
my @v2 = split(/:/, $v1[$i]);
$DoIt = 1 if($reading =~ m/^$v2[0]$/); #Reading matcht auf Regexp
if(($v2[1] && $reading =~ m/^$v2[0]$/) && ($v2[1] =~ m/^(\d+)$/)) {
#Regexp matcht und MinIntervall ist angegeben
my $lt = $defs{$dev->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{TIME};
my $lv = $defs{$dev->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{VALUE};
$lt = 0 if(!$lt);
$lv = "" if(!$lv);
if(($now-$lt < $v2[1]) && ($lv eq $value)) {
# innerhalb MinIntervall und LastValue=Value
$DoIt = 0;
}
}
}
}
}
next if($DoIt == 0);
$defs{$dev->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{TIME} = $now;
$defs{$dev->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{VALUE} = $value;
my $dlt = encode_base64($DbLogType,"");
my $timestamp = encode_base64($ts,"");
my $device = encode_base64($n,"");
my $type = encode_base64($t,"");
my $event = encode_base64($s,"");
my $read = encode_base64($reading,"");
my $val = encode_base64($value,"");
my $ut = encode_base64($unit,"");
$hash->{HELPER}{RUNNING_PID} = BlockingCall("DbLog_Push", "$name|$dlt|$timestamp|$device|$type|$event|$read|$val|$ut", "DbLog_PushDone", 15, "DbLog_Push_ParseAborted", $hash);
}
}
return "";
}
################################################################################################
# Schreibroutine Einfügen Werte in DB non-blocking
#
# param1: hash
# param2: DbLogType -> Current oder History oder Current/History
# param4: Timestamp
# param5: Device
# param6: Type
# param7: Event
# param8: Reading
# param9: Value
# param10: Unit
#
################################################################################################
sub DbLog_Push(@) {
# my ($hash, $DbLogType, $timestamp, $device, $type, $event, $reading, $value, $unit) = @_;
my ($string) = @_;
my ($name,$dlt,$ts,$n,$t,$s,$read,$val,$ut) = split("\\|", $string);
my $hash = $defs{$name};
my $dbconn = $hash->{dbconn};
my $dbuser = $hash->{dbuser};
my $dbpassword = $attr{"sec$name"}{secret};
my $DbLogType = decode_base64($dlt);
my $timestamp = decode_base64($ts);
my $device = decode_base64($n);
my $type = decode_base64($t);
my $event = decode_base64($s);
my $reading = decode_base64($read);
my $value = decode_base64($val);
my $unit = decode_base64($ut);
my $pid = $hash->{HELPER}{RUNNING_PID}{pid};
my $error = 0;
my $dbh;
Log3 ($name, 4, "DbRep $name -> Start DbLog_Push with PID: $pid");
eval {$dbh = DBI->connect("dbi:$dbconn", $dbuser, $dbpassword, { PrintError => 0, RaiseError => 1, AutoInactiveDestroy => 1 });};
if ($@) {
$error = encode_base64($@,"");
Log3 ($name, 2, "DbLog $name - $@");
Log3 ($name, 4, "DbLog $name -> DbLog_Push finished");
return "$name|$error|''|$pid";
}
if ($hash->{DBMODEL} ne 'SQLITE') {
# Daten auf maximale laenge beschneiden
$device = substr($device,0, $columns{DEVICE});
$type = substr($type,0, $columns{TYPE});
$event = substr($event,0, $columns{EVENT});
$reading = substr($reading,0, $columns{READING});
$value = substr($value,0, $columns{VALUE});
$unit = substr($unit,0, $columns{UNIT});
}
$dbh->begin_work();
my $sth_ih = $dbh->prepare_cached("INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)") if (lc($DbLogType) =~ m(history) );
my $sth_ic = $dbh->prepare_cached("INSERT INTO current (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)") if (lc($DbLogType) =~ m(current) );
my $sth_uc = $dbh->prepare_cached("UPDATE current SET TIMESTAMP=?, TYPE=?, EVENT=?, VALUE=?, UNIT=? WHERE (DEVICE=?) AND (READING=?)") if (lc($DbLogType) =~ m(current) );
Log3 $hash->{NAME}, 5, "DbLog: logging of Device: $device , Type: $type , Event: $event , Reading: $reading , Value: $value , Unit: $unit";
eval {
# insert into history
if (lc($DbLogType) =~ m(history) ) {
my $rv_ih = $sth_ih->execute(($timestamp, $device, $type, $event, $reading, $value, $unit));
}
# update or insert current
if (lc($DbLogType) =~ m(current) ) {
my $rv_uc = $sth_uc->execute(($timestamp, $type, $event, $value, $unit, $device, $reading));
if ($rv_uc == 0) {
my $rv_ic = $sth_ic->execute(($timestamp, $device, $type, $event, $reading, $value, $unit));
}
}
};
if ($@) {
$error = encode_base64($@,"");
Log3 ($name, 2, "DbLog $name - Failed to insert new dataset into database: $@");
$dbh->rollback();
$dbh->disconnect();
Log3 ($name, 4, "DbLog $name -> DbLog_Push finished");
return "$name|$error|''|$pid";
}
else {
$dbh->commit();
$dbh->disconnect();
}
Log3 ($name, 4, "DbRep $name -> DbLog_Push finished");
return "$name|''|$s|$pid";
}
#############################################################################################
# Auswertung non-blocking DbLog_Push
#############################################################################################
sub DbLog_PushDone ($) {
my ($string) = @_;
my @a = split("\\|",$string);
my $name = $a[0];
my $hash = $defs{$name};
my $error = decode_base64($a[1]) if($a[1]);
my $event = decode_base64($a[2]);
my $pid = $a[3];
Log3 ($name, 4, "DbLog $name -> Start DbLog_PushDone");
if ($error) {
readingsSingleUpdate($hash, "state", $error, 1);
} else {
readingsSingleUpdate($hash, "state", "last event - ".$event, 0);
}
Log3 ($name, 4, "DbLog $name -> DbLog_PushDone PID: $pid finished");
# delete($hash->{HELPER}{RUNNING_PID};
return;
}
#############################################################################################
# Abbruchroutine Timeout non-blocking DbLog_Push
#############################################################################################
sub DbLog_Push_ParseAborted($) {
my ($hash) = @_;
my $name = $hash->{NAME};
Log3 ($name, 1, "DbLog $name -> $hash->{HELPER}{RUNNING_PID}{fn} timed out");
readingsSingleUpdate($hash, "state", "timeout", 1);
# delete($hash->{HELPER}{RUNNING_PID}{pid});
}
Mit verbose 5 sieht man gut wie die einzelnen Hintergrundprozesse die events in die DB schreiben:
2016.12.16 13:11:59.282 4: DbRep LogDB -> Start DbLog_Push with PID: DEAD:7871
2016.12.16 13:11:59.289 5: DbLog: logging of Device: MySTP_5000 , Type: SMAINVERTER , Event: etotal: 12603.2 , Reading: etotal , Value: 12603.2 , Unit:
2016.12.16 13:11:59.302 4: DbRep LogDB -> Start DbLog_Push with PID: 7873
2016.12.16 13:11:59.309 5: DbLog: logging of Device: MySTP_5000 , Type: SMAINVERTER , Event: etoday: 12.908 , Reading: etoday , Value: 12.908 , Unit:
2016.12.16 13:11:59.313 4: DbRep LogDB -> DbLog_Push finished
2016.12.16 13:11:59.321 4: DbRep LogDB -> DbLog_Push finished
2016.12.16 13:11:59.334 4: DbRep LogDB -> Start DbLog_Push with PID: 7874
2016.12.16 13:11:59.345 5: DbLog: logging of Device: MySTP_5000 , Type: SMAINVERTER , Event: total_pac: 3.320 , Reading: total_pac , Value: 3.320 , Unit:
2016.12.16 13:11:59.349 4: DbRep LogDB -> DbLog_Push finished
2016.12.16 13:11:59.362 4: DbRep LogDB -> Start DbLog_Push with PID: 7875
2016.12.16 13:11:59.376 5: DbLog: logging of Device: MySTP_5000 , Type: SMAINVERTER , Event: 3.320 , Reading: state , Value: 3.320 , Unit:
2016.12.16 13:11:59.379 4: DbRep LogDB -> DbLog_Push finished
2016.12.16 13:11:59.490 5: Notify from Device: Dum.Energy recieved
2016.12.16 13:11:59.523 4: DbRep LogDB -> Start DbLog_Push with PID: DEAD:7876
2016.12.16 13:11:59.531 5: Notify from Device: Dum.Energy recieved
2016.12.16 13:11:59.534 5: DbLog: logging of Device: Dum.Energy , Type: DUMMY , Event: PV: 3320.0 , Reading: PV , Value: 3320.0 , Unit:
2016.12.16 13:11:59.537 4: DbRep LogDB -> DbLog_Push finished
2016.12.16 13:11:59.567 4: DbRep LogDB -> Start DbLog_Push with PID: 7881
2016.12.16 13:11:59.574 5: DbLog: logging of Device: Dum.Energy , Type: DUMMY , Event: TotalConsumption: 3015.7 , Reading: TotalConsumption , Value: 3015.7 , Unit:
2016.12.16 13:11:59.577 4: DbRep LogDB -> DbLog_Push finished
2016.12.16 13:11:59.591 4: DbLog LogDB -> Start DbLog_PushDone
2016.12.16 13:11:59.591 4: DbLog LogDB -> DbLog_PushDone PID: DEAD:7871 finished
2016.12.16 13:11:59.597 4: DbLog LogDB -> Start DbLog_PushDone
2016.12.16 13:11:59.598 4: DbLog LogDB -> DbLog_PushDone PID: 7873 finished
2016.12.16 13:11:59.601 4: DbLog LogDB -> Start DbLog_PushDone
2016.12.16 13:11:59.601 4: DbLog LogDB -> DbLog_PushDone PID: 7874 finished
2016.12.16 13:11:59.606 4: DbLog LogDB -> Start DbLog_PushDone
2016.12.16 13:11:59.606 4: DbLog LogDB -> DbLog_PushDone PID: 7875 finished
2016.12.16 13:11:59.626 4: DbLog LogDB -> Start DbLog_PushDone
2016.12.16 13:11:59.626 4: DbLog LogDB -> DbLog_PushDone PID: DEAD:7876 finished
2016.12.16 13:11:59.630 4: DbLog LogDB -> Start DbLog_PushDone
2016.12.16 13:11:59.630 4: DbLog LogDB -> DbLog_PushDone PID: 7881 finished
Den momentanen Arbeitsstand von DbLog habe ich mal mit angehängt. Später will das auch mal im Forum gemeinsam diskutieren und verbessern.
Jetzt soll es erstmal bei mir problemlos funktionieren ... d.h. außer dem "DEAD" habe ich nichts negatives festgestellt. Alles wird sauber geloggt.
Grüße
Heiko
Etwas knapperes waere mir lieber gewesen...
Wenn ich es richtig sehe, wird in deinem Beispiel das PID in der blockierenden Funktion, d.h. im Kindprozess ausgegeben. Hier ist der Wert von PID das, was vor dem fork() gesetzt war, d.h. die Ausgabe des Kind-PIDs hier wird immer falsch sein. Nur der Vaterprozess (d.h. die Funktion, wo BlockingCall aufgerufen wurde) hat den richtigen PID. Siehe auch "man fork".
Hallo Rudi,
danke ... ja das leuchtet ein. Da muß ich mir etwas anderes überlegen um den Verarbeitungsweg der PID's zu verfolgen.
Schönen Abend noch Rudi.
viele Grüße
Heiko