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

pt-query-digest incorrectly process binlog dump

Bug #1415296 reported by markus_albe
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Toolkit moved to https://jira.percona.com/projects/PT
Confirmed
Undecided
Unassigned

Bug Description

pt-query-digest --limit=100% fails to properly process a binlog dump and queries are grouped under MISC and only first CREATE TABLE seems to be recognized (when I did at least 6 in this binlog); The used binlog_format is STATEMENT (see attached). Was tested with pt 1.0.2, 2.0.5, 2.1.11 and 2.2.13, all resulted in same output:

bin/pt-query-digest --limit=100% --type=binlog ~/sandboxes/rsandbox_5_5_28/master/data/mysql-bin.000005.dump

# 170ms user time, 10ms system time, 24.26M rss, 175.03M vsz
# Current date: Wed Jan 28 00:49:24 2015
# Hostname: lilith
# Files: /home/kolita/sandboxes/rsandbox_5_5_28/master/data/mysql-bin.000005.dump
# Overall: 31 total, 17 unique, 0.01 QPS, 0.00x concurrency ______________
# Time range: 2015-01-27 23:58:37 to 2015-01-28 00:33:52
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 1s 0 1s 32ms 0 175ms 0
# Query size 976 1 161 21.69 33.28 29.17 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 3 3 3 3 3 0 3
# @@session.sq 0 0 0 0 0 0 0
# @@session.sq 0 0 0 0 0 0 0
# @@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 Apdx V/M Item
# ==== ================== ============= ===== ====== ==== ===== ==========
# 1 0x60A094AFC1068ABB 1.0000 100.0% 1 1.0000 1.00 0.00 CREATE TABLE example
# MISC 0xMISC 0.0000 0.0% 30 0.0000 NS 0.0 <12 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0x60A094AFC1068ABB at byte 1226 _____
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | ^ |
# Time range: all events occurred at 2015-01-28 00:21:39
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 1
# Exec time 100 1s 1s 1s 1s 1s 0 1s
# Query size 2 28 28 28 28 28 0 28
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `test`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``test`` LIKE 'example'\G
# SHOW CREATE TABLE ```test```.`example`\G
create table example (i int)\G

When I ran with --limit=10000 (i.e. a number WITHOUT percentage sign) then it would show the right thing:

$ percona-toolkit-1.0.2/bin/pt-query-digest --limit=10000 --type=binlog ~/sandboxes/rsandbox_5_5_28/master/data/mysql-bin.000005.dump

# 170ms user time, 10ms system time, 24.25M rss, 175.03M vsz
# Current date: Wed Jan 28 00:53:03 2015
# Hostname: lilith
# Files: /home/kolita/sandboxes/rsandbox_5_5_28/master/data/mysql-bin.000005.dump
# Overall: 31 total, 17 unique, 0.01 QPS, 0.00x concurrency ______________
# Time range: 2015-01-27 23:58:37 to 2015-01-28 00:33:52
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 1s 0 1s 32ms 0 175ms 0
# Query size 976 1 161 21.69 33.28 29.17 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 3 3 3 3 3 0 3
# @@session.sq 0 0 0 0 0 0 0
# @@session.sq 0 0 0 0 0 0 0
# @@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 Apdx V/M Item
# ==== ================== ============= ===== ====== ==== ===== ==========
# 1 0x60A094AFC1068ABB 1.0000 100.0% 1 1.0000 1.00 0.00 CREATE TABLE example
# 2 0xDB1949DFA66435D5 0.0000 0.0% 1 0.0000 1.00 0.00 CREATE DATABASE otherdb
# 3 0xF650B70E9653ECC3 0.0000 0.0% 1 0.0000 1.00 0.00 CREATE TABLE names
# 4 0xC2722F4C8C694A55 0.0000 0.0% 2 0.0000 1.00 0.00 INSERT test.some
# 5 0x768433D155ACBF0E 0.0000 0.0% 2 0.0000 1.00 0.00 INSERT other
# 6 0x85FFF5AA78E5FF6A 0.0000 0.0% 12 0.0000 1.00 0.00 BEGIN
# 7 0x9A4DF1DB87ACAA94 0.0000 0.0% 1 0.0000 1.00 0.00 CREATE TABLE table_names
# 8 0x72E3D61120689312 0.0000 0.0% 2 0.0000 1.00 0.00 INSERT some
# 9 0x202469423D9EB112 0.0000 0.0% 2 0.0000 1.00 0.00 INSERT test.example
# 10 0x215BBC9A8C2DFA3B 0.0000 0.0% 2 0.0000 1.00 0.00 INSERT table_names
# 11 0x60B6ECC91D903F07 0.0000 0.0% 2 0.0000 1.00 0.00 CREATE TABLE some
# 12 0x77D1C04D96063C34 0.0000 0.0% 1 0.0000 1.00 0.00 CREATE TABLE other
# 13 0xD5EC2077A79B1B2C 0.0000 0.0% 2 0.0000 1.00 0.00 INSERT test.names

# Query 1: 0 QPS, 0x concurrency, ID 0x60A094AFC1068ABB at byte 1226 _____
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | ^ |
# Time range: all events occurred at 2015-01-28 00:21:39
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 1
# Exec time 100 1s 1s 1s 1s 1s 0 1s
# Query size 2 28 28 28 28 28 0 28
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `test`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``test`` LIKE 'example'\G
# SHOW CREATE TABLE ```test```.`example`\G
create table example (i int)\G

# Query 2: 0 QPS, 0x concurrency, ID 0xDB1949DFA66435D5 at byte 1556 _____
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: all events occurred at 2015-01-28 00:21:54
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 1
# Exec time 0 0 0 0 0 0 0 0
# Query size 2 23 23 23 23 23 0 23
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `test`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
create database otherdb\G

# Query 3: 0 QPS, 0x concurrency, ID 0xF650B70E9653ECC3 at byte 1392 _____
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: all events occurred at 2015-01-28 00:21:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 1
# Exec time 0 0 0 0 0 0 0 0
# Query size 2 26 26 26 26 26 0 26
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `test`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``test`` LIKE 'names'\G
# SHOW CREATE TABLE ```test```.`names`\G
create table names (i int)\G

# Query 4: 0.00 QPS, 0x concurrency, ID 0xC2722F4C8C694A55 at byte 4744 __
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: 2015-01-28 00:22:50 to 00:33:15
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 6 63 31 32 31.50 32 0.71 31.50
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb` (1/50%), `test` (1/50%)
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'some'\G
# SHOW CREATE TABLE `test`.`some`\G
insert into test.some values (1)\G

# Query 5: 0.00 QPS, 0x concurrency, ID 0x768433D155ACBF0E at byte 6368 __
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: 2015-01-28 00:23:06 to 00:33:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 5 55 27 28 27.50 28 0.71 27.50
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``otherdb`` LIKE 'other'\G
# SHOW CREATE TABLE ```otherdb```.`other`\G
insert into other values (5)\G

# Query 6: 0.02 QPS, 0x concurrency, ID 0x85FFF5AA78E5FF6A at byte 6616 __
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: 2015-01-28 00:22:50 to 00:33:52
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 38 12
# Exec time 0 0 0 0 0 0 0 0
# Query size 6 60 5 5 5 5 0 5
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb` (9/75%), `test` (3/25%)
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
BEGIN\G

# Query 7: 0 QPS, 0x concurrency, ID 0x9A4DF1DB87ACAA94 at byte 2064 _____
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: all events occurred at 2015-01-28 00:22:17
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 1
# Exec time 0 0 0 0 0 0 0 0
# Query size 3 31 31 31 31 31 0 31
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``otherdb`` LIKE 'table_names'\G
# SHOW CREATE TABLE ```otherdb```.`table_names`\G
create table table_names(i int)\G

# Query 8: 0.00 QPS, 0x concurrency, ID 0x72E3D61120689312 at byte 5956 __
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: 2015-01-28 00:23:04 to 00:33:39
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 5 53 26 27 26.50 27 0.71 26.50
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``otherdb`` LIKE 'some'\G
# SHOW CREATE TABLE ```otherdb```.`some`\G
insert into some values (4)\G

# Query 9: 0.00 QPS, 0x concurrency, ID 0x202469423D9EB112 at byte 5158 __
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: 2015-01-28 00:22:54 to 00:33:20
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 7 69 34 35 34.50 35 0.71 34.50
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb` (1/50%), `test` (1/50%)
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'example'\G
# SHOW CREATE TABLE `test`.`example`\G
insert into test.example values (2)\G

# Query 10: 0.00 QPS, 0x concurrency, ID 0x215BBC9A8C2DFA3B at byte 6761 _
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: 2015-01-28 00:23:10 to 00:33:52
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 6 67 33 34 33.50 34 0.71 33.50
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``otherdb`` LIKE 'table_names'\G
# SHOW CREATE TABLE ```otherdb```.`table_names`\G
insert into table_names values (6)\G

# Query 11: 0.07 QPS, 0x concurrency, ID 0x60B6ECC91D903F07 at byte 1717 _
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: 2015-01-28 00:21:28 to 00:21:58
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 5 50 25 25 25 25 0 25
# @@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 3 3 3 3 3 0 3
# @@session.sq 0 0 0 0 0 0 0 0
# @@session.sq 0 0 0 0 0 0 0 0
# @@session.un 100 1 1 1 1 1 0 1
# error code 0 0 0 0 0 0 0 0
# String:
# @@session.co default
# Databases `otherdb` (1/50%), `test` (1/50%)
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``otherdb`` LIKE 'some'\G
# SHOW CREATE TABLE ```otherdb```.`some`\G
create table some (i int)\G

# Query 12: 0 QPS, 0x concurrency, ID 0x77D1C04D96063C34 at byte 1900 ____
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: all events occurred at 2015-01-28 00:22:08
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 1
# Exec time 0 0 0 0 0 0 0 0
# Query size 2 26 26 26 26 26 0 26
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb`
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM ``otherdb`` LIKE 'other'\G
# SHOW CREATE TABLE ```otherdb```.`other`\G
create table other (i int)\G

# Query 13: 0.00 QPS, 0x concurrency, ID 0xD5EC2077A79B1B2C at byte 5558 _
# This item is included in the report because it matches --limit.
# Scores: Apdex = 1.00 [1.0]*, V/M = 0.00
# Query_time sparkline: | |
# Time range: 2015-01-28 00:22:57 to 00:33:25
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 2
# Exec time 0 0 0 0 0 0 0 0
# Query size 6 65 32 33 32.50 33 0.71 32.50
# error code 0 0 0 0 0 0 0 0
# String:
# Databases `otherdb` (1/50%), `test` (1/50%)
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'names'\G
# SHOW CREATE TABLE `test`.`names`\G
insert into test.names values (3)\G

Not critical but certainly annoying.

Revision history for this message
markus_albe (markus-albe) wrote :
Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :
Download full text (17.7 KiB)

Confirmed with 2.2.13

nilnandan@desktop:~/Downloads$ pt-query-digest --version
pt-query-digest 2.2.13
nilnandan@desktop:~/Downloads$ pt-query-digest --limit=100% --type=binlog mysql-bin.000005.dump

# 200ms user time, 30ms system time, 34.87M rss, 119.98M vsz
# Current date: Mon Feb 2 15:00:08 2015
# Hostname: desktop
# Files: mysql-bin.000005.dump
# Overall: 31 total, 17 unique, 0.01 QPS, 0.00x concurrency ______________
# Time range: 2015-01-27 23:58:37 to 2015-01-28 00:33:52
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 1s 0 1s 32ms 0 175ms 0
# Query size 976 1 161 21.69 33.28 29.17 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 3 3 3 3 3 0 3
# @@session.sq 0 0 0 0 0 0 0
# @@session.sq 0 0 0 0 0 0 0
# @@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 0x60A094AFC1068ABB 1.0000 100.0% 1 1.0000 0.00 CREATE TABLE example
# MISC 0xMISC 0.0000 0.0% 30 0.0000 0.0 <12 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0x60A094AFC1068ABB at byte 1226 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-28 00:21:39
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 1
# Exec time 100 1s 1s 1s 1s 1s 0 1s
# Query size 2 28 28 28 28 28 0 28
# error code 0 0 0 0 0 0 0 0
# String:
# Databases test
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'example'\G
# SHOW CREATE TABLE `test`.`example`\G
create table example (i int)\G
nilnandan@desktop:~/Downloads$
nilnandan@desktop:~/Downloads$
nilnandan@desktop:~/Downloads$ pt-query-digest --limit=10000 --type=binlog mysql-bin.000005.dump

# 140ms user time, 10ms system time,...

Changed in percona-toolkit:
status: New → Confirmed
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-1262

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.