← Index
NYTProf Performance Profile   « block view • line view • sub view »
For -e
  Run on Wed Nov 17 21:45:08 2010
Reported on Wed Nov 17 22:10:35 2010

Filename/home/doy/perl5/perlbrew/perls/perl-5.10.1/lib/site_perl/5.10.1/x86_64-linux/Class/MOP/Method/Wrapped.pm
StatementsExecuted 7036 statements in 118ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
17961138.0ms369msClass::MOP::Method::Wrapped::::__ANON__[:159]Class::MOP::Method::Wrapped::__ANON__[:159] (recurses: max depth 4, inclusive time 12.2ms)
1102113.8ms35.5msClass::MOP::Method::Wrapped::::wrapClass::MOP::Method::Wrapped::wrap
99116.86ms13.9msClass::MOP::Method::Wrapped::::add_around_modifierClass::MOP::Method::Wrapped::add_around_modifier
226416.09ms6.09msClass::MOP::Method::Wrapped::::__ANON__[:69]Class::MOP::Method::Wrapped::__ANON__[:69]
110115.10ms5.10msClass::MOP::Method::Wrapped::::_newClass::MOP::Method::Wrapped::_new
99113.96ms3.96msClass::MOP::Method::Wrapped::::__ANON__[:161]Class::MOP::Method::Wrapped::__ANON__[:161]
30111.52ms28.7msClass::MOP::Method::Wrapped::::__ANON__[:49]Class::MOP::Method::Wrapped::__ANON__[:49]
611621µs958msClass::MOP::Method::Wrapped::::__ANON__[:43]Class::MOP::Method::Wrapped::__ANON__[:43]
1111431µs832µsClass::MOP::Method::Wrapped::::add_before_modifierClass::MOP::Method::Wrapped::add_before_modifier
611217µs458µsClass::MOP::Method::Wrapped::::add_after_modifierClass::MOP::Method::Wrapped::add_after_modifier
11169µs87µsClass::MOP::Method::Wrapped::::BEGIN@4Class::MOP::Method::Wrapped::BEGIN@4
11140µs299µsClass::MOP::Method::Wrapped::::BEGIN@14Class::MOP::Method::Wrapped::BEGIN@14
11139µs108µsClass::MOP::Method::Wrapped::::BEGIN@5Class::MOP::Method::Wrapped::BEGIN@5
11137µs194µsClass::MOP::Method::Wrapped::::BEGIN@7Class::MOP::Method::Wrapped::BEGIN@7
11136µs167µsClass::MOP::Method::Wrapped::::BEGIN@8Class::MOP::Method::Wrapped::BEGIN@8
0000s0sClass::MOP::Method::Wrapped::::__ANON__[:64]Class::MOP::Method::Wrapped::__ANON__[:64]
0000s0sClass::MOP::Method::Wrapped::::__ANON__[:89]Class::MOP::Method::Wrapped::__ANON__[:89]
0000s0sClass::MOP::Method::Wrapped::::_make_compatible_withClass::MOP::Method::Wrapped::_make_compatible_with
0000s0sClass::MOP::Method::Wrapped::::after_modifiersClass::MOP::Method::Wrapped::after_modifiers
0000s0sClass::MOP::Method::Wrapped::::around_modifiersClass::MOP::Method::Wrapped::around_modifiers
0000s0sClass::MOP::Method::Wrapped::::before_modifiersClass::MOP::Method::Wrapped::before_modifiers
0000s0sClass::MOP::Method::Wrapped::::get_original_methodClass::MOP::Method::Wrapped::get_original_method
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
1
2package Class::MOP::Method::Wrapped;
3
4399µs2106µs
# spent 87µs (69+18) within Class::MOP::Method::Wrapped::BEGIN@4 which was called: # once (69µs+18µs) by Class::MOP::Class::BEGIN@8 at line 4
use strict;
# spent 87µs making 1 call to Class::MOP::Method::Wrapped::BEGIN@4 # spent 18µs making 1 call to strict::import
53104µs2177µs
# spent 108µs (39+69) within Class::MOP::Method::Wrapped::BEGIN@5 which was called: # once (39µs+69µs) by Class::MOP::Class::BEGIN@8 at line 5
use warnings;
# spent 108µs making 1 call to Class::MOP::Method::Wrapped::BEGIN@5 # spent 69µs making 1 call to warnings::import
6
73105µs2350µs
# spent 194µs (37+157) within Class::MOP::Method::Wrapped::BEGIN@7 which was called: # once (37µs+157µs) by Class::MOP::Class::BEGIN@8 at line 7
use Carp 'confess';
# spent 194µs making 1 call to Class::MOP::Method::Wrapped::BEGIN@7 # spent 157µs making 1 call to Exporter::import
83223µs2299µs
# spent 167µs (36+132) within Class::MOP::Method::Wrapped::BEGIN@8 which was called: # once (36µs+132µs) by Class::MOP::Class::BEGIN@8 at line 8
use Scalar::Util 'blessed';
# spent 167µs making 1 call to Class::MOP::Method::Wrapped::BEGIN@8 # spent 132µs making 1 call to Exporter::import
9
1016µsour $VERSION = '1.11';
11163µs$VERSION = eval $VERSION;
# spent 11µs executing statements in string eval
1214µsour $AUTHORITY = 'cpan:STEVAN';
13
1433.34ms2299µs
# spent 299µs (40+259) within Class::MOP::Method::Wrapped::BEGIN@14 which was called: # once (40µs+259µs) by Class::MOP::Class::BEGIN@8 at line 14
use base 'Class::MOP::Method';
# spent 299µs making 1 call to Class::MOP::Method::Wrapped::BEGIN@14 # spent 259µs making 1 call to base::import, recursion: max depth 1, sum of overlapping time 259µs
15
16# NOTE:
17# this ugly beast is the result of trying
18# to micro optimize this as much as possible
19# while not completely loosing maintainability.
20# At this point it's "fast enough", after all
21# you can't get something for nothing :)
22
# spent 6.09ms within Class::MOP::Method::Wrapped::__ANON__[/home/doy/perl5/perlbrew/perls/perl-5.10.1/lib/site_perl/5.10.1/x86_64-linux/Class/MOP/Method/Wrapped.pm:69] which was called 226 times, avg 27µs/call: # 110 times (2.94ms+0s) by Class::MOP::Method::Wrapped::wrap at line 87, avg 27µs/call # 99 times (2.50ms+0s) by Class::MOP::Method::Wrapped::add_around_modifier at line 171, avg 25µs/call # 11 times (402µs+0s) by Class::MOP::Method::Wrapped::add_before_modifier at line 128, avg 37µs/call # 6 times (242µs+0s) by Class::MOP::Method::Wrapped::add_after_modifier at line 140, avg 40µs/call
my $_build_wrapped_method = sub {
236785.94ms my $modifier_table = shift;
24 my ($before, $after, $around) = (
25 $modifier_table->{before},
26 $modifier_table->{after},
27 $modifier_table->{around},
28 );
292261.07ms if (@$before && @$after) {
30
# spent 958ms (621µs+957) within Class::MOP::Method::Wrapped::__ANON__[/home/doy/perl5/perlbrew/perls/perl-5.10.1/lib/site_perl/5.10.1/x86_64-linux/Class/MOP/Method/Wrapped.pm:43] which was called 6 times, avg 160ms/call: # 6 times (621µs+957ms) by Class::MOP::Class::__ANON__::SERIAL::11::install_accessors or Class::MOP::Class::__ANON__::SERIAL::15::install_accessors or Class::MOP::Class::__ANON__::SERIAL::19::install_accessors or Class::MOP::Class::__ANON__::SERIAL::5::install_accessors or Class::MOP::Class::__ANON__::SERIAL::8::install_accessors at line 89, avg 160ms/call
$modifier_table->{cache} = sub {
3136517µs6800ms for my $c (@$before) { $c->(@_) };
# spent 800ms making 6 calls to Class::MOP::Class:::before, avg 133ms/call
32 my @rval;
336156ms ((defined wantarray) ?
# spent 156ms making 6 calls to Moose::Meta::Attribute::install_accessors, avg 26.0ms/call
34 ((wantarray) ?
35 (@rval = $around->{cache}->(@_))
36 :
37 ($rval[0] = $around->{cache}->(@_)))
38 :
39 $around->{cache}->(@_));
406104µs6278µs for my $c (@$after) { $c->(@_) };
# spent 278µs making 6 calls to Class::MOP::Class:::after, avg 46µs/call
41 return unless defined wantarray;
42 return wantarray ? @rval : $rval[0];
43 }
44 }
45 elsif (@$before && !@$after) {
46
# spent 28.7ms (1.52+27.2) within Class::MOP::Method::Wrapped::__ANON__[/home/doy/perl5/perlbrew/perls/perl-5.10.1/lib/site_perl/5.10.1/x86_64-linux/Class/MOP/Method/Wrapped.pm:49] which was called 30 times, avg 957µs/call: # 30 times (1.52ms+27.2ms) by Class::MOP::Class::__ANON__::SERIAL::11::_process_options or Class::MOP::Class::__ANON__::SERIAL::15::_process_options or Class::MOP::Class::__ANON__::SERIAL::19::_process_options or Class::MOP::Class::__ANON__::SERIAL::1::_process_options or Class::MOP::Class::__ANON__::SERIAL::5::_process_options or Class::MOP::Class::__ANON__::SERIAL::8::_process_options at line 89, avg 957µs/call
$modifier_table->{cache} = sub {
47901.39ms309.22ms for my $c (@$before) { $c->(@_) };
# spent 9.22ms making 30 calls to Class::MOP::Class:::before, avg 307µs/call
483018.0ms return $around->{cache}->(@_);
# spent 14.1ms making 24 calls to Moose::Meta::Attribute::_process_options, avg 586µs/call # spent 3.91ms making 6 calls to Class::MOP::Class::__ANON__::SERIAL::1::_process_options, avg 652µs/call
49 }
50 }
51 elsif (@$after && !@$before) {
52 $modifier_table->{cache} = sub {
53 my @rval;
54 ((defined wantarray) ?
55 ((wantarray) ?
56 (@rval = $around->{cache}->(@_))
57 :
58 ($rval[0] = $around->{cache}->(@_)))
59 :
60 $around->{cache}->(@_));
61 for my $c (@$after) { $c->(@_) };
62 return unless defined wantarray;
63 return wantarray ? @rval : $rval[0];
64 }
65 }
66 else {
67 $modifier_table->{cache} = $around->{cache};
68 }
69113µs};
70
71
# spent 35.5ms (13.8+21.6) within Class::MOP::Method::Wrapped::wrap which was called 110 times, avg 323µs/call: # 97 times (12.2ms+19.2ms) by Class::MOP::Class::__ANON__[/home/doy/perl5/perlbrew/perls/perl-5.10.1/lib/site_perl/5.10.1/x86_64-linux/Class/MOP/Class.pm:967] at line 953 of Class/MOP/Class.pm, avg 324µs/call # 13 times (1.61ms+2.40ms) by Class::MOP::Class::__ANON__[/home/doy/perl5/perlbrew/perls/perl-5.10.1/lib/site_perl/5.10.1/x86_64-linux/Class/MOP/Class.pm:967] at line 960 of Class/MOP/Class.pm, avg 308µs/call
sub wrap {
7255015.3ms my ( $class, $code, %params ) = @_;
73
742201.35ms (blessed($code) && $code->isa('Class::MOP::Method'))
# spent 729µs making 110 calls to UNIVERSAL::isa, avg 7µs/call # spent 619µs making 110 calls to Scalar::Util::blessed, avg 6µs/call
75 || confess "Can only wrap blessed CODE";
76
77110528µs my $modifier_table = {
# spent 528µs making 110 calls to Class::MOP::Method::body, avg 5µs/call
78 cache => undef,
79 orig => $code,
80 before => [],
81 after => [],
82 around => {
83 cache => $code->body,
84 methods => [],
85 },
86 };
871102.94ms $_build_wrapped_method->($modifier_table);
# spent 2.94ms making 110 calls to Class::MOP::Method::Wrapped::__ANON__[Class/MOP/Method/Wrapped.pm:69], avg 27µs/call
88 return $class->SUPER::wrap(
89183237.0ms18321.36s sub { $modifier_table->{cache}->(@_) },
# spent 958ms making 6 calls to Class::MOP::Method::Wrapped::__ANON__[Class/MOP/Method/Wrapped.pm:43], avg 160ms/call # spent 382ms making 1796 calls to Class::MOP::Method::Wrapped::__ANON__[Class/MOP/Method/Wrapped.pm:159], avg 212µs/call, recursion: max depth 4, sum of overlapping time 12.2ms # spent 28.7ms making 30 calls to Class::MOP::Method::Wrapped::__ANON__[Class/MOP/Method/Wrapped.pm:49], avg 957µs/call
90 # get these from the original
91 # unless explicitly overriden
9211016.8ms package_name => $params{package_name} || $code->package_name,
# spent 16.8ms making 110 calls to Class::MOP::Method::wrap, avg 153µs/call
93 name => $params{name} || $code->name,
94
95 modifier_table => $modifier_table,
96 );
97}
98
99
# spent 5.10ms within Class::MOP::Method::Wrapped::_new which was called 110 times, avg 46µs/call: # 110 times (5.10ms+0s) by Class::MOP::Method::wrap at line 44 of Class/MOP/Method.pm, avg 46µs/call
sub _new {
1004405.61ms my $class = shift;
101 return Class::MOP::Class->initialize($class)->new_object(@_)
102 if $class ne __PACKAGE__;
103
104 my $params = @_ == 1 ? $_[0] : {@_};
105
106 return bless {
107 # inherited from Class::MOP::Method
108 'body' => $params->{body},
109 'associated_metaclass' => $params->{associated_metaclass},
110 'package_name' => $params->{package_name},
111 'name' => $params->{name},
112 'original_method' => $params->{original_method},
113
114 # defined in this class
115 'modifier_table' => $params->{modifier_table}
116 } => $class;
117}
118
119sub get_original_method {
120 my $code = shift;
121 $code->{'modifier_table'}->{orig};
122}
123
124
# spent 832µs (431+402) within Class::MOP::Method::Wrapped::add_before_modifier which was called 11 times, avg 76µs/call: # 11 times (431µs+402µs) by Class::MOP::Class::add_before_method_modifier at line 974 of Class/MOP/Class.pm, avg 76µs/call
sub add_before_modifier {
12544375µs my $code = shift;
126 my $modifier = shift;
127 unshift @{$code->{'modifier_table'}->{before}} => $modifier;
12811402µs $_build_wrapped_method->($code->{'modifier_table'});
# spent 402µs making 11 calls to Class::MOP::Method::Wrapped::__ANON__[Class/MOP/Method/Wrapped.pm:69], avg 37µs/call
129}
130
131sub before_modifiers {
132 my $code = shift;
133 return @{$code->{'modifier_table'}->{before}};
134}
135
136
# spent 458µs (217+242) within Class::MOP::Method::Wrapped::add_after_modifier which was called 6 times, avg 76µs/call: # 6 times (217µs+242µs) by Class::MOP::Class::add_after_method_modifier at line 984 of Class/MOP/Class.pm, avg 76µs/call
sub add_after_modifier {
13724195µs my $code = shift;
138 my $modifier = shift;
139 push @{$code->{'modifier_table'}->{after}} => $modifier;
1406242µs $_build_wrapped_method->($code->{'modifier_table'});
# spent 242µs making 6 calls to Class::MOP::Method::Wrapped::__ANON__[Class/MOP/Method/Wrapped.pm:69], avg 40µs/call
141}
142
143sub after_modifiers {
144 my $code = shift;
145 return @{$code->{'modifier_table'}->{after}};
146}
147
148{
149 # NOTE:
150 # this is another possible candidate for
151 # optimization as well. There is an overhead
152 # associated with the currying that, if
153 # eliminated might make around modifiers
154 # more manageable.
1556994.14ms
# spent 3.96ms within Class::MOP::Method::Wrapped::__ANON__[/home/doy/perl5/perlbrew/perls/perl-5.10.1/lib/site_perl/5.10.1/x86_64-linux/Class/MOP/Method/Wrapped.pm:161] which was called 99 times, avg 40µs/call: # 99 times (3.96ms+0s) by Class::MOP::Method::Wrapped::add_around_modifier at line 168, avg 40µs/call
my $compile_around_method = sub {{
15699230µs my $f1 = pop;
157 return $f1 unless @_;
158 my $f2 = pop;
159179635.0ms1796332ms
# spent 369ms (38.0+331) within Class::MOP::Method::Wrapped::__ANON__[/home/doy/perl5/perlbrew/perls/perl-5.10.1/lib/site_perl/5.10.1/x86_64-linux/Class/MOP/Method/Wrapped.pm:159] which was called 1796 times, avg 206µs/call: # 1796 times (38.0ms+331ms) by Class::MOP::Class::Immutable::Class::MOP::Class::_method_map or Class::MOP::Class::Immutable::Class::MOP::Class::class_precedence_list or Class::MOP::Class::Immutable::Class::MOP::Class::get_all_attributes or Class::MOP::Class::Immutable::Class::MOP::Class::get_meta_instance or Class::MOP::Class::Immutable::Class::MOP::Class::is_immutable or Class::MOP::Class::Immutable::Class::MOP::Class::linearized_isa or Class::MOP::Class::Immutable::Class::MOP::Class::superclasses or Class::MOP::Class::Immutable::Moose::Meta::Class::get_all_attributes or Class::MOP::Class::Immutable::Moose::Meta::Class::get_meta_instance or Class::MOP::Class::Immutable::Moose::Meta::Class::is_immutable or Class::MOP::Class::Immutable::Moose::Meta::Class::linearized_isa or Class::MOP::Class::__ANON__::SERIAL::10::_new or Class::MOP::Class::__ANON__::SERIAL::10::new or Class::MOP::Class::__ANON__::SERIAL::11::_canonicalize_handles or Class::MOP::Class::__ANON__::SERIAL::11::_make_delegation_method or Class::MOP::Class::__ANON__::SERIAL::12::_new or Class::MOP::Class::__ANON__::SERIAL::12::new or Class::MOP::Class::__ANON__::SERIAL::13::_new or Class::MOP::Class::__ANON__::SERIAL::13::new or Class::MOP::Class::__ANON__::SERIAL::15::_canonicalize_handles or Class::MOP::Class::__ANON__::SERIAL::15::_make_delegation_method or Class::MOP::Class::__ANON__::SERIAL::16::_new or Class::MOP::Class::__ANON__::SERIAL::16::new or Class::MOP::Class::__ANON__::SERIAL::17::_eval_environment or Class::MOP::Class::__ANON__::SERIAL::17::_inline_coerce_new_values or Class::MOP::Class::__ANON__::SERIAL::17::_inline_get_old_value_for_trigger or Class::MOP::Class::__ANON__::SERIAL::17::_inline_tc_code or Class::MOP::Class::__ANON__::SERIAL::17::_new or Class::MOP::Class::__ANON__::SERIAL::17::_value_needs_copy or Class::MOP::Class::__ANON__::SERIAL::17::new or Class::MOP::Class::__ANON__::SERIAL::18::_eval_environment or Class::MOP::Class::__ANON__::SERIAL::18::_inline_coerce_new_values or Class::MOP::Class::__ANON__::SERIAL::18::_inline_get_old_value_for_trigger or Class::MOP::Class::__ANON__::SERIAL::18::_inline_tc_code or Class::MOP::Class::__ANON__::SERIAL::18::_new or Class::MOP::Class::__ANON__::SERIAL::18::_value_needs_copy or Class::MOP::Class::__ANON__::SERIAL::18::new or Class::MOP::Class::__ANON__::SERIAL::19::_canonicalize_handles or Class::MOP::Class::__ANON__::SERIAL::19::_make_delegation_method or Class::MOP::Class::__ANON__::SERIAL::20::_new or Class::MOP::Class::__ANON__::SERIAL::20::new or Class::MOP::Class::__ANON__::SERIAL::21::_new or Class::MOP::Class::__ANON__::SERIAL::21::new or Class::MOP::Class::__ANON__::SERIAL::22::_new or Class::MOP::Class::__ANON__::SERIAL::22::new or Class::MOP::Class::__ANON__::SERIAL::2::_generate_BUILDALL or Class::MOP::Class::__ANON__::SERIAL::5::_canonicalize_handles or Class::MOP::Class::__ANON__::SERIAL::5::_make_delegation_method or Class::MOP::Class::__ANON__::SERIAL::6::_new or Class::MOP::Class::__ANON__::SERIAL::6::new or Class::MOP::Class::__ANON__::SERIAL::7::_eval_environment or Class::MOP::Class::__ANON__::SERIAL::7::_inline_check_argument_count or Class::MOP::Class::__ANON__::SERIAL::7::_inline_coerce_new_values or Class::MOP::Class::__ANON__::SERIAL::7::_inline_get_old_value_for_trigger or Class::MOP::Class::__ANON__::SERIAL::7::_inline_tc_code or Class::MOP::Class::__ANON__::SERIAL::7::_new or Class::MOP::Class::__ANON__::SERIAL::7::_value_needs_copy or Class::MOP::Class::__ANON__::SERIAL::7::new or Class::MOP::Class::__ANON__::SERIAL::8::_canonicalize_handles or Class::MOP::Class::__ANON__::SERIAL::8::_make_delegation_method or Class::MOP::Class::__ANON__::SERIAL::9::_new or Class::MOP::Class::__ANON__::SERIAL::9::new or MooseX::Role::Parameterized::Meta::Parameter::_process_options at line 89, avg 206µs/call
push @_, sub { $f2->( $f1, @_ ) };
# spent 344ms making 1796 calls to Class::MOP::Class:::around, avg 191µs/call, recursion: max depth 4, sum of overlapping time 11.7ms
160 redo;
16118µs }};
162
163
# spent 13.9ms (6.86+7.03) within Class::MOP::Method::Wrapped::add_around_modifier which was called 99 times, avg 140µs/call: # 99 times (6.86ms+7.03ms) by Class::MOP::Class::add_around_method_modifier at line 994 of Class/MOP/Class.pm, avg 140µs/call
sub add_around_modifier {
1644956.84ms my $code = shift;
165 my $modifier = shift;
166 unshift @{$code->{'modifier_table'}->{around}->{methods}} => $modifier;
167 $code->{'modifier_table'}->{around}->{cache} = $compile_around_method->(
1681984.53ms @{$code->{'modifier_table'}->{around}->{methods}},
# spent 3.96ms making 99 calls to Class::MOP::Method::Wrapped::__ANON__[Class/MOP/Method/Wrapped.pm:161], avg 40µs/call # spent 566µs making 99 calls to Class::MOP::Method::body, avg 6µs/call
169 $code->{'modifier_table'}->{orig}->body
170 );
171992.50ms $_build_wrapped_method->($code->{'modifier_table'});
# spent 2.50ms making 99 calls to Class::MOP::Method::Wrapped::__ANON__[Class/MOP/Method/Wrapped.pm:69], avg 25µs/call
172 }
173}
174
175sub around_modifiers {
176 my $code = shift;
177 return @{$code->{'modifier_table'}->{around}->{methods}};
178}
179
180sub _make_compatible_with {
181 my $self = shift;
182 my ($other) = @_;
183
184 # XXX: this is pretty gross. the issue here is that CMOP::Method::Wrapped
185 # objects are subclasses of CMOP::Method, but when we get to moose, they'll
186 # need to be compatible with Moose::Meta::Method, which isn't possible. the
187 # right solution here is to make ::Wrapped into a role that gets applied to
188 # whatever the method_metaclass happens to be and get rid of
189 # wrapped_method_metaclass entirely, but that's not going to happen until
190 # we ditch cmop and get roles into the bootstrapping, so. i'm not
191 # maintaining the previous behavior of turning them into instances of the
192 # new method_metaclass because that's equally broken, and at least this way
193 # any issues will at least be detectable and potentially fixable. -doy
194 return $self unless $other->_is_compatible_with($self->_real_ref_name);
195
196 return $self->SUPER::_make_compatible_with(@_);
197}
198
199116µs1;
200
201__END__
Report produced by the NYTProf 4.04 Perl profiler, developed by Tim Bunce and Adam Kaplan.