Skip to:

  1. Skip to Jira Navigation
  2. Skip to Side Navigation
  3. Skip to Main Content

LP #1377887: pt-query-digest fails to parse binary log with RBR events

Description

**Reported in Launchpad by Przemek last update 17-02-2016 13:57:55

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 /!/;

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

  2. Warning: this binlog is either in use or was not closed properly.

  3. 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/!/;
    /*

    */;
    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
    /!/;

  4. 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)
    /!/;

  5. at 295
    #141006 13:04:12 server id 1 end_log_pos 326 CRC32 0x273d074a Xid = 32
    COMMIT/!/;

  6. 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
    /!/;

  7. 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)
    /!/;

  8. at 501
    #141006 13:04:22 server id 1 end_log_pos 532 CRC32 0x5f592894 Xid = 34
    COMMIT/!/;

  9. 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
    /!/;

  10. at 595
    #141006 13:05:51 server id 1 end_log_pos 640 CRC32 0x48d48ebc Table_map: `test`.`t1` mapped to number 70

  11. at 640
    #141006 13:05:51 server id 1 end_log_pos 680 CRC32 0x3fdb95aa Write_rows: table id 70 flags: STMT_END_F

    1.  

      1. INSERT INTO `test`.`t1`

      2. SET

      3. @1=7

  12. at 680
    #141006 13:05:51 server id 1 end_log_pos 711 CRC32 0x840052da Xid = 42
    COMMIT/!/;

  13. 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
    /!/;

  14. at 774
    #141006 13:06:46 server id 1 end_log_pos 819 CRC32 0xa64284a6 Table_map: `test`.`t1` mapped to number 70

  15. at 819
    #141006 13:06:46 server id 1 end_log_pos 859 CRC32 0x2d334616 Delete_rows: table id 70 flags: STMT_END_F

    1.  

      1. DELETE FROM `test`.`t1`

      2. WHERE

      3. @1=1

  16. at 859
    #141006 13:06:46 server id 1 end_log_pos 890 CRC32 0x0e0b3f0b Xid = 44
    COMMIT/!/;
    DELIMITER ;

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

  1. 330ms user time, 20ms system time, 34.46M rss, 229.38M vsz

  2. Current date: Mon Oct 6 13:08:08 2014

  3. Hostname: pmlap

  4. Files: mysql-bin.000010.sql

  5. Overall: 5 total, 4 unique, 0.03 QPS, 0.01x concurrency ________________

  6. Time range: 2014-10-06 13:04:06 to 13:06:46

  7. Attribute total min max avg 95% stddev median

  8. ============ ======= ======= ======= ======= ======= ======= =======

  9. Exec time 1s 0 1s 200ms 992ms 397ms 0

  10. Query size 224 5 132 24.89 130.47 38.72 5.75

  11. @@session.au 1 1 1 1 1 0 1

  12. @@session.au 1 1 1 1 1 0 1

  13. @@session.au 1 1 1 1 1 0 1

  14. @@session.ch 33 33 33 33 33 0 33

  15. @@session.co 33 33 33 33 33 0 33

  16. @@session.co 8 8 8 8 8 0 8

  17. @@session.fo 1 1 1 1 1 0 1

  18. @@session.lc 0 0 0 0 0 0 0

  19. @@session.ps 2 2 2 2 2 0 2

  20. @@session.sq 0 0 0 0 0 0 0

  21. @@session.sq 1.00G 512.00k 1.00G 512.25M 1.00G 723.72M 512.25M

  22. @@session.un 1 1 1 1 1 0 1

  23. error code 0 0 0 0 0 0 0

  1. Profile

  2. Rank Query ID Response time Calls R/Call V/M Item

  3. ==== ================== ============= ===== ====== ===== =========

  4. 1 0x85FFF5AA78E5FF6A 1.0000 100.0% 3 0.3333 0.66 BEGIN

  5. MISC 0xMISC 0.0000 0.0% 2 0.0000 0.0 <1 ITEMS>

  1. Query 1: 0.02 QPS, 0.01x concurrency, ID 0x85FFF5AA78E5FF6A at byte 2338

  2. This item is included in the report because it matches --limit.

  3. Scores: V/M = 0.66

  4. Time range: 2014-10-06 13:04:06 to 13:06:46

  5. Attribute pct total min max avg 95% stddev median

  6. ============ === ======= ======= ======= ======= ======= ======= =======

  7. Count 60 3

  8. Exec time 100 1s 0 1s 333ms 992ms 468ms 0

  9. Query size 8 20 5 5 5 5 0 5

  10. @@session.au 100 1 1 1 1 1 0 1

  11. @@session.au 100 1 1 1 1 1 0 1

  12. @@session.au 100 1 1 1 1 1 0 1

  13. @@session.ch 100 33 33 33 33 33 0 33

  14. @@session.co 100 33 33 33 33 33 0 33

  15. @@session.co 100 8 8 8 8 8 0 8

  16. @@session.fo 100 1 1 1 1 1 0 1

  17. @@session.lc 0 0 0 0 0 0 0 0

  18. @@session.ps 100 2 2 2 2 2 0 2

  19. @@session.sq 0 0 0 0 0 0 0 0

  20. @@session.sq 100 1.00G 512.00k 1.00G 512.25M 1.00G 723.72M 512.25M

  21. @@session.un 100 1 1 1 1 1 0 1

  22. error code 0 0 0 0 0 0 0 0

  23. String:

  24. @@session.co default

  25. Query_time distribution

  26. 1us

  27. 10us

  28. 100us

  29. 1ms

  30. 10ms

  31. 100ms

  32. 1s ################################################################

  33. 10s+
    BEGIN\G

Environment

None

AFFECTED CS IDs

CS0042320

Smart Checklist

Activity

Show:

antonio falzarano April 21, 2021 at 12:59 PM

Hi,

actually with pt-query-digest version 3.3.0 it's not possible to parse binary-logs created with format ROW after decode them.

This kind of format is mandatory on XTRADB clusters, so i think is an issue to take care.

lpjirasync January 24, 2018 at 8:24 PM

**Comment from Launchpad by: Johan De Meersman on: 17-02-2016 13:57:55

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

  1. Rank Query ID Response time Calls R/Call V/M Item

  2. ==== ================== ================= ======= ====== ===== =========

  3. 1 0x85FFF5AA78E5FF6A 314186.0000 97.0% 1085038 0.2896 6.81 BEGIN

  4. 5 0x813031B8BBC3B329 312.0000 0.1% 784 0.3980 7.49 COMMIT

  5. 8 0x89B4BA8C6DB1884F 596.0000 0.2% 398 1.4975 1.36

  6. 10 0xEE10BF7D10CA0B10 565.0000 0.2% 316 1.7880 1.09 UPDATE paragraphs_item_revision

  7. 11 0xD4DCDA74342FCA25 565.0000 0.2% 316 1.7880 1.09 UPDATE paragraphs_item

  8. 12 0x8CF4591547D44AF1 550.0000 0.2% 307 1.7915 1.07 DELETE field_revision_field_article_tekst

into this report:

  1. Rank Query ID Response time Calls R/Call V/M Item

  2. ==== ================== ============== ===== ====== ===== ==============

  3. 1 0xCED5912FB29A2A21 456.0000 4.6% 4539 0.1005 7.87 UPDATE elysia_cron

  4. 2 0xAA174BE9C0C45EB3 459.0000 4.7% 4052 0.1133 7.81 UPDATE elysia_cron

  5. 3 0x122CD1A1B3B706E1 374.0000 3.8% 3257 0.1148 6.86 UPDATE variable

  6. 4 0x813031B8BBC3B329 312.0000 3.2% 784 0.3980 7.49 COMMIT

  7. 7 0x89B4BA8C6DB1884F 596.0000 6.1% 398 1.4975 1.36

  8. 9 0xEE10BF7D10CA0B10 565.0000 5.8% 316 1.7880 1.09 UPDATE paragraphs_item_revision

  9. 10 0xD4DCDA74342FCA25 565.0000 5.8% 316 1.7880 1.09 UPDATE paragraphs_item

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

lpjirasync January 24, 2018 at 8:24 PM

**Comment from Launchpad by: Johan De Meersman on: 17-02-2016 12:55:44

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

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

lpjirasync January 24, 2018 at 8:24 PM

**Comment from Launchpad by: [[Plus] | https://launchpad.net/~cedric-peintre] on: 13-02-2015 16:20:46

Looks good since last release, isn't it?

lpjirasync January 24, 2018 at 8:24 PM

**Comment from Launchpad by: Frank Cizmich on: 01-12-2014 17:53:05

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.

Details

Assignee

Reporter

Priority

Affects versions

Fix versions

Labels

Smart Checklist

Created January 24, 2018 at 8:23 PM
Updated March 4, 2024 at 4:45 PM