Percona Toolkit moved to https://jira.percona.com/projects/PT

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

Bug #1377887 reported by Przemek
32
This bug affects 6 people
Affects Status Importance Assigned to Milestone
Percona Toolkit moved to https://jira.percona.com/projects/PT
Confirmed
Undecided
Frank Cizmich

Bug Description

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

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :
Download full text (8.7 KiB)

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

Read more...

Changed in percona-toolkit:
status: New → Confirmed
Valerii Kravchuk (valerii-kravchuk)
tags: added: i46467
Frank Cizmich (frank-cizmich)
Changed in percona-toolkit:
assignee: nobody → Frank Cizmich (frank-cizmich)
Revision history for this message
[Plus] (cedric-peintre-deactivatedaccount) wrote :

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

Revision history for this message
[Plus] (cedric-peintre-deactivatedaccount) wrote :

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

Revision history for this message
Frank Cizmich (frank-cizmich) wrote :

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.

Revision history for this message
[Plus] (cedric-peintre-deactivatedaccount) wrote :

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

Revision history for this message
Frank Cizmich (frank-cizmich) wrote :

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.

Revision history for this message
[Plus] (cedric-peintre-deactivatedaccount) wrote :

Looks good since last release, isn't it?

Jericho Rivera (jericho-rivera)
tags: added: i52109
Revision history for this message
Johan De Meersman (vegivamp+launchpad) wrote :

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?

Revision history for this message
Johan De Meersman (vegivamp+launchpad) wrote :

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

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-1245

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

Other bug subscribers

Remote bug watches

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