pt-query-digest does not parse general log generated by PS/MySQL 5.7 instance

Bug #1585412 reported by Jericho Rivera
18
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Percona Toolkit moved to https://jira.percona.com/projects/PT
Fix Released
High
Carlos Salguero

Bug Description

[root@centos1 ~]# pt-query-digest --version
pt-query-digest 2.2.17

[root@centos1 ~]# rpm -qa|grep Percona-Server-server
Percona-Server-server-57-5.7.11-4.1.el6.x86_64

[root@centos1 ~]# head -n 20 /var/lib/mysql/centos1.log
/usr/sbin/mysqld, Version: 5.7.11-4-log (Percona Server (GPL), Release 4, Revision 5c940e1). started with:
Tcp port: 3306 Unix socket: /var/lib/mysql/mysql.sock
Time Id Command Argument
2016-05-24T23:34:08.342815Z 5 Query show global variables like '%global%'
2016-05-24T23:34:16.833249Z 5 Query show global variables like '%general%'
2016-05-24T23:34:21.862223Z 5 Quit
2016-05-24T23:34:29.615692Z 6 Connect root@localhost on test using Socket
2016-05-24T23:34:29.615718Z 7 Connect root@localhost on test using Socket
2016-05-24T23:34:29.616064Z 6 Query BEGIN
2016-05-24T23:34:29.616327Z 6 Query SELECT c FROM sbtest1 WHERE id=4969
2016-05-24T23:34:29.616993Z 6 Query SELECT c FROM sbtest1 WHERE id=5320
2016-05-24T23:34:29.617241Z 7 Query BEGIN
2016-05-24T23:34:29.617390Z 6 Query SELECT c FROM sbtest1 WHERE id=5302
2016-05-24T23:34:29.617460Z 7 Query SELECT c FROM sbtest1 WHERE id=6380
2016-05-24T23:34:29.617704Z 6 Query SELECT c FROM sbtest1 WHERE id=4522
2016-05-24T23:34:29.618021Z 6 Query SELECT c FROM sbtest1 WHERE id=4503
2016-05-24T23:34:29.618067Z 7 Query SELECT c FROM sbtest1 WHERE id=4824
2016-05-24T23:34:29.618332Z 6 Query SELECT c FROM sbtest1 WHERE id=5048
2016-05-24T23:34:29.618487Z 7 Query SELECT c FROM sbtest1 WHERE id=4984
2016-05-24T23:34:29.618618Z 6 Query SELECT c FROM sbtest1 WHERE id=4977
[root@centos1 ~]# pt-query-digest --type genlog /var/lib/mysql/centos1.log

# No events processed.

Compared to:

percona-toolkit-2.2.17/bin/pt-query-digest --version
pt-query-digest 2.2.17

./use -e 'select @@version'
+-----------+
| @@version |
+-----------+
| 5.6.29 |
+-----------+

percona-toolkit-2.2.17/bin/pt-query-digest --type genlog data/percona.log | head -n 20

# 680ms user time, 30ms system time, 34.91M rss, 104.31M vsz
# Current date: Wed May 25 07:58:48 2016
# Hostname: percona
# Files: data/percona.log
# Overall: 4.03k total, 14 unique, 1.60 QPS, 0x concurrency ______________
# Time range: 2016-05-25 07:16:06 to 07:58:11
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 0 0 0 0 0 0 0
# Query size 119.08k 11 77 30.23 31.70 2.53 28.75

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0xAA353644DE4C4CB4 0.0000 0.0% 1007 0.0000 0.00 ADMIN QUIT
# 2 0xE3A3649C5FAC418D 0.0000 0.0% 1006 0.0000 0.00 SELECT
# 3 0x5D51E5F01B88B79E 0.0000 0.0% 1006 0.0000 0.00 ADMIN CONNECT
# 4 0xD63F935A9BD316B0 0.0000 0.0% 1003 0.0000 0.00 INSERT test.test?
# 5 0x389FF9DA2DF3DF62 0.0000 0.0% 2 0.0000 0.00 SELECT
# Caught SIGPIPE.
# Exiting on SIGPIPE.

head -20 data/percona.log
/data/perc/mysqlbin/5.6.29/bin/mysqld, Version: 5.6.29 (MySQL Community Server (GPL)). started with:
Tcp port: 5629 Unix socket: /tmp/mysql_sandbox5629.sock
Time Id Command Argument
160525 7:16:06 4 Query SELECT DATABASE()
      4 Init DB test
      4 Query show databases
      4 Query show tables
160525 7:16:33 4 Query create table test1 (id int primary key not null auto_increment) engine=innodb
160525 7:16:42 4 Query insert into test1 values (),(),(),()
160525 7:16:45 4 Quit
160525 7:25:26 5 Connect msandbox@localhost on
      5 Query select @@version_comment limit 1
      5 Query select USER()
160525 7:25:31 5 Query delete from test.test1
160525 7:25:34 5 Quit
160525 7:26:50 6 Connect msandbox@localhost on
      6 Query select @@version_comment limit 1
      6 Query insert into test.test1 values ()
      6 Quit
      7 Connect msandbox@localhost on

I think this is due to the fact that the general log format on 5.7 has changed.

tags: added: pt-query-digest
Changed in percona-toolkit:
status: New → Confirmed
Changed in percona-toolkit:
status: Confirmed → Fix Committed
milestone: none → 2.2.18
assignee: nobody → Carlos Salguero (carlos-salguero)
importance: Undecided → High
Changed in percona-toolkit:
status: Fix Committed → Fix Released
Revision history for this message
monty solomon (monty+launchpad) wrote :

Carlos,

This appears to be broken.

Server version: 5.7.13-6-log Percona Server (GPL), Release 6, Revision e3d58bb
pt-query-digest 2.2.20

% pt-query-digest --type genlog general.log-201703281490716861
# No events processed.

# VersionCheck:12408 10196 0 instances to check
# Pipeline:11562 10196 Pipeline starting at 1490998357.36695
# Pipeline:11574 10196 Pipeline process prep
# Pipeline:11574 10196 Pipeline process input
# FileIterator:11316 10196 Filename: general.log-201703281490716861
# pt_query_digest:13245 10196 Reading general.log-201703281490716861
# pt_query_digest:13246 10196 File size: 4021838570
# Pipeline:11574 10196 Pipeline process GeneralLogParser
# GeneralLogParser:9877 10196 /usr/sbin/mysqld, Version: 5.7.13-6-log (Percona Server (GPL), Release 6, Revision e3d58bb). started with:
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 Tcp port: 3306 Unix socket: /opt/mysql/dbprod/monty-q0.sock
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 Time Id Command Argument
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 2017-03-28T15:02:23.101033Z48437638 Quit
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 2017-03-28T15:02:23.101712Z48436236 Query SELECT
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 2017-03-28T15:02:23.101726Z48435624 Query SELECT
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 2017-03-28T15:02:23.101813Z48436720 Query SELECT
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 2017-03-28T15:02:23.102124Z48435592 Query SELECT
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 2017-03-28T15:02:23.102185Z48436276 Query SELECT
#
# GeneralLogParser:9880 10196 Not start of general log event
# GeneralLogParser:9877 10196 2017-03-28T15:02:23.102719Z48435562 Query SELECT

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

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

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.