Bug #1402776 “Parsing of tcpdump capture from MySQL 5.6 with pt-...” : Bugs : Percona Toolkit moved to https://jira.percona.com/projects/PT

Ovais Tariq (ovais-tariq) on 2014-12-15

description:

updated

Revision history for this message

Ovais Tariq (ovais-tariq) wrote on 2014-12-15:

#1

Here is a sample dump of $event:

$VAR1 = {
  No_good_index_used => 'No',
  No_index_used => 'Yes',
  Query_time => '0.000811',
  Rows_affected => 0,
  Thread_id => 7181212,
  Warning_count => 0,
  arg => '/* mysql-connector-java-5.1.24 ( Revision: ${bzr.revision-id} ) */SHOW VARIABLES WHERE Variable_name =\'language\' OR Variable_name = \'net_write_timeout\' OR Variable_name = \'interactive_timeout\' OR Variable_name = \'wait_timeout\' OR Variable_name = \'character_set_client\' OR Variable_name = \'character_set_connection\' OR Variable_name = \'character_set\' OR Variable_name = \'character_set_server\' OR Variable_name = \'tx_isolation\' OR Variable_name = \'transaction_isolation\' OR Variable_name = \'character_set_results\' OR Variable_name = \'timezone\' OR Variable_name = \'time_zone\' OR Variable_name = \'system_time_zone\' OR Variable_name = \'lower_case_table_names\' OR Variable_name = \'max_allowed_packet\' OR Variable_name = \'net_buffer_length\' OR Variable_name = \'sql_mode\' OR Variable_name = \'query_cache_type\' OR Variable_name = \'query_cache_size\' OR Variable_name = \'init_connect\'',
  bytes => 873,
  cmd => 'Query',
  db => 'db_name^@mysql_native_password',
  fingerprint => 'show variables where variable_name =? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ?',
  host => '192.168.10.25',
  ip => '192.168.10.25',
  port => '54170',
  pos_in_log => 3191192,
  ts => '141212 15:33:45.829984',
  user => 'db_name'
};

Revision history for this message

everflux (tklaunchpad) wrote on 2015-01-17:

#2

I can confirm this bug, I think it should be reported upstream.
The bug was reproducible using mysql-java driver 5.1.34 as well as using PHP.

Revision history for this message

everflux (tklaunchpad) wrote on 2015-01-17:

#3

Example statements to trigger the problem:

USE information_schema;
SHOW TABLES;
USE mydb;
SHOW TABLES;
SELECT * FROM sometable;

result of pt-query-digest:

...
# Databases mydbmysql_native_password
....
# SHOW TABLE STATUS FROM `mydbmysql_native_password` LIKE 'sometable'\G
....

Revision history for this message

everflux (tklaunchpad) wrote on 2015-01-17:

#4

Seems to be even worse if the tcpdump captures a connect/disconnect from the database:

tcpdump -i eth0 -s 65535 -x -nn -q -tttt port 3306 > mysql.tcp.txt
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
^C2409 packets captured
2409 packets received by filter
0 packets dropped by kernel

pt-query-digest --limit 20 --type tcpdump mysql.tcp.txt

....
# Databases mydbmysql_native_password�_runtime_ver...
...
# SHOW TABLE STATUS FROM `mydbmysql_native_password�_runtime_versio1.8.0_25_client_version5.1.34
_client_nameMySQL Connector Java_client_licenseGPL_runtime_vendorOracle Corporation` LIKE 'cdata'\G
# SHOW CREATE TABLE `mydbmysql_native_password�_runtime_versio1.8.0_25_client_version5.1.34
_client_nameMySQL Connector Java_client_licenseGPL_runtime_vendorOracle Corporation`.`cdata`\G
# EXPLAIN /*!50100 PARTITIONS*/
....

Revision history for this message

Nilnandan Joshi (nilnandan-joshi) wrote on 2015-01-19:

#5

FirstExample.java Edit (2.5 KiB, text/x-java)

Download full text (15.3 KiB)

Tried to reproduce the same with attached script FirstExample.java but unable to get that error. I'm seeing normal database name. Please let me know if I'm missing anything here. or need to correct script.

nilnandan@desktop:~$ sudo tcpdump -i eth0 -s 65535 -x -nn -q -tttt port 3306 > mysql.tcp.txt
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
^C68 packets captured
68 packets received by filter
0 packets dropped by kernel
nilnandan@desktop:~$
nilnandan@desktop:~$ sudo /home/nilnandan/Downloads/percona-toolkit-2.2.11/bin/pt-query-digest --limit 20 --type tcpdump mysql.tcp.txt

# 140ms user time, 10ms system time, 32.66M rss, 105.42M vsz
# Current date: Mon Jan 19 16:47:05 2015
# Hostname: desktop
# Files: mysql.tcp.txt
# Overall: 15 total, 13 unique, 204.17 QPS, 0.40x concurrency ____________
# Time range: 2015-01-19 16:46:59.453236 to 16:46:59.526706
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 29ms 0 27ms 2ms 1ms 7ms 93us
# Rows affecte 0 0 0 0 0 0 0
# Query size 330 7 57 22 31.70 11.80 21.45
# Warning coun 0 0 0 0 0 0 0
# Boolean:
# No index use 13% yes, 86% no

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0x5D51E5F01B88B79E 0.0269 91.4% 1 0.0269 0.00 ADMIN CONNECT
# 2 0x911658842DA64DC4 0.0011 3.6% 1 0.0011 0.00 SHOW VARIABLES
# 3 0xA2750AF24EA2AEE6 0.0004 1.2% 1 0.0004 0.00 SHOW COLLATION
# 4 0x132628303F99240D 0.0003 1.0% 2 0.0001 0.00 SHOW TABLES
# 5 0x6C099B0B73EA7633 0.0002 0.5% 2 0.0001 0.00
# 6 0x3A021F4F9152841C 0.0001 0.5% 1 0.0001 0.00 SHOW TABLE STATUS
# 7 0x6602589ABA5C746C 0.0001 0.3% 1 0.0001 0.00 SELECT test
# 8 0x38B3D80280BBFA2A 0.0001 0.3% 1 0.0001 0.00 SET
# 9 0x3AEAAD0E15D725B5 0.0001 0.3% 1 0.0001 0.00 SET
# 10 0xE4CF7146873CCC28 0.0001 0.3% 1 0.0001 0.00 SET
# 11 0xC5F2D057EEEC328B 0.0001 0.2% 1 0.0001 0.00 SHOW CREATE TABLE
# 12 0x44001A2E53C1AB70 0.0001 0.2% 1 0.0001 0.00 SET
# 13 0xAA353644DE4C4CB4 0.0000 0.0% 1 0.0000 0.00 ADMIN QUIT

# Query 1: 0 QPS, 0x concurrency, ID 0x5D51E5F01B88B79E at byte 1540 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.453236
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 1
# Exec time 91 27ms 27ms 27ms 27ms 27ms 0 27ms
# Rows affecte 0 0 0 0 0 0 0 0
# Query size 9 30 30 30 30 30 0 30
# Warning coun 0 0 0 0 0 0 ...

Tried to reproduce the same with attached script FirstExample.java but unable to get that error. I'm seeing normal database name.  Please let me know if I'm missing anything here. or need to correct script.

nilnandan@desktop:~$ sudo tcpdump -i eth0 -s 65535 -x -nn -q -tttt port 3306 > mysql.tcp.txt
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
^C68 packets captured
68 packets received by filter
0 packets dropped by kernel
nilnandan@desktop:~$ 
nilnandan@desktop:~$ sudo /home/nilnandan/Downloads/percona-toolkit-2.2.11/bin/pt-query-digest --limit 20 --type tcpdump mysql.tcp.txt

# 140ms user time, 10ms system time, 32.66M rss, 105.42M vsz
# Current date: Mon Jan 19 16:47:05 2015
# Hostname: desktop
# Files: mysql.tcp.txt
# Overall: 15 total, 13 unique, 204.17 QPS, 0.40x concurrency ____________
# Time range: 2015-01-19 16:46:59.453236 to 16:46:59.526706
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           29ms       0    27ms     2ms     1ms     7ms    93us
# Rows affecte           0       0       0       0       0       0       0
# Query size           330       7      57      22   31.70   11.80   21.45
# Warning coun           0       0       0       0       0       0       0
# Boolean:
# No index use  13% yes,  86% no

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0x5D51E5F01B88B79E  0.0269 91.4%     1 0.0269  0.00 ADMIN CONNECT
#    2 0x911658842DA64DC4  0.0011  3.6%     1 0.0011  0.00 SHOW VARIABLES
#    3 0xA2750AF24EA2AEE6  0.0004  1.2%     1 0.0004  0.00 SHOW COLLATION
#    4 0x132628303F99240D  0.0003  1.0%     2 0.0001  0.00 SHOW TABLES
#    5 0x6C099B0B73EA7633  0.0002  0.5%     2 0.0001  0.00 
#    6 0x3A021F4F9152841C  0.0001  0.5%     1 0.0001  0.00 SHOW TABLE STATUS
#    7 0x6602589ABA5C746C  0.0001  0.3%     1 0.0001  0.00 SELECT test
#    8 0x38B3D80280BBFA2A  0.0001  0.3%     1 0.0001  0.00 SET
#    9 0x3AEAAD0E15D725B5  0.0001  0.3%     1 0.0001  0.00 SET
#   10 0xE4CF7146873CCC28  0.0001  0.3%     1 0.0001  0.00 SET
#   11 0xC5F2D057EEEC328B  0.0001  0.2%     1 0.0001  0.00 SHOW CREATE TABLE
#   12 0x44001A2E53C1AB70  0.0001  0.2%     1 0.0001  0.00 SET
#   13 0xAA353644DE4C4CB4  0.0000  0.0%     1 0.0000  0.00 ADMIN QUIT

# Query 1: 0 QPS, 0x concurrency, ID 0x5D51E5F01B88B79E at byte 1540 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.453236
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time     91    27ms    27ms    27ms    27ms    27ms       0    27ms
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     9      30      30      30      30      30       0      30
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms  ################################################################
# 100ms
#    1s
#  10s+
administrator command: Connect\G

# Query 2: 0 QPS, 0x concurrency, ID 0x911658842DA64DC4 at byte 3795 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.482996
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      3     1ms     1ms     1ms     1ms     1ms       0     1ms
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     4      14      14      14      14      14       0      14
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
SHOW VARIABLES\G

# Query 3: 0 QPS, 0x concurrency, ID 0xA2750AF24EA2AEE6 at byte 59396 ____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.504783
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      1   358us   358us   358us   358us   358us       0   358us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     4      14      14      14      14      14       0      14
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
SHOW COLLATION\G

# Query 4: 1.98k QPS, 0.29x concurrency, ID 0x132628303F99240D at byte 91482
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2015-01-19 16:46:59.524086 to 16:46:59.525097
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         13       2
# Exec time      1   298us    96us   202us   149us   202us    74us   149us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     6      22      11      11      11      11       0      11
# Warning coun   0       0       0       0       0       0       0       0
# Boolean:
# No index use  50% yes,  50% no
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us  ################################################################
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
SHOW TABLES\G

# Query 5: 1.92k QPS, 0.14x concurrency, ID 0x6C099B0B73EA7633 at byte 97448
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2015-01-19 16:46:59.523670 to 16:46:59.524711
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         13       2
# Exec time      0   150us    68us    82us    75us    82us     9us    75us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     8      29       7      22   14.50      22   10.61   14.50
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
USE nil\G

# Query 6: 0 QPS, 0x concurrency, ID 0x3A021F4F9152841C at byte 100206 ___
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.525711
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      0   149us   149us   149us   149us   149us       0   149us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     7      26      26      26      26      26       0      26
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `information_schema` LIKE 'nil'\G
#    SHOW CREATE TABLE `information_schema`.`nil`\G
SHOW TABLE STATUS FROM nil\G

# Query 7: 0 QPS, 0x concurrency, ID 0x6602589ABA5C746C at byte 105976 ___
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.526210
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      0   102us   102us   102us   102us   102us       0   102us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     7      25      25      25      25      25       0      25
# Warning coun   0       0       0       0       0       0       0       0
# Boolean:
# No index use 100% yes,   0% no
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `information_schema` LIKE 'test'\G
#    SHOW CREATE TABLE `information_schema`.`test`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT id, name FROM test\G

# Query 8: 0 QPS, 0x concurrency, ID 0x38B3D80280BBFA2A at byte 2567 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.472392
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      0    95us    95us    95us    95us    95us       0    95us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     4      16      16      16      16      16       0      16
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
SET NAMES latin1\G

# Query 9: 0 QPS, 0x concurrency, ID 0x3AEAAD0E15D725B5 at byte 89568 ____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.516739
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      0    91us    91us    91us    91us    91us       0    91us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     4      16      16      16      16      16       0      16
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
SET autocommit=1\G

# Query 10: 0 QPS, 0x concurrency, ID 0xE4CF7146873CCC28 at byte 3156 ____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.480158
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      0    84us    84us    84us    84us    84us       0    84us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     9      32      32      32      32      32       0      32
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
SET character_set_results = NULL\G

# Query 11: 0 QPS, 0x concurrency, ID 0xC5F2D057EEEC328B at byte 98926 ___
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.525349
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      0    69us    69us    69us    69us    69us       0    69us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     6      22      22      22      22      22       0      22
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
SHOW CREATE TABLE test\G

# Query 12: 0 QPS, 0x concurrency, ID 0x44001A2E53C1AB70 at byte 90157 ___
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.517053
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      0    65us    65us    65us    65us    65us       0    65us
# Rows affecte   0       0       0       0       0       0       0       0
# Query size    17      57      57      57      57      57       0      57
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
SET sql_mode='NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES'\G

# Query 13: 0 QPS, 0x concurrency, ID 0xAA353644DE4C4CB4 at byte 106963 __
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.526706
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       1
# Exec time      0       0       0       0       0       0       0       0
# Rows affecte   0       0       0       0       0       0       0       0
# Query size     8      27      27      27      27      27       0      27
# Warning coun   0       0       0       0       0       0       0       0
# String:
# Databases    information_schema
# Hosts        192.168.1.193
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
administrator command: Quit\G
nilnandan@desktop:~$

Changed in percona-toolkit:
status:	New → Incomplete

Revision history for this message

Nilnandan Joshi (nilnandan-joshi) wrote on 2015-01-19:

#6

The output of above script will be. (run from another instance)

[root@centos65 ~]# java -cp .:mysql-connector-java-3.1.14-bin.jar FirstExample
Connecting to database...
Creating statement...
ID: 1, Name: nilnandanGoodbye!
[root@centos65 ~]#
[root@centos65 ~]#

Revision history for this message

everflux (tklaunchpad) wrote on 2015-01-20:

#7

Would it help if I create a tcpdump dump and provide it for further investigation?

Revision history for this message

Tim Pearson (ttpears) wrote on 2015-01-23:

#8

Confirming bug.

Percona toolkit version: 2.2.11
MySQL Server version: 5.5.40-rel36.1-707.wheezy
TCPDump version: 4.3.0-1

TCPDump command issued:
tcpdump -s 65535 -x -nn -q -tttt -i eth0 -c 500000 port 3306 > mysqltcp.txt

pt-query-digest command:
pt-query-digest --type tcpdump mysqltcp.txt

Output examples:
# String:
# Databases ^@mysql_nat... (1398/76%), <removed>... (421/23%), mysql_nati... (3/0%), <removed>... (1/0%)
# Hosts <removed>
# Users <removed>
# Query_time distribution
# 1us
# 10us
# 100us ##########################################
# 1ms ################################################################
# 10ms ####
# 100ms #
# 1s #
# 10s+
# Tables
# SHOW TABLE STATUS FROM `^@mysql_native_password` LIKE <removed>
# SHOW CREATE TABLE `^@mysql_native_password`.<removed>

Frank Cizmich (frank-cizmich) on 2015-01-23

Changed in percona-toolkit:
status:	Incomplete → Triaged
importance:	Undecided → Medium

Frank Cizmich (frank-cizmich) on 2015-01-23

tags:

added: pt-query-digest

Revision history for this message

Ovais Tariq (ovais-tariq) wrote on 2015-01-23:

#9

Any ideas when we should expect this to be fixed.

Frank Cizmich (frank-cizmich) on 2015-01-25

Changed in percona-toolkit:
assignee:	nobody → Frank Cizmich (frank-cizmich)
milestone:	none → 2.2.14

Revision history for this message

Frank Cizmich (frank-cizmich) wrote on 2015-01-25:

#10

Targeted it for 2.2.14
Will post a patch when it's fixed.

Revision history for this message

everflux (tklaunchpad) wrote on 2015-01-25:

#11

Awesome. Please make sure to also verify with a tool that reads various other meta data. (I believe that was the cause for the really bad output when using the free java/jdbc tool http://www.sql-workbench.net/ just accessing a database I posted earlier.)

Revision history for this message

Ovais Tariq (ovais-tariq) wrote on 2015-01-27:

#12

Thanks Frank.

Revision history for this message

Ovais Tariq (ovais-tariq) wrote on 2015-02-05:

#13

Here is some more bash foo in case you want to parse the schema names correctly and you know what the schema names are like:

/usr/bin/pt-query-digest --type tcpdump mysql.tcp --output slowlog | sed 's/$^use schema_name$.*/\1 /g' | awk '{ if($0 ~ /use schema_name/) {print $1" "$2} else { print $0 } }'

Frank Cizmich (frank-cizmich) on 2015-04-09

Changed in percona-toolkit:
milestone:	2.2.14 → none

Revision history for this message

Jervin R (revin) wrote on 2015-06-25:

#14

Checking if this bug will still be fixed, thought it was targetted for 2.2.14? :)

Revision history for this message

Frank Cizmich (frank-cizmich) wrote on 2015-10-05:

#15

Hi Jervin,

Yes, the bug is still unfixed, although in progress. The cause is a change in MySQL tcp protocol and how it handles authentication, so I needed to revise the whole parsing internals, which bogged me down, .. and as often is the case, other stuff overtook priority.
Will take a new look now.

Changed in percona-toolkit:
status:	Triaged → In Progress
milestone:	none → 2.3.1

Hrvoje Matijakovic (hrvojem) on 2016-03-03

Changed in percona-toolkit:
milestone:	2.2.17 → 2.2.18

Sveta Smirnova (svetasmirnova) on 2016-03-24

tags:

added: i67231

Revision history for this message

Sveta Smirnova (svetasmirnova) wrote on 2016-03-24:

#16

Version 5.5 also affected.

Revision history for this message

everflux (tklaunchpad) wrote on 2016-05-06:

#17

Is there a work around available or a snapshot version of pt-query-digest with a patch?

Revision history for this message

Avadhut Phatarpekar (avadhut-p) wrote on 2016-05-06:

#18

@everflux: Try running it like this:
PERCONA_TOOLKIT_TCP_ERRORS_FILE=/dev/null pt-query-digest --type=tcpdump . . .

Revision history for this message

Sveta Smirnova (svetasmirnova) wrote on 2016-06-08:

#19

Bug is repeatable with version 2.2.17

Test I used.

1. Start MySQL 5.7.13 from MTR:

./mtr --start-dirty innodb &

2. Start tcpdump:

sudo tcpdump -s 65535 -X -nn -q -tttt -i any -c 25 port 13000 > mysqltcp.txt

3. Run following PHP script few times:

php -r '$m=mysqli_connect("127.0.0.1","root","","test",13000); mysqli_real_query($m, "USE information_schema"); mysqli_real_query($m, "SHOW TABLES"); mysqli_real_query($m, "select * from tables");'

sveta@Thinkie:~/build/mysql-5.7/mysql-test$ php --version
PHP 5.5.9-1ubuntu4.17 (cli) (built: May 19 2016 19:05:57)
Copyright (c) 1997-2014 The PHP Group
Zend Engine v2.5.0, Copyright (c) 1998-2014 Zend Technologies
with Zend OPcache v7.0.3, Copyright (c) 1999-2014, by Zend Technologies

Installed from Ubuntu repo

4. Process tcpdump:

PTDEBUG=1 ~/src/percona-toolkit/bin/pt-query-digest --type tcpdump --watch-server 127.0.0.1:13000 --limit 100% mysqltcp.txt 2>err.log >out.log

5. Find in out.log:

# Query 1: 4.50 QPS, 0.01x concurrency, ID 0x5D51E5F01B88B79E at byte 14320
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
...
# Databases test^@mysql_native_password
...
administrator command: Connect\G

Full out.log and tcpdump output will be attached.

Revision history for this message

Sveta Smirnova (svetasmirnova) wrote on 2016-06-08:

#20

tcpdump output Edit (15.2 KiB, text/plain)

Revision history for this message

Sveta Smirnova (svetasmirnova) wrote on 2016-06-08:

#21

pt-query-digest log Edit (5.0 KiB, application/octet-stream)

Revision history for this message

Sveta Smirnova (svetasmirnova) wrote on 2016-06-08:

#22

pt-query-digest error log Edit (85.0 KiB, application/octet-stream)

Revision history for this message

Sveta Smirnova (svetasmirnova) wrote on 2016-06-08:

#23

Workaround to specify PERCONA_TOOLKIT_TCP_ERRORS_FILE=/dev/null does not work for me

Frank Cizmich (frank-cizmich) on 2016-06-13

Changed in percona-toolkit:
status:	In Progress → Fix Committed

Revision history for this message

Sveta Smirnova (svetasmirnova) wrote on 2016-06-15:

#24

I see same corruption if run just pulled pt-query-digest on the attached tcpdump output

Revision history for this message

Sveta Smirnova (svetasmirnova) wrote on 2016-06-22:

#25

With today pull it works fine

EvgeniyPatlan (evgeniy-patlan) on 2016-06-24

Changed in percona-toolkit:
status:	Fix Committed → Fix Released

Revision history for this message

Daniel Guzmán Burgos (nethalo) wrote on 2016-11-16:

#26

Still happening with 5.7 and pt-query-digest 2.2.19

Steps:

On server:
sudo tcpdump -s 65535 -x -nn -q -tttt -i any -c 10000 port 3306 > pepe

Run a couple of queries:
mysql> use `percona`
mysql> select * from `percona`.`sbtest99`;
mysql> select * from `percona`.`sbtest99`;
mysql> select * from `percona`.`sbtest99`;
...

Use pt-query-digest:
root@reports:~# cat pepe | pt-query-digest --type tcpdump --output slowlog | head -n50
Reading from STDIN ...
# Time: 161116 20:53:15.726698
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.001404 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
# administrator command: Connect;
# Time: 161116 20:53:15.727415
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000210 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
select @@version_comment limit 1;
# Time: 161116 20:53:18.533741
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000231 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
SELECT DATABASE();
# Time: 161116 20:53:18.535239
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000203 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
# administrator command: Init_db;
# Time: 161116 20:53:18.537493
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000511 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
show databases;
# Time: 161116 20:53:18.540470
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.002153 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
show tables;
# Time: 161116 20:53:18.545246
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000536 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
# administrator command: Field_list;
# Caught SIGPIPE.

Check the presence of "use mysql_native_password;" on each statement

Still happening with 5.7 and pt-query-digest 2.2.19

Steps:

On server:
sudo tcpdump -s 65535 -x -nn -q -tttt -i any -c 10000 port 3306 > pepe

Run a couple of queries:
mysql> use `percona`
mysql> select * from `percona`.`sbtest99`;
mysql> select * from `percona`.`sbtest99`;
mysql> select * from `percona`.`sbtest99`;
...

Use pt-query-digest:
root@reports:~# cat pepe | pt-query-digest --type tcpdump --output slowlog | head -n50
Reading from STDIN ...
# Time: 161116 20:53:15.726698
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.001404  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
use mysql_native_password;
# administrator command: Connect;
# Time: 161116 20:53:15.727415
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000210  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
use mysql_native_password;
select @@version_comment limit 1;
# Time: 161116 20:53:18.533741
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000231  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
use mysql_native_password;
SELECT DATABASE();
# Time: 161116 20:53:18.535239
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000203  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
use mysql_native_password;
# administrator command: Init_db;
# Time: 161116 20:53:18.537493
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000511  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
use mysql_native_password;
show databases;
# Time: 161116 20:53:18.540470
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.002153  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
use mysql_native_password;
show tables;
# Time: 161116 20:53:18.545246
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000536  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
use mysql_native_password;
# administrator command: Field_list;
# Caught SIGPIPE.

Check the presence of "use mysql_native_password;" on each statement

Carlos Salguero (carlos-salguero) on 2016-11-16

Changed in percona-toolkit:
milestone:	2.2.18 → 2.2.20
status:	Fix Released → In Progress
assignee:	Frank Cizmich (frank-cizmich) → Carlos Salguero (carlos-salguero)

Carlos Salguero (carlos-salguero) on 2016-12-06

Changed in percona-toolkit:
milestone:	2.2.20 → 2.2.21

Revision history for this message

Carlos Salguero (carlos-salguero) wrote on 2016-12-17:

#27

Updated MySQL Protocol Parser to make it able to handle connection flags to properly detect the DB name or leave the field empty if necessary.

Revision history for this message

Carlos Salguero (carlos-salguero) wrote on 2016-12-17:

#28

Fix committed: https://github.com/percona/percona-toolkit/pull/157

Changed in percona-toolkit:
status:	In Progress → Fix Committed

Carlos Salguero (carlos-salguero) on 2017-05-26

Changed in percona-toolkit:
status:	Fix Committed → Fix Released

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-24:

#29

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PT-667

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

Parsing of tcpdump capture from MySQL 5.6 with pt-query-digest adds erroneous \x0mysql_native_password to "use database" statements

Bug Description

Other bug subscribers

Bug attachments

Remote bug watches