Profile of Mail/SpamAssassin/PluginHandler.pm

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

Subroutines
Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
27	1	1	148ms	506ms	Mail::SpamAssassin::PluginHandler::load_plugin
1910	1	1	103ms	96432s	Mail::SpamAssassin::PluginHandler::callback (recurses: max depth 1, inclusive time 15.1s)
12	1	1	5.84ms	8.73ms	Mail::SpamAssassin::PluginHandler::have_callback
1	1	1	2.27ms	2.82ms	Mail::SpamAssassin::PluginHandler::BEGIN@27
27	1	1	670µs	670µs	Mail::SpamAssassin::PluginHandler::register_plugin
12	1	1	52µs	52µs	Mail::SpamAssassin::PluginHandler::CORE:sort (opcode)
1	1	1	36µs	36µs	Mail::SpamAssassin::PluginHandler::BEGIN@26
1	1	1	26µs	92µs	Mail::SpamAssassin::PluginHandler::BEGIN@28
1	1	1	24µs	24µs	Mail::SpamAssassin::PluginHandler::new
1	1	1	22µs	45µs	Mail::SpamAssassin::PluginHandler::BEGIN@32
1	1	1	19µs	137µs	Mail::SpamAssassin::PluginHandler::BEGIN@29
1	1	1	19µs	28µs	Mail::SpamAssassin::PluginHandler::BEGIN@31
1	1	1	19µs	24µs	Mail::SpamAssassin::PluginHandler::BEGIN@33
1	1	1	19µs	71µs	Mail::SpamAssassin::PluginHandler::BEGIN@34
1	1	1	18µs	111µs	Mail::SpamAssassin::PluginHandler::BEGIN@37
1	1	1	17µs	17µ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	62µs	1	36µs	# spent 36µs within Mail::SpamAssassin::PluginHandler::BEGIN@26 which was called: # once (36µs+0s) by Mail::SpamAssassin::BEGIN@76 at line 26 use Mail::SpamAssassin; # spent 36µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@26
27	2	392µs	1	2.82ms	# spent 2.82ms (2.27+546µs) within Mail::SpamAssassin::PluginHandler::BEGIN@27 which was called: # once (2.27ms+546µs) by Mail::SpamAssassin::BEGIN@76 at line 27 use Mail::SpamAssassin::Plugin; # spent 2.82ms making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@27
28	2	59µs	2	159µs	# spent 92µs (26+66) within Mail::SpamAssassin::PluginHandler::BEGIN@28 which was called: # once (26µs+66µs) by Mail::SpamAssassin::BEGIN@76 at line 28 use Mail::SpamAssassin::Util; # spent 92µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@28 # spent 66µs making 1 call to Exporter::import
29	2	55µs	2	255µs	# spent 137µs (19+118) within Mail::SpamAssassin::PluginHandler::BEGIN@29 which was called: # once (19µs+118µs) by Mail::SpamAssassin::BEGIN@76 at line 29 use Mail::SpamAssassin::Logger; # spent 137µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@29 # spent 118µs making 1 call to Exporter::import
30
31	2	52µs	2	36µs	# spent 28µs (19+9) within Mail::SpamAssassin::PluginHandler::BEGIN@31 which was called: # once (19µs+9µs) by Mail::SpamAssassin::BEGIN@76 at line 31 use strict; # spent 28µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@31 # spent 9µs making 1 call to strict::import
32	2	59µs	2	68µs	# spent 45µs (22+23) within Mail::SpamAssassin::PluginHandler::BEGIN@32 which was called: # once (22µs+23µs) by Mail::SpamAssassin::BEGIN@76 at line 32 use warnings; # spent 45µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@32 # spent 23µs making 1 call to warnings::import
33	2	60µs	2	29µs	# spent 24µs (19+5) within Mail::SpamAssassin::PluginHandler::BEGIN@33 which was called: # once (19µs+5µs) by Mail::SpamAssassin::BEGIN@76 at line 33 use bytes; # spent 24µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@33 # spent 5µs making 1 call to bytes::import
34	2	54µs	2	123µs	# spent 71µs (19+52) within Mail::SpamAssassin::PluginHandler::BEGIN@34 which was called: # once (19µs+52µs) by Mail::SpamAssassin::BEGIN@76 at line 34 use re 'taint'; # spent 71µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@34 # spent 52µs making 1 call to re::import
35	2	62µs	1	17µs	# spent 17µs within Mail::SpamAssassin::PluginHandler::BEGIN@35 which was called: # once (17µs+0s) by Mail::SpamAssassin::BEGIN@76 at line 35 use File::Spec; # spent 17µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@35
36
37	1	2µs			# spent 111µs (18+92) within Mail::SpamAssassin::PluginHandler::BEGIN@37 which was called: # once (18µs+92µs) by Mail::SpamAssassin::BEGIN@76 at line 39 use vars qw{
38					@ISA @CONFIG_TIME_HOOKS
39	1	1.69ms	2	203µs	}; # spent 111µs making 1 call to Mail::SpamAssassin::PluginHandler::BEGIN@37 # spent 92µ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 24µs within Mail::SpamAssassin::PluginHandler::new which was called: # once (24µs+0s) by Mail::SpamAssassin::new at line 433 of Mail/SpamAssassin.pm sub new {
64	1	3µs			my $class = shift;
65	1	2µs			my $main = shift;
66	1	2µs			$class = ref($class) \|\| $class;
67	1	6µs			my $self = {
68					plugins => [ ],
69					cbs => { },
70					main => $main
71					};
72	1	3µs			bless ($self, $class);
73	1	10µs			$self;
74					}
75
76					###########################################################################
77
78					# spent 506ms (148+357) within Mail::SpamAssassin::PluginHandler::load_plugin which was called 27 times, avg 18.7ms/call: # 27 times (148ms+357ms) by Mail::SpamAssassin::Conf::load_plugin at line 4949 of Mail/SpamAssassin/Conf.pm, avg 18.7ms/call sub load_plugin {
79	27	68µ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	252µs			foreach my $old_plugin (@{$self->{plugins}}) {
85	351	1.41ms			if (ref($old_plugin) eq $package) {
86					dbg("plugin: did not register $package, already registered");
87					return;
88					}
89					}
90
91	27	44µs			my $ret;
92	27	108µ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	258µs	27	257µs	dbg("plugin: loading $package from \@INC"); # spent 257µs making 27 calls to Mail::SpamAssassin::Logger::dbg, avg 10µs/call
113	27	1.66ms			$ret = eval qq{ require $package; }; # spent 1.55ms executing statements in string eval # spent 793µs executing statements in string eval # spent 653µs executing statements in string eval # spent 645µs executing statements in string eval # spent 453µs executing statements in string eval # spent 446µs executing statements in string eval # spent 416µs executing statements in string eval # spent 393µs executing statements in string eval # spent 392µs executing statements in string eval # spent 391µs executing statements in string eval # spent 391µs executing statements in string eval # spent 386µs executing statements in string eval # spent 385µs executing statements in string eval # spent 380µs executing statements in string eval # spent 357µs executing statements in string eval # spent 356µs executing statements in string eval # spent 351µs executing statements in string eval # spent 341µs executing statements in string eval # spent 328µs executing statements in string eval # spent 320µs executing statements in string eval # spent 318µs executing statements in string eval # spent 317µs executing statements in string eval # spent 314µs executing statements in string eval # spent 312µs executing statements in string eval # spent 311µs executing statements in string eval # spent 296µs executing statements in string eval # spent 8µs executing statements in string eval
114	27	94µs			$path = "(from \@INC)";
115					}
116
117	27	52µ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.65ms			my $plugin = eval $package.q{->new ($self->{main}); }; # spent 25µs executing statements in string eval # spent 23µs executing statements in string eval # spent 23µs executing statements in string eval # spent 22µs executing statements in string eval # spent 19µs executing statements in string eval # spent 19µs executing statements in string eval # spent 19µs executing statements in string eval # spent 19µ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 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 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
130
131	27	128µs			if ($@ \|\| !$plugin) {
132					warn "plugin: failed to create instance of plugin $package: $@\n";
133					}
134
135	27	242µs			if ($plugin) {
136	27	271µs	27	670µs	$self->{main}->{plugins}->register_plugin ($plugin); # spent 670µs making 27 calls to Mail::SpamAssassin::PluginHandler::register_plugin, avg 25µs/call
137	27	249µs	27	304µs	$self->{main}->{conf}->load_plugin_succeeded ($plugin, $package, $path); # spent 304µs making 27 calls to Mail::SpamAssassin::Conf::load_plugin_succeeded, avg 11µs/call
138					}
139					}
140
141					# spent 670µs within Mail::SpamAssassin::PluginHandler::register_plugin which was called 27 times, avg 25µs/call: # 27 times (670µs+0s) by Mail::SpamAssassin::PluginHandler::load_plugin at line 136, avg 25µs/call sub register_plugin {
142	27	54µs			my ($self, $plugin) = @_;
143	27	74µs			$plugin->{main} = $self->{main};
144	54	198µ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	299µs			foreach my $subname (@CONFIG_TIME_HOOKS) {
150	27	116µs			delete $self->{cbs}->{$subname};
151					}
152					}
153
154					###########################################################################
155
156					# spent 8.73ms (5.84+2.89) within Mail::SpamAssassin::PluginHandler::have_callback which was called 12 times, avg 727µs/call: # 12 times (5.84ms+2.89ms) by Mail::SpamAssassin::PluginHandler::callback at line 195, avg 727µ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	55µ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	26µs			my %subsbypri;
165	24	131µs			foreach my $plugin (@{$self->{plugins}}) {
166	324	5.42ms	324	2.72ms	my $methodref = $plugin->can ($subname); # spent 2.72ms making 324 calls to UNIVERSAL::can, avg 8µs/call
167	324	1.98ms			if (defined $methodref) {
168	12	62µs			my $pri = $plugin->{method_priority}->{$subname} \|\| 0;
169
170	12	51µs			$subsbypri{$pri} \|\|= [];
171	24	115µs			push (@{$subsbypri{$pri}}, [ $plugin, $methodref ]);
172
173	12	164µs	12	120µs	dbg("plugin: ${plugin} implements '$subname', priority $pri"); # spent 120µs making 12 calls to Mail::SpamAssassin::Logger::dbg, avg 10µs/call
174					}
175					}
176
177	12	24µs			my @subs;
178	12	225µs	12	52µs	foreach my $pri (sort { $a <=> $b } keys %subsbypri) { # spent 52µs making 12 calls to Mail::SpamAssassin::PluginHandler::CORE:sort, avg 4µs/call
179	16	77µs			push @subs, @{$subsbypri{$pri}};
180					}
181
182	12	81µs			$self->{cbs}->{$subname} = \@subs;
183					}
184
185	24	164µs			return scalar(@{$self->{cbs}->{$subname}});
186					}
187
188					# spent 96432s (103ms+96432) within Mail::SpamAssassin::PluginHandler::callback which was called 1910 times, avg 50.5s/call: # 1910 times (103ms+96432s) by Mail::SpamAssassin::call_plugins at line 2131 of Mail/SpamAssassin.pm, avg 50.5s/call sub callback {
189	1910	3.76ms			my $self = shift;
190	1910	4.52ms			my $subname = shift;
191	1910	3.53ms			my ($ret, $overallret);
192
193					# have we set up the cache entry for this callback type?
194	1910	9.13ms			if (!exists $self->{cbs}->{$subname}) {
195	12	148µs	12	8.73ms	return unless $self->have_callback($subname); # spent 8.73ms making 12 calls to Mail::SpamAssassin::PluginHandler::have_callback, avg 727µs/call
196					}
197
198	3812	19.3ms			foreach my $cbpair (@{$self->{cbs}->{$subname}}) {
199	1444	4.31ms			my ($plugin, $methodref) = @$cbpair;
200
201	1444	4.32ms			$plugin->{_inhibit_further_callbacks} = 0;
202
203					eval {
204	1444	14.2ms	1444	96447s	$ret = &$methodref ($plugin, @_); # spent 96387s making 234 calls to Mail::SpamAssassin::Plugin::TxRep::learn_message, avg 412s/call # spent 45.1s making 234 calls to Mail::SpamAssassin::Plugin::Bayes::learn_message, avg 193ms/call # spent 15.0s making 234 calls to Mail::SpamAssassin::Plugin::URIDNSBL::parsed_metadata, avg 64.1ms/call # spent 152ms making 1 call to Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end # spent 117ms making 501 calls to Mail::SpamAssassin::Plugin::FreeMail::parse_config, avg 234µs/call # spent 66.9ms making 234 calls to Mail::SpamAssassin::Plugin::AskDNS::extract_metadata, avg 286µs/call # spent 33.8ms making 1 call to Mail::SpamAssassin::Plugin::Bayes::learner_new # spent 2.01ms making 1 call to Mail::SpamAssassin::Plugin::FreeMail::finish_parsing_end # spent 1.15ms making 1 call to Mail::SpamAssassin::Plugin::Bayes::learner_close # spent 1.12ms making 1 call to Mail::SpamAssassin::Plugin::TxRep::learner_close # spent 546µs making 1 call to Mail::SpamAssassin::Plugin::Bayes::learner_is_scan_available # spent 19µs making 1 call to Mail::SpamAssassin::Plugin::TxRep::learner_new
205	1444	3.57ms			1;
206	1444	5.86ms			} or do {
207					my $eval_stat = $@ ne '' ? $@ : "errno=$!"; chomp $eval_stat;
208					warn "plugin: eval failed: $eval_stat\n";
209					};
210
211	1444	5.16ms			if (defined $ret) {
212					# dbg("plugin: ${plugin}->${methodref} => $ret");
213					# we are interested in defined but false results too
214	1443	3.31ms			$overallret = $ret if $ret \|\| !defined $overallret;
215					}
216
217	1444	6.75ms			if ($plugin->{_inhibit_further_callbacks}) {
218					# dbg("plugin: $plugin inhibited further callbacks");
219	501	939µs			last;
220					}
221					}
222
223	1906	26.3ms			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	10µs			1;

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