mysqldumpslow broken with PS slow log format

Bug #856910 reported by Jervin R on 2011-09-23
28
This bug affects 5 people
Affects Status Importance Assigned to Milestone
Percona Server
Status tracked in 5.7
5.1
Low
Oleg Tsarev
5.5
Low
Yura Sorokin
5.6
Low
Yura Sorokin
5.7
Low
Yura Sorokin

Bug Description

The statistics line is not being calculated properly because the regexp line does not work well with the PS format.

This can easily be fixed by replacing line 104 from the mysqldumpslow script that ships with 5.1.58 with:

s/\s+#\s+Query_time:\s+(\d+\.?\d*)\s+Lock_time:\s+(\d+\.?\d*)\s+Rows_sent:\s+(\d+\.?\d*).*\n//;

Sample output with PS slow log format:

Count: 1 Time=0.0000s (0s) Lock=0.0000s (0s) Rows=0.0 (0), msandbox[msandbox]@localhost
  # Thread_id: 7 Schema: employees Last_errno: 0 Killed: 0
  # Query_time: 0.259588 Lock_time: 0.046811 Rows_sent: 0 Rows_examined: 0 Rows_affected: 24923 Rows_read: 6
  # Bytes_sent: 56 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
  # InnoDB_trx_id: 3A0
  # QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
  # Filesort: No Filesort_on_disk: No Merge_passes: 0
  # InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
  # InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
  # InnoDB_pages_distinct: 121

Sample output with community slow log format:

Count: 11 Time=0.46s (5s) Lock=0.00s (0s) Rows=0.0 (0), msandbox[msandbox]@localhost
  update emails set locked_at = now() where locked_at is NULL and id = 611336

Count: 12 Time=0.43s (5s) Lock=0.00s (0s) Rows=0.0 (0), msandbox[msandbox]@localhost
  update emails set locked_at = now() where locked_at is NULL and id = 611394

I'm aware this is duplicate of https://bugs.launchpad.net/bugs/734211 - but please see Percona internal issue #18580

Related branches

lp:~tsarev/percona-server/18580
Oleg Tsarev (community): Approve on 2012-01-01
Laurynas Biveinis: Approve on 2011-12-29
Oleg Tsarev (tsarev) on 2011-09-23
Changed in percona-server:
assignee: nobody → Oleg Tsarev (tsarev)
Oleg Tsarev (tsarev) on 2011-12-02
Changed in percona-server:
status: New → Fix Committed
tags: added: cr i18580
Changed in percona-server:
milestone: none → 5.1.61-13.2
Stewart Smith (stewart) on 2012-12-12
tags: added: slow-extended

Based on bug 734211 triage I am setting this to Won't Fix for 5.5+. If a fix for newer versions is desired, please let us know.

Changed in percona-server:
status: Triaged → Won't Fix

We need this fixed for recent 5.6.x as it's still broken:

[root@centos openxs]# mysql
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.6.27-76.0-log Percona Server (GPL), Release 76.0, Revision 5498987

Copyright (c) 2009-2015 Percona LLC and/or its affiliates
Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> flush logs;
Query OK, 0 rows affected (0.25 sec)

mysql> select sleep(5) from mysql.user;
+----------+
| sleep(5) |
+----------+
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
+----------+
9 rows in set (45.00 sec)

mysql> select sleep(10) from mysql.user;
+-----------+
| sleep(10) |
+-----------+
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
| 0 |
+-----------+
9 rows in set (1 min 30.01 sec)

mysql> exit
Bye

This is the slow log as a result:

[root@centos openxs]# ls -l /var/lib/mysql/centos-slow1
-rw-rw----. 1 mysql mysql 1317 Dec 16 19:40 /var/lib/mysql/centos-slow1
[root@centos openxs]# mysqldumpslow /var/lib/mysql/centos-slow1

Reading mysql slow query log from /var/lib/mysql/centos-slow1
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
# Schema: Last_errno: N Killed: N
# Query_time: N.N Lock_time: N.N Rows_sent: N Rows_examined: N Rows_affected: N
# Bytes_sent: N
SET timestamp=N

Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), 0users@0hosts
administrator command: Quit

Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
# Schema: Last_errno: N Killed: N
# Query_time: N.N Lock_time: N.N Rows_sent: N Rows_examined: N Rows_affected: N
# Bytes_sent: N
SET timestamp=N;
flush logs

Count: 2 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
# Schema: Last_errno: N Killed: N
# Query_time: N.N Lock_time: N.N Rows_sent: N Rows_examined: N Rows_affected: N
# Bytes_sent: N
SET timestamp=N;
select sleep(N) from mysql.user

We see zeros in time and rows, and that's obviously wrong.

tags: added: i63376

If we do not fix this to work properly, we should better deprecate the feature formally and remove the script from the code entirely. There is no point to keep mysqldumpslow that is useless.

Based on comment #3 in bug 734211, is pt-query-digest a suitable alternative?

As for removing it, it's an upstream script. Perhaps we can add a note to our docs that mysqldumpslow does not work with PS slow query log?

Well, customer in the issue related explcitly asked either to fix the script or deprecate and remove it. I have to exscalate this request as a result. pt-query-digest was surely presented as an alternative, but the request remains, and IMHO it makes 100% sense.

We decided to change log format, so we should care to make sure everything works with it in our software.

We are going to replace PS-packaged mysqldumpslow with a placeholder script that recommends to use pt-query-digest (maybe MySQL-provided mysqldumpslow if it's MySQL format slow query log that needs to be processed) and does nothing else. We will also have to provide a corresponding man/mysqldumpslow.1.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers