Bug #61572 mysqldumpslow does not include output for rows examined
Submitted: 20 Jun 2011 17:03 Modified: 28 Jun 2011 16:20
Reporter: Kevin Benton Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S4 (Feature request)
Version:5.1.47 OS:Any
Assigned to: CPU Architecture:Any
Tags: Contribution
Triage: Needs Triage: D4 (Minor)

[20 Jun 2011 17:03] Kevin Benton
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
[20 Jun 2011 17:07] Kevin Benton
mysqldump Patch

Attachment: mysqldump.diff (application/octet-stream, text), 2.82 KiB.

[28 Jun 2011 15:45] Kevin Benton
Replacement now includes efficiency ( ( 100 * rows sent ) / rows examined ) and weight ( ( 100 - efficiency ) * query time )

Attachment: mysqldump.diff (application/octet-stream, text), 3.84 KiB.

[28 Jun 2011 15:47] Kevin Benton
Replacing patch with new one that adds capability by adding two new fields that can be used for display and sorting:

f = efficiency
w = weighted efficiency

The previously included patch is also included.
[28 Jun 2011 16:20] Kevin Benton
All - the code attached to this bug up to this point is officially entered into the public domain. I am the creator of the code included herein and did not base this work on any other work except what has already been provided in mysqldumpslow as shown. I release all rights associated with this code.