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

  1. Bug #1377887
  2. Comment #1

Comment 1 for bug 1377887

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

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
### @2='niljoshi'
# at 886
#141009 15:28:41 server id 1 end_log_pos 917 CRC32 0x2de309ab Xid = 14
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
[root@centos65 mysql]#
[root@centos65 mysql]#
[root@centos65 mysql]# pt-query-digest --type binlog mysql-bin.000002.sql

# 270ms user time, 80ms system time, 23.34M rss, 201.49M vsz
# Current date: Thu Oct 9 15:30:03 2014
# Hostname: centos65
# Files: mysql-bin.000002.sql
# Overall: 5 total, 5 unique, 0.07 QPS, 0x concurrency ___________________
# Time range: 2014-10-09 15:27:30 to 15:28:41
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 0 0 0 0 0 0 0
# Query size 216 5 132 30.86 130.47 42.61 7.70
# @@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 1 1 1 1 1 0 1
# @@session.sq 0 0 0 0 0 0 0
# @@session.sq 1.00G 1.00G 1.00G 1.00G 1.00G 0 1.00G
# @@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 0xED535C785F711D08 0.0000 0.0% 1 0.0000 0.00 CREATE DATABASE nil
# 2 0x21A633FA3AB97901 0.0000 0.0% 1 0.0000 0.00 CREATE TABLE t? t1
# 3 0x85FFF5AA78E5FF6A 0.0000 0.0% 3 0.0000 0.00 BEGIN

# Query 1: 0 QPS, 0x concurrency, ID 0xED535C785F711D08 at byte 425 ______
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2014-10-09 15:27:57
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 20 1
# Exec time 0 0 0 0 0 0 0 0
# Query size 8 19 19 19 19 19 0 19
# @@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 1 1 1 1 1 0 1
# @@session.sq 0 0 0 0 0 0 0 0
# @@session.sq 100 1.00G 1.00G 1.00G 1.00G 1.00G 0 1.00G
# @@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+
create database nil\G

# Query 2: 0 QPS, 0x concurrency, ID 0x21A633FA3AB97901 at byte 1092 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2014-10-09 15:28:15
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 20 1
# Exec time 0 0 0 0 0 0 0 0
# Query size 19 42 42 42 42 42 0 42
# error code 0 0 0 0 0 0 0 0
# String:
# Databases nil
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `nil` LIKE 't1'\G
# SHOW CREATE TABLE `nil`.`t1`\G
create table t1 (id int, name varchar(10))\G

# Query 3: 0.27 QPS, 0x concurrency, ID 0x85FFF5AA78E5FF6A at byte 2405 __
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2014-10-09 15:28:30 to 15:28:41
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 60 3
# Exec time 0 0 0 0 0 0 0 0
# Query size 6 15 5 5 5 5 0 5
# error code 0 0 0 0 0 0 0 0
# String:
# Databases nil
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
BEGIN\G
[root@centos65 mysql]# pt-query-digest --version
pt-query-digest 2.2.9
[root@centos65 mysql]#