pt-query-digest outputs tonnes of warnings when combined

[Michael Koziarski]

When running pt-query-digest against our slow query logs I see thousands of warnings printed before the actual report is displayed. While the report itself seems correct, the warnings clutter up emails from cron etc.

The warnings look like:

$ pt-query-digest /var/lib/mysql/mysql-slow.log
Pipeline process 10 (aggregate fingerprint) caused an error: Argument "55A" isn't numeric in numeric gt (>) at (eval 34) line 6, <> line 3.
Pipeline process 10 (aggregate fingerprint) caused an error: Argument "55B" isn't numeric in numeric gt (>) at (eval 34) line 6, <> line 4.
Pipeline process 10 (aggregate fingerprint) caused an error: Argument "55C" isn't numeric in numeric gt (>) at (eval 34) line 6, <> line 5.
Pipeline process 10 (aggregate fingerprint) caused an error: Argument "55D" isn't numeric in numeric gt (>) at (eval 34) line 6, <> line 6.
Pipeline process 10 (aggregate fingerprint) caused an error: Argument "55E" isn't numeric in numeric gt (>) at (eval 34) line 6, <> line 7.
Pipeline process 10 (aggregate fingerprint) caused an error: Argument "55F" isn't numeric in numeric gt (>) at (eval 34) line 6, <> line 8.

When I use --no-report and --filter "print Dumper($event)" It outputs:

Pipeline process 11 (aggregate fingerprint) caused an error: Argument "1B53" isn't numeric in numeric gt (>) at (eval 41) line 233, <> line 4522.
$VAR1 = {
...
  arg => 'SELECT MAX(important_updated_at) important_updated_at FROM `tasks` WHERE `tasks`.`project_id` = 297 LIMIT 1',
  fingerprint => 'select max(important_updated_at) important_updated_at from `tasks` where `tasks`.`project_id` = ? limit ?',
...
};

A example chunk of the slow query log is:

# User@Host: db[db] @ localhost []
# Thread_id: 40 Schema: db Last_errno: 0 Killed: 0
# Query_time: 0.000185 Lock_time: 0.000028 Rows_sent: 1 Rows_examined: 325 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 93 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 56D
SET timestamp=1328583528;
SELECT MAX(important_updated_at) important_updated_at FROM `tasks` WHERE `tasks`.`project_id` = 297 LIMIT 1;

The versions of the server and toolkit are:

Package: percona-toolkit
Version: 2.0.2

Package: percona-server-server-5.5
Version: 5.5.19-rel24.0-204.lucid

Let me know if you require any more information.

[Daniel Nichter (daniel-nichter)]

Thanks for reporting this. I cannot reproduce the issue with the sample log entry, but that's not surprising because pt-query-digest writes subroutines at runtime based on a certain number of events, so sometimes one or even a handful of events aren't enough to reproduce a problem. Could you cut a log file down to the minimal size needed before this problem happens and upload that log? Or, you can email me a log privately from which I can create a sanitized test case?

[Michael Koziarski (michael-koziarski)]

I've emailed you a snapshot of the log which demonstrates the problem. I figured that any attempt by me to sanitize it would likely strip out something important. Feel free to use that to construct a test case so long as there's nothing too incriminating in it

[Baron Schwartz (baron-xaprb)]

Based on what I know of the tool, here's my guess: it finds that the transaction IDs are numeric in the beginning and then JIT compiles an aggregator to handle them as numbers, but then later on they change to hex-codes and break things.

[Michael Koziarski (michael-koziarski)]

Yes, that appears to be correct, the first two transaction ids:

# InnoDB_trx_id: 555
# InnoDB_trx_id: 557

Subsequent ids are hex.

# InnoDB_trx_id: 55B

[Baron Schwartz (baron-xaprb)]

This is actually a duplicate of bug 821694 then.

[Baron Schwartz (baron-xaprb)]

If you're not tracking the other bug, please note that it's been fixed now.