################################################################ # $Id: 98_apptime.pm $ # ################################################################ ##################################################### # package main; use strict; use warnings; use vars qw(%defs); # FHEM device/button definitions use vars qw(%intAt); use vars qw($nextat); sub apptime_Initialize($); sub apptime_Initialize($){ $cmds{"apptime"}{Fn} = "apptime_CommandDispTiming"; $cmds{"apptime"}{Hlp} = "[clear|] [top|all] [] application function calls and duration"; } sub HandleTimeout() { return undef if(!$nextat); my $now = gettimeofday(); return ($nextat-$now) if($now < $nextat); $now += 0.01;# need to cover min delay at least $nextat = 0; ############# # Check the internal list. foreach my $i (sort { $intAt{$a}{TRIGGERTIME} <=> $intAt{$b}{TRIGGERTIME} } keys %intAt) { my $tim = $intAt{$i}{TRIGGERTIME}; my $fn = $intAt{$i}{FN}; if(!defined($tim) || !defined($fn)) { delete($intAt{$i}); next; } elsif($tim <= $now) { my $arg = $intAt{$i}{ARG}; $arg = "" if (!$arg); apptime_getTiming("global","tmr-".$fn.";".$arg,$fn,$arg); delete($intAt{$i}); } else { $nextat = $tim if(!$nextat || $nextat > $tim); } } return undef if(!$nextat); $now = gettimeofday(); # possibly some tasks did timeout in the meantime # we will cover them return ($now+ 0.01 < $nextat) ? ($nextat-$now) : 0.01; } sub CallFn(@) { my $d = shift; my $n = shift; if(!$d || !$defs{$d}) { $d = "" if(!defined($d)); Log 0, "Strange call for nonexistent $d: $n"; return undef; } if(!$defs{$d}{TYPE}) { Log 0, "Strange call for typeless $d: $n"; return undef; } my $fn = $modules{$defs{$d}{TYPE}}{$n}; return "" if(!$fn); my @ret = apptime_getTiming($d,$fn,$fn,@_); if(wantarray){return @ret;} else {return $ret[0];} } sub apptime_getTiming($$$@) { my ($e,$fnName,$fn,@arg) = @_; if (!$defs{$e}{helper} || !$defs{$e}{helper}{bm} || !$defs{$e}{helper}{bm}{$fnName} ){ $defs{$e}{helper}{bm}{$fnName}{max}=0; $defs{$e}{helper}{bm}{$fnName}{mAr}=""; $defs{$e}{helper}{bm}{$fnName}{cnt}=0; $defs{$e}{helper}{bm}{$fnName}{tot}=0; } my $h = $defs{$e}{helper}{bm}{$fnName}; $h->{cnt}++; my $ts1 = gettimeofday(); no strict "refs"; my @ret = &{$fn}(@arg); use strict "refs"; $ts1 = int((gettimeofday()-$ts1)*1000); if ($ts1 && $h->{max}<$ts1){ $h->{max}=$ts1; $h->{mAr}=join ("; ",@arg); } ; $h->{tot}+=$ts1; return @ret; } ##################################### sub apptime_CommandDispTiming($$@) { my ($cl,$param) = @_; my ($sFld,$top,$filter) = split" ",$param; $sFld = "max" if (!$sFld); $top = "top" if (!$top); my %fld = (name=>0,funktion=>1,max=>2,count=>3,total=>4,average=>5,clear=>99); return "$sFld undefined field, use one of ".join(",",keys %fld) if(!defined $fld{$sFld}); my @bmArr; foreach my $d (sort keys %defs) { next if(!$defs{$d}{helper}||!$defs{$d}{helper}{bm}); if ($sFld eq "clear"){ delete $defs{$d}{helper}{bm}; next; } foreach my $f (sort keys %{$defs{$d}{helper}{bm}}) { next if(!defined $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}; push @bmArr,[($n,$t ,$h->{max} ,$h->{cnt} ,$h->{tot} ,$h->{tot} /$h->{cnt} ,$h->{mAr} )]; } } 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("\n %35s %20s %6s %6s %8s %8s %s", "name","function","max","count","total","average","param Max call"); my $end = ($top && $top eq "top")?20:@bmArr-1; $end = @bmArr-1 if ($end>@bmArr-1); $ret .= sprintf("\n %35s %20s %6d %6d %8d %8.2f %s",@{$bmArr[$_]})for (0..$end); return $ret; } 1; =pod =begin html

apptime

    apptime

    apptime provides information about application procedure execution time. It is meant to support finding long runner jobs causing latency as well as overall high cpu usage jobs
    no information about FHEM kernal times and delays will be provided.
    Once started apptime monitors tasks. User may reset counts during operation. apptime itself may add about 1% CPU load in average to FHEM. in order to remove apptime shutdown restart is necessary ist necessary.

    Features:
    • apptime
      apptime is started with the its first call. It will monitor operation from that point in time
      To unload apptime shutdeon restart is necessary
    • apptime clear
      will reset all counts and start fom zero
    • apptime [count|funktion|average|clear|max|name|total] [all]
      display a table sorted by the field selected
      all will display the complete table while by default only the top lines are printed.

    Columns:
    • name
      name of the entity executing the procedure
      if it is a function called by InternalTimer the name starts with tmr-. by then it gives the name of the funktion to be called
    • function
      procedure name which was executed
      if it is an InternalTimer call it gives its calling parameter
    • max
      longest duration measured for this procedure in ms
    • count
      number of calls for this procedure
    • total
      accumulated duration of this procedure over all calls monitored
    • average
      average time a call of this procedure takes
    • param Max call
      gives the parameter of the call with the max duration

=end html =cut