← Index
NYTProf Performance Profile   « line view »
For starman worker -M FindBin --max-requests 50 --workers 2 --user=kohadev-koha --group kohadev-koha --pid /var/run/koha/kohadev/plack.pid --daemonize --access-log /var/log/koha/kohadev/plack.log --error-log /var/log/koha/kohadev/plack-error.log -E deployment --socket /var/run/koha/kohadev/plack.sock /etc/koha/sites/kohadev/plack.psgi
  Run on Fri Jan 8 14:16:49 2016
Reported on Fri Jan 8 14:23:07 2016

Filename/usr/share/perl5/Sub/Quote.pm
StatementsExecuted 0 statements in 0s
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
53913630.4ms69.1msSub::Quote::::quote_subSub::Quote::quote_sub
11601337.38ms8.67msSub::Quote::::quotifySub::Quote::quotify
10113.51ms3.87msSub::Quote::::_clean_evalSub::Quote::_clean_eval
1112.29ms3.12msSub::Quote::::BEGIN@10Sub::Quote::BEGIN@10
111649µs813µsSub::Quote::::BEGIN@3Sub::Quote::BEGIN@3
111646µs4.19msSub::Quote::::BEGIN@7Sub::Quote::BEGIN@7
1022524µs4.71msSub::Quote::::unquote_subSub::Quote::unquote_sub
1011185µs302µsSub::Quote::::capture_unrollSub::Quote::capture_unroll
41139µs66µsSub::Quote::::inlinifySub::Quote::inlinify
201134µs34µsSub::Quote::::CORE:matchSub::Quote::CORE:match (opcode)
81133µs3.21msSub::Quote::::__ANON__[:100]Sub::Quote::__ANON__[:100]
41129µs29µsSub::Quote::::quoted_from_subSub::Quote::quoted_from_sub
82127µs27µsSub::Quote::::CORE:substSub::Quote::CORE:subst (opcode)
11112µs22µsSub::Quote::::BEGIN@152Sub::Quote::BEGIN@152
1118µs24µsSub::Quote::::BEGIN@8Sub::Quote::BEGIN@8
1116µs11µsSub::Quote::::BEGIN@9Sub::Quote::BEGIN@9
1116µs6µsSub::Quote::::BEGIN@11Sub::Quote::BEGIN@11
0000s0sSub::Quote::::CLONESub::Quote::CLONE
0000s0sSub::Quote::::qsubSub::Quote::qsub
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
1package Sub::Quote;
2
33873µs
# spent 813µs (649+164) within Sub::Quote::BEGIN@3 which was called: # once (649µs+164µs) by DBIx::Class::_Util::BEGIN@64 at line 3
use strictures 1;
# spent 813µs making 1 call to Sub::Quote::BEGIN@3 # spent 37µs making 1 call to strictures::VERSION # spent 23µs making 1 call to strictures::import
4
5
# spent 3.87ms (3.51+363µs) within Sub::Quote::_clean_eval which was called 10 times, avg 387µs/call: # 10 times (3.51ms+363µs) by Sub::Quote::unquote_sub at line 157, avg 387µs/call
sub _clean_eval { eval $_[0] }
# spent 0s executing statements in string eval
# includes 74µs spent executing 5 calls to 3 subs defined therein. # spent 0s executing statements in string eval
# includes 75µs spent executing 5 calls to 4 subs defined therein. # spent 0s executing statements in string eval
# includes 37µs spent executing 4 calls to 3 subs defined therein. # spent 0s executing statements in string eval
# includes 64µs spent executing 5 calls to 4 subs defined therein. # spent 0s executing statements in string eval
# includes 1.73ms spent executing 154 calls to 3 subs defined therein. # spent 0s executing statements in string eval
# includes 2.30ms spent executing 422 calls to 3 subs defined therein. # spent 0s executing statements in string eval
# includes 741µs spent executing 125 calls to 3 subs defined therein. # spent 0s executing statements in string eval
# includes 982µs spent executing 136 calls to 3 subs defined therein. # spent 0s executing statements in string eval
# includes 408µs spent executing 22 calls to 3 subs defined therein. # spent 0s executing statements in string eval
# includes 44µs spent executing 4 calls to 3 subs defined therein.
6
724.21ms
# spent 4.19ms (646µs+3.55) within Sub::Quote::BEGIN@7 which was called: # once (646µs+3.55ms) by DBIx::Class::_Util::BEGIN@64 at line 7
use Sub::Defer;
# spent 4.19ms making 1 call to Sub::Quote::BEGIN@7 # spent 22µs making 1 call to Exporter::import
8239µs
# spent 24µs (8+15) within Sub::Quote::BEGIN@8 which was called: # once (8µs+15µs) by DBIx::Class::_Util::BEGIN@64 at line 8
use Scalar::Util qw(weaken);
# spent 24µs making 1 call to Sub::Quote::BEGIN@8 # spent 16µs making 1 call to Exporter::import
9216µs
# spent 11µs (6+5) within Sub::Quote::BEGIN@9 which was called: # once (6µs+5µs) by DBIx::Class::_Util::BEGIN@64 at line 9
use Exporter qw(import);
# spent 11µs making 1 call to Sub::Quote::BEGIN@9 # spent 5µs making 1 call to Exporter::import
1013.12ms
# spent 3.12ms (2.29+828µs) within Sub::Quote::BEGIN@10 which was called: # once (2.29ms+828µs) by DBIx::Class::_Util::BEGIN@64 at line 10
use B ();
# spent 3.12ms making 1 call to Sub::Quote::BEGIN@10
11
# spent 6µs within Sub::Quote::BEGIN@11 which was called: # once (6µs+0s) by DBIx::Class::_Util::BEGIN@64 at line 13
BEGIN {
12 *_HAVE_PERLSTRING = defined &B::perlstring ? sub(){1} : sub(){0};
1316µs}
# spent 6µs making 1 call to Sub::Quote::BEGIN@11
14
15our $VERSION = '1.006001';
16$VERSION = eval $VERSION;
# spent 0s executing statements in string eval
17
18our @EXPORT = qw(quote_sub unquote_sub quoted_from_sub qsub);
19our @EXPORT_OK = qw(quotify capture_unroll inlinify);
20
21our %QUOTED;
22
23
# spent 8.67ms (7.38+1.29) within Sub::Quote::quotify which was called 1160 times, avg 7µs/call: # 1078 times (7.15ms+1.20ms) by Sub::Quote::quote_sub at line 81, avg 8µs/call # 20 times (57µs+26µs) by Sub::Quote::capture_unroll at line 36, avg 4µs/call # 16 times (44µs+13µs) by Method::Generate::Accessor::_generate_core_set at line 564 of Method/Generate/Accessor.pm, avg 4µs/call # 16 times (32µs+15µs) by Method::Generate::Accessor::_generate_simple_set at line 570 of Method/Generate/Accessor.pm, avg 3µs/call # 11 times (26µs+11µs) by Method::Generate::Constructor::_assign_new at line 176 of Method/Generate/Constructor.pm, avg 3µs/call # 6 times (13µs+6µs) by Method::Generate::Accessor::_generate_simple_get at line 334 of Method/Generate/Accessor.pm, avg 3µs/call # 3 times (17µs+6µs) by Method::Generate::Accessor::_generate_simple_has at line 271 of Method/Generate/Accessor.pm, avg 8µs/call # 3 times (5µs+2µs) by Method::Generate::Accessor::_wrap_attr_exception at line 419 of Method/Generate/Accessor.pm, avg 3µs/call # 2 times (18µs+8µs) by Method::Generate::Constructor::_handle_subconstructor at line 121 of Method/Generate/Constructor.pm, avg 13µs/call # 2 times (4µs+2µs) by Method::Generate::Accessor::_generate_get_default at line 315 of Method/Generate/Accessor.pm, avg 3µs/call # once (6µs+2µs) by Method::Generate::Accessor::_generate_simple_clear at line 276 of Method/Generate/Accessor.pm # once (2µs+2µs) by Method::Generate::Accessor::_wrap_attr_exception at line 418 of Method/Generate/Accessor.pm # once (2µs+1µs) by Method::Generate::Accessor::_attr_desc at line 382 of Method/Generate/Accessor.pm
sub quotify {
2411601.29ms ! defined $_[0] ? 'undef()'
# spent 1.29ms making 1160 calls to B::perlstring, avg 1µs/call
25 : _HAVE_PERLSTRING ? B::perlstring($_[0])
26 : qq["\Q$_[0]\E"];
27}
28
29
# spent 302µs (185+117) within Sub::Quote::capture_unroll which was called 10 times, avg 30µs/call: # 10 times (185µs+117µs) by Sub::Quote::unquote_sub at line 132, avg 30µs/call
sub capture_unroll {
30 my ($from, $captures, $indent) = @_;
312034µs join(
# spent 34µs making 20 calls to Sub::Quote::CORE:match, avg 2µs/call
32 '',
33 map {
34 /^([\@\%\$])/
35 or die "capture key should start with \@, \% or \$: $_";
362083µs (' ' x $indent).qq{my ${_} = ${1}{${from}->{${\quotify $_}}};\n};
# spent 83µs making 20 calls to Sub::Quote::quotify, avg 4µs/call
37 } keys %$captures
38 );
39}
40
41
# spent 66µs (39+27) within Sub::Quote::inlinify which was called 4 times, avg 16µs/call: # 4 times (39µs+27µs) by Method::Generate::Accessor::_generate_call_code at line 473 of Method/Generate/Accessor.pm, avg 16µs/call
sub inlinify {
42 my ($code, $args, $extra, $local) = @_;
43 my $do = 'do { '.($extra||'');
44423µs if ($code =~ s/^(\s*package\s+([a-zA-Z0-9:]+);)//) {
# spent 23µs making 4 calls to Sub::Quote::CORE:subst, avg 6µs/call
45 $do .= $1;
46 }
4744µs if ($code =~ s{(\A\s*|\A# BEGIN quote_sub PRELUDE\n.*?# END quote_sub PRELUDE\n\s*)(^\s*)(my\s*\(([^)]+)\)\s*=\s*\@_;)$}{
# spent 4µs making 4 calls to Sub::Quote::CORE:subst, avg 1µs/call
48 my ($pre, $indent, $assign, $code_args) = ($1, $2, $3, $4);
49 if ($code_args eq $args) {
50 $pre . $indent . ($local ? 'local ' : '').'@_ = ('.$args.");\n"
51 . $indent . $assign;
52 }
53 else {
54 $pre . 'my ('.$code_args.') = ('.$args.'); ';
55 }
56 }mse) {
57 #done
58 }
59 elsif ($local || $args ne '@_') {
60 $do .= ($local ? 'local ' : '').'@_ = ('.$args.'); ';
61 }
62 $do.$code.' }';
63}
64
65
# spent 69.1ms (30.4+38.8) within Sub::Quote::quote_sub which was called 539 times, avg 128µs/call: # 144 times (2.78ms+18.6ms) by DBIx::Class::Relationship::Accessor::add_relationship_accessor at line 101 of DBIx/Class/Relationship/Accessor.pm, avg 149µs/call # 144 times (3.71ms+10.8ms) by DBIx::Class::Relationship::Accessor::add_relationship_accessor at line 99 of DBIx/Class/Relationship/Accessor.pm, avg 101µs/call # 144 times (2.92ms+5.02ms) by DBIx::Class::Relationship::Accessor::add_relationship_accessor at line 100 of DBIx/Class/Relationship/Accessor.pm, avg 55µs/call # 53 times (9.43ms+2.51ms) by DBIx::Class::Relationship::Accessor::add_relationship_accessor at line 26 of DBIx/Class/Relationship/Accessor.pm, avg 225µs/call # 22 times (445µs+694µs) by base::import at line 84 of DBIx/Class/ResultSourceProxy.pm, avg 52µs/call # 18 times (10.7ms+593µs) by Class::C3::Componentised::ensure_class_loaded at line 124 of DBIx/Class/Storage/DBI.pm, avg 625µs/call # 4 times (105µs+77µs) by DBIx::Class::Storage::BEGIN@16 at line 76 of DBIx/Class/_Util.pm, avg 45µs/call # 3 times (58µs+90µs) by Class::C3::Componentised::ensure_class_loaded at line 1625 of DBIx/Class/Storage/DBI.pm, avg 49µs/call # 2 times (102µs+158µs) by Method::Generate::Accessor::generate_method at line 116 of Method/Generate/Accessor.pm, avg 130µs/call # 2 times (82µs+66µs) by Method::Generate::Constructor::generate_method at line 114 of Method/Generate/Constructor.pm, avg 74µs/call # once (35µs+40µs) by Method::Generate::Accessor::generate_method at line 183 of Method/Generate/Accessor.pm # once (26µs+38µs) by Method::Generate::Accessor::generate_method at line 137 of Method/Generate/Accessor.pm # once (24µs+40µs) by Method::Generate::Accessor::generate_method at line 156 of Method/Generate/Accessor.pm
sub quote_sub {
66 # HOLY DWIMMERY, BATMAN!
67 # $name => $code => \%captures => \%options
68 # $name => $code => \%captures
69 # $name => $code
70 # $code => \%captures => \%options
71 # $code
72 my $options =
73 (ref($_[-1]) eq 'HASH' and ref($_[-2]) eq 'HASH')
74 ? pop
75 : {};
76 my $captures = ref($_[-1]) eq 'HASH' ? pop : undef;
77 undef($captures) if $captures && !keys %$captures;
78 my $code = pop;
79 my $name = $_[0];
80 my ($package, $hints, $bitmask, $hintshash) = (caller(0))[0,8,9,10];
8110788.35ms my $context
# spent 8.35ms making 1078 calls to Sub::Quote::quotify, avg 8µs/call
82 ="# BEGIN quote_sub PRELUDE\n"
83 ."package $package;\n"
84 ."BEGIN {\n"
85 ." \$^H = ".quotify($hints).";\n"
86 ." \${^WARNING_BITS} = ".quotify($bitmask).";\n"
87 ." \%^H = (\n"
88 . join('', map
89 " ".quotify($_)." => ".quotify($hintshash->{$_}).",",
90 keys %$hintshash)
91 ." );\n"
92 ."}\n"
93 ."# END quote_sub PRELUDE\n";
94 $code = "$context$code";
95 my $quoted_info;
96 my $unquoted;
97
# spent 3.21ms (33µs+3.18) within Sub::Quote::__ANON__[/usr/share/perl5/Sub/Quote.pm:100] which was called 8 times, avg 401µs/call: # 8 times (33µs+3.18ms) by Sub::Defer::undefer_sub at line 22 of Sub/Defer.pm, avg 401µs/call
my $deferred = defer_sub +($options->{no_install} ? undef : $name) => sub {
98 $unquoted if 0;
9983.18ms unquote_sub($quoted_info->[4]);
# spent 3.18ms making 8 calls to Sub::Quote::unquote_sub, avg 397µs/call
10053929.4ms };
# spent 29.4ms making 539 calls to Sub::Defer::defer_sub, avg 54µs/call
101 $quoted_info = [ $name, $code, $captures, \$unquoted, $deferred ];
102539512µs weaken($quoted_info->[3]);
# spent 512µs making 539 calls to Scalar::Util::weaken, avg 950ns/call
103539284µs weaken($quoted_info->[4]);
# spent 284µs making 539 calls to Scalar::Util::weaken, avg 527ns/call
104539250µs weaken($QUOTED{$deferred} = $quoted_info);
# spent 250µs making 539 calls to Scalar::Util::weaken, avg 464ns/call
105 return $deferred;
106}
107
108
# spent 29µs within Sub::Quote::quoted_from_sub which was called 4 times, avg 7µs/call: # 4 times (29µs+0s) by Method::Generate::Accessor::_generate_call_code at line 460 of Method/Generate/Accessor.pm, avg 7µs/call
sub quoted_from_sub {
109 my ($sub) = @_;
110 my $quoted_info = $QUOTED{$sub||''} or return undef;
111 my ($name, $code, $captured, $unquoted, $deferred) = @{$quoted_info};
112 $unquoted &&= $$unquoted;
113 if (($deferred && $deferred eq $sub)
114 || ($unquoted && $unquoted eq $sub)) {
115 return [ $name, $code, $captured, $unquoted, $deferred ];
116 }
117 return undef;
118}
119
120
# spent 4.71ms (524µs+4.19) within Sub::Quote::unquote_sub which was called 10 times, avg 471µs/call: # 8 times (446µs+2.73ms) by Sub::Quote::__ANON__[/usr/share/perl5/Sub/Quote.pm:100] at line 99, avg 397µs/call # 2 times (78µs+1.46ms) by Method::Generate::Constructor::__ANON__[/usr/share/perl5/Method/Generate/Constructor.pm:81] at line 78 of Method/Generate/Constructor.pm, avg 769µs/call
sub unquote_sub {
121 my ($sub) = @_;
122 my $quoted = $QUOTED{$sub} or return undef;
123 my $unquoted = $quoted->[3];
124 unless ($unquoted && $$unquoted) {
125 my ($name, $code, $captures) = @$quoted;
126
127 my $make_sub = "{\n";
128
129 my %captures = $captures ? %$captures : ();
130 $captures{'$_UNQUOTED'} = \$unquoted;
131 $captures{'$_QUOTED'} = \$quoted;
13210302µs $make_sub .= capture_unroll("\$_[1]", \%captures, 2);
# spent 302µs making 10 calls to Sub::Quote::capture_unroll, avg 30µs/call
133
134 $make_sub .= (
135 $name
136 # disable the 'variable $x will not stay shared' warning since
137 # we're not letting it escape from this scope anyway so there's
138 # nothing trying to share it
139 ? " no warnings 'closure';\n sub ${name} {\n"
140 : " \$\$_UNQUOTED = sub {\n"
141 );
142 $make_sub .= " \$_QUOTED if 0;\n";
143 $make_sub .= " \$_UNQUOTED if 0;\n";
144 $make_sub .= $code;
145 $make_sub .= " }".($name ? '' : ';')."\n";
146 if ($name) {
147 $make_sub .= " \$\$_UNQUOTED = \\&${name}\n";
148 }
149 $make_sub .= "}\n1;\n";
150 $ENV{SUB_QUOTE_DEBUG} && warn $make_sub;
151 {
152232µs
# spent 22µs (12+10) within Sub::Quote::BEGIN@152 which was called: # once (12µs+10µs) by DBIx::Class::_Util::BEGIN@64 at line 152
no strict 'refs';
# spent 22µs making 1 call to Sub::Quote::BEGIN@152 # spent 10µs making 1 call to strict::unimport
153 local *{$name} if $name;
154 my ($success, $e);
155 {
156 local $@;
157103.87ms $success = _clean_eval($make_sub, \%captures);
# spent 3.87ms making 10 calls to Sub::Quote::_clean_eval, avg 387µs/call
158 $e = $@;
159 }
160 unless ($success) {
161 die "Eval went very, very wrong:\n\n${make_sub}\n\n$e";
162 }
1631020µs weaken($QUOTED{$$unquoted} = $quoted);
# spent 20µs making 10 calls to Scalar::Util::weaken, avg 2µs/call
164 }
165 }
166 $$unquoted;
167}
168
169sub qsub ($) {
170 goto &quote_sub;
171}
172
173sub CLONE {
174 %QUOTED = map { defined $_ ? (
175 $_->[3] && ${$_->[3]} ? (${ $_->[3] } => $_) : (),
176 $_->[4] ? ($_->[4] => $_) : (),
177 ) : () } values %QUOTED;
178 weaken($_) for values %QUOTED;
179}
180
1811;
182__END__
 
# spent 34µs within Sub::Quote::CORE:match which was called 20 times, avg 2µs/call: # 20 times (34µs+0s) by Sub::Quote::capture_unroll at line 31, avg 2µs/call
sub Sub::Quote::CORE:match; # opcode
# spent 27µs within Sub::Quote::CORE:subst which was called 8 times, avg 3µs/call: # 4 times (23µs+0s) by Sub::Quote::inlinify at line 44, avg 6µs/call # 4 times (4µs+0s) by Sub::Quote::inlinify at line 47, avg 1µs/call
sub Sub::Quote::CORE:subst; # opcode
Report produced by the NYTProf 6.02 Perl profiler, developed by Tim Bunce and Adam Kaplan.