Bug #42027 Incorrect parsing of debug and verbose options for mysqldumpslow
Submitted: 11 Jan 2009 9:41 Modified: 18 Mar 2009 14:57
Reporter: Sveta Smirnova Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: mysqldump Command-line Client Severity:S3 (Non-critical)
Version:5.0, 5.1, 6.0 OS:Any
Assigned to: Tatiana Azundris Nuernberg CPU Architecture:Any
Tags: Contribution

[11 Jan 2009 9:41] Sveta Smirnova
Description:
mysqldumpslow parses options debug and verbose with following way:

GetOptions(\%opt,
    'verbose|v+',# verbose
    'help+',    # write usage info
    'debug|d+', # debug
...

Lately they are used as $opt{d} and $opt{v}

But GetOptions manual says:

The option name may actually be a list of option names, separated by ``|''s, e.g. ``foo|bar|blech=s''. In this example, ``foo'' is the true name of this option.

As result options debug and verbose don't work

How to repeat:
$./mysql-5.1/bin/mysqldumpslow mysql-5.1/data/mysqld51-apple-slow.log.b --debug

Reading mysql slow query log from mysql-5.1/data/mysqld51-apple-slow.log.b
Count: 1  Time=4.32s (4s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into t2 select * from t1

Count: 3  Time=2.53s (7s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into t2 select * from t1 limit N

Count: 3  Time=2.13s (6s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into t1 select * from t1

Suggested fix:
$diff -u ./mysql-5.1/bin/mysqldumpslow  ./mysql-5.1/bin/mysqldumpslow.new 
--- ./mysql-5.1/bin/mysqldumpslow       2009-01-11 12:23:02.000000000 +0300
+++ ./mysql-5.1/bin/mysqldumpslow.new   2009-01-11 12:24:21.000000000 +0300
@@ -17,9 +17,9 @@
 );
 
 GetOptions(\%opt,
-    'verbose|v+',# verbose
+    'v|verbose+',# verbose
     'help+',   # write usage info
-       'debug|d+',     # debug
+       'd|debug+',     # debug
     's=s',     # what to sort by (t, at, l, al, r, ar etc)
     'r!',      # reverse the sort order (largest last instead of first)
     't=i',     # just show the top n queries
[11 Jan 2009 9:43] Sveta Smirnova
Corrected version prints next debug output:

$./mysql-5.1/bin/mysqldumpslow.new mysql-5.1/data/mysqld51-apple-slow.log.b --debug

Reading mysql slow query log from mysql-5.1/data/mysqld51-apple-slow.log.b
[[/Users/apple/Applications/mysql-5.1/libexec/mysqld, Version: 5.1.31-debug (Source distribution). started with:
Tcp port: 3351  Unix socket: /tmp/mysql51.sock
Time                 Id Command    Argument
# Time: 081222 13:09:29
# User@Host: root[root] @ localhost []
# Query_time: 1.181664  Lock_time: 0.000335 Rows_sent: 0  Rows_examined: 16384
use test;
SET timestamp=1229940569;
insert into t1 select * from t1;
#]]
<<>>
<<# Time: 081222 13:09:29
# User@Host: root[root] @ localhost []
# Query_time: 1.181664  Lock_time: 0.000335 Rows_sent: 0  Rows_examined: 16384
use test;
SET timestamp=1229940569;
insert into t1 select * from t1;
#>> at ./mysql-5.1/bin/mysqldumpslow.new line 79, <> chunk 1.
[[# Time: 081222 13:09:29
# User@Host: root[root] @ localhost []
# Query_time: 1.181664  Lock_time: 0.000335 Rows_sent: 0  Rows_examined: 16384
use test;
SET timestamp=1229940569;
insert into t1 select * from t1;
#]]
{{  insert into t1 select * from t1}}

[[ Time: 081222 13:09:32
# User@Host: root[root] @ localhost []
# Query_time: 2.389002  Lock_time: 0.000334 Rows_sent: 0  Rows_examined: 32768
SET timestamp=1229940572;
insert into t1 select * from t1;
#]]
{{  insert into t1 select * from t1}}

[[ Time: 081222 13:09:51
# User@Host: root[root] @ localhost []
# Query_time: 2.810496  Lock_time: 0.000258 Rows_sent: 0  Rows_examined: 65536
SET timestamp=1229940591;
insert into t1 select * from t1;
#]]
{{  insert into t1 select * from t1}}

[[ Time: 081222 13:10:35
# User@Host: root[root] @ localhost []
# Query_time: 4.316867  Lock_time: 0.001729 Rows_sent: 0  Rows_examined: 65536
SET timestamp=1229940635;
insert into t2 select * from t1;
#]]
{{  insert into t2 select * from t1}}

[[ Time: 081222 13:30:38
# User@Host: root[root] @ localhost []
# Query_time: 2.944958  Lock_time: 0.000307 Rows_sent: 0  Rows_examined: 65000
SET timestamp=1229941838;
insert into t2 select * from t1 limit 65000;
#]]
{{  insert into t2 select * from t1 limit N}}

[[ Time: 081222 13:30:42
# User@Host: root[root] @ localhost []
# Query_time: 2.401224  Lock_time: 0.000316 Rows_sent: 0  Rows_examined: 65004
SET timestamp=1229941842;
insert into t2 select * from t1 limit 65004;
#]]
{{  insert into t2 select * from t1 limit N}}

[[ Time: 081222 13:30:47
# User@Host: root[root] @ localhost []
# Query_time: 2.231534  Lock_time: 0.000248 Rows_sent: 0  Rows_examined: 65005
SET timestamp=1229941847;
insert into t2 select * from t1 limit 65005;
]]
{{  insert into t2 select * from t1 limit N}}

Count: 1  Time=4.32s (4s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into t2 select * from t1

Count: 3  Time=2.53s (7s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into t2 select * from t1 limit N

Count: 3  Time=2.13s (6s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into t1 select * from t1
[16 Feb 2009 14:46] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/66509

2749 Tatiana A. Nurnberg	2009-02-16
      Bug#42027: Incorrect parsing of debug and verbose options for mysqldumpslow
      
      Options got normalised to long rather than short options
      since we gave primary name and alias in wrong order.
      Consequently querying for the option using the short
      options (the correct primary name) didn't work, rendering
      the options in question inaccessible.
      
      We restore the right order of the universe, or at least
      the alii for --debug and --verbose.
[24 Feb 2009 8:28] Tatiana Azundris Nuernberg
patch queued for 5.0.79, 5.1.33, 6.0.10 in -bugteam
[9 Mar 2009 14:12] Bugs System
Pushed into 5.0.79 (revid:joro@sun.com-20090309135922-a0di9ebkxoj4d4wv) (version source revid:aelkin@mysql.com-20090224143545-7xc77386o8mg623c) (merge vers: 5.0.79) (pib:6)
[11 Mar 2009 1:49] Paul DuBois
Noted in 5.0.79 changelog.

mysqldumpslow parsed the --debug and --verbose options incorrectly.

Setting report to NDI pending push into 5.1.x/6.0.x.
[13 Mar 2009 19:05] Bugs System
Pushed into 5.1.33 (revid:joro@sun.com-20090313111355-7bsi1hgkvrg8pdds) (version source revid:azundris@mysql.com-20090224080740-l4d4glsqmklmy2wo) (merge vers: 5.1.33) (pib:6)
[14 Mar 2009 1:45] Paul DuBois
Noted in 5.1.33 changelog.

Setting report to NDI pending push into 6.0.x.
[18 Mar 2009 13:17] Bugs System
Pushed into 6.0.11-alpha (revid:joro@sun.com-20090318122208-1b5kvg6zeb4hxwp9) (version source revid:azundris@mysql.com-20090224081255-inew8jun7hkqljnm) (merge vers: 6.0.10-alpha) (pib:6)
[18 Mar 2009 14:57] Paul DuBois
Noted in 6.0.11 changelog.
[9 May 2009 16:43] Bugs System
Pushed into 5.1.34-ndb-6.2.18 (revid:jonas@mysql.com-20090508185236-p9b3as7qyauybefl) (version source revid:jonas@mysql.com-20090508100057-30ote4xggi4nq14v) (merge vers: 5.1.33-ndb-6.2.18) (pib:6)
[9 May 2009 17:40] Bugs System
Pushed into 5.1.34-ndb-6.3.25 (revid:jonas@mysql.com-20090509063138-1u3q3v09wnn2txyt) (version source revid:jonas@mysql.com-20090508175813-s6yele2z3oh6o99z) (merge vers: 5.1.33-ndb-6.3.25) (pib:6)
[9 May 2009 18:37] Bugs System
Pushed into 5.1.34-ndb-7.0.6 (revid:jonas@mysql.com-20090509154927-im9a7g846c6u1hzc) (version source revid:jonas@mysql.com-20090509073226-09bljakh9eppogec) (merge vers: 5.1.33-ndb-7.0.6) (pib:6)