pt-table-checksum redundant argument in printf at /usr/bin/pt-table-checksum line 8171

Bug #1480719 reported by Thomas Deutschmann on 2015-08-02
20
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Percona Toolkit moved to https://jira.percona.com/projects/PT
Fix Released
High
Frank Cizmich

Bug Description

I was running pt-table-checksum while the script showed

08-02T22:49:10 Error checksumming table our_database.a_table_name: Redundant argument in printf at /usr/bin/pt-table-checksum line 8171.

I get the same error again when I just check "our_database.a_table_name"...

Complete command-line used to run the tool:
=====================================
# pt-table-checksum --host <ip> --user <username> --ask-pass

Tool version:
===========
2.2.14

MySQL version of all servers involved:
==============================
percona-server-5.6.25.73.0

Hi Thomas,

I've checked that piece of code and it shows which table is remaining.

 my $self;
   $self = {
      last_reported => $args{start},
      fraction => 0, # How complete the job is
      callback => sub {
         my ($fraction, $elapsed, $remaining, $eta) = @_;
         printf STDERR "$name: %3d%% %s remain\n", <---- you are getting error at this line.
            $fraction * 100,
            Transformers::secs_to_time($remaining),
            Transformers::ts($eta);
      },
      %args,

Can you please provide the PTDEBUG output while running pt-table-checksum? i.e

shell> PTDEBUG=1 pt-table-checksum --host <ip> --user <username> --ask-pass

Also can you provide the exact database and table name? is it contain any special characters?

Changed in percona-toolkit:
status: New → Incomplete
Thomas Deutschmann (whissi) wrote :

Hi Nilnandan,

> Can you please provide the PTDEBUG output while running pt-table-checksum?

Please see the attached pt-table-checksum.log.

> Also can you provide the exact database and table name? is it contain any
> special characters?

I cannot share the identical names but I only replaced [a-z] chars. nothing else. Schema is untouched.

-Thomas

Changed in percona-toolkit:
status: Incomplete → New

Hi Thomas,

Couldn't able to reproduce this.

nilnandan@desktop:~$ pt-table-checksum --user=root --ask-pass --databases=test --tables=nil
Enter MySQL password:
Diffs cannot be detected because no slaves were found. Please read the --recursion-method documentation for information.
            TS ERRORS DIFFS ROWS CHUNKS SKIPPED TIME TABLE
08-11T14:11:50 0 0 5 1 0 0.005 test.nil
nilnandan@desktop:~$

Are you facing this issue with this specific table? or all tables on that server?
Can you provide the structure of that table with original name of columns and data types?

Also can you create the table with same structure but different name and then try to run pt-table-checksum on that? I'm sure there is only one table with that name in the database. (yes, it should not happen but sometimes, its possible due to some bug)

mysql> create table aa_database.ee like aa_database.dd_stats_access;

Changed in percona-toolkit:
status: New → Incomplete
Thomas Deutschmann (whissi) wrote :

Hi Nilnandan,

I am not allowed to post this online, visible and findable for everyone, but I was allowed to send you the details (dump) privately. Please check your inbox (I hope you're fine with that).

Regarding your other questions:

> Are you facing this issue with this specific table? or all tables
> on that server?

Only with this specific table. All the other tables and databases are fine.

Like written in the mail you should be able to reproduce the issue using the dump I provided by mail like I am using different servers.

Hi Thomas,

Thanks for the dump but I could unable to reproduce it.

nilnandan@desktop:~$ mysql -u root -p test < /home/nilnandan/Downloads/pt-checksum-bug-1480719.sql
Enter password:
nilnandan@desktop:~$ pt-table-checksum --user=root --ask-pass --databases=test
Enter MySQL password:
Diffs cannot be detected because no slaves were found. Please read the --recursion-method documentation for information.
Checksumming test.bb_stats_access: 62% 00:18 remain
            TS ERRORS DIFFS ROWS CHUNKS SKIPPED TIME TABLE
08-12T13:07:11 0 0 43420141 81 0 46.987 test.bb_stats_access
08-12T13:07:11 0 0 4 1 0 0.002 test.flushes
08-12T13:07:11 0 0 5 1 0 0.003 test.nil
08-12T13:07:11 0 0 1 1 0 0.002 test.t1
08-12T13:07:11 0 0 0 1 0 0.002 test.t2
08-12T13:07:11 0 0 0 1 0 0.002 test.t3
08-12T13:07:11 0 0 0 1 0 0.002 test.testb
nilnandan@desktop:~$ pt-table-checksum --version
pt-table-checksum 2.2.14
nilnandan@desktop:~$
nilnandan@desktop:~$ mysqld --version
mysqld Ver 5.6.25-73.1 for debian-linux-gnu on x86_64 (Percona Server (GPL), Release 73.1, Revision 07b797f)
nilnandan@desktop:~$

Thomas Deutschmann (whissi) wrote :

Strange, I tested the dump like said on various different mysqld versions:

mysqld Ver 5.6.24-72.2 for Linux on x86_64 (Source distribution) <-- Percona
mysqld Ver 5.6.25-73.0 for Linux on x86_64 (Source distribution) <-- Percona
mysqld Ver 5.6.24 for Win64 on x86_64 (MySQL Community Server (GPL))
mysqld Ver 5.6.26 for Win64 on x86_64 (MySQL Community Server (GPL))
mysqld Ver 5.6.25-73.1 for debian-linux-gnu on x86_64 (Percona Server (GPL), Release 73.1, Revision 07b797f)

This looks like an perl issue:

I am using perl-5.22.0 (Gentoo).

I tested with Debian 7.8 (Wheezy) which uses perl-5.14.2 and I didn't get this error. Tables looks fine.

I tried Arch Linux which also has perl-5.22.0 and I'll get the same error again.

Note: I always tested against the same dedicated mysqld. Only the system with pt-table-checksum changed.

Looks like https://rt.perl.org/Public/Bug/Display.html?id=125469

However I recompiled perl-5.22.0 with http://perl5.git.perl.org/perl.git/commitdiff/082ce9c667e6d73783164fa1abab61806b678b4f but the error is still present.

Maybe you have access to perl-5.22.0, too and can verify?

Changed in percona-toolkit:
status: Incomplete → New
tags: added: pt-table-checksum
Frederic Descamps (lefred) wrote :

I had similar issue with pt-query-digest with a tcpdump sample using perl 5.22 on Fedora.

./pt-query-digest --type tcpdump tcpdump_2015-11-27_18-32.tcp > tcpdump_2015-11-27_18-32.digest
TCP session 172.29.2.24:58642 had errors, will save them in /tmp/pt-query-digest-errors.nxQVV8I
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 157754.
Will retry pipeline process 1 (input) 100 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 316084.
Will retry pipeline process 1 (input) 99 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 479264.
Will retry pipeline process 1 (input) 98 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 628785.
Will retry pipeline process 1 (input) 97 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 781472.
Will retry pipeline process 1 (input) 96 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 941692.
Will retry pipeline process 1 (input) 95 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 1090187.
Will retry pipeline process 1 (input) 94 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 1240569.
Will retry pipeline process 1 (input) 93 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 1399256.
Will retry pipeline process 1 (input) 92 more times.
Pipeline process 2 (input) caused an error: Redundant argument in printf at ./pt-query-digest line 11122, <$fh> line 1554631.
Will retry pipeline process 1 (input) 91 more times.
Pipeline process 6 (iteration) caused an error: Redundant argument in sprintf at ./pt-query-digest line 2556.
Will retry pipeline process 5 (iteration) 2 more times.
Pipeline process 6 (iteration) caused an error: Redundant argument in sprintf at ./pt-query-digest line 2556.
Will retry pipeline process 5 (iteration) 1 more time.
The pipeline caused an error: Pipeline process 6 (iteration) caused an error: Redundant argument in sprintf at ./pt-query-digest line 2556.
Terminating pipeline because process 5 (iteration) caused too many errors.

I ran the same command on CentOS having Perl 5.10 and it worked

Branden Timm (branden-timm) wrote :

I'm having the same issue with pt-query-digest on Fedora 23/Perl 5.22.1:

$ PT_DEBUG=1 pt-query-digest --user {} --ask-pass --review h={},t={} --history h={},t={} --resume prod-resume-file slow-log
Enter password for --review:
Enter password for --history:
# Resuming slow-log from offset 0 because resume file slow-log does not exist (file size: 240795165)...
Pipeline process 2 (input) caused an error: Redundant argument in printf at /usr/bin/pt-query-digest line 11122, <$fh> line 75848.
Will retry pipeline process 1 (input) 100 more times.

# Saved resume file stop_offset 240795165 to prod-resume-file

# 43.5s user time, 60ms system time, 79.57M rss, 283.95M vsz
# Current date: Mon Jan 11 07:54:08 2016
# Hostname: localhost.localdomain
# Files: slow-log
Pipeline process 5 (iteration) caused an error: Redundant argument in sprintf at /usr/bin/pt-query-digest line 2556.
Will retry pipeline process 4 (iteration) 2 more times.

# Saved resume file stop_offset 240795165 to prod-resume-file

# 44s user time, 60ms system time, 79.77M rss, 283.95M vsz
# Current date: Mon Jan 11 07:54:09 2016
# Hostname: localhost.localdomain
# Files: slow-log
Pipeline process 5 (iteration) caused an error: Redundant argument in sprintf at /usr/bin/pt-query-digest line 2556.
Will retry pipeline process 4 (iteration) 1 more time.

# Saved resume file stop_offset 240795165 to prod-resume-file

# 44.5s user time, 70ms system time, 79.77M rss, 283.95M vsz
# Current date: Mon Jan 11 07:54:09 2016
# Hostname: localhost.localdomain
# Files: slow-log
The pipeline caused an error: Pipeline process 5 (iteration) caused an error: Redundant argument in sprintf at /usr/bin/pt-query-digest line 2556.
Terminating pipeline because process 4 (iteration) caused too many errors.

# Saved resume file stop_offset 240795165 to prod-resume-file

Even worse, pt-query-digest still writes out resume file offsets as if it had run successfully, even though nothing has been written to the history/review tables. I suppose this should be a separate bug?

$ cat prod-resume-file
start_offset=0
stop_offset=240795165

Romain GUINOT (romainguinot) wrote :

Same issue for me with pt-query-digest on Fedora 23/Perl 5.22.1 :

Pipeline process 5 (iteration) caused an error: Redundant argument in sprintf at /opt/percona/toolkit/latest/bin/pt-query-digest line 2556
Will retry pipeline process 4 (iteration) 2 more times.
Terminating pipeline because process 4 (iteration) caused too many errors.

Changed in percona-toolkit:
assignee: nobody → Frank Cizmich (frank-cizmich)
Frank Cizmich (frank-cizmich) wrote :

Seems indeed to be a spurious perl bug.
Couldn't reproduce but wrapped offending line in an "eval"
I'm attaching latest pt-table-checksum version with this modification.
Please try it out and see if it works for you.

Frank Cizmich (frank-cizmich) wrote :

Here's the pt-query-digest version

The problematic printf is in the embedded Progress module, so if this works, all other tools will be fixed too.

Please check these out. I appreciate any feedback since this is hard to reproduce.

Changed in percona-toolkit:
status: New → In Progress
importance: Undecided → High
milestone: none → 2.2.17
Frederic Descamps (lefred) wrote :

Hi Frank,

still a problem:

./pt-query-digest mysql_slow.log > mysql_slow.log.digest
Pipeline process 5 (iteration) caused an error: Redundant argument in sprintf at ./pt-query-digest line 2556.
Will retry pipeline process 4 (iteration) 2 more times.
Pipeline process 5 (iteration) caused an error: Redundant argument in sprintf at ./pt-query-digest line 2556.
Will retry pipeline process 4 (iteration) 1 more time.
The pipeline caused an error: Pipeline process 5 (iteration) caused an error: Redundant argument in sprintf at ./pt-query-digest line 2556.
Terminating pipeline because process 4 (iteration) caused too many errors

Romain GUINOT (romainguinot) wrote :

Hi guys,

I have tested as well with the version Frank's posted and it is still an issue for me too.
Please see the partial fix i posted in the related bug : https://bugs.launchpad.net/percona-toolkit/+bug/1536305.
I am not a Perl expert but maybe this will help you diagnosing the main issue.

I've also added a pt-query-digest output sample showing the errors.

Changed in percona-toolkit:
status: In Progress → Fix Committed
Changed in percona-toolkit:
status: Fix Committed → Fix Released

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

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

Other bug subscribers

Remote bug watches

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