svn commit: r569347 - /spamassassin/trunk/lib/Mail/SpamAssassin.pm

[mm...@apache.org]

Author: mmartinec
Date: Fri Aug 24 04:00:01 2007
New Revision: 569347

URL: http://svn.apache.org/viewvc?rev=569347&view=rev
Log:
timing reports: don't lose precision, keep timestamps in floating point

Modified:
    spamassassin/trunk/lib/Mail/SpamAssassin.pm

Modified: spamassassin/trunk/lib/Mail/SpamAssassin.pm
URL: http://svn.apache.org/viewvc/spamassassin/trunk/lib/Mail/SpamAssassin.pm?rev=569347&r1=569346&r2=569347&view=diff
==============================================================================
--- spamassassin/trunk/lib/Mail/SpamAssassin.pm (original)
+++ spamassassin/trunk/lib/Mail/SpamAssassin.pm Fri Aug 24 04:00:01 2007
@@ -1431,11 +1431,13 @@
   # add to any existing elapsed time for this event, since
   # we may call the same timer name multiple times -- this is ok,
   # as long as they are not nested
-  $t->{elapsed} = sprintf("%.2f",
-            (($t->{end} - $t->{start}) * 1000) + ($t->{elapsed} || 0));
+  my $dt = $t->{end} - $t->{start};
+  $dt = 0  if $dt < 0;  # tolerate clock jumps, just in case
+  if (defined $t->{elapsed}) { $t->{elapsed} += $dt }
+  else { $t->{elapsed} = $dt }
 
   if (would_log('dbg', 'timing') > 1) {
-    dbg("timing: '%s' ended after %.0f msecs", $name, $t->{elapsed});
+    dbg("timing: '%s' ended after %.0f ms", $name, $t->{elapsed} * 1000);
   }
 }
 
@@ -1459,17 +1461,15 @@
       $latest = $t->{end};
     }
   }
-  my $total = sprintf("%.2f", ($latest - $earliest) * 1000);
-  if ($total + 0 == 0) { $total = 0.000001; } # avoid div by 0
-
+  my $total = $latest - $earliest;
   my @str = ();
   foreach my $name (@{$self->{timers_order}}) {
     my $elapsed = ($self->{timers}->{$name}->{elapsed}||0);
-    my $pc = sprintf ("%.1f", ($elapsed / $total) * 100.0);
-    push @str, "$name: $elapsed ($pc\%)";
+    my $pc = $total <= 0 || $elapsed >= $total ? 100 : ($elapsed/$total)*100;
+    push @str, sprintf("%s: %.0f (%.1f%%)", $name, $elapsed*1000, $pc);
   }
 
-  return "timing: total $total msecs - ".join(", ", @str);
+  return sprintf("timing: total %.0f ms - %s", $total*1000, join(", ", @str));
 }
 
 ###########################################################################