← Index
NYTProf Performance Profile   « line view »
For ../prof.pl
  Run on Thu Dec 15 15:23:56 2022
Reported on Thu Dec 15 15:27:03 2022

Filename/Users/ether/.perlbrew/libs/36.0@std/lib/perl5/Sub/Defer.pm
StatementsExecuted 2260 statements in 5.68ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
38221.34ms33.8msSub::Defer::::undefer_sub Sub::Defer::undefer_sub
10922705µs1.48msSub::Defer::::_install_coderef Sub::Defer::_install_coderef
1011601µs694µsSub::Defer::::undefer_package Sub::Defer::undefer_package
3722564µs816µsSub::Defer::::defer_sub Sub::Defer::defer_sub
6862530µs8.85msSub::Defer::::__ANON__[:178] Sub::Defer::__ANON__[:178]
10911280µs607µsSub::Defer::::_name_coderef Sub::Defer::_name_coderef
12331204µs204µsSub::Defer::::_getglob Sub::Defer::_getglob
721181µs81µsSub::Defer::::CORE:regcomp Sub::Defer::CORE:regcomp (opcode)
822159µs59µsSub::Defer::::CORE:match Sub::Defer::CORE:match (opcode)
11126µs27µsSub::Defer::::BEGIN@2 Sub::Defer::BEGIN@2
1116µs18µsSub::Defer::::BEGIN@167 Sub::Defer::BEGIN@167
1116µs20µsSub::Defer::::BEGIN@3 Sub::Defer::BEGIN@3
1115µs10µsSub::Defer::::BEGIN@14 Sub::Defer::BEGIN@14
1115µs19µsSub::Defer::::BEGIN@34 Sub::Defer::BEGIN@34
1115µs11µsSub::Defer::::BEGIN@4 Sub::Defer::BEGIN@4
1115µs20µsSub::Defer::::BEGIN@6 Sub::Defer::BEGIN@6
1115µs12µsSub::Defer::::BEGIN@89 Sub::Defer::BEGIN@89
1114µs7µsSub::Defer::::BEGIN@41 Sub::Defer::BEGIN@41
1114µs23µsSub::Defer::::BEGIN@5 Sub::Defer::BEGIN@5
1112µs2µsSub::Defer::::BEGIN@16 Sub::Defer::BEGIN@16
0000s0sJSON::Schema::Modern::Annotation::::newJSON::Schema::Modern::Annotation::new
0000s0sSub::Defer::::CLONE Sub::Defer::CLONE
0000s0sSub::Defer::::__ANON__[:23] Sub::Defer::__ANON__[:23]
0000s0sSub::Defer::::defer_info Sub::Defer::defer_info
0000s0sSub::Defer::::undefer_all Sub::Defer::undefer_all
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
1package Sub::Defer;
2223µs228µs
# spent 27µs (26+1) within Sub::Defer::BEGIN@2 which was called: # once (26µs+1µs) by Sub::Quote::BEGIN@8 at line 2
use strict;
# spent 27µs making 1 call to Sub::Defer::BEGIN@2 # spent 1µs making 1 call to strict::import
3216µs234µs
# spent 20µs (6+14) within Sub::Defer::BEGIN@3 which was called: # once (6µs+14µs) by Sub::Quote::BEGIN@8 at line 3
use warnings;
# spent 20µs making 1 call to Sub::Defer::BEGIN@3 # spent 14µs making 1 call to warnings::import
4214µs217µs
# spent 11µs (5+6) within Sub::Defer::BEGIN@4 which was called: # once (5µs+6µs) by Sub::Quote::BEGIN@8 at line 4
use Exporter qw(import);
# spent 11µs making 1 call to Sub::Defer::BEGIN@4 # spent 6µs making 1 call to Exporter::import
5212µs242µs
# spent 23µs (4+19) within Sub::Defer::BEGIN@5 which was called: # once (4µs+19µs) by Sub::Quote::BEGIN@8 at line 5
use Scalar::Util qw(weaken);
# spent 23µs making 1 call to Sub::Defer::BEGIN@5 # spent 19µs making 1 call to Exporter::import
6243µs235µs
# spent 20µs (5+15) within Sub::Defer::BEGIN@6 which was called: # once (5µs+15µs) by Sub::Quote::BEGIN@8 at line 6
use Carp qw(croak);
# spent 20µs making 1 call to Sub::Defer::BEGIN@6 # spent 15µs making 1 call to Exporter::import
7
811µsour $VERSION = '2.006006';
919µs$VERSION = eval $VERSION;
# spent 2µs executing statements in string eval
10
1110sour @EXPORT = qw(defer_sub undefer_sub undefer_all);
1211µsour @EXPORT_OK = qw(undefer_package defer_info);
13
14125426µs215µs
# spent 204µs within Sub::Defer::_getglob which was called 123 times, avg 2µs/call: # 109 times (172µs+0s) by Sub::Defer::_install_coderef at line 33, avg 2µs/call # 7 times (24µs+0s) by Sub::Defer::undefer_sub at line 88, avg 3µs/call # 7 times (8µs+0s) by Sub::Defer::undefer_sub at line 93, avg 1µs/call # spent 10µs (5+5) within Sub::Defer::BEGIN@14 which was called: # once (5µs+5µs) by Sub::Quote::BEGIN@8 at line 14
sub _getglob { no strict 'refs'; \*{$_[0]} }
# spent 10µs making 1 call to Sub::Defer::BEGIN@14 # spent 5µs making 1 call to strict::unimport
15
16
# spent 2µs within Sub::Defer::BEGIN@16 which was called: # once (2µs+0s) by Sub::Quote::BEGIN@8 at line 25
BEGIN {
1710s my $no_subname;
18 *_subname
19 = defined &Sub::Util::set_subname ? \&Sub::Util::set_subname
20 : defined &Sub::Name::subname ? \&Sub::Name::subname
21 : (eval { require Sub::Util } && defined &Sub::Util::set_subname) ? \&Sub::Util::set_subname
22 : (eval { require Sub::Name } && defined &Sub::Name::subname ) ? \&Sub::Name::subname
2311µs : ($no_subname = 1, sub { $_[1] });
2413µs *_CAN_SUBNAME = $no_subname ? sub(){0} : sub(){1};
25148µs12µs}
# spent 2µs making 1 call to Sub::Defer::BEGIN@16
26
27
# spent 607µs (280+327) within Sub::Defer::_name_coderef which was called 109 times, avg 6µs/call: # 109 times (280µs+327µs) by Sub::Defer::_install_coderef at line 33, avg 6µs/call
sub _name_coderef {
2810942µs shift if @_ > 2; # three args is (target, name, sub)
29109642µs109327µs _CAN_SUBNAME ? _subname(@_) : $_[1];
# spent 327µs making 109 calls to Sub::Util::set_subname, avg 3µs/call
30}
31
32
# spent 1.48ms (705µs+779µs) within Sub::Defer::_install_coderef which was called 109 times, avg 14µs/call: # 99 times (638µs+678µs) by Sub::Quote::quote_sub at line 223 of Sub/Quote.pm, avg 13µs/call # 10 times (67µs+101µs) by Sub::Defer::defer_sub at line 179, avg 17µs/call
sub _install_coderef {
33109263µs218779µs my ($glob, $code) = (_getglob($_[0]), _name_coderef(@_));
# spent 607µs making 109 calls to Sub::Defer::_name_coderef, avg 6µs/call # spent 172µs making 109 calls to Sub::Defer::_getglob, avg 2µs/call
34223µs233µs
# spent 19µs (5+14) within Sub::Defer::BEGIN@34 which was called: # once (5µs+14µs) by Sub::Quote::BEGIN@8 at line 34
no warnings 'redefine';
# spent 19µs making 1 call to Sub::Defer::BEGIN@34 # spent 14µs making 1 call to warnings::unimport
35109308µs if (*{$glob}{CODE}) {
36 *{$glob} = $code;
37 }
38 # perl will sometimes warn about mismatched prototypes coming from the
39 # inheritance cache, so disable them if we aren't redefining a sub
40 else {
41289µs210µs
# spent 7µs (4+3) within Sub::Defer::BEGIN@41 which was called: # once (4µs+3µs) by Sub::Quote::BEGIN@8 at line 41
no warnings 'prototype';
# spent 7µs making 1 call to Sub::Defer::BEGIN@41 # spent 3µs making 1 call to warnings::unimport
4210944µs *{$glob} = $code;
43 }
44}
45
46# We are dealing with three subs. The first is the generator sub. It is
47# provided by the user, so we cannot modify it. When called, it generates the
48# undeferred sub. This is also created, so it also cannot be modified. These
49# are wrapped in a third sub. The deferred sub is generated by us, and when
50# called it uses the generator sub to create the undeferred sub. If it is a
51# named sub, it is installed in the symbol table, usually overwriting the
52# deferred sub. From then on, the deferred sub will goto the undeferred sub
53# if it is called.
54#
55# In %DEFERRED we store array refs with information about these subs. The key
56# is the stringified subref. We have a CLONE method to fix this up in the
57# case of threading to deal with changing refaddrs. The arrayrefs contain:
58#
59# 0. fully qualified sub name (or undef)
60# 1. generator sub
61# 2. options (attributes)
62# 3. scalar ref to undeferred sub (inner reference weakened)
63# 4. deferred sub (deferred only)
64# 5. info arrayref for undeferred sub (deferred only, after undefer)
65#
66# The deferred sub contains a strong reference to its info arrayref, and the
67# undeferred.
68
69our %DEFERRED;
70
71
# spent 33.8ms (1.34+32.4) within Sub::Defer::undefer_sub which was called 38 times, avg 889µs/call: # 25 times (42µs+0s) by Moo::_Utils::_install_modifier at line 79 of Moo/_Utils.pm, avg 2µs/call # 13 times (1.30ms+32.4ms) by JSON::Schema::Modern::Document::OpenAPI::new or JSON::Schema::Modern::Document::new or JSON::Schema::Modern::Error::new or JSON::Schema::Modern::Result::new or JSON::Schema::Modern::new or Method::Generate::Constructor::new or OpenAPI::Modern::new or Sub::Defer::__ANON__[/Users/ether/.perlbrew/libs/36.0@std/lib/perl5/Sub/Defer.pm:178] at line 176, avg 2.60ms/call
sub undefer_sub {
723817µs my ($deferred) = @_;
733878µs my $info = $DEFERRED{$deferred} or return $deferred;
7413539µs my ($target, $maker, $options, $undeferred_ref, $deferred_sub) = @$info;
75
761315µs if (!(
77 $deferred_sub && $deferred eq $deferred_sub
78 || ${$undeferred_ref} && $deferred eq ${$undeferred_ref}
79 )) {
80 return $deferred;
81 }
82
83 return ${$undeferred_ref}
84137µs if ${$undeferred_ref};
851342µs1332.4ms ${$undeferred_ref} = my $made = $maker->();
# spent 29.3ms making 7 calls to Method::Generate::Constructor::__ANON__[Method/Generate/Constructor.pm:101], avg 4.19ms/call # spent 3.06ms making 6 calls to Sub::Quote::__ANON__[Sub/Quote.pm:232], avg 510µs/call
86
87 # make sure the method slot has not changed since deferral time
881338µs724µs if (defined($target) && $deferred eq *{_getglob($target)}{CODE}||'') {
# spent 24µs making 7 calls to Sub::Defer::_getglob, avg 3µs/call
892332µs219µs
# spent 12µs (5+7) within Sub::Defer::BEGIN@89 which was called: # once (5µs+7µs) by Sub::Quote::BEGIN@8 at line 89
no warnings 'redefine';
# spent 12µs making 1 call to Sub::Defer::BEGIN@89 # spent 7µs making 1 call to warnings::unimport
90
91 # I believe $maker already evals with the right package/name, so that
92 # _install_coderef calls are not necessary --ribasushi
93712µs78µs *{_getglob($target)} = $made;
# spent 8µs making 7 calls to Sub::Defer::_getglob, avg 1µs/call
94 }
951316µs my $undefer_info = [ $target, $maker, $options, $undeferred_ref ];
961325µs $info->[5] = $DEFERRED{$made} = $undefer_info;
971339µs1313µs weaken ${$undefer_info->[3]};
# spent 13µs making 13 calls to Scalar::Util::weaken, avg 1µs/call
98
991353µs return $made;
100}
101
102sub undefer_all {
103 undefer_sub($_) for keys %DEFERRED;
104 return;
105}
106
107
# spent 694µs (601+93) within Sub::Defer::undefer_package which was called 10 times, avg 69µs/call: # 10 times (601µs+93µs) by Moo::Role::_undefer_subs at line 288 of Moo/Role.pm, avg 69µs/call
sub undefer_package {
108104µs my $package = shift;
109 undefer_sub($_)
11010150µs for grep {
111333213µs my $name = $DEFERRED{$_} && $DEFERRED{$_}[0];
112333313µs14493µs $name && $name =~ /^${package}::[^:]+$/
# spent 81µs making 72 calls to Sub::Defer::CORE:regcomp, avg 1µs/call # spent 12µs making 72 calls to Sub::Defer::CORE:match, avg 167ns/call
113 } keys %DEFERRED;
1141017µs return;
115}
116
117sub defer_info {
118 my ($deferred) = @_;
119 my $info = $DEFERRED{$deferred||''} or return undef;
120
121 my ($target, $maker, $options, $undeferred_ref, $deferred_sub) = @$info;
122 if (!(
123 $deferred_sub && $deferred eq $deferred_sub
124 || ${$undeferred_ref} && $deferred eq ${$undeferred_ref}
125 )) {
126 delete $DEFERRED{$deferred};
127 return undef;
128 }
129 [
130 $target, $maker, $options,
131 ( $undeferred_ref && $$undeferred_ref ? $$undeferred_ref : ()),
132 ];
133}
134
135
# spent 816µs (564+252) within Sub::Defer::defer_sub which was called 37 times, avg 22µs/call: # 27 times (383µs+22µs) by Sub::Quote::quote_sub at line 235 of Sub/Quote.pm, avg 15µs/call # 10 times (181µs+230µs) by Method::Generate::Constructor::install_delayed at line 101 of Method/Generate/Constructor.pm, avg 41µs/call
sub defer_sub {
1363716µs my ($target, $maker, $options) = @_;
137378µs my $package;
138 my $subname;
1393781µs1047µs ($package, $subname) = $target =~ /^(.*)::([^:]+)$/
# spent 47µs making 10 calls to Sub::Defer::CORE:match, avg 5µs/call
140 or croak "$target is not a fully qualified sub name!"
141 if $target;
1423721µs $package ||= $options && $options->{package} || caller;
1433737µs my @attributes = @{$options && $options->{attributes} || []};
1443711µs if (@attributes) {
145 /\A\w+(?:\(.*\))?\z/s || croak "invalid attribute $_"
146 for @attributes;
147 }
148377µs my $deferred;
149 my $undeferred;
1503739µs my $deferred_info = [ $target, $maker, $options, \$undeferred ];
1513719µs if (@attributes || $target && !_CAN_SUBNAME) {
152 my $code
153 = q[#line ].(__LINE__+2).q[ "].__FILE__.qq["\n]
154 . qq[package $package;\n]
155 . ($target ? "sub $subname" : '+sub') . join('', map " :$_", @attributes)
156 . q[ {
157 package Sub::Defer;
158 # uncoverable subroutine
159 # uncoverable statement
160 $undeferred ||= undefer_sub($deferred_info->[4]);
161 goto &$undeferred; # uncoverable statement
162 $undeferred; # fake lvalue return
163 }]."\n"
164 . ($target ? "\\&$subname" : '');
165 my $e;
166 $deferred = do {
1672170µs230µs
# spent 18µs (6+12) within Sub::Defer::BEGIN@167 which was called: # once (6µs+12µs) by Sub::Quote::BEGIN@8 at line 167
no warnings qw(redefine closure);
# spent 18µs making 1 call to Sub::Defer::BEGIN@167 # spent 12µs making 1 call to warnings::unimport
168 local $@;
169 eval $code or $e = $@; # uncoverable branch true
170 };
171 die $e if defined $e; # uncoverable branch true
172 }
173 else {
174 # duplicated from above
175
# spent 8.85ms (530µs+8.32) within Sub::Defer::__ANON__[/Users/ether/.perlbrew/libs/36.0@std/lib/perl5/Sub/Defer.pm:178] which was called 68 times, avg 130µs/call: # 36 times (250µs+2.85ms) by JSON::Schema::Modern::Document::__ANON__[/Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern/Document.pm:135] at line 120 of /Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern/Document.pm, avg 86µs/call # 24 times (169µs+2.98ms) by JSON::Schema::Modern::__ANON__[/Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern.pm:685] at line 659 of /Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern.pm, avg 131µs/call # 5 times (38µs+572µs) by JSON::Schema::Modern::__ANON__[/Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern.pm:124] at line 124 of /Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern.pm, avg 122µs/call # once (20µs+932µs) by JSON::Schema::Modern::add_vocabulary at line 715 of /Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern.pm # once (13µs+720µs) by JSON::Schema::Modern::add_vocabulary at line 720 of /Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern.pm # once (40µs+269µs) by JSON::Schema::Modern::add_vocabulary at line 721 of /Users/ether/git/JSON-Schema-Modern/lib/JSON/Schema/Modern.pm
$deferred = sub {
17675566µs1333.7ms $undeferred ||= undefer_sub($deferred_info->[4]);
# spent 33.7ms making 13 calls to Sub::Defer::undefer_sub, avg 2.60ms/call
17775368µs75141s goto &$undeferred;
# spent 70.7s making 1 call to OpenAPI::Modern::new # spent 70.6s making 1 call to JSON::Schema::Modern::Document::OpenAPI::new # spent 8.00ms making 1 call to JSON::Schema::Modern::Document::new # spent 5.69ms making 36 calls to Type::Tiny::__ANON__[(eval 432)[Sub/Quote.pm:3]:16], avg 158µs/call # spent 4.20ms making 24 calls to Type::Tiny::__ANON__[(eval 434)[Sub/Quote.pm:3]:16], avg 175µs/call # spent 3.15ms making 1 call to JSON::Schema::Modern::Result::new # spent 91µs making 1 call to Type::Tiny::__ANON__[(eval 425)[Sub/Quote.pm:3]:16] # spent 80µs making 1 call to JSON::Schema::Modern::Error::new # spent 54µs making 1 call to Type::Tiny::__ANON__[(eval 423)[Sub/Quote.pm:3]:16] # spent 52µs making 5 calls to Type::Tiny::__ANON__[(eval 427)[Sub/Quote.pm:3]:16], avg 10µs/call # spent 39µs making 1 call to JSON::Schema::Modern::new # spent 10µs making 1 call to Method::Generate::Constructor::new # spent 5µs making 1 call to Type::Tiny::__ANON__[(eval 426)[Sub/Quote.pm:3]:16]
1783757µs };
1793722µs10168µs _install_coderef($target, $deferred)
# spent 168µs making 10 calls to Sub::Defer::_install_coderef, avg 17µs/call
180 if $target;
181 }
18237145µs3728µs weaken($deferred_info->[4] = $deferred);
# spent 28µs making 37 calls to Scalar::Util::weaken, avg 757ns/call
1833799µs379µs weaken($DEFERRED{$deferred} = $deferred_info);
# spent 9µs making 37 calls to Scalar::Util::weaken, avg 243ns/call
1843794µs return $deferred;
185}
186
187sub CLONE {
188 %DEFERRED = map {
189 defined $_ ? (
190 $_->[4] ? ($_->[4] => $_)
191 : ($_->[3] && ${$_->[3]}) ? (${$_->[3]} => $_)
192 : ()
193 ) : ()
194 } values %DEFERRED;
195}
196
19713µs1;
198__END__
 
# spent 59µs within Sub::Defer::CORE:match which was called 82 times, avg 720ns/call: # 72 times (12µs+0s) by Sub::Defer::undefer_package at line 112, avg 167ns/call # 10 times (47µs+0s) by Sub::Defer::defer_sub at line 139, avg 5µs/call
sub Sub::Defer::CORE:match; # opcode
# spent 81µs within Sub::Defer::CORE:regcomp which was called 72 times, avg 1µs/call: # 72 times (81µs+0s) by Sub::Defer::undefer_package at line 112, avg 1µs/call
sub Sub::Defer::CORE:regcomp; # opcode
Report produced by the NYTProf 6.12 Perl profiler, developed by Tim Bunce based on work by Adam Kaplan and Salvador Fandiño García.