Author: spadkins
Date: Tue Jun 20 12:37:48 2006
New Revision: 6553
Modified:
p5ee/trunk/App-Repository/lib/App/Repository/DBI.pm
p5ee/trunk/App-Repository/lib/App/Repository/MySQL.pm
Log:
added automatic timings on all debug_sql. added explain_sql.
Modified: p5ee/trunk/App-Repository/lib/App/Repository/DBI.pm
==============================================================================
--- p5ee/trunk/App-Repository/lib/App/Repository/DBI.pm (original)
+++ p5ee/trunk/App-Repository/lib/App/Repository/DBI.pm Tue Jun 20 12:37:48 2006
@@ -12,6 +12,7 @@
@ISA = ( "App::Repository" );
use Data::Dumper;
+use Time::HiRes qw(gettimeofday);
use strict;
@@ -382,8 +383,11 @@
$dbh = $self->{dbh};
}
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
if ($debug_sql) {
+ $timer = $self->_get_timer();
print "DEBUG_SQL: _get_row()\n";
print $sql;
}
@@ -410,12 +414,16 @@
}
}
if ($debug_sql) {
- print "DEBUG_SQL: nrows [", (defined $row ? 1 : 0), "] $DBI::errstr\n";
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: nrows [", (defined $row ? 1 : 0), "] ($elapsed_time
sec) $DBI::errstr\n";
if ($debug_sql >= 2) {
print "DEBUG_SQL: [", ($row ? join("|",map { defined $_ ? $_ :
"undef" } @$row) : ""), "]\n";
}
print "\n";
}
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
&App::sub_exit($row) if ($App::trace);
return($row);
@@ -441,8 +449,11 @@
$startrow = $options->{startrow} || 0;
$endrow = $options->{endrow} || 0;
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
if ($debug_sql) {
+ $timer = $self->_get_timer();
print "DEBUG_SQL: _get_rows()\n";
print $sql;
}
@@ -468,7 +479,8 @@
}
}
if ($debug_sql) {
- print "DEBUG_SQL: nrows [", (defined $rows ? ($#$rows+1) : 0), "]
$DBI::errstr\n";
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: nrows [", (defined $rows ? ($#$rows+1) : 0), "]
($elapsed_time sec) $DBI::errstr\n";
if ($debug_sql >= 2) {
foreach my $row (@$rows) {
print "DEBUG_SQL: [", join("|",map { defined $_ ? $_ :
"undef"} @$row), "]\n";
@@ -476,6 +488,9 @@
}
print "\n";
}
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
&App::sub_exit($rows) if ($App::trace);
return($rows);
@@ -2096,17 +2111,24 @@
my $dbh = $self->{dbh};
my $retval = 0;
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
if ($debug_sql) {
+ $timer = $self->_get_timer();
print "DEBUG_SQL: insert()\n";
print "DEBUG_SQL: bind vars [", join("|",map { defined $_ ? $_ :
"undef" } @$row), "]\n";
print $sql;
}
$retval = $dbh->do($sql, undef, @$row) if (defined $dbh);
if ($debug_sql && $debug_sql >= 2) {
- print "DEBUG_SQL: retval [$retval] $DBI::errstr\n";
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: retval [$retval] ($elapsed_time sec) $DBI::errstr\n";
print "\n";
}
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
&App::sub_exit($retval) if ($App::trace);
$retval;
@@ -2125,7 +2147,12 @@
my $nrows = 0;
my $ok = 1;
$sql = $self->_mk_insert_row_sql($table, $cols);
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
+ if ($debug_sql) {
+ $timer = $self->_get_timer();
+ }
foreach my $row (@$rows) {
if ($debug_sql) {
print "DEBUG_SQL: _insert_rows()\n";
@@ -2147,6 +2174,13 @@
last;
}
}
+ if ($debug_sql) {
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: nrows [$nrows] ($elapsed_time sec)\n";
+ }
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
$self->{sql} = $sql;
$self->{numrows} = $nrows;
&App::sub_exit($nrows) if ($App::trace);
@@ -2160,16 +2194,23 @@
my $sql = $self->_mk_delete_sql($table, $params, $cols, $row, $options);
$self->{sql} = $sql;
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
if ($debug_sql) {
+ $timer = $self->_get_timer();
print "DEBUG_SQL: _delete()\n";
print $sql;
}
my $retval = $self->{dbh}->do($sql);
if ($debug_sql) {
- print "DEBUG_SQL: retval [$retval] $DBI::errstr\n";
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: retval [$retval] ($elapsed_time sec) $DBI::errstr\n";
print "\n";
}
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
&App::sub_exit($retval) if ($App::trace);
return($retval);
@@ -2187,17 +2228,24 @@
my $sql = $self->_mk_update_sql($table, $params, $cols, $row, $options);
$self->{sql} = $sql;
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
if ($debug_sql) {
+ $timer = $self->_get_timer();
print "DEBUG_SQL: _update()\n";
print $sql;
}
my $retval = $self->{dbh}->do($sql);
$retval = 0 if ($retval == 0);
if ($debug_sql) {
- print "DEBUG_SQL: retval [$retval] $DBI::errstr\n";
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: retval [$retval] ($elapsed_time sec) $DBI::errstr\n";
print "\n";
}
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
&App::sub_exit($retval) if ($App::trace);
return($retval);
@@ -2213,16 +2261,23 @@
my $dbh = $self->{dbh};
my $retval = 0;
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
if ($debug_sql) {
+ $timer = $self->_get_timer();
print "DEBUG_SQL: _delete_row()\n";
print $sql;
}
$retval = $dbh->do($sql) if (defined $dbh);
if ($debug_sql) {
- print "DEBUG_SQL: retval [$retval] $DBI::errstr\n";
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: retval [$retval] ($elapsed_time sec) $DBI::errstr\n";
print "\n";
}
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
&App::sub_exit($retval) if ($App::trace);
$retval;
@@ -2238,16 +2293,23 @@
my $dbh = $self->{dbh};
my $retval = 0;
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
if ($debug_sql) {
+ $timer = $self->_get_timer();
print "DEBUG_SQL: _delete_rows()\n";
print $sql;
}
$retval = $dbh->do($sql) if (defined $dbh);
if ($debug_sql) {
- print "DEBUG_SQL: retval [$retval] $DBI::errstr\n";
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: retval [$retval] ($elapsed_time sec) $DBI::errstr\n";
print "\n";
}
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
&App::sub_exit($retval) if ($App::trace);
$retval;
@@ -2261,8 +2323,11 @@
my $dbh = $self->{dbh};
my $retval = 0;
- my $debug_sql = $self->{context}{options}{debug_sql};
+ my $context_options = $self->{context}{options};
+ my $debug_sql = $context_options->{debug_sql};
+ my ($timer, $elapsed_time);
if ($debug_sql) {
+ $timer = $self->_get_timer();
print "DEBUG_SQL: _do()\n";
print $sql;
}
@@ -2273,6 +2338,7 @@
else {
$retval = $dbh->do($sql);
}
+ $self->{sql} = $sql;
}
if ($debug_sql) {
my $nrows = 0;
@@ -2284,7 +2350,8 @@
$nrows = $retval;
}
}
- print "DEBUG_SQL: nrows [$nrows] $DBI::errstr\n";
+ $elapsed_time = $self->_read_timer($timer);
+ print "DEBUG_SQL: nrows [$nrows] ($elapsed_time sec) $DBI::errstr\n";
if ($debug_sql >= 2 && ref($retval)) {
foreach my $row (@$retval) {
print "DEBUG_SQL: [", join("|",map { defined $_ ? $_ :
"undef"} @$row), "]\n";
@@ -2292,11 +2359,53 @@
}
print "\n";
}
+ if ($context_options->{explain_sql}) {
+ $self->explain_sql($sql);
+ }
&App::sub_exit($retval) if ($App::trace);
$retval;
}
+sub explain_sql {
+ my ($self, $sql) = @_;
+ # to be overridden for each physical database
+}
+
+sub _get_timer {
+ my ($self) = @_;
+ my ($seconds_start, $microseconds_start) = gettimeofday;
+ my $timer = { seconds_start => $seconds_start, microseconds_start =>
$microseconds_start };
+ return($timer);
+}
+
+sub _read_timer {
+ my ($self, $timer, $reset) = @_;
+ my ($seconds_finish, $microseconds_finish) = gettimeofday;
+ my $seconds_elapsed = $seconds_finish -
$timer->{seconds_start};
+ my $microseconds_elapsed = $microseconds_finish -
$timer->{microseconds_start};
+ if ($microseconds_elapsed < 0) {
+ $microseconds_elapsed += 1000000;
+ $seconds_elapsed -= 1;
+ }
+ my $time_elapsed = sprintf("%d.%06d", $seconds_elapsed,
$microseconds_elapsed);
+ if (defined $reset) {
+ # store values. don't reset the timer.
+ if ($reset == 0) {
+ $timer->{seconds_start} = $seconds_finish;
+ $timer->{microseconds_start} = $microseconds_finish;
+ delete $timer->{time_elapsed};
+ }
+ # reset the timer to be ready for another reading.
+ elsif ($reset) {
+ $timer->{seconds_finish} = $seconds_finish;
+ $timer->{microseconds_finish} = $microseconds_finish;
+ $timer->{time_elapsed} = $time_elapsed;
+ }
+ }
+ return($time_elapsed);
+}
+
######################################################################
# METADATA REPOSITORY METHODS (implements methods from App::Repository)
######################################################################
Modified: p5ee/trunk/App-Repository/lib/App/Repository/MySQL.pm
==============================================================================
--- p5ee/trunk/App-Repository/lib/App/Repository/MySQL.pm (original)
+++ p5ee/trunk/App-Repository/lib/App/Repository/MySQL.pm Tue Jun 20
12:37:48 2006
@@ -66,6 +66,7 @@
&App::sub_exit(defined $self->{dbh}) if ($App::trace);
return(defined $self->{dbh});
}
+
sub _dsn {
&App::sub_entry if ($App::trace);
my ($self) = @_;
@@ -380,5 +381,46 @@
&App::sub_exit() if ($App::trace);
}
+#+----+-------------+-------+-------+-------------------------------------+-------------------+---------+-------------+------+-------+
+#| id | select_type | table | type | possible_keys |
key | key_len | ref | rows | Extra |
+#+----+-------------+-------+-------+-------------------------------------+-------------------+---------+-------------+------+-------+
+#| 1 | SIMPLE | t1 | const | hotel_prop_ds_ak1,hotel_prop_ds_ie1 |
hotel_prop_ds_ak1 | 9 | const,const | 1 | |
+#+----+-------------+-------+-------+-------------------------------------+-------------------+---------+-------------+------+-------+
+sub explain_sql {
+ my ($self, $sql) = @_;
+ my $dbh = $self->{dbh};
+ # NOTE: MySQL "explain" only works for "select".
+ # We convert "update" and "delete" to "select" to explain them.
+ if (defined $dbh) {
+ if ($sql =~ s/^delete/select */is) {
+ # do nothing
+ }
+ elsif ($sql =~ s/^update\s+(.*)\sset\s+.*\swhere/select * from
$1\nwhere/is) {
+ # do nothing
+ }
+ if ($sql =~ /^select/i) {
+ my ($rows);
+print $sql;
+ eval {
+ $rows = $dbh->selectall_arrayref("explain $sql");
+ };
+ print "EXPLAIN_SQL: $DBI::errstr\n";
+ if ($rows) {
+ print
"+----+-------------+-------+-------+-------------------------------------+-------------------+---------+-------------+------+-------+\n";
+ print "| id | select_type | table | type | possible_keys
| key | key_len | ref | rows | Extra
|\n";
+ print
"+----+-------------+-------+-------+-------------------------------------+-------------------+---------+-------------+------+-------+\n";
+ foreach my $row (@$rows) {
+ printf("|%3s | %-12s| %-6s| %-6s| %-36s| %-18s|%8d |
%-12s|%5d | %-6s|\n", @$row);
+ }
+ print
"+----+-------------+-------+-------+-------------------------------------+-------------------+---------+-------------+------+-------+\n";
+ }
+ }
+ else {
+ $sql =~ /^\s*(\S*)/;
+ print "EXPLAIN_SQL: Can't explain $1 statement.\n";
+ }
+ }
+}
+
1;
