Profile of DBIx/Class/Storage/BlockRunner.pm

Filename	/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm
Statements	Executed 75063 statements in 275ms

Subroutines
Calls	P	F	Exclusive Time	Inclusive Time	Subroutine
3001	1	1	67.8ms	1.14s	DBIx::Class::Storage::BlockRunner::run
3001	1	1	65.3ms	1.04s	DBIx::Class::Storage::BlockRunner::_run
3001	2	1	36.2ms	834ms	DBIx::Class::Storage::BlockRunner::__ANON__[:155]
3001	2	1	30.5ms	51.0ms	DBIx::Class::Storage::BlockRunner::__ANON__[:233]
1	1	1	7.78ms	10.0ms	DBIx::Class::Storage::BlockRunner::BEGIN@16
1	1	1	378µs	513µs	DBIx::Class::Storage::BlockRunner::BEGIN@9
1	1	1	13µs	18µs	DBIx::Class::Storage::BlockRunner::BEGIN@4
1	1	1	13µs	239µs	DBIx::Class::Storage::BlockRunner::BEGIN@34
1	1	1	11µs	30µs	DBIx::Class::Storage::BlockRunner::BEGIN@10
1	1	1	10µs	52µs	DBIx::Class::Storage::BlockRunner::__ANON__[:29]
1	1	1	10µs	30µs	DBIx::Class::Storage::BlockRunner::BEGIN@12
1	1	1	10µs	32µs	DBIx::Class::Storage::BlockRunner::BEGIN@11
1	1	1	8µs	13µs	DBIx::Class::Storage::BlockRunner::BEGIN@5
1	1	1	7µs	36µs	DBIx::Class::Storage::BlockRunner::BEGIN@8
1	1	1	6µs	6µs	DBIx::Class::Storage::BlockRunner::BEGIN@7
2	2	1	2µs	2µs	DBIx::Class::Storage::BlockRunner::storage (xsub)
1	1	1	1µs	1µs	DBIx::Class::Storage::BlockRunner::max_attempts (xsub)
1	1	1	700ns	700ns	DBIx::Class::Storage::BlockRunner::wrap_txn (xsub)
0	0	0	0s	0s	DBIx::Class::Storage::BlockRunner::__ANON__[:151]
0	0	0	0s	0s	DBIx::Class::Storage::BlockRunner::__ANON__[:154]
0	0	0	0s	0s	DBIx::Class::Storage::BlockRunner::catch {...}
0	0	0	0s	0s	DBIx::Class::Storage::BlockRunner::last_exception
0	0	0	0s	0s	DBIx::Class::Storage::BlockRunner::throw_exception
0	0	0	0s	0s	DBIx::Class::Storage::BlockRunner::try {...}

Call graph for these subroutines as a Graphviz dot language file.

Line	State ments	Time on line	Calls	Time in subs	Code
1					package # hide from pause until we figure it all out
2					DBIx::Class::Storage::BlockRunner;
3
4	2	31µs	2	22µs	# spent 18µs (13+4) within DBIx::Class::Storage::BlockRunner::BEGIN@4 which was called: # once (13µs+4µs) by DBIx::Class::Storage::BEGIN@16 at line 4 use warnings; # spent 18µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@4 # spent 4µs making 1 call to warnings::import
5	2	29µs	2	19µs	# spent 13µs (8+6) within DBIx::Class::Storage::BlockRunner::BEGIN@5 which was called: # once (8µs+6µs) by DBIx::Class::Storage::BEGIN@16 at line 5 use strict; # spent 13µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@5 # spent 6µs making 1 call to strict::import
6
7	2	22µs	1	6µs	# spent 6µs within DBIx::Class::Storage::BlockRunner::BEGIN@7 which was called: # once (6µs+0s) by DBIx::Class::Storage::BEGIN@16 at line 7 use DBIx::Class::Exception; # spent 6µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@7
8	2	26µs	2	66µs	# spent 36µs (7+29) within DBIx::Class::Storage::BlockRunner::BEGIN@8 which was called: # once (7µs+29µs) by DBIx::Class::Storage::BEGIN@16 at line 8 use DBIx::Class::Carp; # spent 36µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@8 # spent 29µs making 1 call to DBIx::Class::Carp::import
9	2	183µs	2	534µs	# spent 513µs (378+135) within DBIx::Class::Storage::BlockRunner::BEGIN@9 which was called: # once (378µs+135µs) by DBIx::Class::Storage::BEGIN@16 at line 9 use Context::Preserve 'preserve_context'; # spent 513µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@9 # spent 21µs making 1 call to Exporter::import
10	2	52µs	2	49µs	# spent 30µs (11+19) within DBIx::Class::Storage::BlockRunner::BEGIN@10 which was called: # once (11µs+19µs) by DBIx::Class::Storage::BEGIN@16 at line 10 use DBIx::Class::_Util qw(is_exception qsub); # spent 30µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@10 # spent 19µs making 1 call to Exporter::import
11	2	50µs	2	53µs	# spent 32µs (10+22) within DBIx::Class::Storage::BlockRunner::BEGIN@11 which was called: # once (10µs+22µs) by DBIx::Class::Storage::BEGIN@16 at line 11 use Scalar::Util qw(weaken blessed reftype); # spent 32µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@11 # spent 22µs making 1 call to Exporter::import
12	2	124µs	2	51µs	# spent 30µs (10+20) within DBIx::Class::Storage::BlockRunner::BEGIN@12 which was called: # once (10µs+20µs) by DBIx::Class::Storage::BEGIN@16 at line 12 use Try::Tiny; # spent 30µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@12 # spent 20µs making 1 call to Exporter::import
13
14					# DO NOT edit away without talking to riba first, he will just put it back
15					# BEGIN pre-Moo2 import block
16					# spent 10.0ms (7.78+2.26) within DBIx::Class::Storage::BlockRunner::BEGIN@16 which was called: # once (7.78ms+2.26ms) by DBIx::Class::Storage::BEGIN@16 at line 31 BEGIN {
17	1	4µs			my $initial_fatal_bits = (${^WARNING_BITS}\|\|'') & $warnings::DeadBits{all};
18
19	1	5µs			local $ENV{PERL_STRICTURES_EXTRA} = 0;
20					# load all of these now, so that lazy-loading does not escape
21					# the current PERL_STRICTURES_EXTRA setting
22	1	500ns			require Sub::Quote;
23	1	800ns			require Sub::Defer;
24	1	130µs			require Moo;
25	1	88µs			require Moo::Object;
26	1	106µs			require Method::Generate::Accessor;
27	1	162µs			require Method::Generate::Constructor;
28
29	3	29µs	3	406µs	# spent 52µs (10+42) within DBIx::Class::Storage::BlockRunner::__ANON__[/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm:29] which was called: # once (10µs+42µs) by import::into at line 36 of Import/Into.pm Moo->import; # spent 364µs making 1 call to Moo::import # spent 29µs making 1 call to strictures::import # spent 12µs making 1 call to Module::Runtime::use_module
30	1	11µs			${^WARNING_BITS} &= ( $initial_fatal_bits \| ~ $warnings::DeadBits{all} );
31	1	38µs	1	10.0ms	} # spent 10.0ms making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@16
32					# END pre-Moo2 import block
33
34	2	1.42ms	2	465µs	# spent 239µs (13+226) within DBIx::Class::Storage::BlockRunner::BEGIN@34 which was called: # once (13µs+226µs) by DBIx::Class::Storage::BEGIN@16 at line 34 use namespace::clean; # spent 239µs making 1 call to DBIx::Class::Storage::BlockRunner::BEGIN@34 # spent 226µs making 1 call to namespace::clean::import
35
36					=head1 NAME
37
38					DBIx::Class::Storage::BlockRunner - Try running a block of code until success with a configurable retry logic
39
40					=head1 DESCRIPTION
41
42					=head1 METHODS
43
44					=cut
45
46	1	2µs	1	1.55ms	has storage => ( # spent 1.55ms making 1 call to Moo::has
47					is => 'ro',
48					required => 1,
49					);
50
51	1	1µs	1	150µs	has wrap_txn => ( # spent 150µs making 1 call to Moo::has
52					is => 'ro',
53					required => 1,
54					);
55
56					# true - retry, false - rethrow, or you can throw your own (not catching)
57	1	4µs	2	138µs	has retry_handler => ( # spent 135µs making 1 call to Moo::has # spent 4µs making 1 call to DBIx::Class::_Util::qsub
58					is => 'ro',
59					required => 1,
60					isa => qsub q{
61					(Scalar::Util::reftype($_[0])\|\|'') eq 'CODE'
62					or DBIx::Class::Exception->throw('retry_handler must be a CODE reference')
63					},
64					);
65
66	1	2µs	2	342µs	has retry_debug => ( # spent 340µs making 1 call to Moo::has # spent 2µs making 1 call to DBIx::Class::_Util::qsub
67					is => 'rw',
68					# use a sub - to be evaluated on the spot lazily
69					default => qsub '$ENV{DBIC_STORAGE_RETRY_DEBUG}',
70					lazy => 1,
71					);
72
73	1	1µs	1	147µs	has max_attempts => ( # spent 147µs making 1 call to Moo::has
74					is => 'ro',
75					default => 20,
76					);
77
78	1	3µs	2	403µs	has failed_attempt_count => ( # spent 400µs making 1 call to Moo::has # spent 2µs making 1 call to DBIx::Class::_Util::qsub
79					is => 'ro',
80					init_arg => undef, # ensures one can't pass the value in
81					writer => '_set_failed_attempt_count',
82					default => 0,
83					lazy => 1,
84					trigger => qsub q{
85					$_[0]->throw_exception( sprintf (
86					'Reached max_attempts amount of %d, latest exception: %s',
87					$_[0]->max_attempts, $_[0]->last_exception
88					)) if $_[0]->max_attempts <= ($_[1]\|\|0);
89					},
90					);
91
92	1	4µs	2	300µs	has exception_stack => ( # spent 297µs making 1 call to Moo::has # spent 3µs making 1 call to DBIx::Class::_Util::qsub
93					is => 'ro',
94					init_arg => undef,
95					clearer => '_reset_exception_stack',
96					default => qsub q{ [] },
97					lazy => 1,
98					);
99
100					sub last_exception { shift->exception_stack->[-1] }
101
102					sub throw_exception { shift->storage->throw_exception (@_) }
103
104					# spent 1.14s (67.8ms+1.07) within DBIx::Class::Storage::BlockRunner::run which was called 3001 times, avg 379µs/call: # 3001 times (67.8ms+1.07s) by DBIx::Class::Storage::DBI::dbh_do at line 855 of DBIx/Class/Storage/DBI.pm, avg 379µs/call sub run {
105	3001	1.13ms			my $self = shift;
106
107	3001	5.73ms	3001	6.76ms	$self->_reset_exception_stack; # spent 6.76ms making 3001 calls to DBIx::Class::Storage::BlockRunner::_reset_exception_stack, avg 2µs/call
108	3001	5.79ms	3001	23.8ms	$self->_set_failed_attempt_count(0); # spent 23.8ms making 3001 calls to DBIx::Class::Storage::BlockRunner::_set_failed_attempt_count, avg 8µs/call
109
110	3001	1.54ms			my $cref = shift;
111
112	3001	9.79ms	3001	2.55ms	$self->throw_exception('run() requires a coderef to execute as its first argument') # spent 2.55ms making 3001 calls to Scalar::Util::reftype, avg 851ns/call
113					if ( reftype($cref)\|\|'' ) ne 'CODE';
114
115	3001	4.30ms	1	900ns	my $storage = $self->storage; # spent 900ns making 1 call to DBIx::Class::Storage::BlockRunner::storage
116
117	3001	1.76ms			return $cref->( @_ ) if (
118					$storage->{_in_do_block}
119					and
120					! $self->wrap_txn
121					);
122
123	3001	3.50ms			local $storage->{_in_do_block} = 1 unless $storage->{_in_do_block};
124
125	3001	13.0ms	3001	1.04s	return $self->_run($cref, @_); # spent 1.04s making 3001 calls to DBIx::Class::Storage::BlockRunner::_run, avg 345µs/call
126					}
127
128					# this is the actual recursing worker
129					# spent 1.04s (65.3ms+970ms) within DBIx::Class::Storage::BlockRunner::_run which was called 3001 times, avg 345µs/call: # 3001 times (65.3ms+970ms) by DBIx::Class::Storage::BlockRunner::run at line 125, avg 345µs/call sub _run {
130					# internal method - we know that both refs are strong-held by the
131					# calling scope of run(), hence safe to weaken everything
132	3001	13.3ms	3001	4.68ms	weaken( my $self = shift ); # spent 4.68ms making 3001 calls to Scalar::Util::weaken, avg 2µs/call
133	3001	13.0ms	3001	2.58ms	weaken( my $cref = shift ); # spent 2.58ms making 3001 calls to Scalar::Util::weaken, avg 859ns/call
134
135	3001	2.53ms			my $args = @_ ? \@_ : [];
136
137					# from this point on (defined $txn_init_depth) is an indicator for wrap_txn
138					# save a bit on method calls
139	3001	3.62ms	1	700ns	my $txn_init_depth = $self->wrap_txn ? $self->storage->transaction_depth : undef; # spent 700ns making 1 call to DBIx::Class::Storage::BlockRunner::wrap_txn
140	3001	469µs			my $txn_begin_ok;
141
142	3001	1.31ms			my $run_err = '';
143
144					# spent 834ms (36.2+798) within DBIx::Class::Storage::BlockRunner::__ANON__[/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm:155] which was called 3001 times, avg 278µs/call: # 3000 times (36.2ms+797ms) by Context::Preserve::preserve_context at line 32 of Context/Preserve.pm, avg 278µs/call # once (12µs+436µs) by Context::Preserve::preserve_context at line 22 of Context/Preserve.pm return preserve_context {
145					try {
146	3001	1.15ms			if (defined $txn_init_depth) {
147					$self->storage->txn_begin;
148					$txn_begin_ok = 1;
149					}
150	3001	5.59ms	3001	674ms	$cref->( @$args ); # spent 674ms making 3001 calls to DBIx::Class::Storage::DBI::__ANON__[DBIx/Class/Storage/DBI.pm:855], avg 225µs/call
151					} catch {
152					$run_err = $_;
153					(); # important, affects @_ below
154	3001	113ms	6002	798ms	}; # spent 776ms making 3001 calls to Try::Tiny::try, avg 259µs/call # spent 21.5ms making 3001 calls to Try::Tiny::catch, avg 7µs/call
155					# spent 51.0ms (30.5+20.5) within DBIx::Class::Storage::BlockRunner::__ANON__[/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm:233] which was called 3001 times, avg 17µs/call: # 3000 times (30.5ms+20.5ms) by Context::Preserve::preserve_context at line 37 of Context/Preserve.pm, avg 17µs/call # once (16µs+8µs) by Context::Preserve::preserve_context at line 27 of Context/Preserve.pm } replace => sub {
156	3001	2.27ms			my @res = @_;
157
158	3001	3.75ms	1	600ns	my $storage = $self->storage; # spent 600ns making 1 call to DBIx::Class::Storage::BlockRunner::storage
159	3001	2.50ms	1	700ns	my $cur_depth = $storage->transaction_depth; # spent 700ns making 1 call to DBIx::Class::Storage::DBI::mysql::transaction_depth
160
161	3001	1.03ms			if (defined $txn_init_depth and ! is_exception $run_err) {
162					my $delta_txn = (1 + $txn_init_depth) - $cur_depth;
163
164					if ($delta_txn) {
165					# a rollback in a top-level txn_do is valid-ish (seen in the wild and our own tests)
166					carp (sprintf
167					'Unexpected reduction of transaction depth by %d after execution of '
168					. '%s, skipping txn_commit()',
169					$delta_txn,
170					$cref,
171					) unless $delta_txn == 1 and $cur_depth == 0;
172					}
173					else {
174					$run_err = eval { $storage->txn_commit; 1 } ? '' : $@;
175					}
176					}
177
178					# something above threw an error (could be the begin, the code or the commit)
179	3001	9.22ms	3001	20.5ms	if ( is_exception $run_err ) { # spent 20.5ms making 3001 calls to DBIx::Class::_Util::is_exception, avg 7µs/call
180
181					# attempt a rollback if we did begin in the first place
182					if ($txn_begin_ok) {
183					# some DBDs go crazy if there is nothing to roll back on, perform a soft-check
184					my $rollback_exception = $storage->_seems_connected
185					? (! eval { $storage->txn_rollback; 1 }) ? $@ : ''
186					: 'lost connection to storage'
187					;
188
189					if ( $rollback_exception and (
190					! defined blessed $rollback_exception
191					or
192					! $rollback_exception->isa('DBIx::Class::Storage::NESTED_ROLLBACK_EXCEPTION')
193					) ) {
194					$run_err = "Transaction aborted: $run_err. Rollback failed: $rollback_exception";
195					}
196					}
197
198					push @{ $self->exception_stack }, $run_err;
199
200					# this will throw if max_attempts is reached
201					$self->_set_failed_attempt_count($self->failed_attempt_count + 1);
202
203					# init depth of > 0 ( > 1 with AC) implies nesting - no retry attempt queries
204					$storage->throw_exception($run_err) if (
205					(
206					defined $txn_init_depth
207					and
208					$txn_init_depth > ( $storage->{_dbh_autocommit} ? 0 : 1 )
209
210
211					) or ! $self->retry_handler->($self)
212					);
213
214					# we got that far - let's retry
215					carp( sprintf 'Retrying %s (attempt %d) after caught exception: %s',
216					$cref,
217					$self->failed_attempt_count + 1,
218					$run_err,
219					) if $self->retry_debug;
220
221					$storage->ensure_connected;
222					# if txn_depth is > 1 this means something was done to the
223					# original $dbh, otherwise we would not get past the preceding if()
224					$storage->throw_exception(sprintf
225					'Unexpected transaction depth of %d on freshly connected handle',
226					$storage->transaction_depth,
227					) if (defined $txn_init_depth and $storage->transaction_depth);
228
229					return $self->_run($cref, @$args);
230					}
231
232	3001	14.4ms			return wantarray ? @res : $res[0];
233	3001	38.6ms	3001	962ms	}; # spent 962ms making 3001 calls to Context::Preserve::preserve_context, avg 321µs/call
234					}
235
236					=head1 FURTHER QUESTIONS?
237
238					Check the list of L<additional DBIC resources\|DBIx::Class/GETTING HELP/SUPPORT>.
239
240					=head1 COPYRIGHT AND LICENSE
241
242					This module is free software L<copyright\|DBIx::Class/COPYRIGHT AND LICENSE>
243					by the L<DBIx::Class (DBIC) authors\|DBIx::Class/AUTHORS>. You can
244					redistribute it and/or modify it under the same terms as the
245					L<DBIx::Class library\|DBIx::Class/COPYRIGHT AND LICENSE>.
246
247					=cut
248
249	1	17µs	1	409µs	1; # spent 409µs making 1 call to B::Hooks::EndOfScope::XS::__ANON__

					# spent 1µs within DBIx::Class::Storage::BlockRunner::max_attempts which was called: # once (1µs+0s) by DBIx::Class::Storage::BlockRunner::_set_failed_attempt_count at line 29 of (eval 1107)[Sub/Quote.pm:5] sub DBIx::Class::Storage::BlockRunner::max_attempts; # xsub
					# spent 2µs within DBIx::Class::Storage::BlockRunner::storage which was called 2 times, avg 750ns/call: # once (900ns+0s) by DBIx::Class::Storage::BlockRunner::run at line 115 # once (600ns+0s) by DBIx::Class::Storage::BlockRunner::__ANON__[/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm:233] at line 158 sub DBIx::Class::Storage::BlockRunner::storage; # xsub
					# spent 700ns within DBIx::Class::Storage::BlockRunner::wrap_txn which was called: # once (700ns+0s) by DBIx::Class::Storage::BlockRunner::_run at line 139 sub DBIx::Class::Storage::BlockRunner::wrap_txn; # xsub