pt-query-digest fails to parse binary log with RBR events

[Przemek]

The --type binlog mode fails when binlog_format is ROW. Even when there are only some RBR events in the binlog (i.e. using MIXED format), the tool reports just single "BEGIN" query and igores all others.

mysqlbinlog --base64-output=DECODE-ROWS --verbose node1/data/mysql-bin.000010 > mysql-bin.000010.sql

cat mysql-bin.000010.sql
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#141006 13:04:06 server id 101 end_log_pos 120 CRC32 0x33597fec Start: binlog v 4, server v 5.6.21-log created 141006 13:04:06
# Warning: this binlog is either in use or was not closed properly.
# at 120
#141006 13:04:12 server id 1 end_log_pos 195 CRC32 0xd54d7232 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1412593452/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 195
#141006 13:04:12 server id 1 end_log_pos 295 CRC32 0x7a485040 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1412593452/*!*/;
insert into test.t1 values (5)
/*!*/;
# at 295
#141006 13:04:12 server id 1 end_log_pos 326 CRC32 0x273d074a Xid = 32
COMMIT/*!*/;
# at 326
#141006 13:04:22 server id 1 end_log_pos 401 CRC32 0xef9b64c1 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1412593462/*!*/;
BEGIN
/*!*/;
# at 401
#141006 13:04:22 server id 1 end_log_pos 501 CRC32 0x411421e6 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1412593462/*!*/;
insert into test.t1 values (6)
/*!*/;
# at 501
#141006 13:04:22 server id 1 end_log_pos 532 CRC32 0x5f592894 Xid = 34
COMMIT/*!*/;
# at 532
#141006 13:05:51 server id 1 end_log_pos 595 CRC32 0x21658502 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1412593551/*!*/;
SET @@session.sql_mode=524288/*!*/;
BEGIN
/*!*/;
# at 595
#141006 13:05:51 server id 1 end_log_pos 640 CRC32 0x48d48ebc Table_map: `test`.`t1` mapped to number 70
# at 640
#141006 13:05:51 server id 1 end_log_pos 680 CRC32 0x3fdb95aa Write_rows: table id 70 flags: STMT_END_F
### INSERT INTO `test`.`t1`
### SET
### @1=7
# at 680
#141006 13:05:51 server id 1 end_log_pos 711 CRC32 0x840052da Xid = 42
COMMIT/*!*/;
# at 711
#141006 13:06:46 server id 1 end_log_pos 774 CRC32 0xe9be87cd Query thread_id=2 exec_time=1 error_code=0
SET TIMESTAMP=1412593606/*!*/;
BEGIN
/*!*/;
# at 774
#141006 13:06:46 server id 1 end_log_pos 819 CRC32 0xa64284a6 Table_map: `test`.`t1` mapped to number 70
# at 819
#141006 13:06:46 server id 1 end_log_pos 859 CRC32 0x2d334616 Delete_rows: table id 70 flags: STMT_END_F
### DELETE FROM `test`.`t1`
### WHERE
### @1=1
# at 859
#141006 13:06:46 server id 1 end_log_pos 890 CRC32 0x0e0b3f0b Xid = 44
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

pt-query-digest --type binlog mysql-bin.000010.sql

# 330ms user time, 20ms system time, 34.46M rss, 229.38M vsz
# Current date: Mon Oct 6 13:08:08 2014
# Hostname: pmlap
# Files: mysql-bin.000010.sql
# Overall: 5 total, 4 unique, 0.03 QPS, 0.01x concurrency ________________
# Time range: 2014-10-06 13:04:06 to 13:06:46
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 1s 0 1s 200ms 992ms 397ms 0
# Query size 224 5 132 24.89 130.47 38.72 5.75
# @@session.au 1 1 1 1 1 0 1
# @@session.au 1 1 1 1 1 0 1
# @@session.au 1 1 1 1 1 0 1
# @@session.ch 33 33 33 33 33 0 33
# @@session.co 33 33 33 33 33 0 33
# @@session.co 8 8 8 8 8 0 8
# @@session.fo 1 1 1 1 1 0 1
# @@session.lc 0 0 0 0 0 0 0
# @@session.ps 2 2 2 2 2 0 2
# @@session.sq 0 0 0 0 0 0 0
# @@session.sq 1.00G 512.00k 1.00G 512.25M 1.00G 723.72M 512.25M
# @@session.un 1 1 1 1 1 0 1
# error code 0 0 0 0 0 0 0

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== =========
# 1 0x85FFF5AA78E5FF6A 1.0000 100.0% 3 0.3333 0.66 BEGIN
# MISC 0xMISC 0.0000 0.0% 2 0.0000 0.0 <1 ITEMS>

# Query 1: 0.02 QPS, 0.01x concurrency, ID 0x85FFF5AA78E5FF6A at byte 2338
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.66
# Time range: 2014-10-06 13:04:06 to 13:06:46
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 60 3
# Exec time 100 1s 0 1s 333ms 992ms 468ms 0
# Query size 8 20 5 5 5 5 0 5
# @@session.au 100 1 1 1 1 1 0 1
# @@session.au 100 1 1 1 1 1 0 1
# @@session.au 100 1 1 1 1 1 0 1
# @@session.ch 100 33 33 33 33 33 0 33
# @@session.co 100 33 33 33 33 33 0 33
# @@session.co 100 8 8 8 8 8 0 8
# @@session.fo 100 1 1 1 1 1 0 1
# @@session.lc 0 0 0 0 0 0 0 0
# @@session.ps 100 2 2 2 2 2 0 2
# @@session.sq 0 0 0 0 0 0 0 0
# @@session.sq 100 1.00G 512.00k 1.00G 512.25M 1.00G 723.72M 512.25M
# @@session.un 100 1 1 1 1 1 0 1
# error code 0 0 0 0 0 0 0 0
# String:
# @@session.co default
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
BEGIN\G

[Nilnandan Joshi (nilnandan-joshi)]

Able to reproduce the same with pt-query-digest 2.2.9. We can see only DDL, no DML.

[root@centos65 mysql]# mysqlbinlog --base64-output=DECODE-ROWS --verbose mysql-bin.000002 > mysql-bin.000002.sql
[root@centos65 mysql]#
[root@centos65 mysql]# cat mysql-bin.000002
mysql-bin.000002 mysql-bin.000002.sql
[root@centos65 mysql]# cat mysql-bin.000002.sql
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#141009 15:27:30 server id 1 end_log_pos 120 CRC32 0x3ecc7d0c Start: binlog v 4, server v 5.6.21-69.0-log created 141009 15:27:30 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 120
#141009 15:27:57 server id 1 end_log_pos 211 CRC32 0x8ff8e66e Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1412848677/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create database nil
/*!*/;
# at 211
#141009 15:28:15 server id 1 end_log_pos 325 CRC32 0x909a52a5 Query thread_id=1 exec_time=0 error_code=0
use `nil`/*!*/;
SET TIMESTAMP=1412848695/*!*/;
create table t1 (id int, name varchar(10))
/*!*/;
# at 325
#141009 15:28:30 server id 1 end_log_pos 396 CRC32 0x4a311e36 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1412848710/*!*/;
BEGIN
/*!*/;
# at 396
#141009 15:28:30 server id 1 end_log_pos 443 CRC32 0x1a55d406 Table_map: `nil`.`t1` mapped to number 71
# at 443
#141009 15:28:30 server id 1 end_log_pos 493 CRC32 0xad2284bf Write_rows: table id 71 flags: STMT_END_F
### INSERT INTO `nil`.`t1`
### SET
### @1=1
### @2='nilnandan'
# at 493
#141009 15:28:30 server id 1 end_log_pos 524 CRC32 0x7566164e Xid = 12
COMMIT/*!*/;
# at 524
#141009 15:28:36 server id 1 end_log_pos 595 CRC32 0x11320b10 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1412848716/*!*/;
BEGIN
/*!*/;
# at 595
#141009 15:28:36 server id 1 end_log_pos 642 CRC32 0xf1545688 Table_map: `nil`.`t1` mapped to number 71
# at 642
#141009 15:28:36 server id 1 end_log_pos 688 CRC32 0xa1f2f3c6 Write_rows: table id 71 flags: STMT_END_F
### INSERT INTO `nil`.`t1`
### SET
### @1=2
### @2='joshi'
# at 688
#141009 15:28:36 server id 1 end_log_pos 719 CRC32 0x18fdcb10 Xid = 13
COMMIT/*!*/;
# at 719
#141009 15:28:41 server id 1 end_log_pos 790 CRC32 0xdc6cf9cf Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1412848721/*!*/;
BEGIN
/*!*/;
# at 790
#141009 15:28:41 server id 1 end_log_pos 837 CRC32 0x710bd034 Table_map: `nil`.`t1` mapped to number 71
# at 837
#141009 15:28:41 server id 1 end_log_pos 886 CRC32 0xdff4f7fa Write_rows: table id 71 flags: STMT_END_F
### INSERT INTO `nil`.`t1`
### SET
### @1=3...

[[Plus] (cedric-peintre-deactivatedaccount)]

Hi, what is the status of this bug please?
Thx
Cédric

[[Plus] (cedric-peintre-deactivatedaccount)]

FYI, I also noticed this error in debug mode: Unknown event type: CRC32

[Frank Cizmich (frank-cizmich)]

Hi cedric,

At the moment pt-query-digest is not able to process RBR events, so a pure RBR binlog is not going to produce valid results.
It is worth considering in the short term modifying the tool to skip those events when a MIXED format is used, and at a later stage perhaps go all the way and upgrade it to interpret RBR style events.

With respect to CRC32 , can you provide the toolkit version you are using? I understand that issue has been fixed.

[[Plus] (cedric-peintre-deactivatedaccount)]

Thanks for your reply.
Do you have an ETA for a compatibility with MIXED format?

[Frank Cizmich (frank-cizmich)]

I'm not sure it can make it to next release, but we'll try.
Regardless, if a fix is developed we'll post a patch here.

[[Plus] (cedric-peintre-deactivatedaccount)]

Looks good since last release, isn't it?

[Johan De Meersman (vegivamp+launchpad)]

Still seeing this behaviour with 2.2.16. Is there a timeline for a fix? Pretty much all my replicasets are in mixed mode; getting a report that says that over 90% of my processing time was spent on BEGIN statements is rather unhelpful :-p

I suppose a workaround could be as simple as ignoring BEGIN and COMMIT statements entirely, possibly controlled by a commandline switch?

[Johan De Meersman (vegivamp+launchpad)]

Using a simple SED expression to remove the BEGIN sections transforms this report (order by cnt):

# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================= ======= ====== ===== =========
# 1 0x85FFF5AA78E5FF6A 314186.0000 97.0% 1085038 0.2896 6.81 BEGIN
# 5 0x813031B8BBC3B329 312.0000 0.1% 784 0.3980 7.49 COMMIT
# 8 0x89B4BA8C6DB1884F 596.0000 0.2% 398 1.4975 1.36
# 10 0xEE10BF7D10CA0B10 565.0000 0.2% 316 1.7880 1.09 UPDATE paragraphs_item_revision
# 11 0xD4DCDA74342FCA25 565.0000 0.2% 316 1.7880 1.09 UPDATE paragraphs_item
# 12 0x8CF4591547D44AF1 550.0000 0.2% 307 1.7915 1.07 DELETE field_revision_field_article_tekst

into this report:

# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============== ===== ====== ===== ==============
# 1 0xCED5912FB29A2A21 456.0000 4.6% 4539 0.1005 7.87 UPDATE elysia_cron
# 2 0xAA174BE9C0C45EB3 459.0000 4.7% 4052 0.1133 7.81 UPDATE elysia_cron
# 3 0x122CD1A1B3B706E1 374.0000 3.8% 3257 0.1148 6.86 UPDATE variable
# 4 0x813031B8BBC3B329 312.0000 3.2% 784 0.3980 7.49 COMMIT
# 7 0x89B4BA8C6DB1884F 596.0000 6.1% 398 1.4975 1.36
# 9 0xEE10BF7D10CA0B10 565.0000 5.8% 316 1.7880 1.09 UPDATE paragraphs_item_revision
# 10 0xD4DCDA74342FCA25 565.0000 5.8% 316 1.7880 1.09 UPDATE paragraphs_item
# 11 0x8CF4591547D44AF1 550.0000 5.6% 307 1.7915 1.07 DELETE field_revision_field_article_tekst

The latter is considerably more useful, as it both properly identifies the top queries, and also correctly calculates the % respose time for all queries. (I've not looked into the blank query, I assume it's also an RBR artifact)

The (imperfect!) sed expression is as simple as this:

        /\n/!N; /\n.*\n/!N; /\n.*\nBEGIN/d;P;D

[Shahriyar Rzayev (rzayev-sehriyar)]

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