← Index
NYTProf Performance Profile   « line view »
For /usr/local/libexec/sympa/task_manager-debug.pl
  Run on Tue Jun 1 22:32:51 2021
Reported on Tue Jun 1 22:35:08 2021

Filename/usr/local/libexec/sympa/Sympa/Database.pm
StatementsExecuted 71694 statements in 464ms
Subroutines
Calls P F Exclusive
Time
Inclusive
Time
Subroutine
27541165.7ms985msSympa::Database::::do_prepared_querySympa::Database::do_prepared_query
82623121.9ms21.9msSympa::Database::::CORE:substSympa::Database::CORE:subst (opcode)
111100µs7.59msSympa::Database::::connectSympa::Database::connect
32278µs102µsSympa::Database::::get_idSympa::Database::get_id
22126µs170µsSympa::Database::::pingSympa::Database::ping
106222µs22µsSympa::Database::::__dbhSympa::Database::__dbh
331117µs17µsSympa::Database::::CORE:matchSympa::Database::CORE:match (opcode)
11116µs6.80msSympa::Database::::_connectSympa::Database::_connect
6319µs9µsSympa::Database::::CORE:sortSympa::Database::CORE:sort (opcode)
0000s0sSympa::Database::::BEGIN@30Sympa::Database::BEGIN@30
0000s0sSympa::Database::::BEGIN@31Sympa::Database::BEGIN@31
0000s0sSympa::Database::::BEGIN@32Sympa::Database::BEGIN@32
0000s0sSympa::Database::::BEGIN@33Sympa::Database::BEGIN@33
0000s0sSympa::Database::::BEGIN@35Sympa::Database::BEGIN@35
0000s0sSympa::Database::::BEGIN@36Sympa::Database::BEGIN@36
0000s0sSympa::Database::::DESTROYSympa::Database::DESTROY
0000s0sSympa::Database::::__ANON__Sympa::Database::__ANON__ (xsub)
0000s0sSympa::Database::::_newSympa::Database::_new
0000s0sSympa::Database::::disconnectSympa::Database::disconnect
0000s0sSympa::Database::::do_operationSympa::Database::do_operation
0000s0sSympa::Database::::do_querySympa::Database::do_query
0000s0sSympa::Database::::errorSympa::Database::error
0000s0sSympa::Database::::newSympa::Database::new
0000s0sSympa::Database::::prepare_query_log_valuesSympa::Database::prepare_query_log_values
0000s0sSympa::Database::::quoteSympa::Database::quote
0000s0sSympa::Database::::set_persistentSympa::Database::set_persistent
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments
Time
on line
Calls Time
in subs
Code
1# -*- indent-tabs-mode: nil; -*-
2# vim:ft=perl:et:sw=4
3# $Id$
4
5# Sympa - SYsteme de Multi-Postage Automatique
6#
7# Copyright (c) 1997, 1998, 1999 Institut Pasteur & Christophe Wolfhugel
8# Copyright (c) 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
9# 2006, 2007, 2008, 2009, 2010, 2011 Comite Reseau des Universites
10# Copyright (c) 2011, 2012, 2013, 2014, 2015, 2016, 2017 GIP RENATER
11# Copyright 2017, 2018, 2019 The Sympa Community. See the AUTHORS.md file at
12# the top-level directory of this distribution and at
13# <https://github.com/sympa-community/sympa.git>.
14#
15# This program is free software; you can redistribute it and/or modify
16# it under the terms of the GNU General Public License as published by
17# the Free Software Foundation; either version 2 of the License, or
18# (at your option) any later version.
19#
20# This program is distributed in the hope that it will be useful,
21# but WITHOUT ANY WARRANTY; without even the implied warranty of
22# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
23# GNU General Public License for more details.
24#
25# You should have received a copy of the GNU General Public License
26# along with this program. If not, see <http://www.gnu.org/licenses/>.
27
28package Sympa::Database;
29
30use strict;
31use warnings;
32use DBI;
33use English qw(-no_match_vars);
34
35use Sympa;
36use Sympa::Log;
37
38my $log = Sympa::Log->instance;
39
40# Structure to keep track of active connections/connection status
41# Keys: unique ID of connection (includes type, server, port, dbname and user).
42# Values: database handler.
43our %connection_of;
44our %persistent_connection_of;
45
46# Map to driver names from older format of db_type parameter.
47my %driver_aliases = (
48 mysql => 'Sympa::DatabaseDriver::MySQL',
49 Pg => 'Sympa::DatabaseDriver::PostgreSQL',
50);
51
52# Sympa::Database is the proxy class of Sympa::DatabaseDriver subclasses.
53# The constructor may be overridden by _new() method.
54sub new {
55 $log->syslog('debug2', '(%s, %s)', @_);
56 my $class = shift;
57 my $db_type = shift;
58 my %params = @_;
59
60 my $driver = $driver_aliases{$db_type} || $db_type;
61 $driver = 'Sympa::DatabaseDriver::' . $driver
62 unless $driver =~ /::/;
63 unless (eval "require $driver"
# spent 0s executing statements in string eval
64 and $driver->isa('Sympa::DatabaseDriver')) {
65 $log->syslog('err', 'Unable to use %s module: %s',
66 $driver, $EVAL_ERROR || 'Not a Sympa::DatabaseDriver class');
67 return undef;
68 }
69
70 return $driver->_new(
71 $db_type,
72 map {
73 (exists $params{$_} and defined $params{$_})
74 ? ($_ => $params{$_})
75 : ()
76 } ( @{$driver->required_parameters}, @{$driver->optional_parameters}
77 )
78 );
79}
80
81sub _new {
82 my $class = shift;
83 my $db_type = shift;
84 my %params = @_;
85
86 return bless {%params} => $class;
87}
88
89############################################################
90# connect
91############################################################
92# Connect to an SQL database.
93#
94# IN : $options : ref to a hash. Options for the connection process.
95# currently accepts 'keep_trying' : wait and retry until
96# db connection is ok (boolean) ; 'warn' : warn
97# listmaster if connection fails (boolean)
98# OUT : 1 | undef
99#
100##############################################################
101
# spent 7.59ms (100µs+7.49) within Sympa::Database::connect which was called: # once (100µs+7.49ms) by Sympa::DatabaseDriver::PostgreSQL::connect at line 60 of /usr/local/libexec/sympa/Sympa/DatabaseDriver/PostgreSQL.pm
sub connect {
10212µs1249µs $log->syslog('debug3', '(%s)', @_);
# spent 249µs making 1 call to Sympa::Log::syslog
1031800ns my $self = shift;
104
105 # First check if we have an active connection with this server
10615µs152µs if ($self->ping) {
# spent 52µs making 1 call to Sympa::Database::ping
107 $log->syslog('debug3', 'Connection to database %s already available',
108 $self);
109 return 1;
110 }
111
112 # Do we have required parameters?
11317µs1600ns foreach my $param (@{$self->required_parameters}) {
# spent 600ns making 1 call to Sympa::DatabaseDriver::required_parameters
11421µs unless (defined $self->{$param}) {
115 $log->syslog('info', 'Missing parameter %s for DBI connection',
116 $param);
117 return undef;
118 }
119 }
120
121 # Check if required module such as DBD is installed.
12215µs1600ns foreach my $module (@{$self->required_modules}) {
123136µs unless (eval "require $module") {
# spent 0s executing statements in 2 string evals (merged)
124 $log->syslog(
125 'err',
126 'A module for %s is not installed. You should download and install %s',
127 ref($self),
128 $module
129 );
130 Sympa::send_notify_to_listmaster('*', 'missing_dbd',
131 {'db_type' => ref($self), 'db_module' => $module});
132 return undef;
133 }
134 }
13519µs1500ns foreach my $module (@{$self->optional_modules}) {
# spent 500ns making 1 call to Sympa::DatabaseDriver::optional_modules
136 eval "require $module";
137 }
138
139 # Set unique ID to determine connection.
14013µs127µs $self->{_id} = $self->get_id;
# spent 27µs making 1 call to Sympa::Database::get_id
141
142 # Establish new connection.
143
144 # Set environment variables
145 # Used by Oracle (ORACLE_HOME) etc.
1461800ns if ($self->{'db_env'}) {
147 foreach my $env (split /;/, $self->{'db_env'}) {
148 my ($key, $value) = split /=/, $env, 2;
149 $ENV{$key} = $value if ($key);
150 }
151 }
152
153215µs26.81ms $connection_of{$self->{_id}} = eval { $self->_connect };
# spent 6.80ms making 1 call to Sympa::Database::_connect # spent 1µs making 1 call to DBI::common::DESTROY
154
15513µs1118µs unless ($self->ping) {
# spent 118µs making 1 call to Sympa::Database::ping
156 unless ($persistent_connection_of{$self->{_id}}) {
157 $log->syslog('err', 'Can\'t connect to Database %s: %s',
158 $self, $DBI::errstr);
159 $self->{_status} = 'failed';
160 return undef;
161 }
162
163 # Notify listmaster unless the 'failed' status was set earlier.
164 $log->syslog('err', 'Can\'t connect to Database %s, still trying...',
165 $self);
166 unless ($self->{_status} and $self->{_status} eq 'failed') {
167 Sympa::send_notify_to_listmaster('*', 'no_db', {});
168 }
169
170 # Loop until connect works
171 my $sleep_delay = 60;
172 while (1) {
173 sleep $sleep_delay;
174 $connection_of{$self->{_id}} = eval { $self->_connect };
175 last if $self->ping;
176 $sleep_delay += 10;
177 }
178
179 delete $self->{_status};
180
181 $log->syslog('notice', 'Connection to Database %s restored', $self);
182 Sympa::send_notify_to_listmaster('*', 'db_restored', {});
183 }
184
18513µs1241µs $log->syslog('debug2', 'Connected to Database %s', $self);
# spent 241µs making 1 call to Sympa::Log::syslog
186
18713µs return 1;
188}
189
190# Merged into connect(().
191#sub establish_connection();
192
193
# spent 6.80ms (16µs+6.79) within Sympa::Database::_connect which was called: # once (16µs+6.79ms) by Sympa::Database::connect at line 153
sub _connect {
1941400ns my $self = shift;
195
196 my $connection = DBI->connect(
197 $self->build_connect_string, $self->{'db_user'},
198113µs26.79ms $self->{'db_passwd'}, {PrintError => 0}
# spent 6.78ms making 1 call to DBI::connect # spent 5µs making 1 call to Sympa::DatabaseDriver::PostgreSQL::build_connect_string
199 );
200 # Force field names to be lowercased.
201 # This has has been added after some problems of field names
202 # upercased with Oracle.
20315µs11µs $connection->{FetchHashKeyName} = 'NAME_lc' if $connection;
# spent 1µs making 1 call to DBI::common::STORE
204
20513µs return $connection;
206}
207
208
# spent 22µs within Sympa::Database::__dbh which was called 10 times, avg 2µs/call: # 4 times (12µs+0s) by Sympa::Database::do_prepared_query at line 327, avg 3µs/call # 2 times (5µs+0s) by Sympa::Database::ping at line 448, avg 3µs/call # once (2µs+0s) by Sympa::DatabaseDriver::PostgreSQL::connect at line 66 of /usr/local/libexec/sympa/Sympa/DatabaseDriver/PostgreSQL.pm # once (1µs+0s) by Sympa::DatabaseDriver::PostgreSQL::connect at line 68 of /usr/local/libexec/sympa/Sympa/DatabaseDriver/PostgreSQL.pm # once (1µs+0s) by Sympa::Database::do_prepared_query at line 358 # once (900ns+0s) by Sympa::DatabaseDriver::PostgreSQL::connect at line 67 of /usr/local/libexec/sympa/Sympa/DatabaseDriver/PostgreSQL.pm
sub __dbh {
209103µs my $self = shift;
2101025µs return $connection_of{$self->{_id} || ''};
211}
212
213sub do_operation {
214 die 'Not implemented';
215}
216
217sub do_query {
218 my $self = shift;
219 my $query = shift;
220 my @params = @_;
221
222 my $sth;
223
224 $query =~ s/^\s+//;
225 $query =~ s/\s+$//;
226 my $statement = sprintf $query, @params;
227
228 my $s = $statement;
229 $s =~ s/\n\s*/ /g;
230 $log->syslog('debug3', 'Will perform query "%s"', $s);
231
232 unless ($self->__dbh and $sth = $self->__dbh->prepare($statement)) {
233 # Check connection to database in case it would be the cause of the
234 # problem.
235 unless ($self->connect()) {
236 $log->syslog('err', 'Unable to get a handle to %s database',
237 $self->{'db_name'});
238 return undef;
239 } else {
240 unless ($self->__dbh and $sth = $self->__dbh->prepare($statement))
241 {
242 my $trace_statement = sprintf $query,
243 @{$self->prepare_query_log_values(@params)};
244 $log->syslog('err', 'Unable to prepare SQL statement %s: %s',
245 $trace_statement, $self->error);
246 return undef;
247 }
248 }
249 }
250 unless ($sth->execute) {
251 # Check connection to database in case it would be the cause of the
252 # problem.
253 unless ($self->connect()) {
254 $log->syslog('err', 'Unable to get a handle to %s database',
255 $self->{'db_name'});
256 return undef;
257 } else {
258 unless ($sth = $self->__dbh->prepare($statement)) {
259 # Check connection to database in case it would be the cause
260 # of the problem.
261 unless ($self->connect()) {
262 $log->syslog('err',
263 'Unable to get a handle to %s database',
264 $self->{'db_name'});
265 return undef;
266 } else {
267 unless ($sth = $self->__dbh->prepare($statement)) {
268 my $trace_statement = sprintf $query,
269 @{$self->prepare_query_log_values(@params)};
270 $log->syslog('err',
271 'Unable to prepare SQL statement %s: %s',
272 $trace_statement, $self->error);
273 return undef;
274 }
275 }
276 }
277 unless ($sth->execute) {
278 my $trace_statement = sprintf $query,
279 @{$self->prepare_query_log_values(@params)};
280 $log->syslog('err',
281 'Unable to execute SQL statement "%s": %s',
282 $trace_statement, $self->error);
283 return undef;
284 }
285 }
286 }
287
288 return $sth;
289}
290
291
# spent 985ms (65.7+919) within Sympa::Database::do_prepared_query which was called 2754 times, avg 358µs/call: # 2754 times (65.7ms+919ms) by Sympa::DatabaseDriver::PostgreSQL::do_prepared_query at line 105 of /usr/local/libexec/sympa/Sympa/DatabaseDriver/PostgreSQL.pm, avg 358µs/call
sub do_prepared_query {
2922754572µs my $self = shift;
2932754819µs my $query = shift;
2942754850µs my @params = ();
2952754901µs my %types = ();
296
2972754390µs my $sth;
298
299 ## get binding types and parameters
3002754638µs my $i = 0;
30127541.19ms while (scalar @_) {
30282621.69ms my $p = shift;
30382622.91ms if (ref $p eq 'HASH') {
304 # a hashref { sql_type => SQL_type } etc.
305 $types{$i} = $p;
306 push @params, shift;
307 } elsif (ref $p) {
308 $log->syslog('err', 'Unexpected %s object. Ask developer',
309 ref $p);
310 return undef;
311 } else {
31282622.28ms push @params, $p;
313 }
31482622.90ms $i++;
315 }
316
317275410.5ms27542.19ms $query =~ s/^\s+//;
# spent 2.19ms making 2754 calls to Sympa::Database::CORE:subst, avg 795ns/call
318275421.5ms27549.70ms $query =~ s/\s+$//;
# spent 9.70ms making 2754 calls to Sympa::Database::CORE:subst, avg 4µs/call
319275418.7ms275410.00ms $query =~ s/\n\s*/ /g;
# spent 10.00ms making 2754 calls to Sympa::Database::CORE:subst, avg 4µs/call
32027542.95ms2754517ms $log->syslog('debug3', 'Will perform query "%s"', $query);
# spent 517ms making 2754 calls to Sympa::Log::syslog, avg 188µs/call
321
32227543.59ms if ($self->{'cached_prepared_statements'}{$query}) {
323 $sth = $self->{'cached_prepared_statements'}{$query};
324 } else {
32523µs2290µs $log->syslog('debug3',
# spent 290µs making 2 calls to Sympa::Log::syslog, avg 145µs/call
326 'Did not find prepared statement for %s. Doing it', $query);
327240µs8233µs unless ($self->__dbh and $sth = $self->__dbh->prepare($query)) {
# spent 121µs making 2 calls to DBI::db::prepare, avg 60µs/call # spent 101µs making 2 calls to DBD::Pg::db::prepare, avg 50µs/call # spent 12µs making 4 calls to Sympa::Database::__dbh, avg 3µs/call
328 unless ($self->connect()) {
329 $log->syslog('err', 'Unable to get a handle to %s database',
330 $self->{'db_name'});
331 return undef;
332 } else {
333 unless ($self->__dbh and $sth = $self->__dbh->prepare($query))
334 {
335 $log->syslog('err', 'Unable to prepare SQL statement: %s',
336 $self->error);
337 return undef;
338 }
339 }
340 }
341
342 ## bind parameters with special types
343 ## this may be done only once when handle is prepared.
344211µs21µs foreach my $i (sort keys %types) {
# spent 1µs making 2 calls to Sympa::Database::CORE:sort, avg 550ns/call
345 $sth->bind_param($i + 1, $params[$i], $types{$i});
346 }
347
34824µs $self->{'cached_prepared_statements'}{$query} = $sth;
349 }
3502754379ms2754371ms unless ($sth->execute(@params)) {
# spent 371ms making 2754 calls to DBI::st::execute, avg 135µs/call
351 # Check database connection in case it would be the cause of the
352 # problem.
35314µs17.79ms unless ($self->connect()) {
# spent 7.79ms making 1 call to Sympa::DatabaseDriver::PostgreSQL::connect
354 $log->syslog('err', 'Unable to get a handle to %s database',
355 $self->{'db_name'});
356 return undef;
357 } else {
35817µs382µs unless ($sth = $self->__dbh->prepare($query)) {
# spent 42µs making 1 call to DBI::db::prepare # spent 39µs making 1 call to DBD::Pg::db::prepare # spent 1µs making 1 call to Sympa::Database::__dbh
359 unless ($self->connect()) {
360 $log->syslog('err',
361 'Unable to get a handle to %s database',
362 $self->{'db_name'});
363 return undef;
364 } else {
365 unless ($sth = $self->__dbh->prepare($query)) {
366 $log->syslog('err',
367 'Unable to prepare SQL statement: %s',
368 $self->error);
369 return undef;
370 }
371 }
372 }
373
374 ## bind parameters with special types
375 ## this may be done only once when handle is prepared.
37614µs1500ns foreach my $i (sort keys %types) {
# spent 500ns making 1 call to Sympa::Database::CORE:sort
377 $sth->bind_param($i + 1, $params[$i], $types{$i});
378 }
379
380134µs312µs $self->{'cached_prepared_statements'}{$query} = $sth;
# spent 10µs making 2 calls to DBI::common::DESTROY, avg 5µs/call # spent 1µs making 1 call to DBD::_mem::common::DESTROY
38111.18ms11.17ms unless ($sth->execute(@params)) {
# spent 1.17ms making 1 call to DBI::st::execute
382 $log->syslog('err',
383 'Unable to execute SQL statement "%s": %s',
384 $query, $self->error);
385 return undef;
386 }
387 }
388 }
389
390275411.6ms return $sth;
391}
392
393sub prepare_query_log_values {
394 my $self = shift;
395 my @result;
396 foreach my $value (@_) {
397 my $cropped = substr($value, 0, 100);
398 if ($cropped ne $value) {
399 $cropped .= "...[shortened]";
400 }
401 push @result, $cropped;
402 }
403 return \@result;
404}
405
406# DEPRECATED: Use tools::eval_in_time() and fetchall_arrayref().
407#sub fetch();
408
409sub disconnect {
410 my $self = shift;
411
412 my $id = $self->get_id;
413
414 # Don't disconnect persistent connection.
415 return 0 if $persistent_connection_of{$id};
416
417 $connection_of{$id}->disconnect if $connection_of{$id};
418 delete $connection_of{$id};
419 return 1;
420}
421
422# NOT YET USED.
423#sub create_db;
424
425sub error {
426 my $self = shift;
427
428 my $dbh = $self->__dbh;
429 return sprintf '(%s) %s', $dbh->state, ($dbh->errstr || '') if $dbh;
430 return undef;
431}
432
433sub set_persistent {
434 my $self = shift;
435 my $flag = shift;
436
437 if ($flag) {
438 $persistent_connection_of{$self->get_id} = 1;
439 } elsif (defined $flag) {
440 delete $persistent_connection_of{$self->get_id};
441 }
442 return $self;
443}
444
445
# spent 170µs (26+144) within Sympa::Database::ping which was called 2 times, avg 85µs/call: # once (10µs+108µs) by Sympa::Database::connect at line 155 # once (15µs+36µs) by Sympa::Database::connect at line 106
sub ping {
44621µs my $self = shift;
447
44825µs25µs my $dbh = $self->__dbh;
# spent 5µs making 2 calls to Sympa::Database::__dbh, avg 3µs/call
449
450 # Disconnected explicitly.
45121µs return undef unless $dbh;
452 # Some drivers don't have ping().
453213µs27µs return 1 unless $dbh->can('ping');
# spent 7µs making 2 calls to DBI::common::can, avg 3µs/call
454220µs4256µs return $dbh->ping;
# spent 132µs making 2 calls to DBI::db::ping, avg 66µs/call # spent 124µs making 2 calls to DBD::Pg::db::ping, avg 62µs/call
455}
456
457sub quote {
458 my $self = shift;
459 my ($string, $datatype) = @_;
460
461 # quote() does not need actual connection but driver handle.
462 unless ($self->__dbh or $self->connect) {
463 return undef;
464 }
465 return $self->__dbh->quote($string, $datatype);
466}
467
468# No longer used.
469#sub set_fetch_timeout($timeout);
470
471## Returns a character string corresponding to the expression to use in
472## a read query (e.g. SELECT) for the field given as argument.
473## This sub takes a single argument: the name of the field to be used in
474## the query.
475##
476# Moved to Sympa::Upgrade::_get_canonical_write_date().
477#sub get_canonical_write_date;
478
479## Returns a character string corresponding to the expression to use in
480## a write query (e.g. UPDATE or INSERT) for the value given as argument.
481## This sub takes a single argument: the value of the date to be used in
482## the query.
483##
484# Moved to Sympa::Upgrade::_get_canonical_read_date().
485#sub get_canonical_read_date;
486
487# We require that user also matches (except SQLite).
488
# spent 102µs (78+24) within Sympa::Database::get_id which was called 3 times, avg 34µs/call: # 2 times (57µs+18µs) by Sympa::Log::syslog at line 112 of /usr/local/libexec/sympa/Sympa/Log.pm, avg 38µs/call # once (21µs+6µs) by Sympa::Database::connect at line 140
sub get_id {
48931µs my $self = shift;
490
491 return join ';', map {"$_=$self->{$_}"}
492 grep {
493343µs37µs !ref($self->{$_})
# spent 7µs making 3 calls to Sympa::Database::CORE:sort, avg 2µs/call
4942158µs3317µs and defined $self->{$_}
# spent 17µs making 33 calls to Sympa::Database::CORE:match, avg 521ns/call
495 and !/\A_/
496 and !/passw(or)?d/
497 }
498 sort keys %$self;
499}
500
501sub DESTROY {
502 shift->disconnect;
503}
504
5051;
506__END__
 
# spent 17µs within Sympa::Database::CORE:match which was called 33 times, avg 521ns/call: # 33 times (17µs+0s) by Sympa::Database::get_id at line 494, avg 521ns/call
sub Sympa::Database::CORE:match; # opcode
# spent 9µs within Sympa::Database::CORE:sort which was called 6 times, avg 1µs/call: # 3 times (7µs+0s) by Sympa::Database::get_id at line 493, avg 2µs/call # 2 times (1µs+0s) by Sympa::Database::do_prepared_query at line 344, avg 550ns/call # once (500ns+0s) by Sympa::Database::do_prepared_query at line 376
sub Sympa::Database::CORE:sort; # opcode
# spent 21.9ms within Sympa::Database::CORE:subst which was called 8262 times, avg 3µs/call: # 2754 times (10.00ms+0s) by Sympa::Database::do_prepared_query at line 319, avg 4µs/call # 2754 times (9.70ms+0s) by Sympa::Database::do_prepared_query at line 318, avg 4µs/call # 2754 times (2.19ms+0s) by Sympa::Database::do_prepared_query at line 317, avg 795ns/call
sub Sympa::Database::CORE:subst; # opcode