Uploaded image for project: 'Percona Toolkit'
  1. Percona Toolkit
  2. PT-1245

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

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: On Hold
    • Priority: Low
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None

      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/!/;
        /Unable to render embedded object: File (\C utf8 *//*) not found./;
        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. 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. 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

        Smart Checklist

          Attachments

            Activity

              People

              Assignee:
              Unassigned
              Reporter:
              lpjirasync lpjirasync (Inactive)
              Votes:
              4 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated: