pt-query-digest binlog bug in MySQL causes very high exec_time

[Kenny Gryp]

There's a bug in the MySQL binary Log that sometimes creates exec_time=4294967295 (or similar)

Bug: http://bugs.mysql.com/bug.php?id=52704

Shouldn't we make this default for pt-query-digest? Or at least document it as a good start when looking at binary logs?

[Kenny Gryp (gryp)]

Maybe it's not that big of a deal as exec_time is not useful anyway.

Another better solution would be to make the default --order-by Query_time:cnt instead of Query_time:sum for '--type=binlog'

[Nilnandan Joshi (nilnandan-joshi)]

Able to reproduce the same with 5.5.32 while checking test case mentioned in upstream bug.

<?php
 $dbhandle= mysql_connect("127.0.0.1:5532","msandbox","msandbox") or die("connect")
             or die("Could not connect to MySQL");
 $selected = mysql_select_db("test",$dbhandle)
  or die("Could not select examples");

  mysql_query("drop table if exists t1");
  mysql_query("create table t1(id int primary key, msg varchar(100)) engine=innodb");

  for ($i=1; $i< 10000; $i++) {
    if ($i % 100 == 0) echo "$i\r";
    mysql_query("begin");
    mysql_query("insert into t1 set id = $i, msg = md5(rand())");
    mysql_query("commit");
  }
?>

root@nilnandan-Dell-XPS:/home/nilnandan/sandboxes/msb_5_5_32/data# mysqlbinlog mysql-bin.000001 | grep "exec_time=42"
#140819 13:34:46 server id 1 end_log_pos 190925 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:34:50 server id 1 end_log_pos 288641 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:34:54 server id 1 end_log_pos 388481 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:34:55 server id 1 end_log_pos 412961 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:34:59 server id 1 end_log_pos 509681 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:35:03 server id 1 end_log_pos 607121 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:35:06 server id 1 end_log_pos 681856 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:35:15 server id 1 end_log_pos 903761 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:35:21 server id 1 end_log_pos 1053281 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:35:22 server id 1 end_log_pos 1077281 Query thread_id=8 exec_time=4294967295 error_code=0
#140819 13:35:24 server id 1 end_log_pos 1127441 Query thread_id=8 exec_time=4294967295 error_code=0
root@nilnandan-Dell-XPS:/home/nilnandan/sandboxes/msb_5_5_32/data#

[Frank Cizmich (frank-cizmich)]

Thanks Joshi, the script worked fine for me.

Since it's such a specific and improbable number ( 4294967295 ) , maybe we could issue a warning when it appears and *then* default to Query_time:cnt as Kenny suggests.

I agree with OP this should be mentioned in PT docs.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PT-652