Profile of Mail/SpamAssassin/PluginHandler.pm

Filename	/usr/local/lib/perl5/site_perl/Mail/SpamAssassin/PluginHandler.pm
Statements	Executed 27186 statements in 135ms

Subroutines
Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
27	1	1	160ms	575ms	Mail::SpamAssassin::PluginHandler::load_plugin
1910	1	1	105ms	716s	Mail::SpamAssassin::PluginHandler::callback (recurses: max depth 1, inclusive time 14.6s)
12	1	1	6.23ms	8.81ms	Mail::SpamAssassin::PluginHandler::have_callback
1	1	1	2.40ms	3.03ms	Mail::SpamAssassin::PluginHandler::BEGIN@27
27	1	1	778µs	778µs	Mail::SpamAssassin::PluginHandler::register_plugin
12	1	1	47µs	47µs	Mail::SpamAssassin::PluginHandler::CORE:sort (opcode)
1	1	1	40µs	144µs	Mail::SpamAssassin::PluginHandler::BEGIN@28
1	1	1	39µs	39µs	Mail::SpamAssassin::PluginHandler::BEGIN@26
1	1	1	30µs	38µs	Mail::SpamAssassin::PluginHandler::BEGIN@31
1	1	1	27µs	207µs	Mail::SpamAssassin::PluginHandler::BEGIN@29
1	1	1	26µs	94µs	Mail::SpamAssassin::PluginHandler::BEGIN@34
1	1	1	25µs	25µs	Mail::SpamAssassin::PluginHandler::new
1	1	1	23µs	37µs	Mail::SpamAssassin::PluginHandler::BEGIN@33
1	1	1	23µs	161µs	Mail::SpamAssassin::PluginHandler::BEGIN@37
1	1	1	21µs	60µs	Mail::SpamAssassin::PluginHandler::BEGIN@32
1	1	1	20µs	20µs	Mail::SpamAssassin::PluginHandler::BEGIN@35
0	0	0	0s	0s	Mail::SpamAssassin::PluginHandler::finish
0	0	0	0s	0s	Mail::SpamAssassin::PluginHandler::get_loaded_plugins_list

Call graph for these subroutines as a Graphviz dot language file.

Line	State ments	Time on line	Calls	Time in subs	Code
1					# <@LICENSE>
2					# Licensed to the Apache Software Foundation (ASF) under one or more
3					# contributor license agreements. See the NOTICE file distributed with
4					# this work for additional information regarding copyright ownership.
5					# The ASF licenses this file to you under the Apache License, Version 2.0
6					# (the "License"); you may not use this file except in compliance with
7					# the License. You may obtain a copy of the License at:
8					#
9					# http://www.apache.org/licenses/LICENSE-2.0
10					#
11					# Unless required by applicable law or agreed to in writing, software
12					# distributed under the License is distributed on an "AS IS" BASIS,
13					# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14					# See the License for the specific language governing permissions and
15					# limitations under the License.
16					# </@LICENSE>
17
18					=head1 NAME
19
20					Mail::SpamAssassin::PluginHandler - SpamAssassin plugin handler
21
22					=cut
23
24					package Mail::SpamAssassin::PluginHandler;
25
26	2	72µs	1	39µs	# spent 39µs within Mail::SpamAssassin::PluginHandler::BEGIN@26 which was called: # once (39µs+0s) by Mail::SpamAssassin::BEGIN@76 at line 26 use Mail::SpamAssassin; # spent 39µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@26
27	2	424µs	1	3.03ms	# spent 3.03ms (2.40+624µs) within Mail::SpamAssassin::PluginHandler::BEGIN@27 which was called: # once (2.40ms+624µs) by Mail::SpamAssassin::BEGIN@76 at line 27 use Mail::SpamAssassin::Plugin; # spent 3.03ms making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@27
28	2	82µs	2	248µs	# spent 144µs (40+104) within Mail::SpamAssassin::PluginHandler::BEGIN@28 which was called: # once (40µs+104µs) by Mail::SpamAssassin::BEGIN@76 at line 28 use Mail::SpamAssassin::Util; # spent 144µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@28 # spent 104µs making 1 call to Exporter::import
29	2	74µs	2	387µs	# spent 207µs (27+180) within Mail::SpamAssassin::PluginHandler::BEGIN@29 which was called: # once (27µs+180µs) by Mail::SpamAssassin::BEGIN@76 at line 29 use Mail::SpamAssassin::Logger; # spent 207µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@29 # spent 180µs making 1 call to Exporter::import
30
31	2	75µs	2	46µs	# spent 38µs (30+8) within Mail::SpamAssassin::PluginHandler::BEGIN@31 which was called: # once (30µs+8µs) by Mail::SpamAssassin::BEGIN@76 at line 31 use strict; # spent 38µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@31 # spent 8µs making 1 call to strict::import
32	2	72µs	2	100µs	# spent 60µs (21+40) within Mail::SpamAssassin::PluginHandler::BEGIN@32 which was called: # once (21µs+40µs) by Mail::SpamAssassin::BEGIN@76 at line 32 use warnings; # spent 60µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@32 # spent 40µs making 1 call to warnings::import
33	2	75µs	2	52µs	# spent 37µs (23+15) within Mail::SpamAssassin::PluginHandler::BEGIN@33 which was called: # once (23µs+15µs) by Mail::SpamAssassin::BEGIN@76 at line 33 use bytes; # spent 37µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@33 # spent 14µs making 1 call to bytes::import
34	2	59µs	2	162µs	# spent 94µs (26+68) within Mail::SpamAssassin::PluginHandler::BEGIN@34 which was called: # once (26µs+68µs) by Mail::SpamAssassin::BEGIN@76 at line 34 use re 'taint'; # spent 94µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@34 # spent 68µs making 1 call to re::import
35	2	77µs	1	20µs	# spent 20µs within Mail::SpamAssassin::PluginHandler::BEGIN@35 which was called: # once (20µs+0s) by Mail::SpamAssassin::BEGIN@76 at line 35 use File::Spec; # spent 20µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@35
36
37	1	2µs			# spent 161µs (23+138) within Mail::SpamAssassin::PluginHandler::BEGIN@37 which was called: # once (23µs+138µs) by Mail::SpamAssassin::BEGIN@76 at line 39 use vars qw{
38					@ISA @CONFIG_TIME_HOOKS
39	1	1.90ms	2	299µs	}; # spent 161µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@37 # spent 138µs making 1 call to vars::import
40
41	1	8µs			@ISA = qw();
42
43					#Removed $VERSION per BUG 6422
44					#$VERSION = 'bogus'; # avoid CPAN.pm picking up version strings later
45
46					# Normally, the list of active plugins that should be called for a given hook
47					# method name is compiled and cached at runtime. This means that later calls
48					# will not have to traverse the entire plugin list more than once, since the
49					# list of plugins that implement that hook is already cached.
50					#
51					# However, some hooks should not receive this treatment. One of these is
52					# parse_config, which may be compiled before all config files have been read;
53					# if a plugin is loaded from a config file after this has been compiled, it
54					# will not get callbacks.
55					#
56					# Any other such hooks that may be compiled at config-parse-time should be
57					# listed here.
58
59	1	2µs			@CONFIG_TIME_HOOKS = qw( parse_config );
60
61					###########################################################################
62
63					# spent 25µs within Mail::SpamAssassin::PluginHandler::new which was called: # once (25µs+0s) by Mail::SpamAssassin::new at line 433 of Mail/SpamAssassin.pm sub new {
64	1	3µs			my $class = shift;
65	1	3µs			my $main = shift;
66	1	2µs			$class = ref($class) \|\| $class;
67	1	7µs			my $self = {
68					plugins => [ ],
69					cbs => { },
70					main => $main
71					};
72	1	2µs			bless ($self, $class);
73	1	9µs			$self;
74					}
75
76					###########################################################################
77
78					# spent 575ms (160+415) within Mail::SpamAssassin::PluginHandler::load_plugin which was called 27 times, avg 21.3ms/call: # 27 times (160ms+415ms) by Mail::SpamAssassin::Conf::load_plugin at line 4949 of Mail/SpamAssassin/Conf.pm, avg 21.3ms/call sub load_plugin {
79	27	79µs			my ($self, $package, $path, $silent) = @_;
80
81					# Don't load the same plugin twice!
82					# Do this before calling ->new(), otherwise eval rules will be
83					# registered on a nonexistent object
84	54	260µs			foreach my $old_plugin (@{$self->{plugins}}) {
85	351	1.84ms			if (ref($old_plugin) eq $package) {
86					dbg("plugin: did not register $package, already registered");
87					return;
88					}
89					}
90
91	27	61µs			my $ret;
92	27	102µs			if ($path) {
93					# bug 3717:
94					# At least Perl 5.8.0 seems to confuse $cwd internally at some point -- we
95					# need to use an absolute path here else we get a "File not found" error.
96					$path = Mail::SpamAssassin::Util::untaint_file_path(
97					File::Spec->rel2abs($path)
98					);
99
100					# if (exists $INC{$path}) {
101					# dbg("plugin: not loading $package from $path, already loaded");
102					# return;
103					# }
104
105					dbg("plugin: loading $package from $path");
106
107					# use require instead of "do", so we get built-in $INC{filename}
108					# smarts
109					$ret = eval { require $path; };
110					}
111					else {
112	27	334µs	27	299µs	dbg("plugin: loading $package from \@INC"); # spent 299µs making 27 calls to Mail::SpamAssassin::Logger::dbg, avg 11µs/call
113	27	1.63ms			$ret = eval qq{ require $package; }; # spent 708µs executing statements in string eval # spent 575µs executing statements in string eval # spent 538µs executing statements in string eval # spent 450µs executing statements in string eval # spent 383µs executing statements in string eval # spent 368µs executing statements in string eval # spent 363µs executing statements in string eval # spent 354µs executing statements in string eval # spent 351µs executing statements in string eval # spent 350µs executing statements in string eval # spent 344µs executing statements in string eval # spent 342µs executing statements in string eval # spent 327µs executing statements in string eval # spent 320µs executing statements in string eval # spent 318µs executing statements in string eval # spent 315µs executing statements in string eval # spent 308µs executing statements in string eval # spent 305µs executing statements in string eval # spent 300µs executing statements in string eval # spent 298µs executing statements in string eval # spent 291µs executing statements in string eval # spent 283µs executing statements in string eval # spent 272µs executing statements in string eval # spent 268µs executing statements in string eval # spent 261µs executing statements in string eval # spent 250µs executing statements in string eval # spent 8µs executing statements in string eval
114	27	91µs			$path = "(from \@INC)";
115					}
116
117	27	47µs			if (!$ret) {
118					if ($silent) {
119					if ($@) { dbg("plugin: failed to parse tryplugin $path: $@\n"); }
120					elsif ($!) { dbg("plugin: failed to load tryplugin $path: $!\n"); }
121					}
122					else {
123					if ($@) { warn "plugin: failed to parse plugin $path: $@\n"; }
124					elsif ($!) { warn "plugin: failed to load plugin $path: $!\n"; }
125					}
126					return; # failure! no point in continuing here
127					}
128
129	27	1.88ms			my $plugin = eval $package.q{->new ($self->{main}); }; # spent 27µs executing statements in string eval # spent 25µs executing statements in string eval # spent 24µs executing statements in string eval # spent 23µs executing statements in string eval # spent 22µs executing statements in string eval # spent 20µs executing statements in string eval # spent 18µs executing statements in string eval # spent 18µs executing statements in string eval # spent 17µs executing statements in string eval # spent 17µs executing statements in string eval # spent 16µs executing statements in string eval # spent 16µs executing statements in string eval # spent 16µs executing statements in string eval # spent 15µs executing statements in string eval # spent 15µs executing statements in string eval # spent 15µs executing statements in string eval # spent 15µs executing statements in string eval # spent 15µs executing statements in string eval # spent 15µs executing statements in string eval # spent 15µs executing statements in string eval # spent 15µs executing statements in string eval # spent 14µs executing statements in string eval # spent 14µs executing statements in string eval # spent 14µs executing statements in string eval # spent 14µs executing statements in string eval # spent 14µs executing statements in string eval # spent 14µs executing statements in string eval
130
131	27	150µs			if ($@ \|\| !$plugin) {
132					warn "plugin: failed to create instance of plugin $package: $@\n";
133					}
134
135	27	348µs			if ($plugin) {
136	27	283µs	27	778µs	$self->{main}->{plugins}->register_plugin ($plugin); # spent 778µs making 27 calls to Mail::SpamAssassin::PluginHandler::register_plugin, avg 29µs/call
137	27	239µs	27	372µs	$self->{main}->{conf}->load_plugin_succeeded ($plugin, $package, $path); # spent 372µs making 27 calls to Mail::SpamAssassin::Conf::load_plugin_succeeded, avg 14µs/call
138					}
139					}
140
141					# spent 778µs within Mail::SpamAssassin::PluginHandler::register_plugin which was called 27 times, avg 29µs/call: # 27 times (778µs+0s) by Mail::SpamAssassin::PluginHandler::load_plugin at line 136, avg 29µs/call sub register_plugin {
142	27	63µs			my ($self, $plugin) = @_;
143	27	104µs			$plugin->{main} = $self->{main};
144	54	228µs			push (@{$self->{plugins}}, $plugin);
145					# dbg("plugin: registered $plugin");
146
147					# invalidate cache entries for any configuration-time hooks, in case
148					# one has already been built; this plugin may implement that hook!
149	27	404µs			foreach my $subname (@CONFIG_TIME_HOOKS) {
150	27	130µs			delete $self->{cbs}->{$subname};
151					}
152					}
153
154					###########################################################################
155
156					# spent 8.81ms (6.23+2.58) within Mail::SpamAssassin::PluginHandler::have_callback which was called 12 times, avg 735µs/call: # 12 times (6.23ms+2.58ms) by Mail::SpamAssassin::PluginHandler::callback at line 195, avg 735µs/call sub have_callback {
157	12	31µs			my ($self, $subname) = @_;
158
159					# have we set up the cache entry for this callback type?
160	12	54µs			if (!exists $self->{cbs}->{$subname}) {
161					# nope. run through all registered plugins and see which ones
162					# implement this type of callback. sort by priority
163
164	12	25µs			my %subsbypri;
165	24	123µs			foreach my $plugin (@{$self->{plugins}}) {
166	324	5.14ms	324	2.44ms	my $methodref = $plugin->can ($subname); # spent 2.44ms making 324 calls to UNIVERSAL::can, avg 8µs/call
167	324	2.42ms			if (defined $methodref) {
168	12	65µs			my $pri = $plugin->{method_priority}->{$subname} \|\| 0;
169
170	12	45µs			$subsbypri{$pri} \|\|= [];
171	24	114µs			push (@{$subsbypri{$pri}}, [ $plugin, $methodref ]);
172
173	12	149µs	12	93µs	dbg("plugin: ${plugin} implements '$subname', priority $pri"); # spent 93µs making 12 calls to Mail::SpamAssassin::Logger::dbg, avg 8µs/call
174					}
175					}
176
177	12	24µs			my @subs;
178	12	202µs	12	47µs	foreach my $pri (sort { $a <=> $b } keys %subsbypri) { # spent 47µs making 12 calls to Mail::SpamAssassin::PluginHandler::CORE:sort, avg 4µs/call
179	16	68µs			push @subs, @{$subsbypri{$pri}};
180					}
181
182	12	74µs			$self->{cbs}->{$subname} = \@subs;
183					}
184
185	24	143µs			return scalar(@{$self->{cbs}->{$subname}});
186					}
187
188					# spent 716s (105ms+715) within Mail::SpamAssassin::PluginHandler::callback which was called 1910 times, avg 375ms/call: # 1910 times (105ms+715s) by Mail::SpamAssassin::call_plugins at line 2131 of Mail/SpamAssassin.pm, avg 375ms/call sub callback {
189	1910	3.70ms			my $self = shift;
190	1910	4.28ms			my $subname = shift;
191	1910	3.75ms			my ($ret, $overallret);
192
193					# have we set up the cache entry for this callback type?
194	1910	8.33ms			if (!exists $self->{cbs}->{$subname}) {
195	12	136µs	12	8.81ms	return unless $self->have_callback($subname); # spent 8.81ms making 12 calls to Mail::SpamAssassin::PluginHandler::have_callback, avg 735µs/call
196					}
197
198	3812	18.7ms			foreach my $cbpair (@{$self->{cbs}->{$subname}}) {
199	1444	4.21ms			my ($plugin, $methodref) = @$cbpair;
200
201	1444	4.18ms			$plugin->{_inhibit_further_callbacks} = 0;
202
203					eval {
204	1444	13.3ms	1444	730s	$ret = &$methodref ($plugin, @_); # spent 665s making 234 calls to Mail::SpamAssassin::Plugin::TxRep::learn_message, avg 2.84s/call # spent 44.1s making 234 calls to Mail::SpamAssassin::Plugin::Bayes::learn_message, avg 189ms/call # spent 14.5s making 234 calls to Mail::SpamAssassin::Plugin::URIDNSBL::parsed_metadata, avg 61.9ms/call # spent 5.67s making 1 call to Mail::SpamAssassin::Plugin::TxRep::learner_close # spent 131ms making 1 call to Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end # spent 129ms making 501 calls to Mail::SpamAssassin::Plugin::FreeMail::parse_config, avg 257µs/call # spent 81.7ms making 234 calls to Mail::SpamAssassin::Plugin::AskDNS::extract_metadata, avg 349µs/call # spent 29.6ms making 1 call to Mail::SpamAssassin::Plugin::Bayes::learner_new # spent 1.69ms making 1 call to Mail::SpamAssassin::Plugin::FreeMail::finish_parsing_end # spent 1.31ms making 1 call to Mail::SpamAssassin::Plugin::Bayes::learner_close # spent 506µs making 1 call to Mail::SpamAssassin::Plugin::Bayes::learner_is_scan_available # spent 15µs making 1 call to Mail::SpamAssassin::Plugin::TxRep::learner_new
205	1444	3.33ms			1;
206	1444	5.82ms			} or do {
207					my $eval_stat = $@ ne '' ? $@ : "errno=$!"; chomp $eval_stat;
208					warn "plugin: eval failed: $eval_stat\n";
209					};
210
211	1444	5.14ms			if (defined $ret) {
212					# dbg("plugin: ${plugin}->${methodref} => $ret");
213					# we are interested in defined but false results too
214	1443	3.33ms			$overallret = $ret if $ret \|\| !defined $overallret;
215					}
216
217	1444	6.30ms			if ($plugin->{_inhibit_further_callbacks}) {
218					# dbg("plugin: $plugin inhibited further callbacks");
219	501	893µs			last;
220					}
221					}
222
223	1906	29.5ms			return $overallret;
224					}
225
226					###########################################################################
227
228					sub get_loaded_plugins_list {
229					my ($self) = @_;
230					return @{$self->{plugins}};
231					}
232
233					###########################################################################
234
235					sub finish {
236					my $self = shift;
237					delete $self->{cbs};
238					foreach my $plugin (@{$self->{plugins}}) {
239					$plugin->finish();
240					delete $plugin->{main};
241					}
242					delete $self->{plugins};
243					delete $self->{main};
244					}
245
246					###########################################################################
247
248	1	16µs			1;

					# spent 47µs within Mail::SpamAssassin::PluginHandler::CORE:sort which was called 12 times, avg 4µs/call: # 12 times (47µs+0s) by Mail::SpamAssassin::PluginHandler::have_callback at line 178, avg 4µs/call sub Mail::SpamAssassin::PluginHandler::CORE:sort; # opcode