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

[Jericho Rivera]

[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.

[monty solomon (monty+launchpad)]

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

[Shahriyar Rzayev (rzayev-sehriyar)]

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