FHEM Forum

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.

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 :)

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...

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.

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

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.

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.

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

@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.

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.

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.

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.

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.

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.

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.

ja, so in der Art.

Man könnte zb einige Variablen (wo auch immer) definieren und an neuralgischen Punkten abfragen:

if (defined($profiler)) {$profiler-> (blub..)}

Das sollte jo nicht so ins Gewicht fallen. Wichtig ist wo die überall stehen und wie ausdifferenziert die sind.

Im Prinzip sollte apptime (und co) nicht mehr die internen Funktionen verbiegen müssen um seinen job zu erledigen. Rückwärts müsste man also fragen "was braucht man generell um verschiedene Fragen zur Performance zu beantworten?" und dort dann diese codepoints hinschreiben.

Wenn keiner was messen will bleibt es bei "is defined?". Nö? dann weiter ..
Das könnte man noch ein wenig kapseln damit sich nicht zwei module gleichzeitig und nicht kooperativ da andocken.

Wenn man es darauf ankommen lassen möchte kann man das auch über conditional compile komplett neutral lösen.

Am Anfang
use constant ('PROFILE', 0);

später
if( PROFILE ){
      $profile->(blub..);
};

Wenn PROFILE auf '0' steht wird der code mit dem if erst garnicht erzeugt. Kann man dann aber nicht mehr über attribute und co steuern.

google empfiehlt da diese Möglichkeit:
use constant PROFILE= $ENV{PROFILE};

start mit
PROFILE=1 fhem.pl ..

Clever!. Wie ging das früher nur ohne google ;)

Hallo Zusammen,

ich sehe gerade, dass schon die letzte Änderung eventuell erste Nebenwirkungen zeigt https://forum.fhem.de/index.php/topic,75638.msg735154.html#msg735154 (https://forum.fhem.de/index.php/topic,75638.msg735154.html#msg735154).

Modbus hat wohl Antwort Timeouts im 2 Sekunden Bereich. Jedoch nach einem Broadcast und zwischen zwei Sendetelgrammen eine Turnaround Delay Zeit im 100-200ms Bereich Stille zu halten, bevor ein Request gesendet wird, wenn ich das im schnellen Überfliegen grob richtig verstanden habe.

Das könnte nun eventuell schief gehen, wenn das Senden schon regelmäßig zu spät ausgeführt würde. Das könnte dadurch ausglöst sein, dass die Timerverarbeitung nun bis zum Startzeitpunkt von HandleTimeout() ausgeführt wird und nicht mehr während der Verarbeitung die weiter laufende Zeit aktualisiert wird, um in dieser Zeit noch fällig werdende zuvor schon registrierte Timer abzuarbeiten.

Gruß, Ansgar.

Zitat von: herrmannj am 22 Dezember 2017, 00:14:45
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.

Guten Morgen,

Jörg hierzu eine kleine Frage. Ich kann doch zum jetzigen Zeitpunkt bereits mehrere Timer an einen Hash binden.


InternalTimer( gettimeofday()+4, 'LGTV_WebOS_GetForgroundAppInfo', $hash );

Und das passende Remove

RemoveInternalTimer($hash,'LGTV_WebOS_GetForgroundAppInfo');


Oder ist das was anderes?

nach nochmaligem Studium: Du hast Recht! :)

Hallo,

ich habe kein Problem damit, Modbus.pm an ein neues Interface anzupassen.
Bisher greife ich an einer Stelle direkt auf intAt zu, um den Status eines laufenden Timers abzufragen.
Wenn es dafür ein definiertes Interface gäbe, wäre das natürlich eleganter:


   # find internal timeout timer time and calculate remaining timeout
    foreach my $a (keys %intAt) {
        if($intAt{$a}{ARG} eq $arg) {
            $rest = $intAt{$a}{TRIGGERTIME} - $now;
        }
    }


unabhängig davon benötigt Modbus mehrere Timer für z.B.:

• Abfrage von Werten von einem Modbus-Slave in einem definierten Intervall
• Timeout beim Warten auf eine Antwort vom abgefragten Modbus-Slave
• Wartezeit zwischen sequentiellen Abfragen beim Scannen eines Modbus-Slave
• Abarbeiten der Send-Queue

Ich mache das bisher mit InternalTimer und einem Text-Argument a la "queue:$name" um dann in der aufgerufenen Funktion wieder den Hash zum Device-Namen zu holen.
Wenn das künftig eleganter geht, baue ich auch das gerne um.

Gruss
   Stefan

Du würdest so was wie

$tl = internalTimer_TimeLeft($id) benötigen ? Richtig ?

return undef wenn es den Timer nicht gibt, sonst x.y .. (?)

Hallo Stefan,

danke für die Änderungsbereitschaft.

Zitatum den Status eines laufenden Timers abzufragen

Warum hast Du den Weg gewählt? Du könntest Dir doch die Timer selbst in einem hash mit Timeout Zeit merken und wenn der Timer ausgeführt wird, oder Du RemoveInternalTimer nutzt, wieder löschen. Damit wäre der Lookup vermutlich deutlich schneller, da Dein $arg der hashkey wäre.

Aber wie sieht es mit der aktuellen Änderung in fhem.pl aus? Kannst Du damit Nebenwirkungen bezüglich Timing feststellen?

Gruß, Ansgar.

ich versuch das (https://forum.fhem.de/index.php/topic,75638.msg735154.html#msg735154) auch gerade nachzuvollziehen, müssen wir ja wieder glattziehen.

Ich verstehe es aber nicht. Der Zeitpunkt von HandleTimeout() bzw dem callback ist doch unverändert ?

Hallo herrmannj;

ZitatDer Zeitpunkt von HandleTimeout() bzw dem callback ist doch unverändert ?

Nicht ganz.
In der alten Variante wurde in der Schleife über alle timer auch $now aktualisiert, um der Rechenzeit laufender Timerfunktionen Rechnung zu tragen.
Vor der nächsten Timerbehandlung kommt dann auch wieder IO der für weitere Verzögerung sorgen kann.
Außerdem gab es noch die ominöse 0.01 ...
Es gibt also schon Unterschiede.

Es besteht natürlich auch die Möglichkeit eines zufällig aufgetretenen anderen Problems bei dem Beitrag, aber ich kann dazu nicht mal eben ohne irgendwelches Testmaterial nachvollziehen, auf was die Logeinträge wohl alles hinweisen könnten.
Z.B. statt ins Plätzchen in den Abschlusswiderstand gebissen?  ;)

Gruß, Ansgar.

hmmm. Also vorher waren das ja auch eher so plus minus eine Minute wann der callback kam. :) Je nachdem was sonst "so los war".

Mal schauen ob Stefan eine Idee hat.

Nachtrag:
na, wenn der user schreibt dass es mit dem rollback von fhem.pl das beseitigt wird, dann wird es wohl schon was damit zu tun haben. Ich blick nur gerade nicht wo und warum ....

Hallo herrmannj,

Zitatdem rollback von fhem.pl das beseitigt wird, dann wird es wohl schon was damit zu tun haben

Hatte ich spontan auch gedacht, aber entweder wird Modbus sehr selten genutzt oder Modbus Nutzer sind sehr zurückhaltend mit FHEM updates. Mir fehlt da derzeit mehr Problemfeedback anderer User und zur Analyse ohnehin detailiertere Log Datenbasis.

Gruß, Ansgar.

gab es gerade. Bei einem anderen user (erwartungsgemäß) problemlos. Schaun mer mal :)

Zitatimmi benötigt das wohl bei THZ, um alle Timer seines Moduls auf einmal schnell los zu werden.

Ist noch nicht wirklich eine Erklaerung, ich habe mein Vorschlag mit RemoveInternalTimer aber eingebaut.

ZitatNehme 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).

Ich gehe davon aus, dass du
if($now < $nextat) {
    $selectTimestamp = $now;
    return ($nextat-$now);
  }

uebersehen hast. Ich bin imer noch auf dem Standpunkt, dass HandleTimeout nur bei extrem vielen kurzen Timern relevant ist, und ich verstehe noch nicht, wann sowas benoetigt wird. In meiner Produktiv-Installation spart die ganze Optimierung hier grob geschaetzt pro Stunde 1ms. Und das auch nur, weil zwei Geraete alle 5 Minuten pollen.

ZitatMan könnte die Funktionalität doch direkt im core (fhem.pl), genau hier in den timern, abbilden.

Erstens sind die Timer nur ein Teil (CallFn ist mindestens so wichtig, evtl. auch weitere), zweitens muesste man an diversen Stellen (vor dem Aufruf, nach dem Aufruf,) Hooks anbieten. Ich zoegere noch.

Zitatich sehe gerade, dass schon die letzte Änderung eventuell erste Nebenwirkungen zeigt https://forum.fhem.de/index.php/topic,75638.msg735154.html#msg735154 (https://forum.fhem.de/index.php/topic,75638.msg735154.html#msg735154).

Wundere mich wieso. Kann nur an den 0.01 liegen, aber das wuerde ich gerne weghaben.

ZitatBisher greife ich an einer Stelle direkt auf intAt zu, um den Status eines laufenden Timers abzufragen.

Das kann man auch, indem man TRIGGERTIME beim InternalTimer Aufruf merkt. internalTimer_TimeLeft muesste den naechsten Timer zurueckliefern, was wiederum erst nach sortieren bekannt ist, wobei wir bei der Anfangsdiskussion angekommen sind.

Hallo Rudolf,

hier noch eine kleine Abwandlung von HandleTimeout, um dem ursprünglichen Verhalten näher zu kommen.
Einfach ein bischen mehr mit $minCoverExec in die Zukunft vorbereiten und dann in der Schleife abbrechen, wenn es zu viel war bevor der Timer ausgeführt wird:

#####################################
# 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.0; # 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 $minCoverExec = 2; # look ahead to cope 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 ($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) <= $minCoverExec} # 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, but maybe they are a strange signal/flag?
      delete($intAt{$i});
      next;
    }
    if ($tim - gettimeofday() > $minCoverWait) {
      $nextat = $tim; # execution time not reached yet
      last;
    }
    $arg = $intAt{$i}{ARG};
    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";
    delete($intAt{$i});
  }

  foreach my $i (keys(%intAt)) { # find next timer to trigger, 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};
    $nextat = $tim if (   defined($tim)
                       && (   !$nextat # find the next time to trigger
                           || ($nextat > $tim) ) );
  }

  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
}


Gruß, Ansgar.

ich bin da skeptisch. Der callback ist von der Summe der Latenzen _aller_  module, notify, callbacks usw abhängig (gern genommen: > 1000 msec). Der war noch nie, niemals, auf die Millisekunde genau. Wieso sollen jetzt die 10 oder 2ms einen Unterschied machen ?

Hallo,

Bei Modbus gibt es keine harten Timing-Anforderungen, die eine schnelle Reaktion erfordern. Es geht mehr um die Performance oder darum dass Mindest-Wartezeiten nicht unterschritten werden. Bei einigen Geräten wollen die Benutzer viele (mehrere hundert) Werte alle 10 Sekunden abfragen. Wenn das dann nicht optimiert abläuft, dann reicht das im vorgegebenen Intervall nicht und die Send-Queue läuft über bzw. der Anwender muss das Intervall vergrößern. Deshalb sollten die Wartezeiten auch nicht unnötig lang sein.

Spannend wird das Thema Timeouts aber bei gleichzeitiger Nutzung vom Modbus-Modul-internen Intervall-Timer (Abfrage der Werte alle X Sekunden) und zusätzlichem Abfragen von Werten mit get. Die get-Abfragen sind synchron und blockieren Fhem, da Anwender einen Rückgabewert brauchen.

Wenn nun eine get-Abfrage reinkommt, aber das Modul bereits eine reguläre zyklische Abfrage an den Slave gesendet hat, dann soll der Kontrollfluss nicht unterbrochen werden, sonst gibt es keinen Rückgabewert für den get-Befehl.
Deshalb übernimmt in diesem Fall ReadAnswer das Warten / Lesen der ausstehenden Antwort und danach wird der Request für den get-Befehl gesendet und ebenfalls auf die Antwort gewartet.
Diese Übernahme eines ausstehenden ursprünglich asynchronen Requests ist der Punkt, an dem ich die restliche Wartezeit bis zum Timeout lese.


    if ($ioHash->{BUSY}) {                              # Answer for last function code has not yet arrived
        Log3 $name, 5, "$name: Get: Queue is stil busy - taking over the read with ReadAnswer";
        ModbusLD_ReadAnswer($hash);                     # finish last read and wait for the result before next request
        Modbus_EndBUSY ($ioHash);                      # set BUSY to 0, delete REQUEST, clear Buffer, do Profilig
    }

    ModbusLD_Send($hash, $objCombi, "read", 0, 1);      # add at beginning of queue and force send / sleep if necessary
    ($err, $result) = ModbusLD_ReadAnswer($hash, $getName);
    Modbus_EndBUSY ($ioHash);                           # set BUSY to 0, delete REQUEST, clear Buffer, do Profilig


Ansgars Vorschlag, die Timer-Werte für einen Timeout redundant im Modul in einem Hash zu führen, ist vermutlich eine gute alternative Möglichkeit.
Da die Werte aber ohnehin von fhem.pl gespeichert werden, wäre ein Schnittstelle zum Abfragen der tatsächlichen Werte auf Dauer (meiner Meinung nach) schöner.
Ein internalTimer_TimeLeft($id) wäre dafür genau das Richtige. Eine solche Schnittstelle würde auch für künftige Modulautoren die Versuchung reduzieren, auf interne Daten zuzugreifen.
Alternativ muss sich das Modul eben die TRIGGERTIME selbst merken.

Gruss
   Stefan

ZitatDie get-Abfragen sind synchron und blockieren Fhem, da Anwender einen Rückgabewert brauchen.

Ich implementiere in den neueren Modulen wie ZWave get asynchron, der Benutzer wird mit asyncOutput benachrichtigt. Benutzer-Scripte muessen notify verwenden.

Zur gewünschten Änderung:

Bei 95_YAAHM.pm und 95_PostMe.pm ist das nur eine obsolete Zeile gewesen (irgendwie per Copy &  Paste übernommen), kein Problem.

Bei 95_Alarm.pm aber bedeutet das eine größere Änderung. Ich werde mir deswegen weder die Feiertage verderben, noch habe ich bis zum Abschluss meiner LEARNTEC Zeit dazu.
Also wird das nichts vor Mitte Februar.

Da das Modul von ca. 300 Leuten genutzt wird, muss die gewünschte Optimierung auf Wunsch Einzelner eben bis dahin warten.

LG

pah

eilt auch nicht. Du bist Ausrichter der LEARNTEC sehe ich. Spannend!

Hallo,

ich habe den Zugriff auf intAt im Modbus-Modul erst mal entfernt und statt dessen den Ablauf des Timeouts im Modul selbst gespeichert.
Die neue Version habe ich zum Testen gepostet: https://forum.fhem.de/index.php/topic,75638.45.html
Damit sollte das Modbus-Modul einer Optimierung nicht mehr im Weg stehen.
Wenn Roger es kurz testen kann und bestätigt, dass es keine neuen Probleme gibt, checke ich es ein.

Gruss
   Stefan

Hallo Stefan, hallo Rudolf,

vielen Dank für die schnelle Umsetzung.

Ich habe derweil im erste Beitrag apptime noch etwas viariiert, so dass apptime auch spezielle und totale  Durchschnittliche Timerverzögerung ausspuckt.
Auch meine letzter Anpassungsvorschlag zu HandleTimeout() ist da drin.
Ich denke das ist so eine gute Basis, um am Timer weiter zu kommen.

Bei mir sehe eine mittlere Timerverzögerung von etwas mehr als 10ms nach einem clear im "eingeschwungenen" Zustand.

Daran ändert auch $minCoverWait mit 0.01 nichts so dramatisches, außer dass ich auch mal negative Delays zu sehen bekomme.

EDIT: Natürlich sind die Delays mit Vorsicht zu betrachten, da auch gerne "InternalTime(gettimeofday()..."oder  "InternalTime(gettimeofday()+1..." darin einfließt was schon von der nachfolgenden Ausführungszeit beeinflusst wird.

Gruß, Ansgar.

@herrmannj: Ausrichter nicht, aber seit 8 Jahren sozusagen Cheforganisator.

LG

pah

ich habe im Zuge meiner Beschäftigung mit bigbluebutton (das ist ja eigentlich ein e-learning system) gelernt das andere Länder da viel weiter sind (Kanada, in Teilen wohl auch US). Wird aber off-topic... trotzdem spannend.

Kann ich so pauschal nicht bestätigen.

LG

pah

Hallo Rudolf,

ZitatZitat

    immi benötigt das wohl bei THZ, um alle Timer seines Moduls auf einmal schnell los zu werden.

Ist noch nicht wirklich eine Erklaerung, ich habe mein Vorschlag mit RemoveInternalTimer aber eingebaut.

immi will die neue Remove Funktionalität morgen in THZ einbauen.

Gruß, Ansgar.

Hallo Rudolf,

ich habe mal in 95_Alarm etwas genauer hin geschaut.

Hier die Codestelle, die %intAt nutzt:
         #-- deleting all running ats
         $dly = sprintf("alarm%1ddly",$level);
         foreach my $d (sort keys %intAt ) {
            next if( $intAt{$d}{FN} ne "at_Exec" );
            $mga = $intAt{$d}{ARG}{NAME};
            next if( $mga !~ /$dly\d/);
            #Log3 $hash,1,"[Alarm] Killing delayed action $name";
            CommandDelete(undef,"$mga");
         }


Peter will da bestimmte ats loswerden. Und die starten ihren Timer mit ihrem hash als Argument.

Diese spezielle Suche wird von RemoveInternalTimer nicht abgedeckt.

Macht es Sinn RemoveInternalTimer auf so was zu erweitern? Dann kommt der Nächste, der eine andere spezielle Suche benötigt!?!
Er bräuchte eher so was, wie "GetTimerSnapshot" mit einer aktuellen Kopie von %intAt als Rückgabewert um die durchsuchen zu können. So eine Funktion könnte man auch etwas vorfilternd gestalten.

Wenn es immer nur einen at_Exec Timer gleichtzeitig laufend gibt, könntest Du es auch in at mit einem ExecTimerRunning Flag unterstützen, so dass er alle ats durchsuchen könnte, statt %intAt.

Gruß, Ansgar.

Hallo Zusammen,

hier mal eine erste Implementierung nach herrmannjs Vorschlag. Mit der Konstanten UseIntAtA kann man zwischen beiden Varianten wechseln. Allerdings darf man nicht das falsche apptime verwenden, sonst werden alte Timer mit der apptime Initialisierung nicht mehr abgearbeitet.
für fhem.pl:

use vars qw($intAtA);           # Internal at timer hash, global for benchmark, new Version

#####################################
# Return the time to the next event (or undef if there is none)
# and call each function which was scheduled for this time

use constant UseIntAtA    => 1;   #do the code with @{$intAtA} instead of %intAt
use constant MinCoverWait => 0.0002474; # 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
use constant MinCoverExec => 0; #2; # look ahead to cope execution time of firing timers

sub
HandleTimeout()
{
if (UseIntAtA) {
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > 0) { # Timer to handle?
    $selectTimestamp = $now;
    return $dtnext;
  }

  my ($t,$tim,$fn,$arg);
  $nextat = 0;
  while (defined($intAtA) and @{$intAtA}) {
    $tim = $intAtA->[0]->{TRIGGERTIME};
    $fn = $intAtA->[0]->{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      shift @{$intAtA};
      next;
    }
    if ($tim - $now > MinCoverWait) { # time to handle Timer for time of e.g. one character at 38400 at least
      $nextat = $tim; # execution time not reached yet
      last;
    }
    $t = shift @{$intAtA};
    $arg = $t->{ARG};

    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";
  }

  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 > 0) ? $dtnext : 0; # wait until next Timer needs to be handled
}
else {
  return undef if(!$nextat);

  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)) or worse, but only for the currently "firering" timers
                         $intAt{$b}{TRIGGERTIME} }
                    (grep {($intAt{$_}->{TRIGGERTIME}-$now) <= MinCoverExec} # 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, but maybe they are a strange signal/flag?
      delete($intAt{$i});
      next;
    }
    if  (MinCoverExec > MinCoverWait) {
      if ($tim - gettimeofday() > MinCoverWait) {
        $nextat = $tim; # execution time not reached yet
        last;
      }
    }
    $arg = $intAt{$i}{ARG};
    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";
    delete($intAt{$i});
  }

  foreach my $i (keys(%intAt)) { # find next timer to trigger, 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};
    $nextat = $tim if (   defined($tim)
                       && (   !$nextat # find the next time to trigger
                           || ($nextat > $tim) ) );
  }

  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
}
}


#####################################
sub
addInternalTimer { # O(n) add, obsolet
  my ($tim, $fn, $arg) = @_;

  if (defined($intAtA) and @{$intAtA}) {
    my $i = 0;
    foreach (@{$intAtA}) {
      if ($tim < $intAtA->[$i]->{TRIGGERTIME}) {
        splice @{$intAtA}, $i, 0, {
                                   TRIGGERTIME => $tim,
                                   FN => $fn,
                                   ARG => $arg
                                  };
        return;
      };
      $i++;
    };
    $intAtA->[$i] = {
                     TRIGGERTIME => $tim,
                     FN => $fn,
                     ARG => $arg
                    };
    return;   
  } else {
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
    return;
  }
}
#####################################
sub
InternalTimer($$$;$)
{
if (UseIntAtA) {
  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;
  }

  ### O(log(n)) add ###################
  my $i = defined($intAtA)?int(@{$intAtA}):0;

  if ($i) {
    my $t;
    my $ui = $i - 1;
    my $li = 0;
    while ($li <= $ui) {
      $i = int(($ui-$li)/2)+$li;
      $t = $intAtA->[$i]->{TRIGGERTIME};
      if ($tim >= $t) { # in upper half
        $li = ++$i;
      }
      else {            # in lower half
        $ui = $i-1;
      }
    }
    splice @{$intAtA}, $i, 0, { #insert or append new entry
                               TRIGGERTIME => $tim,
                               FN => $fn,
                               ARG => $arg
                              };
  } else { # array creation on first add
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
  }
  #####################################

  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );
  return;
}
else {
  my ($tim, $fn, $arg, $waitIfInitNotDone) = @_;

  return if (!defined($fn));

  $tim = 1 if(!$tim);
  if(!$init_done && $waitIfInitNotDone) {
    select(undef, undef, undef, $tim-gettimeofday());
    no strict "refs";
    &{$fn}($arg);
    use strict "refs";
    return;
  }
  $intAt{$intAtCnt}{TRIGGERTIME} = $tim;
  $intAt{$intAtCnt}{FN} = $fn;
  $intAt{$intAtCnt}{ARG} = $arg;
  $intAtCnt++;
  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );
}
}

sub
RemoveInternalTimer($;$)
{
if (UseIntAtA) {
  return if !defined($intAtA);
  my ($arg, $fn) = @_;
  my $i = 0;
  if ($fn) {
    if (defined($arg)) {
      my ($ia, $if);
      foreach my $a (@{$intAtA}) {
        ($ia, $if) = ($a->{ARG}, $a->{FN});
        splice @{$intAtA}, $i, 1 if(   defined($ia) && ($ia eq $arg)
                                    && defined($if) && ($if eq $fn) );
        $i++;
      }
    }
    else {
      my $if;
      foreach my $a (@{$intAtA}) {
        $if = $a->{FN};
        splice @{$intAtA}, $i, 1 if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
        $i++;
      }
    }
  }
  else {
    return if (!defined($arg));
    my $ia;
    foreach my $a (@{$intAtA}) {
      $ia = $a->{ARG};
      splice @{$intAtA}, $i, 1 if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
      $i++;
    }
  }
}
else {
  my ($arg, $fn) = @_;
  if ($fn) {
    if (defined($arg)) {
      foreach my $a (keys %intAt) {
        my ($ia, $if) = ($intAt{$a}{ARG}, $intAt{$a}{FN});
        delete($intAt{$a}) if(   defined($ia) && ($ia eq $arg)
                              && defined($if) && ($if eq $fn) );
      }
    }
    else {
      foreach my $a (keys %intAt) {
        my $if = $intAt{$a}{FN};
        delete($intAt{$a}) if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
      }
    }
  }
  else {
    return if (!defined($arg));
    foreach my $a (keys %intAt) {
      my $ia = $intAt{$a}{ARG};
      delete($intAt{$a}) if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
    }
  }
}
}


Und hier ein apptime dazu zum Testen und Zeit messen:
################################################################
# 98_apptime:application timing
# $Id: 98_apptime.pm 14087f 2018-01-14 17:01: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($intAtA);           # Internal at timer hash, global for benchmark, new Version
#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;

use constant DEBUG_OUTPUT_INTATA => 0;

use constant MinCoverWait => 0.0002474; # 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


# @{$intAtA}
sub
HandleTimeout()
{
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > 0) { # Timer to handle?
    $selectTimestamp = $now;
    return $dtnext;
  }

  my $handleStart = $now;

  $intatlen = defined($intAtA)?int(@{$intAtA}):0;
  $maxintatlen = $intatlen if ($maxintatlen < $intatlen);

  my $nd = 0;

  my ($t,$tim,$fn,$arg,$fnname,$shortarg,$cv);
  $nextat = 0;
  while (defined($intAtA) and @{$intAtA}) {
    $tim = $intAtA->[0]->{TRIGGERTIME};
    $fn = $intAtA->[0]->{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      shift @{$intAtA};
      next;
    }
    if ($tim - $now > MinCoverWait) { # time to handle Timer for time of e.g. one character at 38400 at least
      $nextat = $tim; # execution time not reached yet
      last;
    }
    $t = shift @{$intAtA};
    $arg = $t->{ARG};

    if (ref($fn) ne "") {
      $cv = svref_2object($fn);
      $fnname = $cv->GV->NAME;
    }
    else {
      $fnname = $fn;
    }
    $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++;
  }
 
  $maxintatdone = $nd if ($maxintatdone < $nd);
  $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 > 0) ? $dtnext : 0; # wait until next Timer needs to be handled
}

#####################################
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;
  }

  my $now = gettimeofday();

  ### O(log(n)) add ###################
  my $i = defined($intAtA)?int(@{$intAtA}):0;

  if ($i) {
    my $t;
    my $ui = $i - 1;
    my $li = 0;
    while ($li <= $ui) {
      $i = int(($ui-$li)/2)+$li;
      $t = $intAtA->[$i]->{TRIGGERTIME};
      if ($tim >= $t) { # in upper half
        $li = ++$i;
      }
      else {            # in lower half
        $ui = $i-1;
      }
    }
    splice @{$intAtA}, $i, 0, { #insert or append new entry
                               TRIGGERTIME => $tim,
                               FN => $fn,
                               ARG => $arg
                              };
  } else { # array creation on first add
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
  }

  if (DEBUG_OUTPUT_INTATA) {
    for ($i=0; $i < (int(@{$intAtA})-1); $i++) {
      next if ($intAtA->[$i]->{TRIGGERTIME} <= $intAtA->[$i+1]->{TRIGGERTIME});
      print "Error in $intAtA inserting $tim $fn\n";
      use Data::Dumper;
      print Data::Dumper->new([$intAtA],[qw($intAtA)])->Indent(1)->Quotekeys(1)->Dump;
      my $h = $intAtA->[$i]->{TRIGGERTIME};
      $intAtA->[$i]->{TRIGGERTIME} = $intAtA->[$i+1]->{TRIGGERTIME};
      $intAtA->[$i+1]->{TRIGGERTIME} = $h;
    }
  }
  #####################################

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

  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );
  return;
};
#####################################
sub
RemoveInternalTimer($;$)
{
  return if !defined($intAtA);
  my ($arg, $fn) = @_;
  my $i = 0;
  if ($fn) {
    if (defined($arg)) {
      my ($ia, $if);
      foreach my $a (@{$intAtA}) {
        ($ia, $if) = ($a->{ARG}, $a->{FN});
        splice @{$intAtA}, $i, 1 if(   defined($ia) && ($ia eq $arg)
                                    && defined($if) && ($if eq $fn) );
        $i++;
      }
    }
    else {
      my $if;
      foreach my $a (@{$intAtA}) {
        $if = $a->{FN};
        splice @{$intAtA}, $i, 1 if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
        $i++;
      }
    }
  }
  else {
    return if (!defined($arg));
    my $ia;
    foreach my $a (@{$intAtA}) {
      $ia = $a->{ARG};
      splice @{$intAtA}, $i, 1 if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
      $i++;
    }
  }
}

#####################################
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 $fnname;
  if (ref($fn) ne "") {
    my $cv = svref_2object($fn);
    $fnname = $cv->GV->NAME;
  }
  else {
    $fnname = $fn;
  }
  my @ret = apptime_getTiming($d,$fnname,$fn,0,@_);

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

sub apptime_getTiming($$$@) {
  my ($e,$fnName,$fn,$tim,@arg) = @_;
  my $h;
  my $tstart;
  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}++;
    }
    $tstart = gettimeofday();
  }

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

  if ($apptimeStatus){
    my $dtcalc = gettimeofday()-$tstart;
    if ($dtcalc && $h->{max} < $dtcalc){
      $h->{max} = $dtcalc;
      $h->{mAr} = @arg?\@arg:undef;
      $h->{mTS}= strftime("%d.%m. %H:%M:%S", localtime());
    }
    if ($tim > 1){
      $totCnt++;
      my $td = $tstart-$tim;
      $totDly    += $td;
      $totDly    = 0 if(!$totCnt);
      $h->{dtotcnt}++;
      $h->{dtot} += $td;
      $h->{dtot} = 0 if(!$h->{dtotcnt});
      $h->{dmx}  = $td if ($h->{dmx} < $td);
    }

    $h->{tot} += $dtcalc;
    $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;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 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-timerinsertTm: %0.1fms; max-timerinsertTm: %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


Damit vergesse ich es zumindestens nicht bis mitte Februar.

Gruß und frohes Fest,

Ansgar.

Wg. dem %intAt Zugriff in Alarm.pm: ich verstehe noch nicht, warum man nicht eine Schleife ueber alle Geraete mit devspec2array macht.

Hallo Rudolf,

ZitatWg. dem %intAt Zugriff in Alarm.pm: ich verstehe noch nicht, warum man nicht eine Schleife ueber alle Geraete mit devspec2array macht.

Und woher weiß die Schleife dann sicher, ob der jeweilige Timer aktiv ist (falls das relevant ist, so weit habe ich nicht geschaut, gehe aber davon aus, dass Peter sich was dabei gedacht hat)? Der Timer kann noch verspätet in der Timer-Warteschlange hängen. Ohne ein Flag, dass mit Timerstart gesetzt und in der Timerroutine zurück gesetzt wird, ist das unklar.

Gruß, Ansgar.

Hallo Zusammen,

auf meinem Testsystem (RasPi2) hat sich mit der Erstimplementation immerhin schon mal die durchschnittliche Timerausführungsverzögerung von etwa mehr als 10ms auf 7,6 ms verringert. Nach wie vor ca. 140 Timer aktiv, aber das sollte in der Variante nicht so relevant sein.

Die Zeit für das Hinzufügen eines Timers, die ich mal statt der Sortierzeit messe, liegt zwischen 0,2 und  27,4ms (wobei ich davon ausgehe, dass das auch noch vom Speichermanagement beeinflusst ist).
Das log(n) Einfügen statt der linearen Suche werde ich wohl bei Gelegenheit mal einbauen.

Gruß, Ansgar.

Zitat von: noansi am 21 Dezember 2017, 14:05:27
00_THZ.pm             RemoveInternalTimer nutzen -> kurzfristige Änderung zugesagt, nutzt Remove Erweiterung

00_THZ.pm fixed
frohe weihnachten
immi

Hallo Zusammen,

hier nun nochmal ein Update mit schnellem InternalTimer.
Mit der Konstanten UseIntAtA kann man zwischen altem Code und dem neuen wechseln. Allerdings darf man nicht das falsche apptime verwenden, sonst werden zuvor bestehende Timer mit der apptime Initialisierung nicht mehr abgearbeitet.
für fhem.pl:

use vars qw($intAtA);           # Internal at timer hash, global for benchmark, new Version

#####################################
# Return the time to the next event (or undef if there is none)
# and call each function which was scheduled for this time

use constant UseIntAtA    => 1;   #do the code with @{$intAtA} instead of %intAt
use constant MinCoverWait => 0.0002474; # 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
use constant MinCoverExec => 0; #2; # look ahead to cope execution time of firing timers

sub
HandleTimeout()
{
if (UseIntAtA) {
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > 0) { # Timer to handle?
    $selectTimestamp = $now;
    return $dtnext;
  }

  my ($t,$tim,$fn,$arg);
  $nextat = 0;
  while (defined($intAtA) and @{$intAtA}) {
    $tim = $intAtA->[0]->{TRIGGERTIME};
    $fn = $intAtA->[0]->{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      shift @{$intAtA};
      next;
    }
    if ($tim - $now > MinCoverWait) { # time to handle Timer for time of e.g. one character at 38400 at least
      $nextat = $tim; # execution time not reached yet
      last;
    }
    $t = shift @{$intAtA};
    $arg = $t->{ARG};

    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";
  }

  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 > 0) ? $dtnext : 0; # wait until next Timer needs to be handled
}
else {
  return undef if(!$nextat);

  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)) or worse, but only for the currently "firering" timers
                         $intAt{$b}{TRIGGERTIME} }
                    (grep {($intAt{$_}->{TRIGGERTIME}-$now) <= MinCoverExec} # 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, but maybe they are a strange signal/flag?
      delete($intAt{$i});
      next;
    }
    if  (MinCoverExec > MinCoverWait) {
      if ($tim - gettimeofday() > MinCoverWait) {
        $nextat = $tim; # execution time not reached yet
        last;
      }
    }
    $arg = $intAt{$i}{ARG};
    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";
    delete($intAt{$i});
  }

  foreach my $i (keys(%intAt)) { # find next timer to trigger, 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};
    $nextat = $tim if (   defined($tim)
                       && (   !$nextat # find the next time to trigger
                           || ($nextat > $tim) ) );
  }

  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
}
}


#####################################
sub
addInternalTimer { # O(n) add, obsolet
  my ($tim, $fn, $arg) = @_;

  if (defined($intAtA) and @{$intAtA}) {
    my $i = 0;
    foreach (@{$intAtA}) {
      if ($tim < $intAtA->[$i]->{TRIGGERTIME}) {
        splice @{$intAtA}, $i, 0, {
                                   TRIGGERTIME => $tim,
                                   FN => $fn,
                                   ARG => $arg
                                  };
        return;
      };
      $i++;
    };
    $intAtA->[$i] = {
                     TRIGGERTIME => $tim,
                     FN => $fn,
                     ARG => $arg
                    };
    return;   
  } else {
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
    return;
  }
}
#####################################
sub
InternalTimer($$$;$)
{
if (UseIntAtA) {
  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;
  }

  ### O(log(n)) add ###################
  my $i = defined($intAtA)?int(@{$intAtA}):0;

  if ($i) {
    my $t;
    my $ui = $i - 1;
    my $li = 0;
    while ($li <= $ui) {
      $i = int(($ui-$li)/2)+$li;
      $t = $intAtA->[$i]->{TRIGGERTIME};
      if ($tim >= $t) { # in upper half
        $li = ++$i;
      }
      else {            # in lower half
        $ui = $i-1;
      }
    }
    splice @{$intAtA}, $i, 0, { #insert or append new entry
                               TRIGGERTIME => $tim,
                               FN => $fn,
                               ARG => $arg
                              };
  } else { # array creation on first add
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
  }
  #####################################

  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );
  return;
}
else {
  my ($tim, $fn, $arg, $waitIfInitNotDone) = @_;

  return if (!defined($fn));

  $tim = 1 if(!$tim);
  if(!$init_done && $waitIfInitNotDone) {
    select(undef, undef, undef, $tim-gettimeofday());
    no strict "refs";
    &{$fn}($arg);
    use strict "refs";
    return;
  }
  $intAt{$intAtCnt}{TRIGGERTIME} = $tim;
  $intAt{$intAtCnt}{FN} = $fn;
  $intAt{$intAtCnt}{ARG} = $arg;
  $intAtCnt++;
  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );
}
}

sub
RemoveInternalTimer($;$)
{
if (UseIntAtA) {
  return if !defined($intAtA);
  my ($arg, $fn) = @_;
  my $i = 0;
  if ($fn) {
    if (defined($arg)) {
      my ($ia, $if);
      foreach my $a (@{$intAtA}) {
        ($ia, $if) = ($a->{ARG}, $a->{FN});
        splice @{$intAtA}, $i, 1 if(   defined($ia) && ($ia eq $arg)
                                    && defined($if) && ($if eq $fn) );
        $i++;
      }
    }
    else {
      my $if;
      foreach my $a (@{$intAtA}) {
        $if = $a->{FN};
        splice @{$intAtA}, $i, 1 if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
        $i++;
      }
    }
  }
  else {
    return if (!defined($arg));
    my $ia;
    foreach my $a (@{$intAtA}) {
      $ia = $a->{ARG};
      splice @{$intAtA}, $i, 1 if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
      $i++;
    }
  }
}
else {
  my ($arg, $fn) = @_;
  if ($fn) {
    if (defined($arg)) {
      foreach my $a (keys %intAt) {
        my ($ia, $if) = ($intAt{$a}{ARG}, $intAt{$a}{FN});
        delete($intAt{$a}) if(   defined($ia) && ($ia eq $arg)
                              && defined($if) && ($if eq $fn) );
      }
    }
    else {
      foreach my $a (keys %intAt) {
        my $if = $intAt{$a}{FN};
        delete($intAt{$a}) if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
      }
    }
  }
  else {
    return if (!defined($arg));
    foreach my $a (keys %intAt) {
      my $ia = $intAt{$a}{ARG};
      delete($intAt{$a}) if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
    }
  }
}
}


Und hier ein apptime dazu zum Testen und Zeit messen:
################################################################
# 98_apptime:application timing
# $Id: 98_apptime.pm 14087f 2018-01-14 17:01: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($intAtA);           # Internal at timer hash, global for benchmark, new Version
#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;

use constant DEBUG_OUTPUT_INTATA => 0;

use constant MinCoverWait => 0.0002474; # 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


# @{$intAtA}
sub
HandleTimeout()
{
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > 0) { # Timer to handle?
    $selectTimestamp = $now;
    return $dtnext;
  }

  my $handleStart = $now;

  $intatlen = defined($intAtA)?int(@{$intAtA}):0;
  $maxintatlen = $intatlen if ($maxintatlen < $intatlen);

  my $nd = 0;

  my ($t,$tim,$fn,$arg,$fnname,$shortarg,$cv);
  $nextat = 0;
  while (defined($intAtA) and @{$intAtA}) {
    $tim = $intAtA->[0]->{TRIGGERTIME};
    $fn = $intAtA->[0]->{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      shift @{$intAtA};
      next;
    }
    if ($tim - $now > MinCoverWait) { # time to handle Timer for time of e.g. one character at 38400 at least
      $nextat = $tim; # execution time not reached yet
      last;
    }
    $t = shift @{$intAtA};
    $arg = $t->{ARG};

    if (ref($fn) ne "") {
      $cv = svref_2object($fn);
      $fnname = $cv->GV->NAME;
    }
    else {
      $fnname = $fn;
    }
    $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++;
  }
 
  $maxintatdone = $nd if ($maxintatdone < $nd);
  $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 > 0) ? $dtnext : 0; # wait until next Timer needs to be handled
}

#####################################
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;
  }

  my $now = gettimeofday();

  ### O(log(n)) add ###################
  my $i = defined($intAtA)?int(@{$intAtA}):0;

  if ($i) {
    my $t;
    my $ui = $i - 1;
    my $li = 0;
    while ($li <= $ui) {
      $i = int(($ui-$li)/2)+$li;
      $t = $intAtA->[$i]->{TRIGGERTIME};
      if ($tim >= $t) { # in upper half
        $li = ++$i;
      }
      else {            # in lower half
        $ui = $i-1;
      }
    }
    splice @{$intAtA}, $i, 0, { #insert or append new entry
                               TRIGGERTIME => $tim,
                               FN => $fn,
                               ARG => $arg
                              };
  } else { # array creation on first add
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
  }

  if (DEBUG_OUTPUT_INTATA) {
    for ($i=0; $i < (int(@{$intAtA})-1); $i++) {
      next if ($intAtA->[$i]->{TRIGGERTIME} <= $intAtA->[$i+1]->{TRIGGERTIME});
      print "Error in $intAtA inserting $tim $fn\n";
      use Data::Dumper;
      print Data::Dumper->new([$intAtA],[qw($intAtA)])->Indent(1)->Quotekeys(1)->Dump;
      my $h = $intAtA->[$i]->{TRIGGERTIME};
      $intAtA->[$i]->{TRIGGERTIME} = $intAtA->[$i+1]->{TRIGGERTIME};
      $intAtA->[$i+1]->{TRIGGERTIME} = $h;
    }
  }
  #####################################

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

  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );
  return;
};
#####################################
sub
RemoveInternalTimer($;$)
{
  return if !defined($intAtA);
  my ($arg, $fn) = @_;
  my $i = 0;
  if ($fn) {
    if (defined($arg)) {
      my ($ia, $if);
      foreach my $a (@{$intAtA}) {
        ($ia, $if) = ($a->{ARG}, $a->{FN});
        splice @{$intAtA}, $i, 1 if(   defined($ia) && ($ia eq $arg)
                                    && defined($if) && ($if eq $fn) );
        $i++;
      }
    }
    else {
      my $if;
      foreach my $a (@{$intAtA}) {
        $if = $a->{FN};
        splice @{$intAtA}, $i, 1 if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
        $i++;
      }
    }
  }
  else {
    return if (!defined($arg));
    my $ia;
    foreach my $a (@{$intAtA}) {
      $ia = $a->{ARG};
      splice @{$intAtA}, $i, 1 if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
      $i++;
    }
  }
}

#####################################
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 $fnname;
  if (ref($fn) ne "") {
    my $cv = svref_2object($fn);
    $fnname = $cv->GV->NAME;
  }
  else {
    $fnname = $fn;
  }
  my @ret = apptime_getTiming($d,$fnname,$fn,0,@_);

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

sub apptime_getTiming($$$@) {
  my ($e,$fnName,$fn,$tim,@arg) = @_;
  my $h;
  my $tstart;
  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}++;
    }
    $tstart = gettimeofday();
  }

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

  if ($apptimeStatus){
    my $dtcalc = gettimeofday()-$tstart;
    if ($dtcalc && $h->{max} < $dtcalc){
      $h->{max} = $dtcalc;
      $h->{mAr} = @arg?\@arg:undef;
      $h->{mTS}= strftime("%d.%m. %H:%M:%S", localtime());
    }
    if ($tim > 1){
      $totCnt++;
      my $td = $tstart-$tim;
      $totDly    += $td;
      $totDly    = 0 if(!$totCnt);
      $h->{dtotcnt}++;
      $h->{dtot} += $td;
      $h->{dtot} = 0 if(!$h->{dtotcnt});
      $h->{dmx}  = $td if ($h->{dmx} < $td);
    }

    $h->{tot} += $dtcalc;
    $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;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 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-timerinsertTm: %0.1fms; max-timerinsertTm: %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


@immi: Many thanks for your fast change of code! Merry Christmas!

Viele Grüße und frohe Weihnachten,

Ansgar.

EDIT: @Rudolf: Ich habe dem MinCoverWait zumindest mal einen Sinn im Bezug auf die Nutzung mit serieller Schnittstelle gegeben. Also der Versuch, nur so lange Timer abzuarbeiten, bis ein weiteres Zeichen über die Schnittstelle reingetrudelt sein könnte. Praktisch macht diese kurze Zeit wohl nur bei sehr wenigen Timern Sinn.
EDIT: Hier noch ein Testergebnis
active-timers: 139; max-active timers: 174; max-timer-load: 3  min-tmrHandlingTm: 0.1ms; max-tmrHandlingTm: 151.4ms; totAvgDly: 6.7ms
min-timerinsertTm: 0.3ms; max-timerinsertTm: 11.9ms
Wegen des etwas größeren Aufwands beim Anlegen eines Timers ist die min Zeit etwas angestiegen, dafür die max-Zeit erwartungsgemäß nochmal deutlich zurück gegangen.
Außerdem ist auch die mittlere Verzögerung bei der Ausführung nochmal etwas zurück gegangen.
Wenn noch jemand magische perl Tricks kennt, mit denen das ganze noch etwas schneller geht, von mir aus gerne.
Und harren wir der Anpassung der verblieben Module. Ich habe aus der Liste betroffener Module eine Streichliste gemacht https://forum.fhem.de/index.php/topic,81365.msg734828.html#msg734828 (https://forum.fhem.de/index.php/topic,81365.msg734828.html#msg734828).
Und ich würde vorschlagen, erst mal diesen Stand umzusetzen, getreu Rudolfs Motto, nicht zu viel auf einmal, damit die Nebenwirkungen gezielter darauf zurück zu führen sind.

Zitat von: rudolfkoenig am 21 Dezember 2017, 22:26:46

Code Auswählen Erweitern

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));
  }
}


Hi Rudolf
I am not sure how to use the new implementation above.

I want to delete all timers connected to function THZ_GetRefresh.

RemoveInternalTimer(undef, "THZ_GetRefresh");
or
RemoveInternalTimer(0, "THZ_GetRefresh");
or
RemoveInternalTimer($hash, "THZ_GetRefresh");


in the past I used directly following code in my module (no problems in the last 55 weeks)
THZ_RemoveInternalTimer("THZ_GetRefresh");


...
sub THZ_RemoveInternalTimer($){
  my ($callingfun) = @_;
  foreach my $a (keys %intAt) {
    delete($intAt{$a}) if($intAt{$a}{FN} eq $callingfun);
  }
}


p.s.
I generate about 20 recurrent timers with
InternalTimer(gettimeofday() + ($timedelay) , "THZ_GetRefresh", \%par, 0);
For each timer \%par is different.

thanks
immi

Your first two proposals should be equivalent with THZ_RemoveInternalTimer.

danke rudolf
auguri e buon anno
immi

Hallo Zusammen,

ich habe oben https://forum.fhem.de/index.php/topic,81365.msg736160.html#msg736160 (https://forum.fhem.de/index.php/topic,81365.msg736160.html#msg736160) noch Rudolfs letzte Änderungen in RemoveInternalTimer sinngemäß eingearbeitet.

Die Streichliste https://forum.fhem.de/index.php/topic,81365.msg734828.html#msg734828 (https://forum.fhem.de/index.php/topic,81365.msg734828.html#msg734828) verharrt leider im Stillstand.
EDIT: Doch nicht. 98_Modbus.pm ist nun auch angepasst. :-) Danke Stefan!

Gruß, Ansgar.

Ich habe die Änderung in 95_Alarm.pm gemacht, das muss aber wegen der größerem Zahl an Nutzern noch ein paar Tage getestet werden.

LG

pah

Hallo Peter,

super! Danke, dass Du noch Zeit dafür gefunden hast!

Gruß, Ansgar.

Ging nur, weil ich seit gestern mit einem üblen Virus mattgesetzt bin ...

LG

pah

Hallo Peter,

ZitatGing nur, weil ich seit gestern mit einem üblen Virus mattgesetzt bin ...

Das ist allerdings kein schöner Anlass dazu.

Gute Besserung!

Gruß, Ansgar.

@Ansgar: koenntest du bitte deine Zeitmessung (fuer InsertTimer/RemoveTimer/HandleTimer) fuer alt(hash)/neu(array) mit etwa den gleichen Anzahl von Elementen ausfuehren? Es waere interessant auch die Summe der Ausfuehrungszeiten und Dauer des Tests zu wissen. Ich habe Schwierigkeiten ein so langsames Testsystem mit so vielen Timern aufzustellen, wuesste aber gerne im Voraus, was die Aenderung bringt.

Ich zoegere noch die Array Variante einzubauen:
- InsertTimer wird langsamer. Beim normalen Ablauf ist #InsertTimer >= #HandleTimer, jedenfalls in den Faellen, wo HandleTimer rechnen muss.
- der Kode wird aufwendiger
- apptime + MilightBridge muss nachgezogen werden. THZ koennte man mit einem parallel gepflegten %intAt "begluecken", andere Problemfaelle habe ich nicht gesehen.

Ich kann dir schonmal gratulieren zum bisherigen Aufraeumergebnis :)

Sieh mal an, Du gratulierst jemand anderem, wenn wir die Aufräumarbeiten erledigen   ;D

LG

pah

Naja pah, eigentlich hast Du ja nur Deinen eigenen Code aufgeräumt  ;D
Ansgar dagegen hat einen fremden Stall ausgemistet  ;)



Grüße

ZitatSieh mal an, Du gratulierst jemand anderem, wenn wir die Aufräumarbeiten erledigen

Klar, er hat ja die Sache ins Rollen gebracht, und die Leute zum Arbeiten bewegt.
Man gratuliert ja auch anderswo dem Manager, auch wenn die Arbeit von anderen erledigt wird :)

Ich bin allgemein als "Not manageable" bekannt, das kanns also nicht sein.

LG

pah

Hallo Zusammen,

ZitatSieh mal an, Du gratulierst jemand anderem, wenn wir die Aufräumarbeiten erledigen

Und ich bin freudig überrascht über die tatkräftige Anpassungsbereitschaft der Entwickler, sogar unter erschwerten Bedingungen!  :)
Dafür nochmal ein fettes Danke!

Zitatapptime + MilightBridge muss nachgezogen werden.

Matthew habe ich bezüglich MilightBridge zumindest schon mal erreicht. Leider konnte ich nicht mit einem Test von Jörgs Änderungsvorschlag direkt überzeugen. Ich hoffe aber, er erinnert sich noch an den Zugang zum SVN.

Martin hat vor kurzem schon mal was an apptime geändert. Ich denke das Nachziehen wird da nicht sehr problematisch werden.

ZitatInsertTimer wird langsamer. Beim normalen Ablauf ist #InsertTimer >= #HandleTimer, jedenfalls in den Faellen, wo HandleTimer rechnen muss.

???
Der Mittelwert zeigt wohl deutlicher, dass es nicht so ist. Oder missverstehe ich Deine Aussage?
Hier ein Stand gemessen von heute morgen ca. 6:15Uhr bis 20Uhr mit neuer @intAt Variante. Vor dem apptime Start lief das System seit gestern 21Uhr.
active-timers: 120; max-active timers: 140; max-timer-load: 8; totAvgDly: 7.8ms
min-tmrHandlingTm: 0.1ms; avg-tmrHandlingTm: 16.9ms; max-tmrHandlingTm: 344.3ms
min-timerinsertTm: 0.2ms; avg-timerinsertTm: 0.4ms; max-timerinsertTm: 30.6ms
min-timerremoveTm: 1.5ms; avg-timerremoveTm: 2.4ms; max-timerremoveTm: 36.6ms
Generell muss man das System nach dem Start erst mal "einschwingen" lassen, bis alle anlaufbedingten Zusatzaufgaben und Timer abgelaufen sind und mal alle Variablen gefüllt sind. (Ich lasse beim Testen das System auch weitgehend "in Ruhe", denn die Webabfragen dauern mitunter recht lange.)
Dann apptime clear und ein Test über mehrere Stunden. Denn die max. Langläufer treten mehr oder minder sporadisch auf und hängen nicht mit dem Code direkt, sondern wohl mit anderen systembedingten Effekten zusammen (Speicherverwaltung? Datenträgerzugriffe? ...).

RemoveInternalTimer ist erwartungsgemäß recht "teuer" im Vergleich.

Zitatkoenntest du bitte deine Zeitmessung (fuer InsertTimer/RemoveTimer/HandleTimer) fuer alt(hash)/neu(array) mit etwa den gleichen Anzahl von Elementen ausfuehren? Es waere interessant auch die Summe der Ausfuehrungszeiten und Dauer des Tests zu wissen. Ich habe Schwierigkeiten ein so langsames Testsystem mit so vielen Timern aufzustellen, wuesste aber gerne im Voraus, was die Aenderung bringt.

Ok, ich ändere den apptime Code noch entsprechend und teste dann nochmal.

Gruß, Ansgar.

Hallo Zusammen,

hier aktuell der letzte Code Stand per Konstante UseIntAtA auswählbar:

#####################################
use vars qw($intAtA);           # Internal at timer hash, global for benchmark, new Version array based

use vars qw(%intAt);            # Internal at timer hash, global for benchmark
use vars qw($intAtCnt);

# Return the time to the next event (or undef if there is none)
# and call each function which was scheduled for this time

use constant UseIntAtA    => 1;   #do the code with @{$intAtA} instead of %intAt
use constant MinCoverWait => 0.0002474; # 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
use constant MinCoverExec => 0; #2; # look ahead to cope execution time of firing timers

sub
HandleTimeout()
{
if (UseIntAtA) {
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > 0) { # Timer to handle?
    $selectTimestamp = $now;
    return $dtnext;
  }

  my ($tim,$fn);
  $nextat = 0;
  while (defined($intAtA) and @{$intAtA}) {
    $tim = $intAtA->[0]->{TRIGGERTIME};
    $fn = $intAtA->[0]->{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      shift @{$intAtA};
      next;
    }
#    if ($tim > $now + MinCoverWait) { # time to handle Timer for time of e.g. one character at 38400 at least
    if ($tim > $now) {
      $nextat = $tim; # execution time not reached yet
      last;
    }

    no strict "refs";
    &{$fn}(shift(@{$intAtA})->{ARG}); # this can delete a timer and can add a timer not covered by the current loops TRIGGERTIME sorted list
    use strict "refs";

    $now = gettimeofday(); # reduce delay related to execution time of previous timers
  }

  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);
  }

  if(!$nextat) {
    $selectTimestamp = $now;
    return undef;
  }

  $now = gettimeofday(); # if some callbacks took longer
  $selectTimestamp = $now;
 
  $dtnext = $nextat-$now;
  return ($dtnext > 0) ? $dtnext : 0; # wait until next Timer needs to be handled
}
else {
  return undef if(!$nextat);

  my $now = gettimeofday();
  if($now < $nextat) {
    $selectTimestamp = $now;
    return ($nextat-$now);
  }

  $nextat = 0;
  #############
  # Check the internal list.
  foreach my $i (sort { $intAt{$a}{TRIGGERTIME} <=>
                        $intAt{$b}{TRIGGERTIME} }
                 grep { $intAt{$_}{TRIGGERTIME} <= $now } # sort is slow
                        keys %intAt) {
    $i = "" if(!defined($i)); # Forum #40598
    next if(!$intAt{$i}); # deleted in the loop
    my $tim = $intAt{$i}{TRIGGERTIME};
    my $fn = $intAt{$i}{FN};
    if(!defined($tim) || !defined($fn)) {
      delete($intAt{$i});
      next;
    }

    no strict "refs";
    &{$fn}($intAt{$i}{ARG});
    use strict "refs";

    delete($intAt{$i});
  }

  foreach my $i (keys %intAt) {
    my $tim = $intAt{$i}{TRIGGERTIME};
    $nextat = $tim if(defined($tim) && (!$nextat || $nextat > $tim));
  }

  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);
  }

  if(!$nextat) {
    $selectTimestamp = $now;
    return undef;
  }

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

  return ($now < $nextat) ? ($nextat-$now) : 0;
}
}

#####################################
sub
InternalTimer($$$;$)
{
if (UseIntAtA) {
  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;
  }

  ### O(log(n)) add ###################
  my $i = defined($intAtA)?int(@{$intAtA}):0;

  if ($i) {
    my $t;
    my $ui = $i - 1;
    my $li = 0;
    while ($li <= $ui) {
      $i = int(($ui-$li)/2)+$li;
      $t = $intAtA->[$i]->{TRIGGERTIME};
      if ($tim >= $t) { # in upper half
        $li = ++$i;
      }
      else {            # in lower half
        $ui = $i-1;
      }
    }
    splice @{$intAtA}, $i, 0, { #insert or append new entry
                               TRIGGERTIME => $tim,
                               FN => $fn,
                               ARG => $arg
                              };
  } else { # array creation on first add
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
  }
  #####################################

  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );
}
else {
  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;
  }
  $intAt{$intAtCnt}{TRIGGERTIME} = $tim;
  $intAt{$intAtCnt}{FN} = $fn;
  $intAt{$intAtCnt}{ARG} = $arg;
  $intAtCnt++;
  $nextat = $tim if(!$nextat || $nextat > $tim);
}
}

sub
RemoveInternalTimer($;$)
{
if (UseIntAtA) {
  return if (!defined($intAtA) || !@{$intAtA});
  my ($arg, $fn) = @_;
  if ($fn) {
    if (defined($arg)) {
      my ($ia, $if);
      my $i = int(@{$intAtA});
      while($i--) {
        ($ia, $if) = ($intAtA->[$i]->{ARG}, $intAtA->[$i]->{FN});
        splice @{$intAtA}, $i, 1 if(   defined($ia) && ($ia eq $arg)
                                    && defined($if) && ($if eq $fn) );
      }
    }
    else {
      my $if;
      my $i = int(@{$intAtA});
      while($i--) {
        $if = $intAtA->[$i]->{FN};
        splice @{$intAtA}, $i, 1 if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
      }
    }
  }
  else {
    return if (!defined($arg));
    my $ia;
    my $i = int(@{$intAtA});
    while($i--) {
      $ia = $intAtA->[$i]->{ARG};
      splice @{$intAtA}, $i, 1 if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
    }
  }
}
else {
  my ($arg, $fn) = @_;
  return if(!$arg && !$fn);
  foreach my $a (keys %intAt) {
    my ($ia, $if) = ($intAt{$a}{ARG}, $intAt{$a}{FN});
    delete($intAt{$a}) if((!$arg || ($ia && $ia eq $arg)) &&
                          (!$fn  || ($if && $if eq $fn)));
  }
}
}

Beim RemoveInternalTimer gab es noch eine Unschärfe beim Löschen mehrerer Timer, da foreach unbeindruckt vom Löschen eines Array Elements den "Index" höher zählt und somit direkt hintereinander liegende Timer nicht komplett gelöscht wurden.

Nun ein apptime zum Test mit dem bisherigen Stand zu Timern mit %intAt:
################################################################
# 98_apptime:application timing
# $Id: 98_apptime.pm 14087e 2018-01-21 00:00:00Z 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($intAtA);           # Internal at timer hash, global for benchmark, new Version
use vars qw(%intAt);           # Internal at timer, global for benchmark, old Version
use vars qw($intAtCnt);        # counter for Internal at timer
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".
                          " or apptime <pause|cont>".
                          " or apptime <nhours> [hours] [numberofdummytimers]";
}

my $IntatLen       = 0;
my $maxIntatLen    = 0;
my $maxIntatDone   = 0;

my $totTmrHandleTm = 0;
my $minTmrHandleTm = 1000000;
my $maxTmrHandleTm = 0;
my $TmrHandleTmCnt = 0;

my $totIntatSortTm = 0;
my $minIntatSortTm = 1000000;
my $maxIntatSortTm = 0;
my $IntatSortTmCnt = 0;

my $totRemoveTm    = 0;
my $minRemoveTm    = 1000000;
my $maxRemoveTm    = 0;
my $RemoveTmCnt    = 0;

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

my $measStartTm    = gettimeofday();
my $timedRun       = 0;
my $measStopTm     = $measStartTm;

use constant DEBUG_OUTPUT_INTATA => 0;

use constant MinCoverWait => 0.0002474; # 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 $lovrhd = 0;

# %intAt
sub
HandleTimeout()
{
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  if($now < $nextat) {
    $selectTimestamp = $now;
    return ($nextat-$now);
  }

  if ($apptimeStatus){
    $IntatLen = scalar(keys %intAt);
    $maxIntatLen = $IntatLen if ($maxIntatLen < $IntatLen);
  }

  my $tovrhd = 0;
  my $nd = 0;

  my $handleStart = gettimeofday();

  my ($tim,$fn);

  $nextat = 0;
  #############
  # Check the internal list.
  foreach my $i (sort { $intAt{$a}{TRIGGERTIME} <=>
                        $intAt{$b}{TRIGGERTIME} }
                 grep { $intAt{$_}{TRIGGERTIME} <= $now } # sort is slow
                        keys %intAt) {
    $i = "" if(!defined($i)); # Forum #40598
    next if(!$intAt{$i}); # deleted in the loop
    $tim = $intAt{$i}{TRIGGERTIME};
    $fn = $intAt{$i}{FN};
    if(!defined($tim) || !defined($fn)) {
      delete($intAt{$i});
      next;
    }

    apptime_getTiming("global", "tmr-", $tim>1?$tim:($handleStart+$tovrhd), \$lovrhd, $fn, $intAt{$i}{ARG}); $tovrhd += $lovrhd; $nd++; # this can delete a timer and can add a timer not covered by the current loops TRIGGERTIME sorted list

    delete($intAt{$i});
  }
 
  foreach my $i (keys %intAt) {
    my $tim = $intAt{$i}{TRIGGERTIME};
    $nextat = $tim if(defined($tim) && (!$nextat || $nextat > $tim));
  }

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

    apptime_getTiming("global", "nice-", $handleStart+$tovrhd, \$lovrhd, $entry->{fn}, $entry->{arg}); $tovrhd += $lovrhd;

    $nextat = 1 if(%prioQueues);
  }

  if(!$nextat) {
    $selectTimestamp = $now;

    if ($apptimeStatus){
      $handleStart = gettimeofday() - $handleStart - $tovrhd;
      $totTmrHandleTm += $handleStart;
      $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
      $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
      $TmrHandleTmCnt++;

      $maxIntatDone = $nd if ($maxIntatDone < $nd);
    }
    return undef;
  }

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

  if ($apptimeStatus){
    $handleStart = $now - $handleStart - $tovrhd;
    $totTmrHandleTm += $handleStart;
    $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
    $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
    $TmrHandleTmCnt++;

    $maxIntatDone = $nd if ($maxIntatDone < $nd);
  }

  return ($now < $nextat) ? ($nextat-$now) : 0;
}

#####################################
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;
  }

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }

  $intAt{$intAtCnt}{TRIGGERTIME} = $tim;
  $intAt{$intAtCnt}{FN} = $fn;
  $intAt{$intAtCnt}{ARG} = $arg;
  $intAtCnt++;
  $nextat = $tim if(!$nextat || $nextat > $tim);

  if ($apptimeStatus){
    my $IntatSortTm = gettimeofday() - $now;
    $totIntatSortTm += $IntatSortTm;
    $minIntatSortTm = $IntatSortTm if ($minIntatSortTm > $IntatSortTm);
    $maxIntatSortTm = $IntatSortTm if ($maxIntatSortTm < $IntatSortTm);
    $IntatSortTmCnt++;
  }
}

#####################################
sub
RemoveInternalTimer($;$)
{
  my ($arg, $fn) = @_;
  return if(!$arg && !$fn);

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }

  foreach my $a (keys %intAt) {
    my ($ia, $if) = ($intAt{$a}{ARG}, $intAt{$a}{FN});
    delete($intAt{$a}) if((!$arg || ($ia && $ia eq $arg)) &&
                          (!$fn  || ($if && $if eq $fn)));
  }

  if ($apptimeStatus){
    my $RemoveTm = gettimeofday() - $now;
    $totRemoveTm += $RemoveTm;
    $minRemoveTm = $RemoveTm if ($minRemoveTm > $RemoveTm);
    $maxRemoveTm = $RemoveTm if ($maxRemoveTm < $RemoveTm);
    $RemoveTmCnt++;
  }
}

#####################################
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, "", 0, undef, $fn, @_);

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

#####################################
# Alternative to CallFn with optional functions in $defs, Forum #64741
sub
CallInstanceFn(@)
{
  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;
  }
  my $fn = $defs{$d}{$n} ? $defs{$d}{$n} : $defs{$d}{".$n"};
  return CallFn($d, $n, @_) if(!$fn);

  my @ret = apptime_getTiming($d, "", 0, undef, $fn, @_);

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

#####################################
sub apptime_getTiming($$$$$@) {
  my ($e,$calltype,$tim,$ptovrhd,$fn,@arg) = @_;

  my $tcall;
  my $tstart;
  my $h;
  if ($apptimeStatus){
    $tcall = gettimeofday(); # time of call
    my $shArg;
    if ($calltype ne "") {
      $shArg = (defined($arg[0])?$arg[0]:"");
      if (ref($shArg) eq "HASH") {
        if (!defined($shArg->{NAME})) {
          $shArg = "HASH_unnamed";
        }
        else {
          $shArg = $shArg->{NAME};
        }
      }
      ($shArg,undef) = split(/:|;/,$shArg,2); # for special long args with delim ;
    }
    else {
      $shArg = "";
    }
    my $tfnm;
    if (ref($fn) ne "") {
      my $cv = svref_2object($fn);
      $tfnm = $cv->GV->NAME;
    }
    else {
      $tfnm = $fn;
    }

    my $fnName = $calltype.$tfnm;
    $fnName .= ";".$shArg if (($calltype ne "") && ($shArg ne ""));
    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}++;
    }
    $tstart = gettimeofday(); # time of execution start call
  }

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

  if ($apptimeStatus && defined($h)){
    my $tstop = gettimeofday();
    my $dtcalc = $tstop-$tstart; # execution time
    if ($dtcalc && $h->{max} < $dtcalc){
      $h->{max} = $dtcalc;
      $h->{mAr} = @arg?\@arg:undef;
      $h->{mTS}= strftime("%d.%m. %H:%M:%S", localtime($tstart));
    }
    $h->{tot} += $dtcalc;
    $h->{tot} = 0 if(!$h->{cnt});
    if ($tim > 1){ # call delay for timers with time set
      $totCnt++;
      $dtcalc = $tcall-$tim;
      $totDly += $dtcalc;
      $totDly = 0 if(!$totCnt);
      $h->{dtotcnt}++;
      $h->{dtot} += $dtcalc;
      $h->{dtot} = 0 if(!$h->{dtotcnt});
      $h->{dmx}  = $dtcalc if ($h->{dmx} < $dtcalc);
    }
    ${$ptovrhd} = ($tstart-$tcall-$tstop)+gettimeofday() if (defined($ptovrhd));
  }
  return @ret;
}


#####################################
sub apptime_timedstop($) {
  if ($timedRun) {
    $measStopTm    = gettimeofday();
    $apptimeStatus = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy");
  }
}
#####################################
sub apptime_dummy($) {
  InternalTimer(gettimeofday()+rand(120),"apptime_dummy","apptime_dummy",0) if ($apptimeStatus && $timedRun);
  return;
}


#####################################
sub apptime_CommandDispTiming($$@) {
  my ($cl,$param) = @_;
  my ($sFld,$top,$filter) = split" ",$param;
  $sFld = "max" if (!$sFld);
  return "Use apptime ".$cmds{"apptime"}{Hlp} if ($sFld eq "help");
  $top = "top" if (!$top);
  my %fld = (name=>0,function=>1,max=>2,count=>3,total=>4,average=>5,maxDly=>6,avgDly=>7,nhours=>97,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
    $apptimeStatus  = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
  }
  elsif ($sFld eq "cont"){# further collection of data
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 0;
  }
  elsif ($sFld eq "clear"){# clear
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
    $measStartTm    = gettimeofday();
  }
  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;
     
      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;
     
      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;
     
      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    elsif ($sFld =~ m/(pause|cont)/){
    }
    elsif ($sFld eq "nhours"){
      delete $defs{$d}{helper}{bm};
      $totDly         = 0;
      $totCnt         = 0;
      $maxIntatLen    = 0;
      $maxIntatDone   = 0;
     
      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;
     
      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;
     
      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    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
                    )];
      }
    }
  }

  if ($sFld eq "nhours"){# further collection of data, clear also
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 1;
    $top = 2/60 if ($top eq "top");
    my $now = gettimeofday();
    InternalTimer($now+3600*$top,"apptime_timedstop","apptime_timedstop",0);
    $measStartTm    = $now;
    $measStopTm     = $measStartTm;
    if (defined($filter) && $filter =~ /^\d+$/) {
      $filter = int($filter);
      $filter = 1 if ($filter < 1);
      for (my $i=1; $i <= $filter; $i++) {
        InternalTimer($now+rand($i*300/$filter),"apptime_dummy","apptime_dummy",0);
      }
    }
  }

  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; totAvgDly: %0.1fus;  lovrhd: %0.1fus;  tot-meas-time: %0.1fs\n",
                     $IntatLen,$maxIntatLen,$maxIntatDone,($totCnt?$totDly/$totCnt*1000000:-1),$lovrhd*1000000,($timedRun?($apptimeStatus?(gettimeofday()-$measStartTm):($measStopTm-$measStartTm)):(gettimeofday()-$measStartTm)));
  $ret .= sprintf("min-tmrHandlingTm: %8.1fus; avg-tmrHandlingTm: %8.1fus; max-tmrHandlingTm: %10.1fus;  tot-tmrHandlingTm: %0.1fs\n",
                  ($minTmrHandleTm<$maxTmrHandleTm?$minTmrHandleTm*1000000:-1),($TmrHandleTmCnt?$totTmrHandleTm/$TmrHandleTmCnt*1000000:-1),($minTmrHandleTm<$maxTmrHandleTm?$maxTmrHandleTm*1000000:-1),$totTmrHandleTm);
  $ret .= sprintf("min-timerInsertTm: %8.1fus; avg-timerInsertTm: %8.1fus; max-timerInsertTm: %10.1fus;  tot-timerInsertTm: %0.1fs\n",
                  ($minIntatSortTm<$maxIntatSortTm?$minIntatSortTm*1000000:-1),($IntatSortTmCnt?$totIntatSortTm/$IntatSortTmCnt*1000000:-1),($minIntatSortTm<$maxIntatSortTm?$maxIntatSortTm*1000000:-1),$totIntatSortTm);
  $ret .= sprintf("min-timerRemoveTm: %8.1fus; avg-timerRemoveTm: %8.1fus; max-timerRemoveTm: %10.1fus;  tot-timerRemoveTm: %0.1fs\n",
                  ($minRemoveTm<$maxRemoveTm?$minRemoveTm*1000000:-1),($RemoveTmCnt?$totRemoveTm/$RemoveTmCnt*1000000:-1),($minRemoveTm<$maxRemoveTm?$maxRemoveTm*1000000:-1),$totRemoveTm);
  $ret .= ($apptimeStatus ? "" : ($timedRun?"--- apptime timed run result ---\n":"------ apptime PAUSED data collection ----------\n"))
            .sprintf("\nTimes in ms:\n %-40s %-35s %9s %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 %9.2f %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 nhours [hours] [numberofdummytimers]</code></dt>
          <dd>
            <p>
                Clears data and starts a collection of data for [hours] hours.
                Without arguments it collects for 2 minutes.
                With [numberofdummytimers] the timer queue can be filled with randomly executed dummy timers.
            </p>
          </dd>
      <dt><code><kbd>apptime cont</code></dt>
          <dd>
            <p>
                Continue data collection after pause.
            </p>
          </dd>
      <dt><code><kbd>apptime [count|function|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

Mein 8h Test liefert damit:
active-timers: 124; max-active timers: 140; max-timer-load: 6; totAvgDly: 9370.4us;  lovrhd: 602.0us;  tot-meas-time: 28800.0s
min-tmrHandlingTm:   4292.0us; avg-tmrHandlingTm:  23309.6us; max-tmrHandlingTm:   270588.2us;  tot-tmrHandlingTm: 811.6s
min-timerInsertTm:     93.9us; avg-timerInsertTm:    191.5us; max-timerInsertTm:    45178.9us;  tot-timerInsertTm: 9.7s
min-timerRemoveTm:   3718.9us; avg-timerRemoveTm:   5271.2us; max-timerRemoveTm:    29942.0us;  tot-timerRemoveTm: 109.5s
und mit 500 zusätzlichen Timern:
active-timers: 619; max-active timers: 640; max-timer-load: 125; totAvgDly: 25532.6us;  lovrhd: 464.9us;  tot-meas-time: 28800.0s
min-tmrHandlingTm:  22713.9us; avg-tmrHandlingTm:  31163.7us; max-tmrHandlingTm:   646313.2us;  tot-tmrHandlingTm: 7850.7s
min-timerInsertTm:     86.1us; avg-timerInsertTm:    172.2us; max-timerInsertTm:    50928.8us;  tot-timerInsertTm: 50.3s
min-timerRemoveTm:  19276.1us; avg-timerRemoveTm:  25109.0us; max-timerRemoveTm:   129202.1us;  tot-timerRemoveTm: 560.9s

Weiter im nächsten Beitrag:

Nun ein apptime mit neuem Code für Array Timer Handling:
################################################################
# 98_apptime:application timing
# $Id: 98_apptime.pm 14087e 2018-01-21 00:00:00Z 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($intAtA);           # Internal at timer hash, global for benchmark, new Version
#use vars qw(%intAt);           # Internal at timer, global for benchmark, old Version
#use vars qw($intAtCnt);        # counter for Internal at timer
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".
                          " or apptime <pause|cont>".
                          " or apptime <nhours> [hours] [numberofdummytimers]";
}

my $IntatLen       = 0;
my $maxIntatLen    = 0;
my $maxIntatDone   = 0;

my $totTmrHandleTm = 0;
my $minTmrHandleTm = 1000000;
my $maxTmrHandleTm = 0;
my $TmrHandleTmCnt = 0;

my $totIntatSortTm = 0;
my $minIntatSortTm = 1000000;
my $maxIntatSortTm = 0;
my $IntatSortTmCnt = 0;

my $totRemoveTm    = 0;
my $minRemoveTm    = 1000000;
my $maxRemoveTm    = 0;
my $RemoveTmCnt    = 0;

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

my $measStartTm    = gettimeofday();
my $timedRun       = 0;
my $measStopTm     = $measStartTm;

use constant DEBUG_OUTPUT_INTATA => 0;

use constant MinCoverWait => 0.0002474; # 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 $lovrhd = 0;

# @{$intAtA}
sub
HandleTimeout()
{
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > 0) { # Timer to handle?
    $selectTimestamp = $now;
    return $dtnext;
  }

  if ($apptimeStatus){
    $IntatLen = defined($intAtA)?int(@{$intAtA}):0;
    $maxIntatLen = $IntatLen if ($maxIntatLen < $IntatLen);
  }

  my $tovrhd = 0;
  my $nd = 0;

  my $handleStart = gettimeofday();

  my ($tim,$fn);
  $nextat = 0;
  while (defined($intAtA) and @{$intAtA}) {
    $tim = $intAtA->[0]->{TRIGGERTIME};
    $fn = $intAtA->[0]->{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      shift @{$intAtA};
      next;
    }
#    if ($tim > $now + MinCoverWait) { # time to handle Timer for time of e.g. one character at 38400 at least
    if ($tim > $now) {
      $nextat = $tim; # execution time not reached yet
      last;
    }

    apptime_getTiming("global", "tmr-", $tim>1?$tim:($handleStart+$tovrhd), \$lovrhd, $fn, shift(@{$intAtA})->{ARG}); $tovrhd += $lovrhd; $nd++; # this can delete a timer and can add a timer not covered by the current loops TRIGGERTIME sorted list

    $now = gettimeofday(); # reduce delay related to execution time of previous timers
  }

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

    apptime_getTiming("global", "nice-", $handleStart+$tovrhd, \$lovrhd, $entry->{fn}, $entry->{arg}); $tovrhd += $lovrhd;

    $nextat = 1 if(%prioQueues);
  }

  if(!$nextat) {
    $selectTimestamp = $now;

    if ($apptimeStatus){
      $handleStart = gettimeofday() - $handleStart - $tovrhd;
      $totTmrHandleTm += $handleStart;
      $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
      $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
      $TmrHandleTmCnt++;

      $maxIntatDone = $nd if ($maxIntatDone < $nd);
    }
    return undef;
  }

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

  if ($apptimeStatus){
    $handleStart = $now - $handleStart - $tovrhd;
    $totTmrHandleTm += $handleStart;
    $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
    $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
    $TmrHandleTmCnt++;

    $maxIntatDone = $nd if ($maxIntatDone < $nd);
  }
 
  $dtnext = $nextat-$now;
  return ($dtnext > 0) ? $dtnext : 0; # wait until next Timer needs to be handled
}

#####################################
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;
  }

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }

  ### O(log(n)) add ###################
  my $i = defined($intAtA)?int(@{$intAtA}):0;

  if ($i) {
    my $t;
    my $ui = $i - 1;
    my $li = 0;
    while ($li <= $ui) {
      $i = int(($ui-$li)/2)+$li;
      $t = $intAtA->[$i]->{TRIGGERTIME};
      if ($tim >= $t) { # in upper half
        $li = ++$i;
      }
      else {            # in lower half
        $ui = $i-1;
      }
    }
    splice @{$intAtA}, $i, 0, { #insert or append new entry
                               TRIGGERTIME => $tim,
                               FN => $fn,
                               ARG => $arg
                              };
  } else { # array creation on first add
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
  }
  ####

  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );

  if (DEBUG_OUTPUT_INTATA) {
    for ($i=0; $i < (int(@{$intAtA})-1); $i++) {
      next if ($intAtA->[$i]->{TRIGGERTIME} <= $intAtA->[$i+1]->{TRIGGERTIME});
      print "Error in $intAtA inserting $tim $fn\n";
      use Data::Dumper;
      print Data::Dumper->new([$intAtA],[qw($intAtA)])->Indent(1)->Quotekeys(1)->Dump;
      my $h = $intAtA->[$i]->{TRIGGERTIME};
      $intAtA->[$i]->{TRIGGERTIME} = $intAtA->[$i+1]->{TRIGGERTIME};
      $intAtA->[$i+1]->{TRIGGERTIME} = $h;
    }
  }

  if ($apptimeStatus){
    my $IntatSortTm = gettimeofday() - $now;
    $totIntatSortTm += $IntatSortTm;
    $minIntatSortTm = $IntatSortTm if ($minIntatSortTm > $IntatSortTm);
    $maxIntatSortTm = $IntatSortTm if ($maxIntatSortTm < $IntatSortTm);
    $IntatSortTmCnt++;
  }

  return;
}

#####################################
sub
RemoveInternalTimer($;$)
{
  return if (!defined($intAtA) || !@{$intAtA});

  my ($arg, $fn) = @_;

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }
 
  if ($fn) {
    if (defined($arg)) {
      my ($ia, $if);
      my $i = int(@{$intAtA});
      while($i--) {
        ($ia, $if) = ($intAtA->[$i]->{ARG}, $intAtA->[$i]->{FN});
        splice @{$intAtA}, $i, 1 if(   defined($ia) && ($ia eq $arg)
                                    && defined($if) && ($if eq $fn) );
      }
    }
    else {
      my $if;
      my $i = int(@{$intAtA});
      while($i--) {
        $if = $intAtA->[$i]->{FN};
        splice @{$intAtA}, $i, 1 if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
      }
    }
  }
  else {
    return if (!defined($arg));
    my $ia;
    my $i = int(@{$intAtA});
    while($i--) {
      $ia = $intAtA->[$i]->{ARG};
      splice @{$intAtA}, $i, 1 if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
    }
  }

  if ($apptimeStatus){
    my $RemoveTm = gettimeofday() - $now;
    $totRemoveTm += $RemoveTm;
    $minRemoveTm = $RemoveTm if ($minRemoveTm > $RemoveTm);
    $maxRemoveTm = $RemoveTm if ($maxRemoveTm < $RemoveTm);
    $RemoveTmCnt++;
  }
}

#####################################
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, "", 0, undef, $fn, @_);

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

#####################################
# Alternative to CallFn with optional functions in $defs, Forum #64741
sub
CallInstanceFn(@)
{
  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;
  }
  my $fn = $defs{$d}{$n} ? $defs{$d}{$n} : $defs{$d}{".$n"};
  return CallFn($d, $n, @_) if(!$fn);

  my @ret = apptime_getTiming($d, "", 0, undef, $fn, @_);

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

#####################################
sub apptime_getTiming($$$$$@) {
  my ($e,$calltype,$tim,$ptovrhd,$fn,@arg) = @_;

  my $tcall;
  my $tstart;
  my $h;
  if ($apptimeStatus){
    $tcall = gettimeofday(); # time of call
    my $shArg;
    if ($calltype ne "") {
      $shArg = (defined($arg[0])?$arg[0]:"");
      if (ref($shArg) eq "HASH") {
        if (!defined($shArg->{NAME})) {
          $shArg = "HASH_unnamed";
        }
        else {
          $shArg = $shArg->{NAME};
        }
      }
      ($shArg,undef) = split(/:|;/,$shArg,2); # for special long args with delim ;
    }
    else {
      $shArg = "";
    }
    my $tfnm;
    if (ref($fn) ne "") {
      my $cv = svref_2object($fn);
      $tfnm = $cv->GV->NAME;
    }
    else {
      $tfnm = $fn;
    }

    my $fnName = $calltype.$tfnm;
    $fnName .= ";".$shArg if (($calltype ne "") && ($shArg ne ""));
    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}++;
    }
    $tstart = gettimeofday(); # time of execution start call
  }

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

  if ($apptimeStatus && defined($h)){
    my $tstop = gettimeofday();
    my $dtcalc = $tstop-$tstart; # execution time
    if ($dtcalc && $h->{max} < $dtcalc){
      $h->{max} = $dtcalc;
      $h->{mAr} = @arg?\@arg:undef;
      $h->{mTS}= strftime("%d.%m. %H:%M:%S", localtime($tstart));
    }
    $h->{tot} += $dtcalc;
    $h->{tot} = 0 if(!$h->{cnt});
    if ($tim > 1){ # call delay for timers with time set
      $totCnt++;
      $dtcalc = $tcall-$tim;
      $totDly += $dtcalc;
      $totDly = 0 if(!$totCnt);
      $h->{dtotcnt}++;
      $h->{dtot} += $dtcalc;
      $h->{dtot} = 0 if(!$h->{dtotcnt});
      $h->{dmx}  = $dtcalc if ($h->{dmx} < $dtcalc);
    }
    ${$ptovrhd} = ($tstart-$tcall-$tstop)+gettimeofday() if (defined($ptovrhd));
  }
  return @ret;
}


#####################################
sub apptime_timedstop($) {
  if ($timedRun) {
    $measStopTm    = gettimeofday();
    $apptimeStatus = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy");
  }
}
#####################################
sub apptime_dummy($) {
  InternalTimer(gettimeofday()+rand(120),"apptime_dummy","apptime_dummy",0) if ($apptimeStatus && $timedRun);
  return;
}


#####################################
sub apptime_CommandDispTiming($$@) {
  my ($cl,$param) = @_;
  my ($sFld,$top,$filter) = split" ",$param;
  $sFld = "max" if (!$sFld);
  return "Use apptime ".$cmds{"apptime"}{Hlp} if ($sFld eq "help");
  $top = "top" if (!$top);
  my %fld = (name=>0,function=>1,max=>2,count=>3,total=>4,average=>5,maxDly=>6,avgDly=>7,nhours=>97,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
    $apptimeStatus  = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
  }
  elsif ($sFld eq "cont"){# further collection of data
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 0;
  }
  elsif ($sFld eq "clear"){# clear
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
    $measStartTm    = gettimeofday();
  }
  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;
     
      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;
     
      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;
     
      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    elsif ($sFld =~ m/(pause|cont)/){
    }
    elsif ($sFld eq "nhours"){
      delete $defs{$d}{helper}{bm};
      $totDly         = 0;
      $totCnt         = 0;
      $maxIntatLen    = 0;
      $maxIntatDone   = 0;
     
      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;
     
      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;
     
      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    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
                    )];
      }
    }
  }

  if ($sFld eq "nhours"){# further collection of data, clear also
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 1;
    $top = 2/60 if ($top eq "top");
    my $now = gettimeofday();
    InternalTimer($now+3600*$top,"apptime_timedstop","apptime_timedstop",0);
    $measStartTm    = $now;
    $measStopTm     = $measStartTm;
    if (defined($filter) && $filter =~ /^\d+$/) {
      $filter = int($filter);
      $filter = 1 if ($filter < 1);
      for (my $i=1; $i <= $filter; $i++) {
        InternalTimer($now+rand($i*300/$filter),"apptime_dummy","apptime_dummy",0);
      }
    }
  }

  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; totAvgDly: %0.1fus;  lovrhd: %0.1fus;  tot-meas-time: %0.1fs\n",
                     $IntatLen,$maxIntatLen,$maxIntatDone,($totCnt?$totDly/$totCnt*1000000:-1),$lovrhd*1000000,($timedRun?($apptimeStatus?(gettimeofday()-$measStartTm):($measStopTm-$measStartTm)):(gettimeofday()-$measStartTm)));
  $ret .= sprintf("min-tmrHandlingTm: %8.1fus; avg-tmrHandlingTm: %8.1fus; max-tmrHandlingTm: %10.1fus;  tot-tmrHandlingTm: %0.1fs\n",
                  ($minTmrHandleTm<$maxTmrHandleTm?$minTmrHandleTm*1000000:-1),($TmrHandleTmCnt?$totTmrHandleTm/$TmrHandleTmCnt*1000000:-1),($minTmrHandleTm<$maxTmrHandleTm?$maxTmrHandleTm*1000000:-1),$totTmrHandleTm);
  $ret .= sprintf("min-timerInsertTm: %8.1fus; avg-timerInsertTm: %8.1fus; max-timerInsertTm: %10.1fus;  tot-timerInsertTm: %0.1fs\n",
                  ($minIntatSortTm<$maxIntatSortTm?$minIntatSortTm*1000000:-1),($IntatSortTmCnt?$totIntatSortTm/$IntatSortTmCnt*1000000:-1),($minIntatSortTm<$maxIntatSortTm?$maxIntatSortTm*1000000:-1),$totIntatSortTm);
  $ret .= sprintf("min-timerRemoveTm: %8.1fus; avg-timerRemoveTm: %8.1fus; max-timerRemoveTm: %10.1fus;  tot-timerRemoveTm: %0.1fs\n",
                  ($minRemoveTm<$maxRemoveTm?$minRemoveTm*1000000:-1),($RemoveTmCnt?$totRemoveTm/$RemoveTmCnt*1000000:-1),($minRemoveTm<$maxRemoveTm?$maxRemoveTm*1000000:-1),$totRemoveTm);
  $ret .= ($apptimeStatus ? "" : ($timedRun?"--- apptime timed run result ---\n":"------ apptime PAUSED data collection ----------\n"))
            .sprintf("\nTimes in ms:\n %-40s %-35s %9s %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 %9.2f %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 nhours [hours] [numberofdummytimers]</code></dt>
          <dd>
            <p>
                Clears data and starts a collection of data for [hours] hours.
                Without arguments it collects for 2 minutes.
                With [numberofdummytimers] the timer queue can be filled with randomly executed dummy timers.
            </p>
          </dd>
      <dt><code><kbd>apptime cont</code></dt>
          <dd>
            <p>
                Continue data collection after pause.
            </p>
          </dd>
      <dt><code><kbd>apptime [count|function|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

Mein 8h Test liefert damit:
active-timers: 120; max-active timers: 137; max-timer-load: 6; totAvgDly: 5899.9us;  lovrhd: 726.0us;  tot-meas-time: 28800.0s
min-tmrHandlingTm:     80.1us; avg-tmrHandlingTm:  18719.1us; max-tmrHandlingTm:   247625.4us;  tot-tmrHandlingTm: 553.3s
min-timerInsertTm:    259.9us; avg-timerInsertTm:    462.6us; max-timerInsertTm:    21012.1us;  tot-timerInsertTm: 22.5s
min-timerRemoveTm:   1831.1us; avg-timerRemoveTm:   2879.7us; max-timerRemoveTm:    32797.1us;  tot-timerRemoveTm: 58.9s
und mit 500 zusätzlichen Timern:
active-timers: 629; max-active timers: 639; max-timer-load: 28; totAvgDly: 4111.3us;  lovrhd: 313.3us;  tot-meas-time: 28800.0s
min-tmrHandlingTm:     79.2us; avg-tmrHandlingTm:   4057.2us; max-tmrHandlingTm:  3177133.3us;  tot-tmrHandlingTm: 1029.8s
min-timerInsertTm:    284.9us; avg-timerInsertTm:    503.3us; max-timerInsertTm:    24554.0us;  tot-timerInsertTm: 145.4s
min-timerRemoveTm:   8804.1us; avg-timerRemoveTm:  12683.4us; max-timerRemoveTm:    58601.9us;  tot-timerRemoveTm: 261.4s

Mit
apptime nhours [AnzahlStunden] [AnzahlDummyTimer]
kann man einen n-Stündigen Test laufen lassen, der nach der gewählten Zeit auf pause umschaltet und man dann das Ergebnis mit "apptime" anzeigen lassen kann.
Außerdem kann man damit noch Dummy Timer erzeugen, die über den Testzeitraum laufen, um eine gewisse Timerlast zu simulieren.

Ich habe die Ausgaben für den Timertest auf µs umgestellt, um auch auf schnelleren Systemen hoffentlich noch was von den Zeiten sehen zu können.
Da apptime selbst auch Rechenzeit benötigt, habe ich die meißte Zeit davon beim Timerhandling auch noch mit ermittelt und lasse sie abziehen. Das Feld "lovrhd" gibt den letzten Overhead beim letzten gehandleten Timer wieder, um einen Wert dafür sichtbar zu machen.
Die Timerhandlingszeiten enthalten auch die Timerausführungszeit selbst.

Die Summenzeiten sind nun auch in der Ausgabe.

@Rudolf:

Zitat- InsertTimer wird langsamer.

Ja und ist so leider unvermeidlich. Allerdings ist zum Zeitpunkt der Timer-Erstellung eher Zeit dafür, als zum Zeitpunkt der Timer-Ausführung -> totAvgDly sinkt.

Zitat- der Kode wird aufwendiger

Ja, leider kenne ich keine fertige Perl Funktion, die das einsortieren in der gewünschten Art zu einem Funktionsaufruf schrumpfen lässt.
Müsste sort und grep in perl noch ausprogrammiert werden, dann wäre der bisherige Code wohl aufwändiger.  ;)
Bei RemoveInternalTimer ist es messbar ebenfalls vorteilhaft, nur das notwendigste in der Schleife zu prüfen. Zumeist wird RemoveInternalTimer mit nur einem der beiden Parameter verwendet. Das zeigt sich auch im Testergebnis.

Zitatmit etwa den gleichen Anzahl von Elementen ausfuehren

Auf meinem Testsystem liegt die Timeranzahl immer zwischen 120 und 140 nach etwa 0.5h Laufzeit nach Systemstart.
Ganz "leer" Räumen kann ich mein Testsystem jedoch leider nicht, da es auch "produktiv" läuft.

Wie an max-timerRemoveTm zu sehen, muss es eine andere Ursache dafür geben, als den Code selbst, da sie linear mit der Anzahl der Timer skalieren müsste.

Gruß, Ansgar.

Vielen Dank fuer die Muehe und die langen Messreihen.

Ich habs versucht (auch durch code-studieren) die Bedeutung der Zahlen zu verstehen, bin aber nicht sicher, ob es mir gelungen ist: Stimmt es, dass keiner der Zahlen den Aufwand widergibt, der im HandleTimeout beim Auswahl des naechsten Eintrages entsteht, also das, was wir optimieren moechten? tmrHandling beinhaltet auch den Funktionsaufruf, d.h. man kann nur dann auf den "Auswahl-Aufwand" schliessen, wenn man annimmt, dass die aufgerufenen Funktionen im Durchschnitt in beiden Faellen genauso lange gebraucht haben.

Bei 120 gleichzeitig aktiven Timern waeren das im Schnitt 4.6 (oder 3.5?) ms "Gewinn" pro Aufruf beim Auswahl-Aufwand in der Array Version. Demgegenueber stehen 0.3ms "Verlust" beim Einfuegen des Timers.
Fuer die uneingeweihten: der Auswahl-Aufwand tritt einmal auf beim Ausloesen des Timers.

Ich gehe also davon aus, dass nach einem Umbau auf Array auf Installationen mit sehr vielen Timern die FHEM-Timer etwas genauer aufgerufen werden.

Zur Klarstellung: ich werde fuer fhem.pl kein Code uebernehmen, das muss ich selbst schreiben, wenn ich das in einem Jahr noch verstehen soll. Und ich habe nicht vor aus FHEM einen Signalprozessor zu machen, d.h. es ist mir wichtiger verstaendlichen Code zu haben, als die letzte ms rauszuholen.

Hallo Rudolf,

ZitatStimmt es, dass keiner der Zahlen den Aufwand widergibt, der im HandleTimeout beim Auswahl des naechsten Eintrages entsteht, also das, was wir optimieren moechten? tmrHandling beinhaltet auch den Funktionsaufruf, d.h. man kann nur dann auf den "Auswahl-Aufwand" schliessen, wenn man annimmt, dass die aufgerufenen Funktionen im Durchschnitt in beiden Faellen genauso lange gebraucht haben.

Korrekt.
Allerdings kann ich die Zahlenergebnisse mit erneutem Lauf unter gleichen "Umgebungsbedingungen" recht gut reproduzieren, so dass indirekt auf eine Verbesserung geschlossen werden kann.
Man kann natürlich auch die Rechenzeit für die Auswahl des nächsten Timers auch noch messen. Nur jede Messung erfordert auch wieder Rechenzeit und übertreiben wollte ich es damit nicht, sondern möglichst ohnehin schon vorhandene Messungen in apptime nutzen.

ZitatBei 120 gleichzeitig aktiven Timern waeren das im Schnitt 4.6 (oder 3.5?) ms "Gewinn" pro Aufruf beim Auswahl-Aufwand in der Array Version. Demgegenueber stehen 0.3ms "Verlust" beim Einfuegen des Timers.
Fuer die uneingeweihten: der Auswahl-Aufwand tritt einmal auf beim Ausloesen des Timers.

Am besten baue ich die zusätzliche Messung wohl auch noch ein.

ZitatZur Klarstellung: ich werde fuer fhem.pl kein Code uebernehmen, das muss ich selbst schreiben, wenn ich das in einem Jahr noch verstehen soll. Und ich habe nicht vor aus FHEM einen Signalprozessor zu machen, d.h. es ist mir wichtiger verstaendlichen Code zu haben, als die letzte ms rauszuholen.

Das habe ich auch nicht anders erwartet. Der ursprüngliche Vorschlag aus dem ersten Beitrag hat halt etwas interessante Eigendynamik bekommen.  ;)
Beim Einsortieren muss man auch sehr darauf achten, am Ende nicht doch am falschen Index raus zu kommen. Probiert habe ich es nicht erwarte aber, dass die Nutzung von sort hier deutlich ungünstiger ausfallen würde.

Vom Verhalten her ergibt sich bei HandleTimer auch ein kleiner Unterschied, falls ein neuer Timer in einer Timerroutine mit Ausführungszeit 1 oder gettimeofday erzeugt wird. Dann wird er auch gleich im gleichen HandleTimeraufruf noch ausgeführt, während er in Deinem bisherigen Code erst im nächsten Aufruf von HandleTimer zur Ausführung kommt.

Gruß und Danke für's drüber schauen, Ansgar.

Hallo Rudolf,

hier schon mal der apptime Code ergänzt um die Zeitmessung für den Handlingsaufwand.

Zum bisherigen %intAt Code:
################################################################
# 98_apptime:application timing
# $Id: 98_apptime.pm 14087f 2018-01-26 00:00:00Z 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($intAtA);           # Internal at timer hash, global for benchmark, new Version
use vars qw(%intAt);           # Internal at timer, global for benchmark, old Version
use vars qw($intAtCnt);        # counter for Internal at timer
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".
                          " or apptime <pause|cont>".
                          " or apptime <nhours> [hours] [numberofdummytimers]";
}

my $IntatLen       = 0;
my $maxIntatLen    = 0;
my $maxIntatDone   = 0;

my $totTmrHandleCalc = 0;
my $minTmrHandleCalc = 1000000;
my $maxTmrHandleCalc = 0;

my $totTmrHandleTm = 0;
my $minTmrHandleTm = 1000000;
my $maxTmrHandleTm = 0;
my $TmrHandleTmCnt = 0;

my $totIntatSortTm = 0;
my $minIntatSortTm = 1000000;
my $maxIntatSortTm = 0;
my $IntatSortTmCnt = 0;

my $totRemoveTm    = 0;
my $minRemoveTm    = 1000000;
my $maxRemoveTm    = 0;
my $RemoveTmCnt    = 0;

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

my $measStartTm    = gettimeofday();
my $timedRun       = 0;
my $measStopTm     = $measStartTm;

use constant DEBUG_OUTPUT_INTATA => 0;

use constant MinCoverWait => 0.0002474; # 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 $lovrhd = 0;
my $appcalctm = 0;

# %intAt
sub
HandleTimeout()
{
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  if($now < $nextat) {
    $selectTimestamp = $now;
    return ($nextat-$now);
  }

  if ($apptimeStatus){
    $IntatLen = scalar(keys %intAt);
    $maxIntatLen = $IntatLen if ($maxIntatLen < $IntatLen);
  }

  my $tovrhd = 0;
  my $nd = 0;
  $appcalctm = 0;

  my $handleStart = gettimeofday();

  my ($tim,$fn);

  $nextat = 0;
  #############
  # Check the internal list.
  foreach my $i (sort { $intAt{$a}{TRIGGERTIME} <=>
                        $intAt{$b}{TRIGGERTIME} }
                 grep { $intAt{$_}{TRIGGERTIME} <= $now } # sort is slow
                        keys %intAt) {
    $i = "" if(!defined($i)); # Forum #40598
    next if(!$intAt{$i}); # deleted in the loop
    $tim = $intAt{$i}{TRIGGERTIME};
    $fn = $intAt{$i}{FN};
    if(!defined($tim) || !defined($fn)) {
      delete($intAt{$i});
      next;
    }

    apptime_getTiming("global", "tmr-", $tim>1?$tim:($handleStart+$tovrhd), \$lovrhd, \$appcalctm, $fn, $intAt{$i}{ARG}); $tovrhd += $lovrhd; $nd++; # this can delete a timer and can add a timer not covered by the current loops TRIGGERTIME sorted list

    delete($intAt{$i});
  }
 
  foreach my $i (keys %intAt) {
    my $tim = $intAt{$i}{TRIGGERTIME};
    $nextat = $tim if(defined($tim) && (!$nextat || $nextat > $tim));
  }

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

    apptime_getTiming("global", "nice-", $handleStart+$tovrhd, \$lovrhd, \$appcalctm, $entry->{fn}, $entry->{arg}); $tovrhd += $lovrhd;

    $nextat = 1 if(%prioQueues);
  }

  if(!$nextat) {
    $selectTimestamp = $now;

    if ($apptimeStatus){
      $handleStart = gettimeofday() - $handleStart - $tovrhd;
      $totTmrHandleTm += $handleStart;
      $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
      $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
      $TmrHandleTmCnt++;
      $handleStart -= $appcalctm;
      $totTmrHandleCalc += $handleStart;
      $minTmrHandleCalc = $handleStart if ($minTmrHandleCalc > $handleStart);
      $maxTmrHandleCalc = $handleStart if ($maxTmrHandleCalc < $handleStart);

      $maxIntatDone = $nd if ($maxIntatDone < $nd);
    }
    return undef;
  }

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

  if ($apptimeStatus){
    $handleStart = $now - $handleStart - $tovrhd;
    $totTmrHandleTm += $handleStart;
    $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
    $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
    $TmrHandleTmCnt++;
    $handleStart -= $appcalctm;
    $totTmrHandleCalc += $handleStart;
    $minTmrHandleCalc = $handleStart if ($minTmrHandleCalc > $handleStart);
    $maxTmrHandleCalc = $handleStart if ($maxTmrHandleCalc < $handleStart);

    $maxIntatDone = $nd if ($maxIntatDone < $nd);
  }

  return ($now < $nextat) ? ($nextat-$now) : 0;
}

#####################################
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;
  }

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }

  $intAt{$intAtCnt}{TRIGGERTIME} = $tim;
  $intAt{$intAtCnt}{FN} = $fn;
  $intAt{$intAtCnt}{ARG} = $arg;
  $intAtCnt++;
  $nextat = $tim if(!$nextat || $nextat > $tim);

  if ($apptimeStatus){
    my $IntatSortTm = gettimeofday() - $now;
    $totIntatSortTm += $IntatSortTm;
    $minIntatSortTm = $IntatSortTm if ($minIntatSortTm > $IntatSortTm);
    $maxIntatSortTm = $IntatSortTm if ($maxIntatSortTm < $IntatSortTm);
    $IntatSortTmCnt++;
  }
}

#####################################
sub
RemoveInternalTimer($;$)
{
  my ($arg, $fn) = @_;
  return if(!$arg && !$fn);

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }

  foreach my $a (keys %intAt) {
    my ($ia, $if) = ($intAt{$a}{ARG}, $intAt{$a}{FN});
    delete($intAt{$a}) if((!$arg || ($ia && $ia eq $arg)) &&
                          (!$fn  || ($if && $if eq $fn)));
  }

  if ($apptimeStatus){
    my $RemoveTm = gettimeofday() - $now;
    $totRemoveTm += $RemoveTm;
    $minRemoveTm = $RemoveTm if ($minRemoveTm > $RemoveTm);
    $maxRemoveTm = $RemoveTm if ($maxRemoveTm < $RemoveTm);
    $RemoveTmCnt++;
  }
}

#####################################
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, "", 0, undef, undef, $fn, @_);

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

#####################################
# Alternative to CallFn with optional functions in $defs, Forum #64741
sub
CallInstanceFn(@)
{
  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;
  }
  my $fn = $defs{$d}{$n} ? $defs{$d}{$n} : $defs{$d}{".$n"};
  return CallFn($d, $n, @_) if(!$fn);

  my @ret = apptime_getTiming($d, "", 0, undef, undef, $fn, @_);

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

#####################################
sub apptime_getTiming($$$$$$@) {
  my ($e,$calltype,$tim,$ptovrhd,$ptfcalc,$fn,@arg) = @_;

  my $tcall;
  my $tstart;
  my $h;
  if ($apptimeStatus){
    $tcall = gettimeofday(); # time of call
    my $shArg;
    if ($calltype ne "") {
      $shArg = (defined($arg[0])?$arg[0]:"");
      if (ref($shArg) eq "HASH") {
        if (!defined($shArg->{NAME})) {
          $shArg = "HASH_unnamed";
        }
        else {
          $shArg = $shArg->{NAME};
        }
      }
      ($shArg,undef) = split(/:|;/,$shArg,2); # for special long args with delim ;
    }
    else {
      $shArg = "";
    }
    my $tfnm;
    if (ref($fn) ne "") {
      my $cv = svref_2object($fn);
      $tfnm = $cv->GV->NAME;
    }
    else {
      $tfnm = $fn;
    }

    my $fnName = $calltype.$tfnm;
    $fnName .= ";".$shArg if (($calltype ne "") && ($shArg ne ""));
    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}++;
    }
    $tstart = gettimeofday(); # time of execution start call
  }

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

  if ($apptimeStatus && defined($h)){
    my $tstop = gettimeofday();
    my $dtcalc = $tstop-$tstart; # execution time
    ${$ptfcalc} += $dtcalc if (defined($ptfcalc));
    if ($dtcalc && $h->{max} < $dtcalc){
      $h->{max} = $dtcalc;
      $h->{mAr} = @arg?\@arg:undef;
      $h->{mTS}= strftime("%d.%m. %H:%M:%S", localtime($tstart));
    }
    $h->{tot} += $dtcalc;
    $h->{tot} = 0 if(!$h->{cnt});
    if ($tim > 1){ # call delay for timers with time set
      $totCnt++;
      $dtcalc = $tcall-$tim;
      $totDly += $dtcalc;
      $totDly = 0 if(!$totCnt);
      $h->{dtotcnt}++;
      $h->{dtot} += $dtcalc;
      $h->{dtot} = 0 if(!$h->{dtotcnt});
      $h->{dmx}  = $dtcalc if ($h->{dmx} < $dtcalc);
    }
    ${$ptovrhd} = ($tstart-$tcall-$tstop)+gettimeofday() if (defined($ptovrhd));
  }
  return @ret;
}


#####################################
sub apptime_timedstop($) {
  if ($timedRun) {
    $measStopTm    = gettimeofday();
    $apptimeStatus = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy");
  }
}
#####################################
sub apptime_dummy($) {
  InternalTimer(gettimeofday()+rand(120),"apptime_dummy","apptime_dummy",0) if ($apptimeStatus && $timedRun);
  return;
}


#####################################
sub apptime_CommandDispTiming($$@) {
  my ($cl,$param) = @_;
  my ($sFld,$top,$filter) = split" ",$param;
  $sFld = "max" if (!$sFld);
  return "Use apptime ".$cmds{"apptime"}{Hlp} if ($sFld eq "help");
  $top = "top" if (!$top);
  my %fld = (name=>0,function=>1,max=>2,count=>3,total=>4,average=>5,maxDly=>6,avgDly=>7,nhours=>97,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
    $apptimeStatus  = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
  }
  elsif ($sFld eq "cont"){# further collection of data
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 0;
  }
  elsif ($sFld eq "clear"){# clear
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
    $measStartTm    = gettimeofday();
  }
  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;

      $totTmrHandleCalc = 0;
      $minTmrHandleCalc = 1000000;
      $maxTmrHandleCalc = 0;

      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;

      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;

      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    elsif ($sFld =~ m/(pause|cont)/){
    }
    elsif ($sFld eq "nhours"){
      delete $defs{$d}{helper}{bm};
      $totDly         = 0;
      $totCnt         = 0;
      $maxIntatLen    = 0;
      $maxIntatDone   = 0;

      $totTmrHandleCalc = 0;
      $minTmrHandleCalc = 1000000;
      $maxTmrHandleCalc = 0;

      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;

      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;

      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    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
                    )];
      }
    }
  }

  if ($sFld eq "nhours"){# further collection of data, clear also
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 1;
    $top = 2/60 if ($top eq "top");
    my $now = gettimeofday();
    InternalTimer($now+3600*$top,"apptime_timedstop","apptime_timedstop",0);
    $measStartTm    = $now;
    $measStopTm     = $measStartTm;
    if (defined($filter) && $filter =~ /^\d+$/) {
      $filter = int($filter);
      $filter = 1 if ($filter < 1);
      for (my $i=1; $i <= $filter; $i++) {
        InternalTimer($now+rand($i*300/$filter),"apptime_dummy","apptime_dummy",0);
      }
    }
  }

  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; totAvgDly: %0.1fus;  lovrhd: %0.1fus;  tot-meas-time: %0.1fs\n",
                     $IntatLen,$maxIntatLen,$maxIntatDone,($totCnt?$totDly/$totCnt*1000000:-1),$lovrhd*1000000,($timedRun?($apptimeStatus?(gettimeofday()-$measStartTm):($measStopTm-$measStartTm)):(gettimeofday()-$measStartTm)));
  $ret .= sprintf("min-tmrHandlingTm: %8.1fus; avg-tmrHandlingTm: %8.1fus; max-tmrHandlingTm: %10.1fus;  tot-tmrHandlingTm: %0.1fs\n",
                  ($minTmrHandleTm<$maxTmrHandleTm?$minTmrHandleTm*1000000:-1),($TmrHandleTmCnt?$totTmrHandleTm/$TmrHandleTmCnt*1000000:-1),($minTmrHandleTm<$maxTmrHandleTm?$maxTmrHandleTm*1000000:-1),$totTmrHandleTm);
  $ret .= sprintf("min-tmrHandleCalc: %8.1fus; avg-tmrHandleCalc: %8.1fus; max-tmrHandleCalc: %10.1fus;  tot-tmrHandleCalc: %0.1fs\n",
                  ($minTmrHandleCalc<$maxTmrHandleCalc?$minTmrHandleCalc*1000000:-1),($TmrHandleTmCnt?$totTmrHandleCalc/$TmrHandleTmCnt*1000000:-1),($minTmrHandleCalc<$maxTmrHandleCalc?$maxTmrHandleCalc*1000000:-1),$totTmrHandleCalc);
  $ret .= sprintf("min-timerInsertTm: %8.1fus; avg-timerInsertTm: %8.1fus; max-timerInsertTm: %10.1fus;  tot-timerInsertTm: %0.1fs\n",
                  ($minIntatSortTm<$maxIntatSortTm?$minIntatSortTm*1000000:-1),($IntatSortTmCnt?$totIntatSortTm/$IntatSortTmCnt*1000000:-1),($minIntatSortTm<$maxIntatSortTm?$maxIntatSortTm*1000000:-1),$totIntatSortTm);
  $ret .= sprintf("min-timerRemoveTm: %8.1fus; avg-timerRemoveTm: %8.1fus; max-timerRemoveTm: %10.1fus;  tot-timerRemoveTm: %0.1fs\n",
                  ($minRemoveTm<$maxRemoveTm?$minRemoveTm*1000000:-1),($RemoveTmCnt?$totRemoveTm/$RemoveTmCnt*1000000:-1),($minRemoveTm<$maxRemoveTm?$maxRemoveTm*1000000:-1),$totRemoveTm);
  $ret .= ($apptimeStatus ? "" : ($timedRun?"--- apptime timed run result ---\n":"------ apptime PAUSED data collection ----------\n"))
            .sprintf("\nTimes in ms:\n %-40s %-35s %9s %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 %9.2f %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 nhours [hours] [numberofdummytimers]</code></dt>
          <dd>
            <p>
                Clears data and starts a collection of data for [hours] hours.
                Without arguments it collects for 2 minutes.
                With [numberofdummytimers] the timer queue can be filled with randomly executed dummy timers.
            </p>
          </dd>
      <dt><code><kbd>apptime cont</code></dt>
          <dd>
            <p>
                Continue data collection after pause.
            </p>
          </dd>
      <dt><code><kbd>apptime [count|function|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


weiter im nächsten Beitrag...

und zum neuen Arraybasierten Code:
################################################################
# 98_apptime:application timing
# $Id: 98_apptime.pm 14087f 2018-01-26 00:00:00Z 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($intAtA);           # Internal at timer hash, global for benchmark, new Version
#use vars qw(%intAt);           # Internal at timer, global for benchmark, old Version
#use vars qw($intAtCnt);        # counter for Internal at timer
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".
                          " or apptime <pause|cont>".
                          " or apptime <nhours> [hours] [numberofdummytimers]";
}

my $IntatLen       = 0;
my $maxIntatLen    = 0;
my $maxIntatDone   = 0;

my $totTmrHandleCalc = 0;
my $minTmrHandleCalc = 1000000;
my $maxTmrHandleCalc = 0;

my $totTmrHandleTm = 0;
my $minTmrHandleTm = 1000000;
my $maxTmrHandleTm = 0;
my $TmrHandleTmCnt = 0;

my $totIntatSortTm = 0;
my $minIntatSortTm = 1000000;
my $maxIntatSortTm = 0;
my $IntatSortTmCnt = 0;

my $totRemoveTm    = 0;
my $minRemoveTm    = 1000000;
my $maxRemoveTm    = 0;
my $RemoveTmCnt    = 0;

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

my $measStartTm    = gettimeofday();
my $timedRun       = 0;
my $measStopTm     = $measStartTm;

use constant DEBUG_OUTPUT_INTATA => 0;

use constant MinCoverWait => 0.0002474; # 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 $lovrhd = 0;
my $appcalctm = 0;

# @{$intAtA}
sub
HandleTimeout()
{
  return undef if(!$nextat);
 
  my $now = gettimeofday();
  my $dtnext = $nextat-$now;
  if($dtnext > 0) { # Timer to handle?
    $selectTimestamp = $now;
    return $dtnext;
  }

  if ($apptimeStatus){
    $IntatLen = defined($intAtA)?int(@{$intAtA}):0;
    $maxIntatLen = $IntatLen if ($maxIntatLen < $IntatLen);
  }

  my $tovrhd = 0;
  my $nd = 0;
  $appcalctm = 0;

  my $handleStart = gettimeofday();

  my ($tim,$fn);
  $nextat = 0;
  while (defined($intAtA) and @{$intAtA}) {
    $tim = $intAtA->[0]->{TRIGGERTIME};
    $fn = $intAtA->[0]->{FN};
    if(!defined($fn) || !defined($tim)) { # clean up bad entries
      shift @{$intAtA};
      next;
    }
#    if ($tim > $now + MinCoverWait) { # time to handle Timer for time of e.g. one character at 38400 at least
    if ($tim > $now) {
      $nextat = $tim; # execution time not reached yet
      last;
    }

    apptime_getTiming("global", "tmr-", $tim>1?$tim:($handleStart+$tovrhd), \$lovrhd, \$appcalctm, $fn, shift(@{$intAtA})->{ARG}); $tovrhd += $lovrhd; $nd++; # this can delete a timer and can add a timer not covered by the current loops TRIGGERTIME sorted list

    $now = gettimeofday(); # reduce delay related to execution time of previous timers
  }

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

    apptime_getTiming("global", "nice-", $handleStart+$tovrhd, \$lovrhd, \$appcalctm, $entry->{fn}, $entry->{arg}); $tovrhd += $lovrhd;

    $nextat = 1 if(%prioQueues);
  }

  if(!$nextat) {
    $selectTimestamp = $now;

    if ($apptimeStatus){
      $handleStart = gettimeofday() - $handleStart - $tovrhd;
      $totTmrHandleTm += $handleStart;
      $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
      $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
      $TmrHandleTmCnt++;
      $handleStart -= $appcalctm;
      $totTmrHandleCalc += $handleStart;
      $minTmrHandleCalc = $handleStart if ($minTmrHandleCalc > $handleStart);
      $maxTmrHandleCalc = $handleStart if ($maxTmrHandleCalc < $handleStart);

      $maxIntatDone = $nd if ($maxIntatDone < $nd);
    }
    return undef;
  }

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

  if ($apptimeStatus){
    $handleStart = $now - $handleStart - $tovrhd;
    $totTmrHandleTm += $handleStart;
    $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
    $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
    $TmrHandleTmCnt++;
    $handleStart -= $appcalctm;
    $totTmrHandleCalc += $handleStart;
    $minTmrHandleCalc = $handleStart if ($minTmrHandleCalc > $handleStart);
    $maxTmrHandleCalc = $handleStart if ($maxTmrHandleCalc < $handleStart);

    $maxIntatDone = $nd if ($maxIntatDone < $nd);
  }
 
  $dtnext = $nextat-$now;
  return ($dtnext > 0) ? $dtnext : 0; # wait until next Timer needs to be handled
}

#####################################
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;
  }

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }

  ### O(log(n)) add ###################
  my $i = defined($intAtA)?int(@{$intAtA}):0;

  if ($i) {
    my $t;
    my $ui = $i - 1;
    my $li = 0;
    while ($li <= $ui) {
      $i = int(($ui-$li)/2)+$li;
      $t = $intAtA->[$i]->{TRIGGERTIME};
      if ($tim >= $t) { # in upper half
        $li = ++$i;
      }
      else {            # in lower half
        $ui = $i-1;
      }
    }
    splice @{$intAtA}, $i, 0, { #insert or append new entry
                               TRIGGERTIME => $tim,
                               FN => $fn,
                               ARG => $arg
                              };
  } else { # array creation on first add
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
  }
  ####

  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );

  if (DEBUG_OUTPUT_INTATA) {
    for ($i=0; $i < (int(@{$intAtA})-1); $i++) {
      next if ($intAtA->[$i]->{TRIGGERTIME} <= $intAtA->[$i+1]->{TRIGGERTIME});
      print "Error in $intAtA inserting $tim $fn\n";
      use Data::Dumper;
      print Data::Dumper->new([$intAtA],[qw($intAtA)])->Indent(1)->Quotekeys(1)->Dump;
      my $h = $intAtA->[$i]->{TRIGGERTIME};
      $intAtA->[$i]->{TRIGGERTIME} = $intAtA->[$i+1]->{TRIGGERTIME};
      $intAtA->[$i+1]->{TRIGGERTIME} = $h;
    }
  }

  if ($apptimeStatus){
    my $IntatSortTm = gettimeofday() - $now;
    $totIntatSortTm += $IntatSortTm;
    $minIntatSortTm = $IntatSortTm if ($minIntatSortTm > $IntatSortTm);
    $maxIntatSortTm = $IntatSortTm if ($maxIntatSortTm < $IntatSortTm);
    $IntatSortTmCnt++;
  }

  return;
}

#####################################
sub
RemoveInternalTimer($;$)
{
  return if (!defined($intAtA) || !@{$intAtA});

  my ($arg, $fn) = @_;

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }
 
  if ($fn) {
    if (defined($arg)) {
      my ($ia, $if);
      my $i = int(@{$intAtA});
      while($i--) {
        ($ia, $if) = ($intAtA->[$i]->{ARG}, $intAtA->[$i]->{FN});
        splice @{$intAtA}, $i, 1 if(   defined($ia) && ($ia eq $arg)
                                    && defined($if) && ($if eq $fn) );
      }
    }
    else {
      my $if;
      my $i = int(@{$intAtA});
      while($i--) {
        $if = $intAtA->[$i]->{FN};
        splice @{$intAtA}, $i, 1 if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
      }
    }
  }
  else {
    return if (!defined($arg));
    my $ia;
    my $i = int(@{$intAtA});
    while($i--) {
      $ia = $intAtA->[$i]->{ARG};
      splice @{$intAtA}, $i, 1 if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
    }
  }

  if ($apptimeStatus){
    my $RemoveTm = gettimeofday() - $now;
    $totRemoveTm += $RemoveTm;
    $minRemoveTm = $RemoveTm if ($minRemoveTm > $RemoveTm);
    $maxRemoveTm = $RemoveTm if ($maxRemoveTm < $RemoveTm);
    $RemoveTmCnt++;
  }
}

#####################################
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, "", 0, undef, undef, $fn, @_);

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

#####################################
# Alternative to CallFn with optional functions in $defs, Forum #64741
sub
CallInstanceFn(@)
{
  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;
  }
  my $fn = $defs{$d}{$n} ? $defs{$d}{$n} : $defs{$d}{".$n"};
  return CallFn($d, $n, @_) if(!$fn);

  my @ret = apptime_getTiming($d, "", 0, undef, undef, $fn, @_);

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

#####################################
sub apptime_getTiming($$$$$$@) {
  my ($e,$calltype,$tim,$ptovrhd,$ptfcalc,$fn,@arg) = @_;

  my $tcall;
  my $tstart;
  my $h;
  if ($apptimeStatus){
    $tcall = gettimeofday(); # time of call
    my $shArg;
    if ($calltype ne "") {
      $shArg = (defined($arg[0])?$arg[0]:"");
      if (ref($shArg) eq "HASH") {
        if (!defined($shArg->{NAME})) {
          $shArg = "HASH_unnamed";
        }
        else {
          $shArg = $shArg->{NAME};
        }
      }
      ($shArg,undef) = split(/:|;/,$shArg,2); # for special long args with delim ;
    }
    else {
      $shArg = "";
    }
    my $tfnm;
    if (ref($fn) ne "") {
      my $cv = svref_2object($fn);
      $tfnm = $cv->GV->NAME;
    }
    else {
      $tfnm = $fn;
    }

    my $fnName = $calltype.$tfnm;
    $fnName .= ";".$shArg if (($calltype ne "") && ($shArg ne ""));
    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}++;
    }
    $tstart = gettimeofday(); # time of execution start call
  }

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

  if ($apptimeStatus && defined($h)){
    my $tstop = gettimeofday();
    my $dtcalc = $tstop-$tstart; # execution time
    ${$ptfcalc} += $dtcalc if (defined($ptfcalc));
    if ($dtcalc && $h->{max} < $dtcalc){
      $h->{max} = $dtcalc;
      $h->{mAr} = @arg?\@arg:undef;
      $h->{mTS}= strftime("%d.%m. %H:%M:%S", localtime($tstart));
    }
    $h->{tot} += $dtcalc;
    $h->{tot} = 0 if(!$h->{cnt});
    if ($tim > 1){ # call delay for timers with time set
      $totCnt++;
      $dtcalc = $tcall-$tim;
      $totDly += $dtcalc;
      $totDly = 0 if(!$totCnt);
      $h->{dtotcnt}++;
      $h->{dtot} += $dtcalc;
      $h->{dtot} = 0 if(!$h->{dtotcnt});
      $h->{dmx}  = $dtcalc if ($h->{dmx} < $dtcalc);
    }
    ${$ptovrhd} = ($tstart-$tcall-$tstop)+gettimeofday() if (defined($ptovrhd));
  }
  return @ret;
}


#####################################
sub apptime_timedstop($) {
  if ($timedRun) {
    $measStopTm    = gettimeofday();
    $apptimeStatus = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy");
  }
}
#####################################
sub apptime_dummy($) {
  InternalTimer(gettimeofday()+rand(120),"apptime_dummy","apptime_dummy",0) if ($apptimeStatus && $timedRun);
  return;
}


#####################################
sub apptime_CommandDispTiming($$@) {
  my ($cl,$param) = @_;
  my ($sFld,$top,$filter) = split" ",$param;
  $sFld = "max" if (!$sFld);
  return "Use apptime ".$cmds{"apptime"}{Hlp} if ($sFld eq "help");
  $top = "top" if (!$top);
  my %fld = (name=>0,function=>1,max=>2,count=>3,total=>4,average=>5,maxDly=>6,avgDly=>7,nhours=>97,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
    $apptimeStatus  = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
  }
  elsif ($sFld eq "cont"){# further collection of data
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 0;
  }
  elsif ($sFld eq "clear"){# clear
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
    $measStartTm    = gettimeofday();
  }
  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;

      $totTmrHandleCalc = 0;
      $minTmrHandleCalc = 1000000;
      $maxTmrHandleCalc = 0;

      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;

      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;

      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    elsif ($sFld =~ m/(pause|cont)/){
    }
    elsif ($sFld eq "nhours"){
      delete $defs{$d}{helper}{bm};
      $totDly         = 0;
      $totCnt         = 0;
      $maxIntatLen    = 0;
      $maxIntatDone   = 0;

      $totTmrHandleCalc = 0;
      $minTmrHandleCalc = 1000000;
      $maxTmrHandleCalc = 0;
     
      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;
     
      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;
     
      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    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
                    )];
      }
    }
  }

  if ($sFld eq "nhours"){# further collection of data, clear also
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 1;
    $top = 2/60 if ($top eq "top");
    my $now = gettimeofday();
    InternalTimer($now+3600*$top,"apptime_timedstop","apptime_timedstop",0);
    $measStartTm    = $now;
    $measStopTm     = $measStartTm;
    if (defined($filter) && $filter =~ /^\d+$/) {
      $filter = int($filter);
      $filter = 1 if ($filter < 1);
      for (my $i=1; $i <= $filter; $i++) {
        InternalTimer($now+rand($i*300/$filter),"apptime_dummy","apptime_dummy",0);
      }
    }
  }

  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; totAvgDly: %0.1fus;  lovrhd: %0.1fus;  tot-meas-time: %0.1fs\n",
                     $IntatLen,$maxIntatLen,$maxIntatDone,($totCnt?$totDly/$totCnt*1000000:-1),$lovrhd*1000000,($timedRun?($apptimeStatus?(gettimeofday()-$measStartTm):($measStopTm-$measStartTm)):(gettimeofday()-$measStartTm)));
  $ret .= sprintf("min-tmrHandlingTm: %8.1fus; avg-tmrHandlingTm: %8.1fus; max-tmrHandlingTm: %10.1fus;  tot-tmrHandlingTm: %0.1fs\n",
                  ($minTmrHandleTm<$maxTmrHandleTm?$minTmrHandleTm*1000000:-1),($TmrHandleTmCnt?$totTmrHandleTm/$TmrHandleTmCnt*1000000:-1),($minTmrHandleTm<$maxTmrHandleTm?$maxTmrHandleTm*1000000:-1),$totTmrHandleTm);
  $ret .= sprintf("min-tmrHandleCalc: %8.1fus; avg-tmrHandleCalc: %8.1fus; max-tmrHandleCalc: %10.1fus;  tot-tmrHandleCalc: %0.1fs\n",
                  ($minTmrHandleCalc<$maxTmrHandleCalc?$minTmrHandleCalc*1000000:-1),($TmrHandleTmCnt?$totTmrHandleCalc/$TmrHandleTmCnt*1000000:-1),($minTmrHandleCalc<$maxTmrHandleCalc?$maxTmrHandleCalc*1000000:-1),$totTmrHandleCalc);
  $ret .= sprintf("min-timerInsertTm: %8.1fus; avg-timerInsertTm: %8.1fus; max-timerInsertTm: %10.1fus;  tot-timerInsertTm: %0.1fs\n",
                  ($minIntatSortTm<$maxIntatSortTm?$minIntatSortTm*1000000:-1),($IntatSortTmCnt?$totIntatSortTm/$IntatSortTmCnt*1000000:-1),($minIntatSortTm<$maxIntatSortTm?$maxIntatSortTm*1000000:-1),$totIntatSortTm);
  $ret .= sprintf("min-timerRemoveTm: %8.1fus; avg-timerRemoveTm: %8.1fus; max-timerRemoveTm: %10.1fus;  tot-timerRemoveTm: %0.1fs\n",
                  ($minRemoveTm<$maxRemoveTm?$minRemoveTm*1000000:-1),($RemoveTmCnt?$totRemoveTm/$RemoveTmCnt*1000000:-1),($minRemoveTm<$maxRemoveTm?$maxRemoveTm*1000000:-1),$totRemoveTm);
  $ret .= ($apptimeStatus ? "" : ($timedRun?"--- apptime timed run result ---\n":"------ apptime PAUSED data collection ----------\n"))
            .sprintf("\nTimes in ms:\n %-40s %-35s %9s %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 %9.2f %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 nhours [hours] [numberofdummytimers]</code></dt>
          <dd>
            <p>
                Clears data and starts a collection of data for [hours] hours.
                Without arguments it collects for 2 minutes.
                With [numberofdummytimers] the timer queue can be filled with randomly executed dummy timers.
            </p>
          </dd>
      <dt><code><kbd>apptime cont</code></dt>
          <dd>
            <p>
                Continue data collection after pause.
            </p>
          </dd>
      <dt><code><kbd>apptime [count|function|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


Die Ausführungszeit für die Ausführung der eigentlichen Timerroutine wird von der Handlingszeit mit Timerroutine abgezogen und das ergibt die tmrHandleCalc Zeiten.
Dass prioQueues auch mit eingehen, hast Du beim Code Studium sicherlich schon gesehen. Ich hoffe, dass stört Dich nicht sehr. Ansonsten kann ich die auch noch raus rechnen.

Die Testläufe dauern leider...

Gruß, Ansgar.

PS: Die Beitrags-Vorschau zeigt immer den ganzen Beitragstext, auch wenn er beim Speichern dann abgeschnitten wird. Wäre schön, aber jetzt nicht immens wichtig, wenn die Vorschau das Limit ebenfalls berücksichtigen würde.

Zitat von: noansi am 26 Januar 2018, 00:19:23
Vom Verhalten her ergibt sich bei HandleTimer auch ein kleiner Unterschied, falls ein neuer Timer in einer Timerroutine mit Ausführungszeit 1 oder gettimeofday erzeugt wird. Dann wird er auch gleich im gleichen HandleTimeraufruf noch ausgeführt, während er in Deinem bisherigen Code erst im nächsten Aufruf von HandleTimer zur Ausführung kommt.

Falls Rudi doch übernehmen sollte: hier würde ich Kompatibilität zu bestehenden Umsetzung sehr schätzen. (Timer wird erst im nächsten Durchlauf ausgeführt). Diese Eigenschaft verwende ich tatsächlich produktiv, andere eventuell auch.

Hallo Jörg, hallo Rudolf,

ZitatFalls Rudi doch übernehmen sollte: hier würde ich Kompatibilität zu bestehenden Umsetzung sehr schätzen. (Timer wird erst im nächsten Durchlauf ausgeführt). Diese Eigenschaft verwende ich tatsächlich produktiv, andere eventuell auch.

Guter Hinweis (wofür nutzt Du sie?).

Lässt sich im Prinzip auch relativ leicht umsetzen indem erst alle abgelaufenen Timer in ein globales "Execute"-Array verschoben werden und dieses Array dann in einer Schleife mit shift abgearbeitet wird, statt die Timer direkt mit shift abzuarbeiten. Kostet wohl etwas mehr Zeit, aber wohl nicht dramatisch oder wird eventuell durch die Codelokalität wieder kompensiert.
RemoveInternalTimer müßte dieses globale "Execute"-Array ebenfalls durchsuchen und ggf. darin zu löschende Timer löschen, da Timerroutinen auch RemoveInternalTimer nutzen. Würde wohl nur unwesentlich mehr Zeit benötigen.

Gruß, Ansgar.

Zitat von: noansi am 26 Januar 2018, 22:26:49
wofür nutzt Du sie?

Ich missbrauche sie :)

Indem ich timer auf 0 setze habe ich einen hack um Funktionen aufzurufen nachdem die notify loop abgearbeitet und bevor etwas in der select oder in anderen timern passieren kann. Wenn das nicht mehr geht müsste ich einen anderen hack dafür suchen. Um der Frage vorzubeugen: ja man braucht das, es ist ein funktionell zentraler Punkt.

Zitatich werde fuer fhem.pl kein Code uebernehmen

Gut.

Ich denke, jetzt sollte langsam mal Schluss sein. Die Diskussion dreht sich im Kreis, missionarischer Eifer ist in einer Open Source Community nicht angebracht.

LG

pah

Hallo Jörg,

ZitatIndem ich timer auf 0 setze habe ich einen hack um Funktionen aufzurufen nachdem die notify loop abgearbeitet und bevor ... oder in anderen timern passieren kann.

Welche Module nutzen das so?
Jetzt schon dünnes Eis. ;)
Ein "Internaltimer(0.5, ...)" würde sicher schon vorher ausgeführt, da in InternalTimer aus Deiner 0 oder undef eine 1 wird. Und es gibt keinen Hinweis im Code, das ein Wert zwischen 0 und 1 verboten ist.
Andere Module dürfen auch undef, 0 und 1 verwenden und damit schon vor Deinem Timer landen. Das wäre wohl eine kleine Diskussion mit Rudolf wert, wenn der Einfluss anderer Module eine Problem für Deinen Hack darstellen kann.

Ich bau Deinen Kompatibilitätswunsch mal bei mir ein.

@Peter:

ZitatIch denke, jetzt sollte langsam mal Schluss sein. Die Diskussion dreht sich im Kreis, missionarischer Eifer ist in einer Open Source Community nicht angebracht.

HM ist auf eine (empirisch begründete) IO-Antwortzeit oder -Fortsetzungszeit von 100 bis etwa 130ms (je nach device) angewiesen, damit das Gegenüber nicht wieder einschläft oder abbricht.
Mit Missionieren hat es nichts zu tun, zu versuchen, die Wahrscheinlichkeit für eine durchgehend funktionierende Kommunikation zu erhöhen. TimerHandling ist diesbezüglich nur eine Baustelle.
Rudolf hat nicht ausgeschlossen, den Code Gedanken sinngemäß nochmal neu zu programmieren, sofern Argumente ihn überzeugen.
Module mit vielen laufenden Timern werden mit nLog(n) zum Argument.
Der Code ist meinerseits auch als Angebot zu verstehen, dass Rudolf (ebenso wie andere User) nutzen kann. Ausnahmsweise ist er auch mal recht einfach in verschiedenen fhem.pl Versionen einzubauen.

Immerhin hat die Diskussion schon dazu geführt, dass die von Rudolf angebotene Timer API fast überall in den Modulen auch komplett genutzt wird.

Gruß, Ansgar.

Hallo Zusammen,

hier noch der geänderte apptime Code mit der von Jörg gewünschten Kompatibilität:
################################################################
# 98_apptime:application timing
# $Id: 98_apptime.pm 14087g 2018-01-27 00:00:00Z 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($nextat);     # next timer timeout, fhem.pl
use vars qw($intAtA);     # Internal at timer hash, global for benchmark, new Version
use vars qw($intAtAExec); # Internal at timer exec hash, global for benchmark, new Version

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".
                          " or apptime <pause|cont>".
                          " or apptime <nhours> [hours] [numberofdummytimers]";
}

my $IntatLen       = 0;
my $maxIntatLen    = 0;
my $maxIntatDone   = 0;

my $totTmrHandleCalc = 0;
my $minTmrHandleCalc = 1000000;
my $maxTmrHandleCalc = 0;

my $totTmrHandleTm = 0;
my $minTmrHandleTm = 1000000;
my $maxTmrHandleTm = 0;
my $TmrHandleTmCnt = 0;

my $totIntatSortTm = 0;
my $minIntatSortTm = 1000000;
my $maxIntatSortTm = 0;
my $IntatSortTmCnt = 0;

my $totRemoveTm    = 0;
my $minRemoveTm    = 1000000;
my $maxRemoveTm    = 0;
my $RemoveTmCnt    = 0;

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

my $measStartTm    = gettimeofday();
my $timedRun       = 0;
my $measStopTm     = $measStartTm;

my $lovrhd = 0;
my $appcalctm = 0;

use constant DEBUG_OUTPUT_INTATA => 0;

use constant MinCoverWait => 0; #0.0002474; # 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

# @{$intAtA}
sub
HandleTimeout()
{
  return undef if(!$nextat || !defined($intAtA));

  my $now = gettimeofday();
  my $tim = $nextat-$now;
  if($tim > 0) { # Timer to handle?
    $selectTimestamp = $now;
    return $tim;
  }

  my $n = int(@{$intAtA});

  if ($apptimeStatus){
    $IntatLen = $n;
    $maxIntatLen = $IntatLen if ($maxIntatLen < $IntatLen);
  }
  my $tovrhd = 0;
  my $nd = 0;
  $appcalctm = 0;
  my $handleStart = gettimeofday();

  my $i = -1; # check timers timed out for execution
  while (++$i < $n) {
    $tim = $intAtA->[$i]->{TRIGGERTIME};
    if (MinCoverWait) {
      last if (defined($tim) && ($tim > ($now + MinCoverWait))); # no more timer timeout for execution
    }
    else {
      last if (defined($tim) && ($tim > $now)); # no more timer timeout for execution
    }
  }
  if ($i) {
    @{$intAtAExec} = splice(@{$intAtA}, 0, $i); # see https://forum.fhem.de/index.php/topic,81365.msg756314.html#msg756314
  }

  my $fn; # execute timers
  while (defined($intAtAExec) && @{$intAtAExec}) {
    $tim = $intAtAExec->[0]->{TRIGGERTIME};
    $fn = $intAtAExec->[0]->{FN};
    if (!defined($fn) || !defined($tim)) { # clean up bad entries
      shift @{$intAtAExec};
      next;
    }

    apptime_getTiming("global", "tmr-", $tim>1?$tim:($handleStart+$tovrhd), \$lovrhd, \$appcalctm, $fn, shift(@{$intAtAExec})->{ARG}); $tovrhd += $lovrhd; $nd++; # this can add a timer not covered by the current loops TRIGGERTIME sorted list, but wanted by https://forum.fhem.de/index.php/topic,81365.msg756314.html#msg756314

  }

  $nextat = 0; # set next timer timeout
  while (defined($intAtA->[0])) {
    $tim = $intAtA->[0]->{TRIGGERTIME};
    if (defined($tim)) {
      $nextat = $tim; # time of execution for next timer
      last;
    }
    shift @{$intAtA}; # clean up bad entries
  }

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

    apptime_getTiming("global", "nice-", $handleStart+$tovrhd, \$lovrhd, \$appcalctm, $entry->{fn}, $entry->{arg}); $tovrhd += $lovrhd;

    $nextat = 1 if(%prioQueues);
  }

  if(!$nextat) {
    $selectTimestamp = $now;

    if ($apptimeStatus){
      $handleStart = gettimeofday() - $handleStart - $tovrhd;
      $totTmrHandleTm += $handleStart;
      $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
      $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
      $TmrHandleTmCnt++;
      $handleStart -= $appcalctm;
      $totTmrHandleCalc += $handleStart;
      $minTmrHandleCalc = $handleStart if ($minTmrHandleCalc > $handleStart);
      $maxTmrHandleCalc = $handleStart if ($maxTmrHandleCalc < $handleStart);

      $maxIntatDone = $nd if ($maxIntatDone < $nd);
    }
    return undef;
  }

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

  if ($apptimeStatus){
    $handleStart = $now - $handleStart - $tovrhd;
    $totTmrHandleTm += $handleStart;
    $minTmrHandleTm = $handleStart if ($minTmrHandleTm > $handleStart);
    $maxTmrHandleTm = $handleStart if ($maxTmrHandleTm < $handleStart);
    $TmrHandleTmCnt++;
    $handleStart -= $appcalctm;
    $totTmrHandleCalc += $handleStart;
    $minTmrHandleCalc = $handleStart if ($minTmrHandleCalc > $handleStart);
    $maxTmrHandleCalc = $handleStart if ($maxTmrHandleCalc < $handleStart);

    $maxIntatDone = $nd if ($maxIntatDone < $nd);
  }

  $tim = $nextat-$now;
  return ($tim > 0) ? $tim : 0; # wait until next Timer needs to be handled
}

#####################################
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;
  }

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }

  ### O(log(n)) add ###################
  my $i = defined($intAtA)?int(@{$intAtA}):0;

  if ($i) {
    my $t;
    my $ui = $i - 1;
    my $li = 0;
    while ($li <= $ui) {
      $i = int(($ui-$li)/2)+$li;
      $t = $intAtA->[$i]->{TRIGGERTIME};
      if ($tim >= $t) { # in upper half
        $li = ++$i;
      }
      else {            # in lower half
        $ui = $i-1;
      }
    }
    splice(@{$intAtA}, $i, 0, { #insert or append new entry
                               TRIGGERTIME => $tim,
                               FN => $fn,
                               ARG => $arg
                              });
  } else { # array creation on first add
    $intAtA->[0] = {
                    TRIGGERTIME => $tim,
                    FN => $fn,
                    ARG => $arg
                   };
  }
  ####

  $nextat = $tim if(   !$nextat
                    || ($nextat > $tim) );

  if (DEBUG_OUTPUT_INTATA) {
    for ($i=0; $i < (int(@{$intAtA})-1); $i++) {
      next if ($intAtA->[$i]->{TRIGGERTIME} <= $intAtA->[$i+1]->{TRIGGERTIME});
      print "Error in $intAtA inserting $tim $fn\n";
      use Data::Dumper;
      print Data::Dumper->new([$intAtA],[qw($intAtA)])->Indent(1)->Quotekeys(1)->Dump;
      my $h = $intAtA->[$i]->{TRIGGERTIME};
      $intAtA->[$i]->{TRIGGERTIME} = $intAtA->[$i+1]->{TRIGGERTIME};
      $intAtA->[$i+1]->{TRIGGERTIME} = $h;
    }
  }

  if ($apptimeStatus){
    my $IntatSortTm = gettimeofday() - $now;
    $totIntatSortTm += $IntatSortTm;
    $minIntatSortTm = $IntatSortTm if ($minIntatSortTm > $IntatSortTm);
    $maxIntatSortTm = $IntatSortTm if ($maxIntatSortTm < $IntatSortTm);
    $IntatSortTmCnt++;
  }

  return;
}

#####################################
sub
RemoveInternalTimer($;$)
{
  my ($arg, $fn) = @_;

  my $now;
  if ($apptimeStatus){
    $now = gettimeofday();
  }
 
  if ($fn) { # keep constant results out of the loop
    if (defined($arg)) { # keep constant results out of the loop
      my ($ia, $if, $i);
      if (defined($intAtA) && @{$intAtA}) {
        $i = int(@{$intAtA});
        while($i--) {
          ($ia, $if) = ($intAtA->[$i]->{ARG}, $intAtA->[$i]->{FN});
          splice(@{$intAtA}, $i, 1) if(   defined($ia) && ($ia eq $arg)
                                       && defined($if) && ($if eq $fn) );
        }
      }
      if (defined($intAtAExec) && @{$intAtAExec}) { # remove also from timers ready for execution
        $i = int(@{$intAtAExec});
        while($i--) {
          ($ia, $if) = ($intAtAExec->[$i]->{ARG}, $intAtAExec->[$i]->{FN});
          splice(@{$intAtAExec}, $i, 1) if(   defined($ia) && ($ia eq $arg)
                                           && defined($if) && ($if eq $fn) );
        }
      }
    }
    else { # keep constant results out of the loop
      my ($if, $i);
      if (defined($intAtA) && @{$intAtA}) {
        $i = int(@{$intAtA});
        while($i--) {
          $if = $intAtA->[$i]->{FN};
          splice(@{$intAtA}, $i, 1) if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
        }
      }
      if (defined($intAtAExec) && @{$intAtAExec}) { # remove also from timers ready for execution
        $i = int(@{$intAtAExec});
        while($i--) {
          $if = $intAtAExec->[$i]->{FN};
          splice(@{$intAtAExec}, $i, 1) if(defined($if) && ($if eq $fn)); #remove any timer with $fn function call
        }
      }
    }
  }
  else {
    return if (!defined($arg));
    # keep constant results out of the loop
    my ($ia, $i);
    if (defined($intAtA) && @{$intAtA}) {
      $i = int(@{$intAtA});
      while($i--) {
        $ia = $intAtA->[$i]->{ARG};
        splice(@{$intAtA}, $i, 1) if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
      }
    }
    if (defined($intAtAExec) && @{$intAtAExec}) { # remove also from timers ready for execution
      $i = int(@{$intAtAExec});
      while($i--) {
        $ia = $intAtAExec->[$i]->{ARG};
        splice(@{$intAtAExec}, $i, 1) if(defined($ia) && ($ia eq $arg)); #remove any timer with $arg argument
      }
    }
  }

  if ($apptimeStatus){
    my $RemoveTm = gettimeofday() - $now;
    $totRemoveTm += $RemoveTm;
    $minRemoveTm = $RemoveTm if ($minRemoveTm > $RemoveTm);
    $maxRemoveTm = $RemoveTm if ($maxRemoveTm < $RemoveTm);
    $RemoveTmCnt++;
  }
}

#####################################
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, "", 0, undef, undef, $fn, @_);

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

#####################################
# Alternative to CallFn with optional functions in $defs, Forum #64741
sub
CallInstanceFn(@)
{
  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;
  }
  my $fn = $defs{$d}{$n} ? $defs{$d}{$n} : $defs{$d}{".$n"};
  return CallFn($d, $n, @_) if(!$fn);

  my @ret = apptime_getTiming($d, "", 0, undef, undef, $fn, @_);

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

#####################################
sub apptime_getTiming($$$$$$@) {
  my ($e,$calltype,$tim,$ptovrhd,$ptfcalc,$fn,@arg) = @_;

  my $tcall;
  my $tstart;
  my $h;
  if ($apptimeStatus){
    $tcall = gettimeofday(); # time of call
    my $shArg;
    if ($calltype ne "") {
      $shArg = (defined($arg[0])?$arg[0]:"");
      if (ref($shArg) eq "HASH") {
        if (!defined($shArg->{NAME})) {
          $shArg = "HASH_unnamed";
        }
        else {
          $shArg = $shArg->{NAME};
        }
      }
      ($shArg,undef) = split(/:|;/,$shArg,2); # for special long args with delim ;
    }
    else {
      $shArg = "";
    }
    my $tfnm;
    if (ref($fn) ne "") {
      my $cv = svref_2object($fn);
      $tfnm = $cv->GV->NAME;
    }
    else {
      $tfnm = $fn;
    }

    my $fnName = $calltype.$tfnm;
    $fnName .= ";".$shArg if (($calltype ne "") && ($shArg ne ""));
    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}++;
    }
    $tstart = gettimeofday(); # time of execution start call
  }

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

  if ($apptimeStatus && defined($h)){
    my $tstop = gettimeofday();
    my $dtcalc = $tstop-$tstart; # execution time of timer/CallFn function
    ${$ptfcalc} += $dtcalc if (defined($ptfcalc));
    if ($dtcalc && $h->{max} < $dtcalc){
      $h->{max} = $dtcalc;
      $h->{mAr} = @arg?\@arg:undef;
      $h->{mTS}= strftime("%d.%m. %H:%M:%S", localtime($tstart));
    }
    $h->{tot} += $dtcalc;
    $h->{tot} = 0 if(!$h->{cnt});
    if ($tim > 1){ # call delay for timers with time set
      $totCnt++;
      $dtcalc = $tcall-$tim;
      $totDly += $dtcalc;
      $totDly = 0 if(!$totCnt);
      $h->{dtotcnt}++;
      $h->{dtot} += $dtcalc;
      $h->{dtot} = 0 if(!$h->{dtotcnt});
      $h->{dmx}  = $dtcalc if ($h->{dmx} < $dtcalc);
    }
    ${$ptovrhd} = ($tstart-$tcall-$tstop)+gettimeofday() if (defined($ptovrhd));
  }
  return @ret;
}


#####################################
sub apptime_timedstop($) {
  if ($timedRun) {
    $measStopTm    = gettimeofday();
    $apptimeStatus = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy");
  }
}
#####################################
sub apptime_dummy($) {
  InternalTimer(gettimeofday()+rand(120),"apptime_dummy","apptime_dummy",0) if ($apptimeStatus && $timedRun); # new timer to keep up timer load
  return;
}


#####################################
sub apptime_CommandDispTiming($$@) {
  my ($cl,$param) = @_;
  my ($sFld,$top,$filter) = split" ",$param;
  $sFld = "max" if (!$sFld);
  return "Use apptime ".$cmds{"apptime"}{Hlp} if ($sFld eq "help");
  $top = "top" if (!$top);
  my %fld = (name=>0,function=>1,max=>2,count=>3,total=>4,average=>5,maxDly=>6,avgDly=>7,nhours=>97,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
    $apptimeStatus  = 0;#stop collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
  }
  elsif ($sFld eq "cont"){# further collection of data
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 0;
  }
  elsif ($sFld eq "clear"){# clear
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $timedRun       = 0;
    $measStartTm    = gettimeofday();
  }
  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;

      $totTmrHandleCalc = 0;
      $minTmrHandleCalc = 1000000;
      $maxTmrHandleCalc = 0;

      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;

      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;

      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    elsif ($sFld =~ m/(pause|cont)/){
    }
    elsif ($sFld eq "nhours"){
      delete $defs{$d}{helper}{bm};
      $totDly         = 0;
      $totCnt         = 0;
      $maxIntatLen    = 0;
      $maxIntatDone   = 0;

      $totTmrHandleCalc = 0;
      $minTmrHandleCalc = 1000000;
      $maxTmrHandleCalc = 0;
     
      $totTmrHandleTm = 0;
      $minTmrHandleTm = 1000000;
      $maxTmrHandleTm = 0;
      $TmrHandleTmCnt = 0;
     
      $totIntatSortTm = 0;
      $minIntatSortTm = 1000000;
      $maxIntatSortTm = 0;
      $IntatSortTmCnt = 0;
     
      $totRemoveTm    = 0;
      $minRemoveTm    = 1000000;
      $maxRemoveTm    = 0;
      $RemoveTmCnt    = 0;
    }
    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
                    )];
      }
    }
  }

  if ($sFld eq "nhours"){# further collection of data, clear also
    $apptimeStatus  = 0;#pause collecting data
    RemoveInternalTimer("apptime_dummy") if ($timedRun);
    RemoveInternalTimer("apptime_timedstop") if ($timedRun);
    $apptimeStatus  = 1;#continue collecting data
    $timedRun       = 1;
    $top = 2/60 if ($top eq "top");
    my $now = gettimeofday();
    InternalTimer($now+3600*$top,"apptime_timedstop","apptime_timedstop",0);
    $measStartTm    = $now;
    $measStopTm     = $measStartTm;
    if (defined($filter) && $filter =~ /^\d+$/) {
      $filter = int($filter);
      $filter = 1 if ($filter < 1);
      for (my $i=1; $i <= $filter; $i++) {
        InternalTimer($now+rand($i*300/$filter),"apptime_dummy","apptime_dummy",0);
      }
    }
  }

  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; totAvgDly: %0.1fus;  lovrhd: %0.1fus;  tot-meas-time: %0.1fs\n",
                     $IntatLen,$maxIntatLen,$maxIntatDone,($totCnt?$totDly/$totCnt*1000000:-1),$lovrhd*1000000,($timedRun?($apptimeStatus?(gettimeofday()-$measStartTm):($measStopTm-$measStartTm)):(gettimeofday()-$measStartTm)));
  $ret .= sprintf("min-tmrHandlingTm: %8.1fus; avg-tmrHandlingTm: %8.1fus; max-tmrHandlingTm: %10.1fus;  tot-tmrHandlingTm: %0.1fs\n",
                  ($minTmrHandleTm<$maxTmrHandleTm?$minTmrHandleTm*1000000:-1),($TmrHandleTmCnt?$totTmrHandleTm/$TmrHandleTmCnt*1000000:-1),($minTmrHandleTm<$maxTmrHandleTm?$maxTmrHandleTm*1000000:-1),$totTmrHandleTm);
  $ret .= sprintf("min-tmrHandleCalc: %8.1fus; avg-tmrHandleCalc: %8.1fus; max-tmrHandleCalc: %10.1fus;  tot-tmrHandleCalc: %0.1fs\n",
                  ($minTmrHandleCalc<$maxTmrHandleCalc?$minTmrHandleCalc*1000000:-1),($TmrHandleTmCnt?$totTmrHandleCalc/$TmrHandleTmCnt*1000000:-1),($minTmrHandleCalc<$maxTmrHandleCalc?$maxTmrHandleCalc*1000000:-1),$totTmrHandleCalc);
  $ret .= sprintf("min-timerInsertTm: %8.1fus; avg-timerInsertTm: %8.1fus; max-timerInsertTm: %10.1fus;  tot-timerInsertTm: %0.1fs\n",
                  ($minIntatSortTm<$maxIntatSortTm?$minIntatSortTm*1000000:-1),($IntatSortTmCnt?$totIntatSortTm/$IntatSortTmCnt*1000000:-1),($minIntatSortTm<$maxIntatSortTm?$maxIntatSortTm*1000000:-1),$totIntatSortTm);
  $ret .= sprintf("min-timerRemoveTm: %8.1fus; avg-timerRemoveTm: %8.1fus; max-timerRemoveTm: %10.1fus;  tot-timerRemoveTm: %0.1fs\n",
                  ($minRemoveTm<$maxRemoveTm?$minRemoveTm*1000000:-1),($RemoveTmCnt?$totRemoveTm/$RemoveTmCnt*1000000:-1),($minRemoveTm<$maxRemoveTm?$maxRemoveTm*1000000:-1),$totRemoveTm);
  $ret .= ($apptimeStatus ? "" : ($timedRun?"--- apptime timed run result ---\n":"------ apptime PAUSED data collection ----------\n"))
            .sprintf("\nTimes in ms:\n %-40s %-35s %9s %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 %9.2f %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 nhours [hours] [numberofdummytimers]</code></dt>
          <dd>
            <p>
                Clears data and starts a collection of data for [hours] hours.
                Without arguments it collects for 2 minutes.
                With [numberofdummytimers] the timer queue can be filled with randomly executed dummy timers.
            </p>
          </dd>
      <dt><code><kbd>apptime cont</code></dt>
          <dd>
            <p>
                Continue data collection after pause.
            </p>
          </dd>
      <dt><code><kbd>apptime [count|function|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


Und noch die Messergebnisse damit:
active-timers: 121; max-active timers: 140; max-timer-load: 6; totAvgDly: 6154.8us;  lovrhd: 11364.0us;  tot-meas-time: 28800.0s
min-tmrHandlingTm:     98.0us; avg-tmrHandlingTm:  16836.6us; max-tmrHandlingTm:   233326.2us;  tot-tmrHandlingTm: 588.1s
min-tmrHandleCalc:     98.0us; avg-tmrHandleCalc:    506.8us; max-tmrHandleCalc:    17735.2us;  tot-tmrHandleCalc: 17.7s
min-timerInsertTm:    253.9us; avg-timerInsertTm:    448.4us; max-timerInsertTm:    20633.0us;  tot-timerInsertTm: 22.5s
min-timerRemoveTm:   1608.1us; avg-timerRemoveTm:   2541.1us; max-timerRemoveTm:    23631.1us;  tot-timerRemoveTm: 52.5s
active-timers: 621; max-active timers: 642; max-timer-load: 26; totAvgDly: 4500.7us;  lovrhd: 345.0us;  tot-meas-time: 28800.0s
min-tmrHandlingTm:     97.0us; avg-tmrHandlingTm:   3963.5us; max-tmrHandlingTm:  3046512.1us;  tot-tmrHandlingTm: 1057.4s
min-tmrHandleCalc:     97.0us; avg-tmrHandleCalc:    484.3us; max-tmrHandleCalc:    32743.9us;  tot-tmrHandleCalc: 129.2s
min-timerInsertTm:    249.1us; avg-timerInsertTm:    486.5us; max-timerInsertTm:    21290.1us;  tot-timerInsertTm: 141.7s
min-timerRemoveTm:   7215.0us; avg-timerRemoveTm:  10840.3us; max-timerRemoveTm:    57260.0us;  tot-timerRemoveTm: 231.9s

Sowie mit dem bisherigen %intAt Code:
active-timers: 120; max-active timers: 138; max-timer-load: 6; totAvgDly: 9371.2us;  lovrhd: 540.0us;  tot-meas-time: 28800.0s
min-tmrHandlingTm:   3971.1us; avg-tmrHandlingTm:  23275.2us; max-tmrHandlingTm:   337680.1us;  tot-tmrHandlingTm: 791.8s
min-tmrHandleCalc:   3971.1us; avg-tmrHandleCalc:   5554.5us; max-tmrHandleCalc:    37329.9us;  tot-tmrHandleCalc: 188.9s
min-timerInsertTm:     93.0us; avg-timerInsertTm:    192.4us; max-timerInsertTm:    23152.1us;  tot-timerInsertTm: 9.5s
min-timerRemoveTm:   3598.0us; avg-timerRemoveTm:   5165.2us; max-timerRemoveTm:    35218.0us;  tot-timerRemoveTm: 106.2s
active-timers: 623; max-active timers: 643; max-timer-load: 15; totAvgDly: 22116.0us;  lovrhd: 509.0us;  tot-meas-time: 28800.0s
min-tmrHandlingTm:  23454.0us; avg-tmrHandlingTm:  31502.1us; max-tmrHandlingTm:   643678.9us;  tot-tmrHandlingTm: 7979.3s
min-tmrHandleCalc:  23124.7us; avg-tmrHandleCalc:  27036.3us; max-tmrHandleCalc:   162222.1us;  tot-tmrHandleCalc: 6848.1s
min-timerInsertTm:     88.0us; avg-timerInsertTm:    171.8us; max-timerInsertTm:    47435.0us;  tot-timerInsertTm: 50.7s
min-timerRemoveTm:  18451.9us; avg-timerRemoveTm:  24214.5us; max-timerRemoveTm:   113241.0us;  tot-timerRemoveTm: 569.0s

ZitatBei 120 gleichzeitig aktiven Timern waeren das im Schnitt 4.6 (oder 3.5?) ms "Gewinn" pro Aufruf beim Auswahl-Aufwand in der Array Version. Demgegenueber stehen 0.3ms "Verlust" beim Einfuegen des Timers.

Also im Schnitt 5ms bei 120 Timern
und 26.5ms bei 620 Timern.

Gruß, Ansgar.

Hallo Zusammen,

hier https://forum.fhem.de/index.php/topic,24436.msg732585.html#msg732585 (https://forum.fhem.de/index.php/topic,24436.msg732585.html#msg732585) habe ich mal das mit einem Modul 97_timerTS.pm gemacht, was apptime tut, um die geänderten Timer Funktionen mit der Standard fhem.pl nutzen zu können.

Mit LoadModule muss 97_timerTS.pm nur geladen werden und überschreibt damit die Timer Funktionen aus fhem.pl und übernimmt bei der Initialiserung laufende Timer aus %IntAt.

Entsprechend Streichliste sind damit nur noch Probleme mit 30_MilightBridge.pm zu erwarten solange sich an dem Verhalten der Timerfunktionen aus fhem.pl nichts ändert.

Gruß, Ansgar.

Hänge mich mal rein zum mitlesen . Das scheint ja meinen FREEZEMON über kurz oder lang obsolet zu machen...


Kurz, weil mobil...

Hallo KernSani,

ZitatDas scheint ja meinen FREEZEMON über kurz oder lang obsolet zu machen...

ok, kannte ich noch nicht.

Der wäre ohne Anpassungen auch betroffen, würde aber prinzipiell davon profitieren können.  ;)

Gruß, Ansgar.

Zitat von: noansi am 04 Februar 2018, 18:48:17
Hallo KernSani,
ok, kannte ich noch nicht.

gibt's ja auch erst seit gestern :-D

Ich habe jetzt meine Variante eingecheckt, d.h. InternalTimer ist von %intAt auf dem nach TRIGGERTIME sortierten @intAtA umgestellt.

Folgen:
- Der Overhead fuer das Ausfuehren der richtigen Funktion ist bei vielen kurzen Timern deutlich geringer, da das Sortieren entfaellt. Nebeneffekt: Wiederholende at Definitionen, die zur gleichen Zeit ausgefuehrt werden, behalten jetzt ihre Reihenfolge.
- InternalTimer() ist etwas langsamer, da die richtige Stelle gesucht werden muss. Wegen binaerer Suche sollte der Zusatzaufwand sich in Grenzen halten, und geringer sein als das Sortieren.
- Aufwand fuer RemoveInternalTimer sollte in etwa gleich bleiben.
- Codegroesse ist in etwa gleich geblieben, Komplexitaet ist wg. der Binaersuche gestiegen.

%intAt wird weitergepflegt, da apptime und freezemon davon abhaengen, und der Aufwand fuer die Pflege minimal ist.
Nachdem diese Befehle auf @intAtA umgestellt haben, werde ich die %intAt Pflege entfernen.

Ich habe zwar jetzt eine Weile getestet, kann aber nicht ausschliessen, dass es unerwartete Nebeneffekte hat: bitte in der naechsten Zeit daran denken.

Hallo Rudolf,

vielen Dank für's übernehmen.  :)

Ergänzend trifft noch zu:

ZitatVom Verhalten her ergibt sich bei HandleTimer auch ein kleiner Unterschied, falls ein neuer Timer in einer Timerroutine mit Ausführungszeit 1 oder gettimeofday erzeugt wird. Dann wird er auch gleich im gleichen HandleTimeraufruf noch ausgeführt, während er in Deinem bisherigen Code erst im nächsten Aufruf von HandleTimer zur Ausführung kommt.

Ausführungszeitpunkt 0 führt zu 1, trifft also auch zu.

D.h. Jörg muss sich damit zurecht finden vgl. https://forum.fhem.de/index.php/topic,81365.msg756314.html#msg756314 (https://forum.fhem.de/index.php/topic,81365.msg756314.html#msg756314).

Gruß, Ansgar.

Dann werde ich mir heute abend mal die neue Version saugen und versuchen freezemon so umzubauen, dass es mit beidem zurecht kommt...


Kurz, weil mobil...

Zitat von: noansi am 18 Februar 2018, 16:54:27
Hallo Rudolf,

vielen Dank für's übernehmen.  :)

Ergänzend trifft noch zu:Ausführungszeitpunkt 0 führt zu 1, trifft also auch zu.

D.h. Jörg muss sich damit zurecht finden vgl. https://forum.fhem.de/index.php/topic,81365.msg756314.html#msg756314 (https://forum.fhem.de/index.php/topic,81365.msg756314.html#msg756314).

Gruß, Ansgar.

Grmpf. Aber ich hab einen hack in der Schublade 😀

ZitatVom Verhalten her ergibt sich bei HandleTimer auch ein kleiner Unterschied, falls ein neuer Timer in einer Timerroutine mit Ausführungszeit 1 oder gettimeofday erzeugt wird. Dann wird er auch gleich im gleichen HandleTimeraufruf noch ausgeführt, während er in Deinem bisherigen Code erst im nächsten Aufruf von HandleTimer zur Ausführung kommt.

Genauer: wenn man in der beim InternalTimer spezifizierten Funktion einen weiteren InternalTimer mit $timeout << gettimeofday() aufruft, dann wird dieser Eintrag am Anfang des Arrays eingetragen, und damit nach Beenden des aktuellen Aufrufs ausgefuehrt. Dabei ist "<<" leider variabel: da $now vor der Schleife geholt wird, die einzelnen ausgefuehrten Funktionen unterschiedlich lang dauern koennen, und die Genauigkeit von gettimeofday nicht gerantiert ist, ist diese Differenz unbestimmt. Wenn man aber etwas ganz Kleines (aber noch per float Darstellbares) auf gettimeofday() draufaddiert, dann sollte es nicht mehr in der aktuellen HandleTimeout abgearbeitet werden.

Hallo zusammen,

am 20.02. habe ich auf die aktuelle fhem.pl (das gesamte FHEM) upgedated. Die neueste Version war 16228 2018-02-20. Ab diesem Zeitpunkt habe ich beobachtet dass die CPU-Auslastung stetig bis 25% (4 CPU's -> entspricht 100% f. eine CPU) hochgeklettert ist. Verbunden war dieser Anstieg ab einer gewissen Stufe mit fortlaufenden Freezes. Nach einem Restart war alles wieder ok um sofort wieder entsprechend anzusteigen.

Der beschriebene Vorgang schaukelte sich so über mehrere Stunden auf. Die RAM-Auslastung blieb über die gesamte Zeit weitgehend unauffällig bei 300-400MB.

Nun bin ich wieder auf die fhem.pl 16204 2018-02-17 zurück gegangen. Mit dieser Version läuft alles wieder chic so wie es sein soll mit 0 -1 % Auslastung.

In dem angehängten SVG habe ich die CPU-Auslastungsentwicklung dokumentiert. Die steilen Flanken nach 0 sind jeweils Restarts bis ich heute wieder zurück auf die lauffähige Version gegangen bin.
FHEM.pl habe ich erstmal vom Update-Prozess ausgenommen.
Auf meiner Testmaschine ist dieses Verhalten nicht so stark ausgeprägt und betriebsverhindernd, wobei auf dieser Instanz z.B. kein Homematic läuft.

Es ist zu vermuten, dass diese Problematik mit den hier im Thread beschriebenen Änderungen in Zusammenhang steht.

LG,
Heiko

Ich beobachte ebenfalls erhöhte CPU Last durch den FHEM Prozess. Nicht im kritischen Bereich, da die CPU auch gut dimensioniert ist. Aber doch deutlich sichtbar, gute 10% höher im Schnitt seit Update und Restart gestern und seitdem langsam aber sichtbar ansteigend.

fhem.pl ist rev 16214, also genau dieser Change hier.
Ich gehe jetzt zurück auf 16211 und beobachte das mal.

Update 23.02. 07:00
Mit der 16211 alles stabil und kein Anstieg der CPU nach bisher 8 Stunden.

Ich habe einen erneuten Test mit fhem.pl 16228 2018-02-20 durchgeführt.
Im Produktivsystem hatte ich noch 99_perfmon.pm aktiv. Die Komponente habe ich deaktiviert.
Ergebnis ist, dass die CPU-Auslastung sich langsamer als vorher in die Höhe schraubt, d.h. der Anstieg ist flacher wie im beigefügten SVG zu sehen ist.

Grundsätzlich bleibt es aber bei dem beschriebenen Verhalten.
Es macht nun etwa einen Anstieg von ca. 1% CPU-Auslastung pro Stunde aus, jetzt nach ca. 10 h Testlaufzeit beträgt die Grundlast durch perl 9 %.

Bin nun auch wieder zurück auf Version fhem.pl 16204 vom 2018-02-17.

Grüße
Heiko

Load kann, muss aber nicht hilfreich sein, zeigt die Anzahl der Prozesse, die was tun wollen, d.h. auch Warten auf Netz oder Platte zaehlt, nicht nur aktive CPU Nutzung. Allerdings ist die gezeigte Linie nicht in Ordnung, wenn FHEM die Ursache ist. Was liefert
{ @intAtA }
{ int(keys %intAt) }
zurueck, jeweils nach dem Start und nach einem relevanten Load-Anstieg?

Soweit ich sehe, startet perfmon nur einen Timer einmal die Sekunde, provoziert also eher das Problem. Ich hatte hier auch schon eine (sonst leere) Konfiguration mit 60 at Definitionen mit Logging, die jeweils alle 10s zugeschlagen haben, ohne Auffaelligkeiten laenger am laufen, mit 0.3% CPU Auslastung.