pt-query-digest profile shows incorrect UNION statement
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona Toolkit moved to https://jira.percona.com/projects/PT |
Confirmed
|
Undecided
|
Unassigned |
Bug Description
Some of the values in the WHERE clause contain the string 'union' and pt-query-digest incorrectly displays that the UNION statement is being used for some items displayed in the response-time profile.
Using pt-query-digest 2.2.19
grep -c UNION slow.log
0
pt-query-digest slow.log
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0xBA52E9840CF0EDB3 30.4562 22.6% 216 0.1410 0.00 SELECT UNION rainmaker.
# 6 0x02423A5E62328BD1 5.1513 3.8% 43 0.1198 0.00 SELECT UNION instance_status
# Query 1: 0.03 QPS, 0.00x concurrency, ID 0xBA52E9840CF0EDB3 at byte 94948916
SELECT instance_id, name, value FROM rainmaker.
tags: | added: pt-table-checksum |
Thank you for the report.
Verified as described.
To repeat:
mysql> set global log_output='file';
Query OK, 0 rows affected (0.00 sec)
mysql> set global long_query_time=0;
Query OK, 0 rows affected (0.00 sec)
mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.00 sec)
mysql> select user, host from mysql.user where user in ('tasty- union', 'rough- union') ;
Empty set (0.00 sec)
mysql> \q
Bye
$ ~/src/percona- toolkit/ bin/pt- query-digest --limit=100% var/mysqld. 1/mysqld- slow.log
# 160ms user time, 0 system time, 35.09M rss, 103.07M vsz 1/mysqld- slow.log
# Current date: Mon Dec 12 15:07:15 2016
# Hostname: Thinkie
# Files: var/mysqld.
# Overall: 9 total, 6 unique, 0.19 QPS, 0.00x concurrency ________________
# Time range: 2016-12-12 15:04:57 to 15:05:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 168ms 58us 166ms 19ms 163ms 51ms 316us
# Lock time 865us 0 217us 96us 214us 91us 103us
# Rows sent 7 0 6 0.78 5.75 1.79 0
# Rows examine 18 0 6 2 5.75 2.23 0
# Rows affecte 0 0 0 0 0 0 0
# Bytes sent 751 0 186 83.44 183.58 60.22 112.70
# Query size 352 10 77 39.11 76.28 27.55 26.08
# Profile ####### ####### ####### ####### ####### ####### ####### ####### #
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0x35AAC71503957920 0.1663 98.9% 1 0.1663 0.00 FLUSH
# 2 0x351C5BE9210F20D3 0.0011 0.7% 3 0.0004 0.00 SELECT UNION mysql.user
# 3 0x5CBA2034458B5BC9 0.0003 0.2% 1 0.0003 0.00 SHOW DATABASES
# 4 0x132628303F99240D 0.0002 0.1% 1 0.0002 0.00 SHOW TABLES
# 5 0xE3A3649C5FAC418D 0.0001 0.1% 1 0.0001 0.00 SELECT
# 6 0xAA353644DE4C4CB4 0.0001 0.1% 2 0.0001 0.00 ADMIN QUIT
...
# Query 2: 0.07 QPS, 0.00x concurrency, ID 0x351C5BE9210F20D3 at byte 2294
# Scores: V/M = 0.00
# Time range: 2016-12-12 15:04:58 to 15:05:43
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 33 3
# Exec time 0 1ms 359us 370us 366us 366us 5us 366us
# Lock time 73 640us 209us 217us 213us 214us 4us 204us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 66 12 4 4 4 4 0 4
# Rows affecte 0 0 0 0 0 0 0 0
# Bytes sent 46 351 117 117 117 117 0 117
# Query size 65 231 77 77 77 77 0 77
# String:
# Databases test
# Hosts localhost
# Last errno 0
# Users root
# Query_time distribution
# 1us
# 10us
# 100us #######
# 1ms
# 10ms
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `mysql` LIKE 'user'\G
# SHOW CREAT...