pt-query-digest profile shows incorrect UNION statement

[monty solomon]

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.puppet_var
# 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.puppet_var WHERE (puppet_var.valid_until is null) AND instance_id IN('tasty-union','rough-union'/*... omitted 100 items ...*/)\G

[Sveta Smirnova (svetasmirnova)]

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
# Current date: Mon Dec 12 15:07:15 2016
# Hostname: Thinkie
# Files: var/mysqld.1/mysqld-slow.log
# 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...

[Shahriyar Rzayev (rzayev-sehriyar)]

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