Optimierungsvorschlag "HandleTimeout()" in fhem.pl

Begonnen von noansi, 20 Dezember 2017, 21:54:02

Vorheriges Thema - Nächstes Thema

noansi

Hallo Rudolf,

ich habe mit mal HandleTimout() angesehen und mir ist aufgefallen, dass Du darin sort über alle Timer laufen läßt.
Ich habe mal etwas Zeitmessung betrieben und für ca. 230 Timer, die bei mir Normalzustand sind, benötigt nur das Sortieren etwa 23ms auf meinem RasPi.

Mit dem folgenden Code ist der Sortieraufwand auf die zum Aufrufzeitpunkt auszuführenden Timer reduziert, was in der Regel eine geringe Anzahl ist. Damit komme ich auf etwa 11.5ms. Und unter der Vorraussetzung vieler wartendener Timer gegenüber wenigen auszuführenden Timern wird aus O(N*log(N)) ein O(N).

Zur Messung habe ich die Array Bildung vor die foreach Anweisung gelegt. Ich vermute, dass diese Zwischennutzung einer Arrayvariablen noch etwas Zusatzaufwand bedeutet.

#####################################
# Return the time to the next event (or undef if there is none)
# and call each function which was scheduled for this time
sub
HandleTimeout()
{
  return undef if(!$nextat);

  my $minCoverWait = 0.01; # 0.01 by Rudolf, but it should be set only on systems that need it!?! Any way to discover?
                           #      it depends on execution times if timers run a little bit too early
  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > $minCoverWait) { # need to cover min delay at least
    $selectTimestamp = $now;
    return $dtnext;
  }

  my ($tim,$fn,$arg); # just for reuse in the loops
  $nextat = 0;
  #############
  # Check the internal list.
  foreach my $i ( sort {$intAt{$a}{TRIGGERTIME} <=> # O(n*log(n)) ore worse,but only for the "firering" timers
                         $intAt{$b}{TRIGGERTIME} }
                    (grep {($intAt{$_}->{TRIGGERTIME}-$now) <= $minCoverWait} # just O(N)
                       keys(%intAt)) ) { # get the timers to execute due to timeout and sort just them ascending by time -> faster as normally about 1 to 5 timers may be timing out and xx-times more are waiting
    $i = "" if(!defined($i)); # Forum #40598
    next if(!$intAt{$i}); # deleted in the loop
    $tim = $intAt{$i}{TRIGGERTIME};
    $fn = $intAt{$i}{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      delete($intAt{$i});
      next;
    }
    $arg = $intAt{$i}{ARG};
    delete($intAt{$i});
    no strict "refs";
    &{$fn}($arg); # this can delete a timer and can add a timer not covered by the current loops TRIGGERTIME sorted list
    use strict "refs";
  }

  foreach my $i (keys(%intAt)) { # find next timer to trigger and clean up, O(N-done) as we need to search all the unsorted rest
    $i = "" if(!defined($i)); # Forum #40598
    next if(!$intAt{$i}); # let the line above still work
    $tim = $intAt{$i}{TRIGGERTIME};
    $fn = $intAt{$i}{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      delete($intAt{$i});
      next;
    }
    $nextat = $tim if (   ($nextat > $tim) # find the next time to trigger
                       || !$nextat);
  }

  if(%prioQueues) {
    my $nice = minNum(keys %prioQueues);
    my $entry = shift(@{$prioQueues{$nice}});
    delete $prioQueues{$nice} if(!@{$prioQueues{$nice}});
    &{$entry->{fn}}($entry->{arg});
    $nextat = 1 if(%prioQueues);
  }

  $now = gettimeofday(); # if some callbacks took longer
  $selectTimestamp = $now;

  return undef if !$nextat;
 
  $dtnext = $nextat-$now;
  return ($dtnext > $minCoverWait) ? $dtnext : $minCoverWait; # need to cover min delay at least
}


Ich glaube, berücksichtigt zu haben, was Dein bisheriger Code tut. Aber natürlich kann ich mich auch täuschen.
Gewundert hat mich, dass Du erst alle Timer nach Startzeit sortierts, aber dann trotzdem die Schleife über alle laufen läßt, obwohl eigentlich ein Abbruch nach dem Setzen von $nextat auf Grund der Sortierung möglich erscheint.

Zum Testen habe ich Martins apptime modifiziert, da darin ohnehin diese Funktion nachgebildet wird, um die Zeitmessung für Timer einzuklinken und dann diese Zusatzausgabe zu erzeugen:

################################################################
# 98_apptime:application timing
# $Id: 98_apptime.pm 14087d 2017-12-22 14:15:38Z noansi $
# based on $Id: 98_apptime.pm 14087 2017-04-23 13:45:38Z martinp876 $
################################################################

#####################################################
#
package main;

use strict;
use warnings;
use B qw(svref_2object);

use vars qw(%defs); # FHEM device/button definitions
use vars qw(%intAt);
use vars qw($nextat);

sub apptime_getTiming($$$@);
sub apptime_Initialize($);

my $apptimeStatus;

sub apptime_Initialize($){
  $apptimeStatus  = 1;#set active by default

  $cmds{"apptime"}{Fn} = "apptime_CommandDispTiming";
  $cmds{"apptime"}{Hlp} = "[clear|<field>|timer|nice] [top|all] [<filter>],application function calls and duration";
}

my $intatlen       = 0;
my $maxintatlen    = 0;
my $maxintatdone   = 0;
my $minTmrHandleTm = 1000000;
my $maxTmrHandleTm = 0;
my $minintatsorttm = 1000000;
my $maxintatsorttm = 0;

my $totDly         = 0;
my $totCnt         = 0;

sub
HandleTimeout()
{
  return undef if(!$nextat);

  my $minCoverWait = 0.00; # 0.01 by Rudi, but it should be set only on systems that need it!?!
  my $minCoverExec = 2; # look ahead due to execution time of firing timers

  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > $minCoverWait) { # need to cover min delay at least
    $selectTimestamp = $now;
    return $dtnext;
  }

  my $handleStart = $now;

  #############
  # Check the internal list.
  my @intAtKeys = keys(%intAt);

  my @intAtSort = (sort {$intAt{$a}{TRIGGERTIME} <=>
                         $intAt{$b}{TRIGGERTIME} }
                    (grep {($intAt{$_}->{TRIGGERTIME}-$now) <= $minCoverExec}
                       @intAtKeys)); # get the timers to execute due to timeout and sort ascending by time

  my $intatsorttm = gettimeofday()-$now;

  $intatlen = int(@intAtKeys);
  $maxintatlen = $intatlen if ($maxintatlen < $intatlen);

  my $nd = 0;

  my ($tim,$fn,$arg,$fnname,$shortarg,$cv);
  $nextat = 0;
  foreach my $i (@intAtSort) {
    $i = "" if(!defined($i)); # Forum #40598
    next if(!$intAt{$i}); # deleted in the loop
    $tim = $intAt{$i}{TRIGGERTIME};
    $fn = $intAt{$i}{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      delete($intAt{$i});
      next;
    }
    if ($tim - gettimeofday() > $minCoverWait) {
      $nextat = $tim; # execution time not reached yet
      last;
    }
    $arg = $intAt{$i}{ARG};

    $fnname = $fn;
    if (ref($fn) ne "") {
      $cv = svref_2object($fn);
      $fnname = $cv->GV->NAME;
    }
    $shortarg = (defined($arg)?$arg:"");
    $shortarg = "HASH_unnamed" if (   (ref($shortarg) eq "HASH")
                                   && !defined($shortarg->{NAME}) );
    ($shortarg,undef) = split(/:|;/,$shortarg,2); # for special long args with delim ;
    apptime_getTiming("global","tmr-".$fnname.";".$shortarg, $fn, $tim, $arg); # this can delete a timer and can add a timer not covered by the current loops TRIGGERTIME sorted list
    $nd++;

    delete($intAt{$i});
  }
  $maxintatdone = $nd if ($maxintatdone < $nd);

  $now = gettimeofday();

  foreach my $i (keys(%intAt)) { #(keys(%intAt)) (@intAtKeys)
    $i = "" if(!defined($i)); # Forum #40598
    next if(!$intAt{$i}); # deleted in the loop
    $tim = $intAt{$i}{TRIGGERTIME};
    $nextat = $tim if (   defined($tim)
                       && (   !$nextat # find the next time to trigger
                           || ($nextat > $tim) ) );
  }

  $intatsorttm += gettimeofday() - $now;
  $minintatsorttm = $intatsorttm if ($minintatsorttm > $intatsorttm);
  $maxintatsorttm = $intatsorttm if ($maxintatsorttm < $intatsorttm);

  $now = gettimeofday();

  if(%prioQueues) {
    my $nice = minNum(keys %prioQueues);
    my $entry = shift(@{$prioQueues{$nice}});
    delete $prioQueues{$nice} if(!@{$prioQueues{$nice}});

    $cv = svref_2object($entry->{fn});
    $fnname = $cv->GV->NAME;
    $shortarg = (defined($entry->{arg})?$entry->{arg}:"");
    $shortarg = "HASH_unnamed" if (   (ref($shortarg) eq "HASH")
                                   && !defined($shortarg->{NAME}) );
    ($shortarg,undef) = split(/:|;/,$shortarg,2);
    apptime_getTiming("global","nice-".$fnname.";".$shortarg, $entry->{fn}, $now, $entry->{arg});

    $nextat = 1 if(%prioQueues);
  }

  $now = gettimeofday(); # if some callbacks took longer
  $selectTimestamp = $now;

  $handleStart = $now - $handleStart;
  $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
  $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);

  return undef if !$nextat;
 
  $dtnext = $nextat-$now;
  return ($dtnext > $minCoverWait) ? $dtnext : $minCoverWait; # need to cover min delay at least
}
sub
CallFn(@) {
  my $d = shift;
  my $n = shift;

  if(!$d || !$defs{$d}) {
    $d = "<undefined>" if(!defined($d));
    Log 0, "Strange call for nonexistent $d: $n";
    return undef;
  }
  if(!$defs{$d}{TYPE}) {
    Log 0, "Strange call for typeless $d: $n";
    return undef;
  }
  my $fn = $modules{$defs{$d}{TYPE}}{$n};
  return "" if(!$fn);
 
  my @ret = apptime_getTiming($d,$fn,$fn,0,@_);

  if(wantarray){return @ret;}
  else         {return $ret[0];}
}

sub apptime_getTiming($$$@) {
  my ($e,$fnName,$fn,$tim,@arg) = @_;
  my $h;
  my $ts1;
  if ($apptimeStatus){
    if (!$defs{$e}{helper} ||
        !$defs{$e}{helper}{bm} ||
        !$defs{$e}{helper}{bm}{$fnName} ){
   
      %{$defs{$e}{helper}{bm}{$fnName}} =(max => 0, mAr => "",
                                          cnt => 1, tot => 0,
                                          dmx => -1000, dtotcnt => 0, dtot => 0,
                                          mTS => "");
   
      $h = $defs{$e}{helper}{bm}{$fnName};
    }
    else{
      $h = $defs{$e}{helper}{bm}{$fnName};
      $h->{cnt}++;
    }
    $ts1 = gettimeofday();
    if ($tim > 1){
      my $td = $ts1-$tim;
      $totCnt++;
      $totDly    += $td;
      $totDly    = 0 if(!$totCnt);
      $h->{dtotcnt}++;
      $h->{dtot} += $td;
      $h->{dtot} = 0 if(!$h->{dtotcnt});
      $h->{dmx}  = $td if ($h->{dmx} < $td);
    }
  }

  no strict "refs";
  my @ret = &{$fn}(@arg);
  use strict "refs";

  if ($apptimeStatus){
    $ts1 = gettimeofday()-$ts1;
    if ($ts1 && $h->{max} < $ts1){
      $h->{max} = $ts1;
      $h->{mAr} = @arg?\@arg:undef;
      $h->{mTS}= strftime("%d.%m. %H:%M:%S", localtime());
    }
   
    $h->{tot} += $ts1;
    $h->{tot} = 0 if(!$h->{cnt});
  }
  return @ret;
}

#####################################
sub apptime_CommandDispTiming($$@) {
  my ($cl,$param) = @_;
  my ($sFld,$top,$filter) = split" ",$param;
  $sFld = "max" if (!$sFld);
  $top = "top" if (!$top);
  my %fld = (name=>0,function=>1,max=>2,count=>3,total=>4,average=>5,maxDly=>6,avgDly=>7,cont=>98,pause=>98,clear=>99,timer=>2,nice=>2);
  return "$sFld undefined field, use one of ".join(",",keys %fld)
        if(!defined $fld{$sFld});
  my @bmArr;
  my @a = map{"$defs{$_}:$_"} keys (%defs); # prepare mapping hash 2 name
  $_ =~ s/[HASH\(\)]//g foreach(@a);
 
  if ($sFld eq "pause"){# no further collection of data, clear also
    $apptimeStatus  = 0;#stop collecting data
  }
  elsif ($sFld eq "cont"){# no further collection of data, clear also
    $apptimeStatus  = 1;#continue collecting data
  }
  elsif ($sFld eq "timer"){
    $sFld = "max";
    $filter = defined($filter)?$filter:"";
    $filter = "\^tmr-.*".$filter if ($filter !~ /^\^tmr-/);
  }
  elsif ($sFld eq "nice"){
    $sFld = "max";
    $filter = defined($filter)?$filter:"";
    $filter = "\^nice-.*".$filter if ($filter !~ /^\^nice-/);
  }

  foreach my $d (sort keys %defs) {
    next if(!$defs{$d}{helper}||!$defs{$d}{helper}{bm});
    if ($sFld eq "clear"){
      delete $defs{$d}{helper}{bm};
      $totDly         = 0;
      $totCnt         = 0;
      $maxintatlen    = 0;
      $maxintatdone   = 0;
      $minintatsorttm = 1000000;
      $maxintatsorttm = 0;
    }
    elsif ($sFld =~ m/(pause|cont)/){
    }
    else{
      foreach my $f (sort keys %{$defs{$d}{helper}{bm}}) {
        next if(!defined $defs{$d}{helper}{bm}{$f}{cnt} || !$defs{$d}{helper}{bm}{$f}{cnt});
        next if($filter && $d !~ m/$filter/ && $f !~ m/$filter/);
        my ($n,$t) = ($d,$f);
        ($n,$t) = split(";",$f,2) if ($d eq "global");
        $t = "" if (!defined $t);
        my $h = $defs{$d}{helper}{bm}{$f};
     
        my $arg = "";
        if ($h->{mAr} && scalar(@{$h->{mAr}})){
          foreach my $i (0..scalar(@{$h->{mAr}})){
            if(ref(${$h->{mAr}}[$i]) eq 'HASH' and exists(${$h->{mAr}}[$i]->{NAME})){
              ${$h->{mAr}}[$i] = "HASH(".${$h->{mAr}}[$i]->{NAME}.")";
            }
          }
          $arg = join ("; ", map { $_ // "(undef)" } @{$h->{mAr}});
         }
     
        push @bmArr,[($n,$t
                     ,$h->{max}*1000
                     ,$h->{cnt}
                     ,$h->{tot}*1000
                     ,($h->{cnt}?($h->{tot}/$h->{cnt})*1000:0)
                     ,(($h->{dmx}>-1000)?$h->{dmx}*1000:0)
                     ,($h->{dtotcnt}?($h->{dtot}/$h->{dtotcnt})*1000:0)
                     ,$h->{mTS}
                     ,$arg
                    )];
      }
    }
  }

  return "apptime initialized\n\nUse apptime ".$cmds{"apptime"}{Hlp} if ($maxTmrHandleTm < $minTmrHandleTm);

  my $field = $fld{$sFld};
  if ($field>1){@bmArr = sort { $b->[$field] <=> $a->[$field] } @bmArr;}
  else         {@bmArr = sort { $b->[$field] cmp $a->[$field] } @bmArr;}
  my $ret = sprintf("active-timers: %d; max-active timers: %d; max-timer-load: %d  ",$intatlen,$maxintatlen,$maxintatdone);
  $ret .= sprintf("min-tmrHandlingTm: %0.1fms; max-tmrHandlingTm: %0.1fms; totAvgDly: %0.1fms\n",$minTmrHandleTm*1000,$maxTmrHandleTm*1000,($totCnt?$totDly/$totCnt*1000:0));
  $ret .= sprintf("min-timersortTm: %0.1fms; max-timersortTm: %0.1fms\n",$minintatsorttm*1000,$maxintatsorttm*1000);
  $ret .= ($apptimeStatus ? "" : "------ apptime PAUSED data collection ----------\n")
            .sprintf("\n %-40s %-35s %6s %8s %10s %8s %8s %8s %-15s %s",
                     "name","function","max","count","total","average","maxDly","avgDly","TS Max call","param Max call");
  my $end = ($top && $top eq "top")?40:@bmArr-1;
  $end = @bmArr-1 if ($end>@bmArr-1);

  $ret .= sprintf("\n %-40s %-35s %6d %8d %10.2f %8.2f %8.2f %8.2f %-15s %s",@{$bmArr[$_]})for (0..$end);
  return $ret;
}

1;
=pod
=item command
=item summary    support to analyse function performance
=item summary_DE Unterst&uuml;tzung bei der Performanceanalyse von Funktionen
=begin html

<a name="apptime"></a>
<h3>apptime</h3>
<div style="padding-left: 2ex;">
  <h4><code>apptime</code></h4>
    <p>
        apptime provides information about application procedure execution time.
        It is designed to identify long running jobs causing latency as well as
        general high <abbr>CPU</abbr> usage jobs.
    </p>
    <p>
        No information about <abbr>FHEM</abbr> kernel times and delays will be provided.
    </p>
    <p>
        Once started, apptime  monitors tasks. User may reset counter during operation.
        apptime adds about 1% <abbr>CPU</abbr> load in average to <abbr>FHEM</abbr>.
    </p>
    <p>
        In order to remove apptime, <kbd>shutdown restart</kbd> is necessary.
    </p>
    <p>
        <strong>Features</strong>
    </P>
    <dl>
      <dt><code><kbd>apptime</kbd></code></dt>
        <dd>
            <p>
              <kbd>apptime</kbd> is started with the its first call and continously monitor operations.<br>
              To unload apptime, <kbd>shutdown restart</kbd> is necessary.<br> </li>
            </p>
        </dd>
      <dt><code><kbd>apptime clear</code></dt>
          <dd>
            <p>
                Reset all counter and start from zero.
            </p>
          </dd>
      <dt><code><kbd>apptime pause</code></dt>
          <dd>
            <p>
                Suspend accumulation of data. Data is not cleared.
            </p>
          </dd>
      <dt><code><kbd>apptime cont</code></dt>
          <dd>
            <p>
                Continue data collection after pause.
            </p>
          </dd>
      <dt><code><kbd>apptime [count|funktion|average|clear|max|name|total] [all]</kbd></code></dt>
        <dd>
            <p>
                Display a table sorted by the field selected.
            </p>
            <p>
                <strong><kbd>all</kbd></strong> will display the complete table while by default only the top lines are printed.<
            </p>
        </dd>
    </dl>
    <p>
        <strong>Columns:</strong>
    </p>
    <dl>
      <dt><strong>name</strong></dt>
        <dd>
            <p>
                Name of the entity executing the procedure.
            </p>
            <p>
                If it is a function called by InternalTimer the name starts with <var>tmr-</var>.
                By then it gives the name of the function to be called.
            </p>
        </dd>
      <dt><strong>function</strong><dt>
          <dd>
            <p>
                Procedure name which was executed.
            </p>
            <p>
                If it is an <var>InternalTimer</var> call it gives its calling parameter.
            </p>
          </dd>
      <dt><strong>max</strong></dt>
        <dd>
            <p>
                Longest duration measured for this procedure in <abbr>ms</abbr>.
            </p>
        </dd>
      <dt><strong>count</strong></dt>
        <dd>
            <p>
                Number of calls for this procedure.
            </p>
        </dt>
      <dt><strong>total</strong></dt>
        <dd>
            <p>
                Accumulated duration of this procedure over all calls monitored.
            </p>
        </dd>
      <dt><strong>average</strong></dt>
        <dd>
            <p>
                Average time a call of this procedure takes.
            </p>
        </dd>
      <dt><strong>maxDly</strong></dt>
        <dd>
            <p>
                Maximum delay of a timer call to its schedules time.
                This column is not relevant for non-timer calls.
            </p>
        </dd>
      <dt><strong>param Max call</strong></dt>
        <dd>
            <p>
                Gives the parameter of the call with the longest duration.
            </p>
        </dd>
    </dl>
</div>

=end html
=cut


Noch eine Frage. Was passiert auf Systemen, für die "# need to cover min delay at least" mit 0.01s zutrifft, wenn mann mit select weniger als 0.01s warten will?
Wartet es dann einfach nicht oder wartet es dann, bis ein IO Ereignis eintritt?

Und noch eine Frage: Warum behandelst Du die prioQueues nach den Timern?

Gruß, Ansgar.

EDIT: apptime noch etwas verfeinert und aktualisiert
EDIT2: apptime um Durchschnittliche Timerverzögerung ergänzt
EDIT3: apptime keys verringert bzw. zusammengefasst. Einem HASH(hexnumm) wird wohl selten nachgegangen, ohne Name.

rudolfkoenig

Zitatca. 230 Timer, die bei mir Normalzustand sind
Darf ich fragen, wozu man soviele Timer braucht?

ZitatDamit komme ich auf etwa 11.5ms.
Ich habe dein Patch in etwa uebernommen.

Das mit 0.01 habe ich entfernt, da ich nicht mehr genau weiss, wozu es gut ist.
Evtl. muss ich es wieder einbauen, aber dann weiss ich mehr :)

herrmannj

ZitatDarf ich fragen, wozu man soviele Timer braucht?
timeouts und so, da kommt halt was zusammen.

btw, spräche etwas dagegen aus dem hash (%intAt) ein Array zu machen und zwar so das die timer in der Reihenfolge der Ausführung dort liegen ? Dann müsste das sortieren doch nur beim einfügen erforderlich sein, bzw man müsste eben per split an der richtigen Stellen den Timer einfügen.

Beim ausführen ist dann immer array[0] der nächste und kann per shift gleich raus. Der Inhalt des array könnte ja meinetwegen der key vom %intAt sein, dann bleibt der code um %intAt einigermaßen stehen.

Edit: warum ? da dürften nur noch nanosec nach bleiben...

rudolfkoenig

Zitattimeouts und so, da kommt halt was zusammen.
Auf meinem System sind es 16 Stueck. Und sortieren von 1000 dauert 3ms. Und das wird nur dann ausgefuehrt, falls einer der Timer zuschlaegt.

Zitatspräche etwas dagegen aus dem hash (%intAt) ein Array zu machen
Es gibt 11 Module, die auf %intAt zugreifen, und keiner von denen ist unter meinem Obhut.

herrmannj

#4
ZitatEs gibt 11 Module, die auf %intAt zugreifen, und keiner von denen ist unter meinem Obhut.
irgendwas ist immer. So what.

Ich hab das mal als proposal angehängt. Unvollständig (kein remove, keine priorityQueue). HandleTimeout ist bei mir nicht mehr messbar, insert sauschnell (ns)

Schaut Euch das Konzept bitte mal an. Wenn es Zustimmung findet arbeite ich den Rest gern aus, bzw wenn noansi übernehmen mag, gern (Er hat den Stein ja ins Rollen gebracht). Mir geht es nur darum die Idee zu demonstrieren und messbar zu machen.


sub
HandleTimeout() {
  return unless (defined($timerQueue) and @{$timerQueue});
 
  my $now = gettimeofday();
  if($now < $timerQueue->[0]->{'TRIGGERTIME'}) {
    $selectTimestamp = $now;
    return ($timerQueue->[0]->{'TRIGGERTIME'} - $now);
  };
  my $t = shift @{$timerQueue};
  my $fn = $t->{'FN'};
  my $arg = $t->{'ARG'};
  print "call $fn \n";
  if (ref $fn eq 'CODE') {
    $fn->($arg);
  } else {
    (\&$fn)->($arg);
  }; 
  return HandleTimeout();
};

sub
addInternalTimer {
  my ($tim, $fn, $arg) = @_;
  print "insert $tim $fn \n";
  if (defined($timerQueue) and @{$timerQueue}) {
    my $i = 0;
    foreach (@{$timerQueue}) {
      if ($timerQueue->[$i]->{'TRIGGERTIME'} > $tim) {
        splice @{$timerQueue}, $i, 0, {
          'TRIGGERTIME' => $tim,
          'FN' => $fn,
          'ARG' => $arg,
        };
        return;
      };
      $i++;
    };
    $timerQueue->[$i] = {
      'TRIGGERTIME' => $tim,
      'FN' => $fn,
      'ARG' => $arg,
    };
    return;   
  } else {
    $timerQueue->[0] = {
      'TRIGGERTIME' => $tim,
      'FN' => $fn,
      'ARG' => $arg,
    };
    return;
  };
};

#####################################
sub
InternalTimer($$$;$)
{
  my ($tim, $fn, $arg, $waitIfInitNotDone) = @_;

  $tim = 1 if(!$tim);
  if(!$init_done && $waitIfInitNotDone) {
    select(undef, undef, undef, $tim-gettimeofday());
    no strict "refs";
    &{$fn}($arg);
    use strict "refs";
    return;
  }

  addInternalTimer($tim, $fn, $arg);
  use Data::Dumper;
  print Data::Dumper->new([$timerQueue],[qw($timerQueue)])->Indent(1)->Quotekeys(1)->Dump;
  return;
};


Ergänzt:
Code erweitert auf {FN} = Name | Coderef,
rekursion richtig gemacht
insert #0 korrigiert

noansi

#5
Hallo Rudolf,

ZitatDarf ich fragen, wozu man soviele Timer braucht?
Viele Watchdogs und Timeouts für Sensoren, Failsafetimeouts etc. oder regelmäßige Veränderungen, die ich mir eingebaut habe. Damit kommen viele Langläufer zusammen.
Danke für den Einbau!
Timer nutze ich mittlerweile häufig, um notify Lawinen aufzubrechen, damit IO nicht so lange steht. Ob ein Reading sofort oder eine s später aktualisiert wird (und damit sein notify losbricht), ist meistens nicht relevant, respektive man kann sich systembedingt ohnehin nicht auf ein exaktes Timing verlassen. Lange stehendes IO ist dagegen relevant.

ZitatDas mit 0.01 habe ich entfernt, da ich nicht mehr genau weiss, wozu es gut ist.
In 00_CUL.pm Zeile 648 gibt es noch diesen Hinweis:
648     if ($dDly > 0.01){# wait less then 10 ms will not work
649       $dDly = 0.1 if($dDly > 0.1);
650       Log3 $hash->{NAME}, 5, "CUL $id dly:".int($dDly*1000)."ms";
651       select(undef, undef, undef, $dDly);
652     }



Zitatspräche etwas dagegen aus dem hash (%intAt) ein Array zu machen
Danke herrmannj, finde ich super, daran hatte ich auch gedacht und es erst mal mit einem zusätzlichen Array mit Startzeit und key probiert.
Mir ist dann aber auch aufgefallen, das %intAt in anderen Modulen direkt verwendet wird, so wie Rudolf es schon angemerkt hat. Böse Falle, selbst wenn man nicht auf ein Array wechseln müßte.
Damit muss beim Einfügen eines Timers für alle Fälle schon wieder voll durchsortiert werden. Aber auch damit ist nicht sicher gestellt, dass bis zur Abarbeitung der Timer wieder was verändert wurde.
Auf Basis der hashes ist das schon ganz gut gelöst, so wie Rudolf das gemacht hat.

Wie ich gelernt habe, müßten die Maintainer all dieser Module diese, vermutlich historisch bedingte, "%intAt Direktnutzungsseuche" erst mal auf das Funktionsinterface umstellen. Bekommst Du die dazu?

Nur wenn die Timerfunktionalität komplett gekappselt werden könnte, dann kann solcher Wildwuchs verhindert werden. Ich glaube, das ist ein Monsterprojekt wegen der "Sichtbarkeit" von Variablen, wenn man Funktionen nach Namen aufruft. Das wird aber so häufig verwendet, insbesondere schon bei den Timern selbst.


@Rudolf: Remove könnte teilweise schneller genutzt werden, wenn InternalTimer den Hashkey nebst Aufrufdaten zurück liefern würde, so dass das nutzende Modul seinen Timer direkt aber dennoch eindeutig über eine zusätzliche Remove Funktion löschen kann.
Über so eine eindeutige Zugriffsmöglichkeit wäre es auch denkbar, einen existierenden Timer zu aktualisieren oder modifizieren.

Etwas schneller geht Remove prinzipiell schon so, also feste Abfragen konstante Ergebnisse raus aus der Schleife:
sub
RemoveInternalTimer($;$)
{
  my ($arg, $fn) = @_;
  if ($fn) {
    if (defined($arg)) {
      foreach my $a (keys %intAt) {
        delete($intAt{$a}) if($intAt{$a}{ARG} eq $arg &&
                              ($intAt{$a}{FN} eq $fn));
      }
    }
    else {
      foreach my $a (keys %intAt) {
        delete($intAt{$a}) if($intAt{$a}{FN} eq $fn); #remove any timer with $fn function call
      }
    }
  }
  else {
    return if (!defined($arg));
    foreach my $a (keys %intAt) {
      delete($intAt{$a}) if($intAt{$a}{ARG} eq $arg); #remove any timer with $arg argument
    }
  }
}


Gruß, Ansgar.

herrmannj

das mit den modulen finde ich jetzt nicht soo schlimm. Wenn man immer Angst hat etwas bestehendes an zufassen dann geht es nie voran.

Ich sehe auch nur 11 (auf die Schnelle). Davon sind schon eins WifiLight und 2mal Milight (weil von WifiLight geforked), das sind schon mal 3. Wobei ich nur die Hoheit über WifiLight habe, milight scheint verwaist. Könnte ich aber, ist ja mein code.

In WifiLight fasse ich %intAt an weil es "damals" keine vernünftige remove gab. Könnte(müsste) man heute direkt über remove machen. Den "anderen" wird es genau so gehen. Alles lösbar.

noansi

#7
Hallo herrmannj,

Zitatdas mit den modulen finde ich jetzt nicht soo schlimm. Wenn man immer Angst hat etwas bestehendes an zufassen dann geht es nie voran.

Sehe ich auch so.
Nur wenn ich das mache, dann kommt meistens gleich so viel zusammen, dass es hinterher Maintainer nicht übernehmen können oder wollen. Oder es nicht so übernehmen wie gedacht. Also bleibt nur der Weg der kleinen Schritte.

Schritt 0 hast Du gemacht mit etwas Performance Test eines Alternativlösungsansatz. Nebenbei auf welcher Hardwarebasis? Ich teste auf RasPi 2.

Schritt 1 wäre also: alle Module, die %intAt nutzen werden auf Funktionsnutzung umgestellt. Hier mal eine Liste mit Kommentar dazu.
98_Modbus.pm       "böser" Kandidat, nutzt Timer Daten -> Änderung eingepflegt
95_Alarm.pm          RemoveInternalTimer nutzen -> Änderung im Test nur "use vars qw(%intAt);" steht noch ungenutzt im Code
95_YAAHM.pm         nur "use vars qw(%intAt);" entfernen? -> Änderung kosmetisch, wird nicht genutzt
00_THZ.pm             RemoveInternalTimer nutzen -> kurzfristige Änderung zugesagt, nutzt Remove Erweiterung
95_PostMe.pm        nur "use vars qw(%intAt);" entfernen? -> Änderung kosmetisch, wird nicht genutzt
00_SONOS.pm        nur "use vars qw(%intAt);" entfernen? -> Änderung kosmetisch, wird nicht genutzt
32_WifiLight.pm       RemoveInternalTimer nutzen, wie schon genannt -> Änderung soll die Tage passieren
59_Twilight.pm         Nutzung bereits auskommentiert, weg mit dem Komentar  ;) -> Änderung kosmetisch
30_MilightBridge.pm  RemoveInternalTimer nutzen, wie schon genannt -> Änderung wäre machbar
31_MilightDevice.pm Nutzung bereits auskommentiert, weg mit dem Komentar  ;) -> Änderung kosmetisch

98_apptime.pm       Zwangsläufig heftig umzustellen und "Testumgebung" -> mit Vorschlag erstellt

fhem.pl                    soll verändert werden, lokale Nutzung überschaubar -> Vorschlag ist erstellt und in beschränkter Testumgebung getestet

Gruß, Ansgar.

EDIT: übrige relevante Maintainer per PM angeschrieben, mal schauen, was sich tut.
EDIT 2: Statusergänzung aus Feedback
EDIT 3: Statusergänzung aus Feedback, Module aus SVN sind angepasst

rudolfkoenig

@Ansgar:
Soll RemoveInternalTimer jetzt schneller werden oder flexibler? Denn Sinn von "nur fn zu spezifizieren" verstehe ich zwar nicht, man koennte es aber mit deutlich weniger Aenderung so realisieren:
sub
RemoveInternalTimer($;$)
{
  my ($arg, $fn) = @_;
  return if(!$arg && !$fn);
  foreach my $a (keys %intAt) {
    delete($intAt{$a}) if((!$arg || $intAt{$a}{ARG} eq $arg) &&
                          (!$fn || $intAt{$a}{FN} eq $fn));
  }
}

Falls ich verstehe, wann Loeschen nur mit fn sinnvoll ist, dann baue ich das ein :)

@herrmannj: wir koennen es gerne Umbauen, wenn alle "RemoveInternalTimer" Kandidaten umgestellt haben. 98_apptime ist keine zwingende Applikation und kann nachgezogen werden, und Modbus ist selbst Schuld. Bin aber gerne behilflich, um Modbus ein "Leben danach" zu ermoeglichen.

noansi

Hallo Rudolf,

ZitatFalls ich verstehe, wann Loeschen nur mit fn sinnvoll ist, dann baue ich das ein
Ist eine riskante Option, aber immi benötigt das wohl bei THZ, um alle Timer seines Moduls auf einmal schnell los zu werden. Ich hoffe er stellt das hier nochmal klar und er legt Wert auf ein schnelles Remove.

Zitatmit deutlich weniger Aenderung
Mir ging es primär darum, die Abfragen innerhalb der jeweiligen Schleife auf das nötigste zu begrenzen, um wiederholte Auswertung zu minimieren. Oder ist der Perl Compiler so clever, das selbst zu optimieren?

Gruß, Ansgar.

herrmannj

Zitat@herrmannj: wir koennen es gerne Umbauen, wenn alle "RemoveInternalTimer" Kandidaten umgestellt haben. 98_apptime ist keine zwingende Applikation und kann nachgezogen werden, und Modbus ist selbst Schuld. Bin aber gerne behilflich, um Modbus ein "Leben danach" zu ermoeglichen.
Yepp. Keine Hektik. Für WifiLight mach ich das die Tage. Es ist ohnehin guter Stil die gekapselten Aufrufe zu nehmen. Ist halt gewachsen und da kann man ja auch mal aufräumen. Entweder man geht mit der Zeit - oder man geht mit der Zeit...

Im übrigen ist es ja auch denkbar das einige Autoren %intAt direkt verwenden weil sie Funktionalitäten benötigen die sonst nicht gehen. Da muss man mal die Rückmeldungen abwarten.

Ich bin auch gestern nur eingestiegen weil ich den code a) sowieso an anderer Stelle benötige und mir b) das auch schon immer ineffizient vorgekommen ist. Schön das noansi das mal strukturiert angepackt hat!

Performance Gedanken finde ich an dieser zentralen Stelle auch sehr sehr wichtig. Genau diese Stelle ist die am häufigsten angesteuerte in fhem. Wenn ich jetzt mal die 25ms zugrunde lege (nicht nachgemessen):

Nehme ich mal 20 Nachrichten pro Sekunde (5 rein, 5 raus). Die Netzwerkverbindung ist moderat, jede Nachricht benötigt 2 mal select.
20 x 25ms sind 500ms (auf 1Sekunde). Dann _würde_ (ist ja Theorie) 50% der Zeit für das Sortieren der Timer "verbraten". Die Zahlen lassen sich alle hinterfragen aber das Prinzip kommt rüber.

noansi

Hallo zusammen,

ZitatGenau diese Stelle ist die am häufigsten angesteuerte in fhem
Daher auch meine Bemühungen, an dieser Stelle möglichst nichts zu verschenken. Die eigentlichen Timerfunktionen sind schon "schlimm" genug.  ;)

RemoveInternalTimer ist auch gern genommen, häufig vermutlich aus bequemer Vorsicht, wie ich es auch anfangs gemacht habe.

Gruß, Ansgar.

herrmannj

kann man ja auch optimieren. Der patch oben ist nur POC. Produktiv kann der zu Problemen führen: das aktuelle Verhalten ist das ein "$arg" (in der Praxis Instanz $hash) nur _einen_ timer registrieren kann. Mit der Änderungen auf array könnte ein "$arg" mehrfach registriert werden.

Wenn sich bestehende Module auf das aktuelle verhalten verlassen (also nicht einen laufenden timer löschen und neu setzen sondern einfach neu setzen obwohl noch einer "pending" ist) dann _könnte_ der patch zu Problemen führen. Das gilt noch mehr für remove.

Produktiv würde ich parallel einen hash führen dessen key die "$args" sind. Dann kann man vor dem Installieren eines Timers prüfen ob er schon gesetzt ist (und remove implizit aufrufen, welches den Timer und key löscht). Das setzen des keys kostet kaum performance weil dort ja nicht sortiert werden muss.

Wenn man das nicht macht müsste man beim löschen das komplette array durchlaufen und _alle_ timer löschen (bei denen $arg und $fn passen). Das wäre langsamer, aber immer noch um Größenordnungen schneller als das gesamte aktuelle Vorgehen.

Beim insert (ins array) kann man auch noch optimieren: der muss ja nicht von 0 aufwärts alle array Elemente durchprobieren. Wenn man das Element in der Mitte als erste Probe nimmt und dann jeweils nach unten (oder oben, je nachdem ob die Probe früher oder später ergibt) gegen die Hälfte der verbleibenden Elemente testet (und dann wieder gegen die Hälfte der Hälfte usw) kann man das auch noch weiter beschleunigen. Das halte ich aber schon für absolutes fine-tunung.

herrmannj

#13
Zitat98_apptime ist keine zwingende Applikation und kann nachgezogen werden,
@Rudi: wie denkst Du darüber da (irgendwo) eine offizielle Schnittstelle einzubauen.

Pefmon und apptime sind ja eigentlich nur hacks gewesen (ok für apptime kann ich nicht sprechen, bei perfmon bin ich mir sicher ;) ) und beide module werden ja oft und gern eingesetzt. Man könnte die Funktionalität doch direkt im core (fhem.pl), genau hier in den timern, abbilden.

Eventuell so das sich Hilfsmodule dort einklinken können ohne das Funktionen gekapert werden müssen. Wenn man das halbwegs durchdenkt bekommt man vmtl sogar noch mehr (aussagefähigere) Daten raus.

Ergänzung:
natürlich so das es perfomance neutral ist wenn die Funktionen vom user nicht benötigt werden.

noansi

Hallo herrmannj,

ZitatEventuell so das sich Hilfsmodule dort einklinken können ohne das Funktionen gekapert werden müssen. Wenn man das halbwegs durchdenkt bekommt man vmtl sogar noch mehr (aussagefähigere) Daten raus.
Grundsätzlich keine schlechte Idee. Kann so was über Codereferenzvariablen, über die Kernfunktionen aufgerufen werden, ermöglicht werden? Also so, dass man durch das Verbiegen der Codreferenzvariablen, die z.B. HandleTimeout() aufruft, eine Alternativfunktion aufrufen könnte. Und nach Nutzung die Variable wieder auf den alten Wert zurückstellt, also so was wie apptime zum selektiven ein- und ausschalten mit der Möglichkeit Testcode zu ergänzen oder die Funktion mal vollständig testweise zu ersetzen.

Ständig auf Verdacht Performancedaten zu messen oder gar zu sammeln halte ich dagegen für problematisch mit Blick auf die schwächere Hardwarebasis, die gerne als günstiger Dauerläufer genutzt wird.
Und das spezielle Problem, das man beleuchten möchte, würde vermutlich gerade nicht durch Standardfunktionen abgedeckt.

Gruß, Ansgar.