pt-query-digest 32bit variable counters break output (are shown as 0)
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona Toolkit moved to https://jira.percona.com/projects/PT |
Fix Released
|
Medium
|
Frank Cizmich |
Bug Description
As you can see in the following example (trivial slow log with only one query), once the counters exceed 4G (2^32), the output breaks and 0 is displayed instead.
So, we have the following:
Rows_sent = 10
Rows_examined = 4294967297 (4G + 1)
Rows_affected: 4294967296 (4G)
Rows_read: 1024
(note the same happens with InnoDB_IO_*, InnoDB_
Then, pt-query-digest report as example below will show:
# Rows sent 10 10 10 10 10 0 10
# Rows examine 0 0 0 0 0 0 0
# Rows affecte 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
# Rows read 1.00k 1.00k 1.00k 1.00k 1.00k 0 1.00k
Clearly, rows_examined is wrongly displayed as 0.
Example to reproduce this:
$ cat mysql-slow.log
# User@Host: user[user] @ [192.168.1.2]
# Thread_id: 434469 Schema: some_schema Last_errno: 1265 Killed: 0
# Query_time: 29304.231566 Lock_time: 0.000480 Rows_sent: 10 Rows_examined: 4294967297 Rows_affected: 4294967296 Rows_read: 1024
# Bytes_sent: 153 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 936E5
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 4294967296 InnoDB_IO_r_bytes: 4294967297 InnoDB_IO_r_wait: 5008.481097
# InnoDB_
# InnoDB_
use some_schema;
SET timestamp=
load data local infile '/tmp/load.tsv' into table test;
$ pt-query-digest --group-by fingerprint --order-by InnoDB_
# 520ms user time, 80ms system time, 31.88M rss, 110.12M vsz
# Current date: Thu Feb 18 16:21:38 2016
# Hostname: bm-support01
# Files: mysql-slow.log
# Overall: 1 total, 1 unique, 0 QPS, 0x concurrency _______
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 29304s 29304s 29304s 29304s 29304s 0 29304s
# Lock time 480us 480us 480us 480us 480us 0 480us
# Rows sent 10 10 10 10 10 0 10
# Rows examine 0 0 0 0 0 0 0
# Rows affecte 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
# Rows read 1.00k 1.00k 1.00k 1.00k 1.00k 0 1.00k
# Bytes sent 153 153 153 153 153 0 153
# Merge passes 0 0 0 0 0 0 0
# Tmp tables 0 0 0 0 0 0 0
# Tmp disk tbl 0 0 0 0 0 0 0
# Tmp tbl size 0 0 0 0 0 0 0
# Query size 55 55 55 55 55 0 55
# InnoDB:
# IO r bytes 0 0 0 0 0 0 0
# IO r ops 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
# IO r wait 5008s 5008s 5008s 5008s 5008s 0 5008s
# pages distin 64.00k 64.00k 64.00k 64.00k 64.00k 0 64.00k
# queue wait 0 0 0 0 0 0 0
# rec lock wai 0 0 0 0 0 0 0
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================= ===== ========== ===== =======
# 1 0x13A200BAE26EB6B7 29304.2316 100.0% 1 29304.2316 0.00 LOAD DATA test
# Query 1: 0 QPS, 0x concurrency, ID 0x13A200BAE26EB6B7 at byte 0 ________
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 100 1
# Exec time 100 29304s 29304s 29304s 29304s 29304s 0 29304s
# Lock time 100 480us 480us 480us 480us 480us 0 480us
# Rows sent 100 10 10 10 10 10 0 10
# Rows examine 0 0 0 0 0 0 0 0
# Rows affecte 100 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
# Rows read 100 1.00k 1.00k 1.00k 1.00k 1.00k 0 1.00k
# Bytes sent 100 153 153 153 153 153 0 153
# Merge passes 0 0 0 0 0 0 0 0
# Tmp tables 0 0 0 0 0 0 0 0
# Tmp disk tbl 0 0 0 0 0 0 0 0
# Tmp tbl size 0 0 0 0 0 0 0 0
# Query size 100 55 55 55 55 55 0 55
# InnoDB:
# IO r bytes 0 0 0 0 0 0 0 0
# IO r ops 100 4.00G 4.00G 4.00G 4.00G 4.00G 0 4.00G
# IO r wait 100 5008s 5008s 5008s 5008s 5008s 0 5008s
# pages distin 100 64.00k 64.00k 64.00k 64.00k 64.00k 0 64.00k
# queue wait 0 0 0 0 0 0 0 0
# rec lock wai 0 0 0 0 0 0 0 0
# String:
# Databases some_schema
# InnoDB trxID 936E5
# Last errno 1265
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ #######
# Tables
# SHOW TABLE STATUS FROM `some_schema` LIKE 'test'\G
# SHOW CREATE TABLE `some_schema`
load data local infile '/tmp/load.tsv' into table test
\G
Changed in percona-toolkit: | |
status: | New → Confirmed |
Changed in percona-toolkit: | |
status: | Confirmed → Opinion |
assignee: | nobody → Frank Cizmich (frank-cizmich) |
Changed in percona-toolkit: | |
milestone: | none → 2.2.17 |
importance: | Undecided → Medium |
Changed in percona-toolkit: | |
milestone: | 2.2.17 → 2.2.18 |
Changed in percona-toolkit: | |
status: | Triaged → Fix Committed |
Changed in percona-toolkit: | |
status: | Fix Committed → Fix Released |
You can work around this setting --attribute- value-limit 0
Some bug in MySQLs slow log sometimes outputted spurious and false huge values , thus the limit option, with a default of 4G
Maybe this should be optional.