← Index
NYTProf Performance Profile   « line view »
For t/bug-md-11.t
  Run on Fri Mar 8 13:27:24 2024
Reported on Fri Mar 8 13:30:23 2024

Filename/home/micha/.plenv/versions/5.38.2/lib/perl5/site_perl/5.38.2/Test2/Event.pm
StatementsExecuted 65 statements in 1.89ms
Subroutines
Calls P F Exclusive
Time
Inclusive
Time
Subroutine
111274µs450µsTest2::Event::::BEGIN@21Test2::Event::BEGIN@21
111265µs835µsTest2::Event::::BEGIN@20Test2::Event::BEGIN@20
111225µs340µsTest2::Event::::BEGIN@22Test2::Event::BEGIN@22
111140µs252µsTest2::Event::::BEGIN@17Test2::Event::BEGIN@17
111138µs274µsTest2::Event::::BEGIN@24Test2::Event::BEGIN@24
111137µs224µsTest2::Event::::BEGIN@18Test2::Event::BEGIN@18
111134µs228µsTest2::Event::::BEGIN@14Test2::Event::BEGIN@14
111132µs230µsTest2::Event::::BEGIN@19Test2::Event::BEGIN@19
111128µs206µsTest2::Event::::BEGIN@15Test2::Event::BEGIN@15
111124µs208µsTest2::Event::::BEGIN@16Test2::Event::BEGIN@16
11119µs24µsTest2::Event::::common_facet_dataTest2::Event::common_facet_data
11110µs12µsTest2::Event::::BEGIN@2Test2::Event::BEGIN@2
3118µs14µsTest2::Event::::eidTest2::Event::eid
3116µs6µsTest2::Event::::add_hubTest2::Event::add_hub
1115µs71µsTest2::Event::::BEGIN@10Test2::Event::BEGIN@10
1115µs38µsTest2::Event::::BEGIN@7Test2::Event::BEGIN@7
1114µs24µsTest2::Event::::BEGIN@11Test2::Event::BEGIN@11
2224µs4µsTest2::Event::::meta_facet_dataTest2::Event::meta_facet_data
1113µs16µsTest2::Event::::BEGIN@12Test2::Event::BEGIN@12
1113µs17µsTest2::Event::::BEGIN@8Test2::Event::BEGIN@8
1113µs19µsTest2::Event::::BEGIN@3Test2::Event::BEGIN@3
1112µs2µsTest2::Event::::BEGIN@23Test2::Event::BEGIN@23
0000s0sTest2::Event::::FACET_TYPESTest2::Event::FACET_TYPES
0000s0sTest2::Event::::add_amnestyTest2::Event::add_amnesty
0000s0sTest2::Event::::callbackTest2::Event::callback
0000s0sTest2::Event::::causes_failTest2::Event::causes_fail
0000s0sTest2::Event::::diagnosticsTest2::Event::diagnostics
0000s0sTest2::Event::::facet_dataTest2::Event::facet_data
0000s0sTest2::Event::::facetsTest2::Event::facets
0000s0sTest2::Event::::globalTest2::Event::global
0000s0sTest2::Event::::in_subtestTest2::Event::in_subtest
0000s0sTest2::Event::::increments_countTest2::Event::increments_count
0000s0sTest2::Event::::load_facetTest2::Event::load_facet
0000s0sTest2::Event::::nestedTest2::Event::nested
0000s0sTest2::Event::::no_displayTest2::Event::no_display
0000s0sTest2::Event::::relatedTest2::Event::related
0000s0sTest2::Event::::sets_planTest2::Event::sets_plan
0000s0sTest2::Event::::subtest_idTest2::Event::subtest_id
0000s0sTest2::Event::::summaryTest2::Event::summary
0000s0sTest2::Event::::terminateTest2::Event::terminate
0000s0sTest2::Event::::validate_facet_dataTest2::Event::validate_facet_data
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments
Time
on line
Calls Time
in subs
Code
1package Test2::Event;
2219µs214µs
# spent 12µs (10+2) within Test2::Event::BEGIN@2 which was called: # once (10µs+2µs) by Test2::Event::Ok::BEGIN@8 at line 2
use strict;
# spent 12µs making 1 call to Test2::Event::BEGIN@2 # spent 2µs making 1 call to strict::import
3228µs235µs
# spent 19µs (3+16) within Test2::Event::BEGIN@3 which was called: # once (3µs+16µs) by Test2::Event::Ok::BEGIN@8 at line 3
use warnings;
# spent 19µs making 1 call to Test2::Event::BEGIN@3 # spent 16µs making 1 call to warnings::import
4
51300nsour $VERSION = '1.302198';
6
7217µs271µs
# spent 38µs (5+33) within Test2::Event::BEGIN@7 which was called: # once (5µs+33µs) by Test2::Event::Ok::BEGIN@8 at line 7
use Scalar::Util qw/blessed reftype/;
# spent 38µs making 1 call to Test2::Event::BEGIN@7 # spent 33µs making 1 call to Exporter::import
8220µs232µs
# spent 17µs (3+14) within Test2::Event::BEGIN@8 which was called: # once (3µs+14µs) by Test2::Event::Ok::BEGIN@8 at line 8
use Carp qw/croak/;
# spent 17µs making 1 call to Test2::Event::BEGIN@8 # spent 14µs making 1 call to Exporter::import
9
10220µs2138µs
# spent 71µs (5+66) within Test2::Event::BEGIN@10 which was called: # once (5µs+66µs) by Test2::Event::Ok::BEGIN@8 at line 10
use Test2::Util::HashBase qw/trace -amnesty uuid -_eid -hubs/;
# spent 71µs making 1 call to Test2::Event::BEGIN@10 # spent 66µs making 1 call to Test2::Util::HashBase::import
11217µs243µs
# spent 24µs (4+20) within Test2::Event::BEGIN@11 which was called: # once (4µs+20µs) by Test2::Event::Ok::BEGIN@8 at line 11
use Test2::Util::ExternalMeta qw/meta get_meta set_meta delete_meta/;
# spent 24µs making 1 call to Test2::Event::BEGIN@11 # spent 20µs making 1 call to Exporter::import
12217µs228µs
# spent 16µs (3+12) within Test2::Event::BEGIN@12 which was called: # once (3µs+12µs) by Test2::Event::Ok::BEGIN@8 at line 12
use Test2::Util qw/pkg_to_file gen_uid/;
# spent 16µs making 1 call to Test2::Event::BEGIN@12 # spent 12µs making 1 call to Exporter::import
13
14278µs1228µs
# spent 228µs (134+94) within Test2::Event::BEGIN@14 which was called: # once (134µs+94µs) by Test2::Event::Ok::BEGIN@8 at line 14
use Test2::EventFacet::About();
# spent 228µs making 1 call to Test2::Event::BEGIN@14
15263µs1206µs
# spent 206µs (128+78) within Test2::Event::BEGIN@15 which was called: # once (128µs+78µs) by Test2::Event::Ok::BEGIN@8 at line 15
use Test2::EventFacet::Amnesty();
# spent 206µs making 1 call to Test2::Event::BEGIN@15
16262µs1208µs
# spent 208µs (124+84) within Test2::Event::BEGIN@16 which was called: # once (124µs+84µs) by Test2::Event::Ok::BEGIN@8 at line 16
use Test2::EventFacet::Assert();
# spent 208µs making 1 call to Test2::Event::BEGIN@16
17271µs1252µs
# spent 252µs (140+112) within Test2::Event::BEGIN@17 which was called: # once (140µs+112µs) by Test2::Event::Ok::BEGIN@8 at line 17
use Test2::EventFacet::Control();
# spent 252µs making 1 call to Test2::Event::BEGIN@17
18267µs1224µs
# spent 224µs (137+87) within Test2::Event::BEGIN@18 which was called: # once (137µs+87µs) by Test2::Event::Ok::BEGIN@8 at line 18
use Test2::EventFacet::Error();
# spent 224µs making 1 call to Test2::Event::BEGIN@18
19271µs1230µs
# spent 230µs (132+98) within Test2::Event::BEGIN@19 which was called: # once (132µs+98µs) by Test2::Event::Ok::BEGIN@8 at line 19
use Test2::EventFacet::Info();
# spent 230µs making 1 call to Test2::Event::BEGIN@19
20271µs1835µs
# spent 835µs (265+570) within Test2::Event::BEGIN@20 which was called: # once (265µs+570µs) by Test2::Event::Ok::BEGIN@8 at line 20
use Test2::EventFacet::Meta();
# spent 835µs making 1 call to Test2::Event::BEGIN@20
212113µs1450µs
# spent 450µs (274+176) within Test2::Event::BEGIN@21 which was called: # once (274µs+176µs) by Test2::Event::Ok::BEGIN@8 at line 21
use Test2::EventFacet::Parent();
# spent 450µs making 1 call to Test2::Event::BEGIN@21
222158µs1340µs
# spent 340µs (225+115) within Test2::Event::BEGIN@22 which was called: # once (225µs+115µs) by Test2::Event::Ok::BEGIN@8 at line 22
use Test2::EventFacet::Plan();
# spent 340µs making 1 call to Test2::Event::BEGIN@22
23210µs12µs
# spent 2µs within Test2::Event::BEGIN@23 which was called: # once (2µs+0s) by Test2::Event::Ok::BEGIN@8 at line 23
use Test2::EventFacet::Trace();
# spent 2µs making 1 call to Test2::Event::BEGIN@23
242940µs1274µs
# spent 274µs (138+136) within Test2::Event::BEGIN@24 which was called: # once (138µs+136µs) by Test2::Event::Ok::BEGIN@8 at line 24
use Test2::EventFacet::Hub();
# spent 274µs making 1 call to Test2::Event::BEGIN@24
25
26# Legacy tools will expect this to be loaded now
271600nsrequire Test2::Util::Trace;
28
2913µsmy %LOADED_FACETS = (
30 'about' => 'Test2::EventFacet::About',
31 'amnesty' => 'Test2::EventFacet::Amnesty',
32 'assert' => 'Test2::EventFacet::Assert',
33 'control' => 'Test2::EventFacet::Control',
34 'errors' => 'Test2::EventFacet::Error',
35 'info' => 'Test2::EventFacet::Info',
36 'meta' => 'Test2::EventFacet::Meta',
37 'parent' => 'Test2::EventFacet::Parent',
38 'plan' => 'Test2::EventFacet::Plan',
39 'trace' => 'Test2::EventFacet::Trace',
40 'hubs' => 'Test2::EventFacet::Hub',
41);
42
43sub FACET_TYPES { sort values %LOADED_FACETS }
44
45sub load_facet {
46 my $class = shift;
47 my ($facet) = @_;
48
49 return $LOADED_FACETS{$facet} if exists $LOADED_FACETS{$facet};
50
51 my @check = ($facet);
52 if ('s' eq substr($facet, -1, 1)) {
53 push @check => substr($facet, 0, -1);
54 }
55 else {
56 push @check => $facet . 's';
57 }
58
59 my $found;
60 for my $check (@check) {
61 my $mod = "Test2::EventFacet::" . ucfirst($facet);
62 my $file = pkg_to_file($mod);
63 next unless eval { require $file; 1 };
64 $found = $mod;
65 last;
66 }
67
68 return undef unless $found;
69 $LOADED_FACETS{$facet} = $found;
70}
71
72sub causes_fail { 0 }
73sub increments_count { 0 }
74sub diagnostics { 0 }
75sub no_display { 0 }
76sub subtest_id { undef }
77
78sub callback { }
79
80sub terminate { () }
81sub global { () }
82sub sets_plan { () }
83
84sub summary { ref($_[0]) }
85
86sub related {
87 my $self = shift;
88 my ($event) = @_;
89
90 my $tracea = $self->trace or return undef;
91 my $traceb = $event->trace or return undef;
92
93 my $uuida = $tracea->uuid;
94 my $uuidb = $traceb->uuid;
95 if ($uuida && $uuidb) {
96 return 1 if $uuida eq $uuidb;
97 return 0;
98 }
99
100 my $siga = $tracea->signature or return undef;
101 my $sigb = $traceb->signature or return undef;
102
103 return 1 if $siga eq $sigb;
104 return 0;
105}
106
107
# spent 6µs within Test2::Event::add_hub which was called 3 times, avg 2µs/call: # 3 times (6µs+0s) by Test2::Hub::send at line 293 of Test2/Hub.pm, avg 2µs/call
sub add_hub {
1083400ns my $self = shift;
10937µs unshift @{$self->{+HUBS}} => @_;
110}
111
112sub add_amnesty {
113 my $self = shift;
114
115 for my $am (@_) {
116 $am = {%$am} if ref($am) ne 'ARRAY';
117 $am = Test2::EventFacet::Amnesty->new($am);
118
119 push @{$self->{+AMNESTY}} => $am;
120 }
121}
122
12337µs36µs
# spent 14µs (8+6) within Test2::Event::eid which was called 3 times, avg 5µs/call: # 3 times (8µs+6µs) by Test2::Hub::send at line 280 of Test2/Hub.pm, avg 5µs/call
sub eid { $_[0]->{+_EID} ||= gen_uid() }
# spent 6µs making 3 calls to Test2::Util::gen_uid, avg 2µs/call
124
125
# spent 24µs (19+5) within Test2::Event::common_facet_data which was called: # once (19µs+5µs) by Test2::Event::Plan::facet_data at line 74 of Test2/Event/Plan.pm
sub common_facet_data {
1261200ns my $self = shift;
127
1281200ns my %out;
129
13012µs $out{about} = {package => ref($self) || undef};
13112µs1800ns if (my $uuid = $self->uuid) {
132 $out{about}->{uuid} = $uuid;
133 }
134
1351600ns $out{about}->{eid} = $self->{+_EID} || $self->eid;
136
13714µs1800ns if (my $trace = $self->trace) {
138 $out{trace} = { %$trace };
139 }
140
14112µs1700ns if (my $hubs = $self->hubs) {
142 $out{hubs} = $hubs;
143 }
144
145 $out{amnesty} = [map {{ %{$_} }} @{$self->{+AMNESTY}}]
1461300ns if $self->{+AMNESTY};
147
14813µs13µs if (my $meta = $self->meta_facet_data) {
# spent 3µs making 1 call to Test2::Event::meta_facet_data
149 $out{meta} = $meta;
150 }
151
15212µs return \%out;
153}
154
155
# spent 4µs within Test2::Event::meta_facet_data which was called 2 times, avg 2µs/call: # once (3µs+0s) by Test2::Event::common_facet_data at line 148 # once (1µs+0s) by Test2::Event::V2::facet_data at line 69 of Test2/Event/V2.pm
sub meta_facet_data {
1562300ns my $self = shift;
157
1582700ns my $key = Test2::Util::ExternalMeta::META_KEY();
159
16024µs my $hash = $self->{$key} or return undef;
161 return {%$hash};
162}
163
164sub facet_data {
165 my $self = shift;
166
167 my $out = $self->common_facet_data;
168
169 $out->{about}->{details} = $self->summary || undef;
170 $out->{about}->{no_display} = $self->no_display || undef;
171
172 # Might be undef, we want to preserve that
173 my $terminate = $self->terminate;
174 $out->{control} = {
175 global => $self->global || 0,
176 terminate => $terminate,
177 has_callback => $self->can('callback') == \&callback ? 0 : 1,
178 };
179
180 $out->{assert} = {
181 no_debug => 1, # Legacy behavior
182 pass => $self->causes_fail ? 0 : 1,
183 details => $self->summary,
184 } if $self->increments_count;
185
186 $out->{parent} = {hid => $self->subtest_id} if $self->subtest_id;
187
188 if (my @plan = $self->sets_plan) {
189 $out->{plan} = {};
190
191 $out->{plan}->{count} = $plan[0] if defined $plan[0];
192 $out->{plan}->{details} = $plan[2] if defined $plan[2];
193
194 if ($plan[1]) {
195 $out->{plan}->{skip} = 1 if $plan[1] eq 'SKIP';
196 $out->{plan}->{none} = 1 if $plan[1] eq 'NO PLAN';
197 }
198
199 $out->{control}->{terminate} ||= 0 if $out->{plan}->{skip};
200 }
201
202 if ($self->causes_fail && !$out->{assert}) {
203 $out->{errors} = [
204 {
205 tag => 'FAIL',
206 fail => 1,
207 details => $self->summary,
208 }
209 ];
210 }
211
212 my %IGNORE = (trace => 1, about => 1, control => 1);
213 my $do_info = !grep { !$IGNORE{$_} } keys %$out;
214
215 if ($do_info && !$self->no_display && $self->diagnostics) {
216 $out->{info} = [
217 {
218 tag => 'DIAG',
219 debug => 1,
220 details => $self->summary,
221 }
222 ];
223 }
224
225 return $out;
226}
227
228sub facets {
229 my $self = shift;
230 my %out;
231
232 my $data = $self->facet_data;
233 my @errors = $self->validate_facet_data($data);
234 die join "\n" => @errors if @errors;
235
236 for my $facet (keys %$data) {
237 my $class = $self->load_facet($facet);
238 my $val = $data->{$facet};
239
240 unless($class) {
241 $out{$facet} = $val;
242 next;
243 }
244
245 my $is_list = reftype($val) eq 'ARRAY' ? 1 : 0;
246 if ($is_list) {
247 $out{$facet} = [map { $class->new($_) } @$val];
248 }
249 else {
250 $out{$facet} = $class->new($val);
251 }
252 }
253
254 return \%out;
255}
256
257sub validate_facet_data {
258 my $class_or_self = shift;
259 my ($f, %params);
260
261 $f = shift if @_ && (reftype($_[0]) || '') eq 'HASH';
262 %params = @_;
263
264 $f ||= $class_or_self->facet_data if blessed($class_or_self);
265 croak "No facet data" unless $f;
266
267 my @errors;
268
269 for my $k (sort keys %$f) {
270 my $fclass = $class_or_self->load_facet($k);
271
272 push @errors => "Could not find a facet class for facet '$k'"
273 if $params{require_facet_class} && !$fclass;
274
275 next unless $fclass;
276
277 my $v = $f->{$k};
278 next unless defined($v); # undef is always fine
279
280 my $is_list = $fclass->is_list();
281 my $got_list = reftype($v) eq 'ARRAY' ? 1 : 0;
282
283 push @errors => "Facet '$k' should be a list, but got a single item ($v)"
284 if $is_list && !$got_list;
285
286 push @errors => "Facet '$k' should not be a list, but got a a list ($v)"
287 if $got_list && !$is_list;
288 }
289
290 return @errors;
291}
292
293sub nested {
294 my $self = shift;
295
296 Carp::cluck("Use of Test2::Event->nested() is deprecated, use Test2::Event->trace->nested instead")
297 if $ENV{AUTHOR_TESTING};
298
299 if (my $hubs = $self->{+HUBS}) {
300 return $hubs->[0]->{nested} if @$hubs;
301 }
302
303 my $trace = $self->{+TRACE} or return undef;
304 return $trace->{nested};
305}
306
307sub in_subtest {
308 my $self = shift;
309
310 Carp::cluck("Use of Test2::Event->in_subtest() is deprecated, use Test2::Event->trace->hid instead")
311 if $ENV{AUTHOR_TESTING};
312
313 my $hubs = $self->{+HUBS};
314 if ($hubs && @$hubs) {
315 return undef unless $hubs->[0]->{nested};
316 return $hubs->[0]->{hid}
317 }
318
319 my $trace = $self->{+TRACE} or return undef;
320 return undef unless $trace->{nested};
321 return $trace->{hid};
322}
323
32413µs1;
325
326__END__