Description:
The slow query log processor has Rows Examined available to it yet it does not report it. Having the ability to compare rows examined to rows returned is extremely helpful in identifying inefficient queries.
How to repeat:
See description
Suggested fix:
--- mysqldumpslow 2010-05-07 10:17:19.000000000 -0500
+++ mysqldumpslow 2011-06-20 11:46:44.000000000 -0500
@@ -8,8 +8,8 @@
use strict;
use Getopt::Long;
-# t=time, l=lock time, r=rows
-# at, al, and ar are the corresponding averages
+# t=time, l=lock time, r=rows sent, e=rows examined
+# at, al, ar, and ae are the corresponding averages
my %opt = (
s => 'at',
@@ -83,8 +83,8 @@
s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//;
my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('','');
- s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;
- my ($t, $l, $r) = ($1, $2, $3);
+ s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+)\s+Rows_examined: ([0-9.]+).*\n//;
+ my ($t, $l, $r, $e) = ($1, $2, $3, $4);
$t -= $l unless $opt{l};
# remove fluff that mysqld writes to log when it (re)starts:
@@ -121,6 +121,7 @@
$s->{t} += $t;
$s->{l} += $l;
$s->{r} += $r;
+ $s->{e} += $e;
$s->{users}->{$user}++ if $user;
$s->{hosts}->{$host}++ if $host;
@@ -129,10 +130,11 @@
foreach (keys %stmt) {
my $v = $stmt{$_} || die;
- my ($c, $t, $l, $r) = @{ $v }{qw(c t l r)};
+ my ($c, $t, $l, $r, $e) = @{ $v }{qw(c t l r e)};
$v->{at} = $t / $c;
$v->{al} = $l / $c;
$v->{ar} = $r / $c;
+ $v->{ae} = $e / $c;
}
my @sorted = sort { $stmt{$b}->{$opt{s}} <=> $stmt{$a}->{$opt{s}} } keys %stmt;
@@ -141,13 +143,13 @@
foreach (@sorted) {
my $v = $stmt{$_} || die;
- my ($c, $t,$at, $l,$al, $r,$ar) = @{ $v }{qw(c t at l al r ar)};
+ my ($c, $t,$at, $l,$al, $r,$ar, $e,$ae) = @{ $v }{qw(c t at l al r ar e ae)};
my @users = keys %{$v->{users}};
my $user = (@users==1) ? $users[0] : sprintf "%dusers",scalar @users;
my @hosts = keys %{$v->{hosts}};
my $host = (@hosts==1) ? $hosts[0] : sprintf "%dhosts",scalar @hosts;
- printf "Count: %d Time=%.2fs (%ds) Lock=%.2fs (%ds) Rows=%.1f (%d), $user\@$host\n%s\n\n",
- $c, $at,$t, $al,$l, $ar,$r, $_;
+ printf "Count: %d Time=%.2fs (%ds) Lock=%.2fs (%ds) Rows Sent=%.1f (%d) Rows Examined=%.1f (%d), $user\@$host\n%s\n\n",
+ $c, $at,$t, $al,$l, $ar,$r, $ae,$e, $_;
}
sub usage {
@@ -163,11 +165,13 @@
-v verbose
-d debug
- -s ORDER what to sort by (al, at, ar, c, l, r, t), 'at' is default
+ -s ORDER what to sort by (ae, al, at, ar, c, e, l, r, t), 'at' is default
+ ae: average rows examined
al: average lock time
ar: average rows sent
at: average query time
c: count
+ e: rows examined
l: lock time
r: rows sent
t: query time
Description: The slow query log processor has Rows Examined available to it yet it does not report it. Having the ability to compare rows examined to rows returned is extremely helpful in identifying inefficient queries. How to repeat: See description Suggested fix: --- mysqldumpslow 2010-05-07 10:17:19.000000000 -0500 +++ mysqldumpslow 2011-06-20 11:46:44.000000000 -0500 @@ -8,8 +8,8 @@ use strict; use Getopt::Long; -# t=time, l=lock time, r=rows -# at, al, and ar are the corresponding averages +# t=time, l=lock time, r=rows sent, e=rows examined +# at, al, ar, and ae are the corresponding averages my %opt = ( s => 'at', @@ -83,8 +83,8 @@ s/^#? Time: \d{6}\s+\d+:\d+:\d+.*\n//; my ($user,$host) = s/^#? User\@Host:\s+(\S+)\s+\@\s+(\S+).*\n// ? ($1,$2) : ('',''); - s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//; - my ($t, $l, $r) = ($1, $2, $3); + s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+)\s+Rows_examined: ([0-9.]+).*\n//; + my ($t, $l, $r, $e) = ($1, $2, $3, $4); $t -= $l unless $opt{l}; # remove fluff that mysqld writes to log when it (re)starts: @@ -121,6 +121,7 @@ $s->{t} += $t; $s->{l} += $l; $s->{r} += $r; + $s->{e} += $e; $s->{users}->{$user}++ if $user; $s->{hosts}->{$host}++ if $host; @@ -129,10 +130,11 @@ foreach (keys %stmt) { my $v = $stmt{$_} || die; - my ($c, $t, $l, $r) = @{ $v }{qw(c t l r)}; + my ($c, $t, $l, $r, $e) = @{ $v }{qw(c t l r e)}; $v->{at} = $t / $c; $v->{al} = $l / $c; $v->{ar} = $r / $c; + $v->{ae} = $e / $c; } my @sorted = sort { $stmt{$b}->{$opt{s}} <=> $stmt{$a}->{$opt{s}} } keys %stmt; @@ -141,13 +143,13 @@ foreach (@sorted) { my $v = $stmt{$_} || die; - my ($c, $t,$at, $l,$al, $r,$ar) = @{ $v }{qw(c t at l al r ar)}; + my ($c, $t,$at, $l,$al, $r,$ar, $e,$ae) = @{ $v }{qw(c t at l al r ar e ae)}; my @users = keys %{$v->{users}}; my $user = (@users==1) ? $users[0] : sprintf "%dusers",scalar @users; my @hosts = keys %{$v->{hosts}}; my $host = (@hosts==1) ? $hosts[0] : sprintf "%dhosts",scalar @hosts; - printf "Count: %d Time=%.2fs (%ds) Lock=%.2fs (%ds) Rows=%.1f (%d), $user\@$host\n%s\n\n", - $c, $at,$t, $al,$l, $ar,$r, $_; + printf "Count: %d Time=%.2fs (%ds) Lock=%.2fs (%ds) Rows Sent=%.1f (%d) Rows Examined=%.1f (%d), $user\@$host\n%s\n\n", + $c, $at,$t, $al,$l, $ar,$r, $ae,$e, $_; } sub usage { @@ -163,11 +165,13 @@ -v verbose -d debug - -s ORDER what to sort by (al, at, ar, c, l, r, t), 'at' is default + -s ORDER what to sort by (ae, al, at, ar, c, e, l, r, t), 'at' is default + ae: average rows examined al: average lock time ar: average rows sent at: average query time c: count + e: rows examined l: lock time r: rows sent t: query time