pt-query-digest 32bit variable counters break output (are shown as 0)

Bug #1547225 reported by Agustín
6
This bug affects 1 person
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_pages_distinct, etc., so the fix should include these counters, too).

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_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 65536
use some_schema;
SET timestamp=1455618263;
load data local infile '/tmp/load.tsv' into table test;

$ pt-query-digest --group-by fingerprint --order-by InnoDB_IO_r_bytes:sum mysql-slow.log

# 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`.`test`\G
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)
Revision history for this message
Frank Cizmich (frank-cizmich) wrote :

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.

tags: added: pt-query-digest
Revision history for this message
Peter Schwaller (peter-schwaller) wrote :

We'll update the docs appropriately.

Changed in percona-toolkit:
status: Opinion → Invalid
Changed in percona-toolkit:
milestone: none → 2.2.17
importance: Undecided → Medium
Changed in percona-toolkit:
milestone: 2.2.17 → 2.2.18
Revision history for this message
Agustín (agustin-gallego) wrote :

Hi,

Thanks for reviewing this. I wonder if it makes sense (if defaults will remain as they are now) to print a warning when this is detected, instead of silently setting them to 0?

Something like:

"[Warning] Some fields have been truncated to 0 due to <insert explanation>. Use --attribute-value-limit=0 if you want to override this check. <link to doc, bug, etc.>"

Revision history for this message
Frank Cizmich (frank-cizmich) wrote :

The warning should definitely be considered.
Also, probably elevating default by some amount, since I think this is originally a spurious MySQL bug due to the 32 bit limit, that should be solved by now.

Changed in percona-toolkit:
status: Invalid → Triaged
Changed in percona-toolkit:
status: Triaged → Fix Committed
Changed in percona-toolkit:
status: Fix Committed → Fix Released
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-701

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.