MySQL Bugs: #79828: mysqldumpslow does not aggregate times

Bug #79828	mysqldumpslow does not aggregate times
Submitted:	3 Jan 2016 23:22	Modified:	3 Jan 2016 23:37
Reporter:	Ivan Pavlovic	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Command-line Clients	Severity:	S3 (Non-critical)
Version:	5.7.10, 5.7.17	OS:	CentOS
Assigned to:		CPU Architecture:	Any
Tags:	mysqldumpslow

Description:
Hi Team,

mysqldumpslow does not aggregate times/rows (query_time/lock_time; rows_sent/rows_examined) in MySQL 5.7.10 version.

Best Regards,

Ivan Pavlovic

How to repeat:
The slow quey log is activated and contains entries like:

/usr/sbin/mysqld, Version: 5.7.10 (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 2016-01-03T23:29:26.735647+01:00
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 0.010279  Lock_time: 0.000110 Rows_sent: 100  Rows_examined: 10749
SET timestamp=1451860166;
SELECT SQL_NO_CACHE INET_NTOA(IP_SRC_ADDR),INET_NTOA(IP_DST_ADDR),L4_SRC_PORT,VLAN_ID,INFO FROM flowsv4 WHERE FIRST_SWITCHED <= 1451829078 AND FIRST_SWITCHED >= 1451828478 ORDER BY BYTES DESC LIMIT 100;
# Time: 2016-01-03T23:29:39.642017+01:00
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 0.022714  Lock_time: 0.000132 Rows_sent: 100  Rows_examined: 25232
SET timestamp=1451860179;
SELECT SQL_NO_CACHE INET_NTOA(IP_SRC_ADDR),INET_NTOA(IP_DST_ADDR),L4_SRC_PORT,VLAN_ID,INFO FROM flowsv4 WHERE FIRST_SWITCHED <= 1451829078 AND FIRST_SWITCHED >= 1451827478 ORDER BY BYTES DESC LIMIT 100;
# Time: 2016-01-03T23:29:50.281932+01:00
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 0.024283  Lock_time: 0.000144 Rows_sent: 100  Rows_examined: 27045
SET timestamp=1451860190;
SELECT SQL_NO_CACHE INET_NTOA(IP_SRC_ADDR),INET_NTOA(IP_DST_ADDR),L4_SRC_PORT,VLAN_ID,INFO FROM flowsv4 WHERE FIRST_SWITCHED <= 1451829078 AND FIRST_SWITCHED >= 1451826478 ORDER BY BYTES DESC LIMIT 100;
# Time: 2016-01-03T23:39:53.306700+01:00
# User@Host: root[root] @ localhost []  Id:     5
# Query_time: 388.912490  Lock_time: 0.000108 Rows_sent: 13  Rows_examined: 48261
SET timestamp=1451860793;
SELECT SQL_NO_CACHE INET_NTOA(IP_SRC_ADDR),INET_NTOA(IP_DST_ADDR),L4_SRC_PORT,VLAN_ID,INFO FROM flowsv4 WHERE FIRST_SWITCHED <= 1451829078 AND FIRST_SWITCHED >= 1451823478 ORDER BY BYTES DESC LIMIT 100;

The aggregated times/rows from mysqldumpslow output are always 0.00 (N.N), so sort by query_time/lock_time/rows_sent is not possible:

Reading mysql slow query log from /var/log/mysql/slow_query_log.log
Count: 6  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  Time: N-N-03T23:N:N.N+N:N
  # User@Host: root[root] @ localhost []  Id:     N
  # Query_time: N.N  Lock_time: N.N Rows_sent: N  Rows_examined: N
  SET timestamp=N;

Count: 6  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  Time: N-N-03T23:N:N.N+N:N
  # User@Host: root[root] @ localhost []  Id:     N
  # Query_time: N.N  Lock_time: N.N Rows_sent: N  Rows_examined: N
  SET timestamp=N;
  SELECT SQL_NO_CACHE INET_NTOA(IP_SRC_ADDR),INET_NTOA(IP_DST_ADDR),L4_SRC_PORT,VLAN_ID,INFO FROM flowsv4 WHERE FIRST_SWITCHED <= N AND FIRST_SWITCHED >= N ORDER BY BYTES DESC LIMIT N

Additional info:

Variable_name            Value                         
-----------------------  ------------------------------
innodb_version           5.7.10                                      
version                  5.7.10                        
version_comment          MySQL Community Server (GPL)  
version_compile_machine  x86_64                        
version_compile_os       Linux   
slow_query_log           ON
long_query_time          0.000000
log_timestamps           SYSTEM

Hi Ivan, 

Thanks for reporting the bug. It is verified as reported.

kind regards
Bogdan Kecman

[arhimed@gedora]$ cat SPORI57.log
/home/arhimed/MYSQL/5.7.7/bin/mysqld, Version: 5.7.7-rc-log (MySQL Community Server (GPL)). started with:
Tcp port: 5707  Unix socket: /tmp/mysql_sandbox5707.sock
Time                 Id Command    Argument
# Time: 2016-01-03T19:49:16.917840Z
# User@Host: msandbox[msandbox] @ localhost []  Id:     2
# Query_time: 10.000174  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1287;
select sleep(10);

[arhimed@gedora]$ cat SPORI55.log
/home/arhimed/MYSQL/5.5.43/bin/mysqld, Version: 5.5.43-log (MySQL Community Server (GPL)). started with:
Tcp port: 5543  Unix socket: /tmp/mysql_sandbox5543.sock
Time                 Id Command    Argument
# Time: 160103 20:47:23
# User@Host: msandbox[msandbox] @ localhost []
# Query_time: 10.000160  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1451850443;
select sleep( 10);

msb_5_7_7]$ ./my sqldumpslow  data/SPORI57.log

Reading mysql slow query log from data/SPORI57.log
Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  # Time: N-N-03T19:N:N.917840Z
  # User@Host: msandbox[msandbox] @ localhost []  Id:     N
  # Query_time: N.N  Lock_time: N.N Rows_sent: N  Rows_examined: N
  SET timestamp=N;
  select sleep(N)

msb_5_5_43]$ ./my sqldumpslow  data/SPORI55.log

Reading mysql slow query log from data/SPORI55.log
Count: 1  Time=10.00s (10s)  Lock=0.00s (0s)  Rows=1.0 (1), msandbox[msandbox]@localhost
  select sleep( N)

Bug #85326 marked as duplicate of this