Optimierungsvorschlag "HandleTimeout()" in fhem.pl

[Prof. Dr. Peter Henning]

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

LG

pah

[noansi]

Hallo Zusammen,

Sieh 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!

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

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

Code Auswählen Erweitern

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.

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.

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

Gruß, Ansgar.

[noansi]

Hallo Zusammen,

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

Code Auswählen Erweitern

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

Code Auswählen Erweitern

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

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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:

[noansi]

Nun ein apptime mit neuem Code für Array Timer Handling:

Code Auswählen Erweitern

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

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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

Code Auswählen Erweitern

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:

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

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

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

[rudolfkoenig]

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.

[noansi]

Hallo Rudolf,

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.

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.

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.

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

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.

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.

[noansi]

Hallo Rudolf,

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

Zum bisherigen %intAt Code:

Code Auswählen Erweitern

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

[noansi]

und zum neuen Arraybasierten Code:

Code Auswählen Erweitern

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

[herrmannj]

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.

[noansi]

Hallo Jörg, hallo Rudolf,

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.

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.

[herrmannj]

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.

[Prof. Dr. Peter Henning]

ich 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

[noansi]

Hallo Jörg,

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

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

[noansi]

Hallo Zusammen,

hier noch der geänderte apptime Code mit der von Jörg gewünschten Kompatibilität:

Code Auswählen Erweitern

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

Code Auswählen Erweitern

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

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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

Code Auswählen Erweitern

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

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.

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

Gruß, Ansgar.

[noansi]

Hallo Zusammen,

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