You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@spamassassin.apache.org by jh...@apache.org on 2011/07/25 03:54:27 UTC
svn commit: r1150527 - in /spamassassin/trunk:
lib/Mail/SpamAssassin/Plugin/Check.pm masses/plugins/HitFreqsRuleTiming.pm
Author: jhardin
Date: Mon Jul 25 01:54:27 2011
New Revision: 1150527
URL: http://svn.apache.org/viewvc?rev=1150527&view=rev
Log:
Revert revision 1150225 at request of Michael Parker, performance improvements and more-human-readable output changes to HitFreqsRuleTiming plugin instead.
Modified:
spamassassin/trunk/lib/Mail/SpamAssassin/Plugin/Check.pm
spamassassin/trunk/masses/plugins/HitFreqsRuleTiming.pm
Modified: spamassassin/trunk/lib/Mail/SpamAssassin/Plugin/Check.pm
URL: http://svn.apache.org/viewvc/spamassassin/trunk/lib/Mail/SpamAssassin/Plugin/Check.pm?rev=1150527&r1=1150526&r2=1150527&view=diff
==============================================================================
--- spamassassin/trunk/lib/Mail/SpamAssassin/Plugin/Check.pm (original)
+++ spamassassin/trunk/lib/Mail/SpamAssassin/Plugin/Check.pm Mon Jul 25 01:54:27 2011
@@ -310,8 +310,6 @@ sub run_generic_tests {
my $package_name = __PACKAGE__;
my $methodname = $package_name."::_".$ruletype."_tests_".$clean_priority;
- my $do_timing = would_log('dbg', 'ruletimes');
-
if (!defined &{$methodname} || $doing_user_rules) {
# use %nopts for named parameter-passing; it's more friendly
@@ -336,7 +334,6 @@ sub run_generic_tests {
$self->push_evalstr_prefix($pms, '
# start_rules_plugin_code '.$ruletype.' '.$priority.'
my $scoresptr = $self->{conf}->{scores};
- my $time = time;
');
if (defined $opts{pre_loop_body}) {
$opts{pre_loop_body}->($self, $pms, $conf, %nopts);
@@ -344,18 +341,7 @@ sub run_generic_tests {
$self->add_evalstr($pms,
$self->start_rules_plugin_code($ruletype, $priority) );
while (my($rulename, $test) = each %{$opts{testhash}->{$priority}}) {
- if ($do_timing > 1 && $ruletype ne "meta") {
- $self->add_evalstr($pms, '
- $time = time;
- ');
- }
$opts{loop_body}->($self, $pms, $conf, $rulename, $test, %nopts);
- if ($do_timing > 1 && $ruletype ne "meta") {
- $self->add_evalstr($pms, '
- $time = time - $time;
- dbg(sprintf("ruletimes: '.$ruletype.' '.$rulename.' %.4f s", $time));
- ');
- }
}
if (defined $opts{post_loop_body}) {
$opts{post_loop_body}->($self, $pms, $conf, %nopts);
@@ -437,7 +423,6 @@ sub begin_evalstr_chunk {
my $package_name = __PACKAGE__;
my $evalstr = <<"EOT";
package $package_name;
-use Time::HiRes qw(time);
sub $chunk_methodname {
my \$self = shift;
EOT
Modified: spamassassin/trunk/masses/plugins/HitFreqsRuleTiming.pm
URL: http://svn.apache.org/viewvc/spamassassin/trunk/masses/plugins/HitFreqsRuleTiming.pm?rev=1150527&r1=1150526&r2=1150527&view=diff
==============================================================================
--- spamassassin/trunk/masses/plugins/HitFreqsRuleTiming.pm (original)
+++ spamassassin/trunk/masses/plugins/HitFreqsRuleTiming.pm Mon Jul 25 01:54:27 2011
@@ -8,9 +8,9 @@
# The ASF licenses this file to you under the Apache License, Version 2.0
# (the "License"); you may not use this file except in compliance with
# the License. You may obtain a copy of the License at:
-#
+#
# http://www.apache.org/licenses/LICENSE-2.0
-#
+#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
@@ -25,7 +25,7 @@ use Mail::SpamAssassin::Logger;
use strict;
use warnings;
-use Time::HiRes qw(gettimeofday tv_interval);
+use Time::HiRes qw(time);
use vars qw(@ISA);
@ISA = qw(Mail::SpamAssassin::Plugin);
@@ -41,25 +41,26 @@ sub new {
runs => { },
max => { },
};
+ $mailsaobject->{RuleTimingTotal} = 0;
bless ($self, $class);
}
sub start_rules {
my ($self, $options) = @_;
- $options->{permsgstatus}->{RuleTimingStart} = [gettimeofday()];
+ $options->{permsgstatus}->{RuleTimingStart} = Time::HiRes::time();
}
sub ran_rule {
- my @now = gettimeofday();
+ my $time = Time::HiRes::time();
my ($self, $options) = @_;
my $permsg = $options->{permsgstatus};
my $mailsa = $permsg->{main};
my $name = $options->{rulename};
- my $duration = tv_interval($permsg->{RuleTimingStart}, \@now);
- @{$permsg->{RuleTimingStart}} = @now;
+ my $duration = $time - $permsg->{RuleTimingStart};
+ $permsg->{RuleTimingStart} = $time;
unless ($mailsa->{rule_timing}{duration}{$name}) {
$mailsa->{rule_timing}{duration}{$name} = 0;
@@ -68,6 +69,7 @@ sub ran_rule {
# TODO: record all runs and compute std dev
+ $mailsa->{RuleTimingTotal} += $duration;
$mailsa->{rule_timing}{runs}{$name}++;
$mailsa->{rule_timing}{duration}{$name} += $duration;
$mailsa->{rule_timing}{max}{$name} = $duration
@@ -77,6 +79,9 @@ sub ran_rule {
sub finish {
my $self = shift;
my $mailsa = $self->{main};
+ my $total = $mailsa->{RuleTimingTotal};
+
+ $total = 0.00000001 if $total == 0;
# take a ref to speed up the sorting
my $dur_ref = $mailsa->{rule_timing}{duration};
@@ -86,16 +91,30 @@ sub finish {
$dur_ref->{$b} <=> $dur_ref->{$a}
} keys %{$dur_ref})
{
- $s .= sprintf "T %30s %8.3f %8.3f %4d\n", $rule,
+ $s .= sprintf "T %30s %9.4f %9.4f %4d %5.2f%%\n", $rule,
$mailsa->{rule_timing}{duration}->{$rule},
$mailsa->{rule_timing}{max}->{$rule},
- $mailsa->{rule_timing}{runs}->{$rule};
+ $mailsa->{rule_timing}{runs}->{$rule},
+ ($mailsa->{rule_timing}{duration}->{$rule} / $total) * 100
+ ;
}
- open (OUT, ">timing.log") or warn "cannot write to timing.log";
+ my $sl = $s;
+ $s =~ s/\s+\S+$//gm; # revert to v1 format
+
+ my $cwd;
+ chomp($cwd = `pwd`);
+ warn "HitFreqsRuleTiming: writing timing data to $cwd/timing.log\n";
+ open (OUT, ">timing.log") or warn "cannot write to $cwd/timing.log\n";
print OUT "v1\n"; # forward compatibility
print OUT $s;
- close OUT or warn "cannot write to timing.log";
+ close OUT or warn "cannot write to $cwd/timing.log\n";
+
+ if (would_log("dbg", "rules")) { # write more readable format to debug log
+ $sl =~ s/^T //gm;
+ $sl = (sprintf "Total time: %9.4f s\n", $total) . "rulename ovl(s) max(s) #run %tot\n" . $sl;
+ dbg("rules: timing: $sl");
+ }
$self->SUPER::finish();
}