Merge fix-1045317-pt-osc-statistics

bin/pt-online-schema-change

@@ -19,6 +19,7 @@ BEGIN {
       VersionParser
       DSNParser
       Daemon
+      ReportFormatter
       Quoter
       TableNibbler
       TableParser
@@ -2309,6 +2310,359 @@ sub _d {
 # End Daemon package
 # ###########################################################################
 
+# ###########################################################################
+# ReportFormatter package
+# This package is a copy without comments from the original.  The original
+# with comments and its test file can be found in the Bazaar repository at,
+#   lib/ReportFormatter.pm
+#   t/lib/ReportFormatter.t
+# See https://launchpad.net/percona-toolkit for more information.
+# ###########################################################################
+{
+package ReportFormatter;
+
+use strict;
+use warnings FATAL => 'all';
+use English qw(-no_match_vars);
+use constant PTDEBUG => $ENV{PTDEBUG} || 0;
+
+use List::Util qw(min max);
+use POSIX qw(ceil);
+
+eval { require Term::ReadKey };
+my $have_term = $EVAL_ERROR ? 0 : 1;
+
+sub new {
+   my ( $class, %args ) = @_;
+   my @required_args = qw();
+   foreach my $arg ( @required_args ) {
+      die "I need a $arg argument" unless $args{$arg};
+   }
+   my $self = {
+      underline_header     => 1,
+      line_prefix          => '# ',
+      line_width           => 78,
+      column_spacing       => ' ',
+      extend_right         => 0,
+      truncate_line_mark   => '...',
+      column_errors        => 'warn',
+      truncate_header_side => 'left',
+      strip_whitespace     => 1,
+      %args,              # args above can be overriden, args below cannot
+      n_cols              => 0,
+   };
+
+   if ( ($self->{line_width} || '') eq 'auto' ) {
+      die "Cannot auto-detect line width because the Term::ReadKey module "
+         . "is not installed" unless $have_term;
+      ($self->{line_width}) = GetTerminalSize();
+   }
+   PTDEBUG && _d('Line width:', $self->{line_width});
+
+   return bless $self, $class;
+}
+
+sub set_title {
+   my ( $self, $title ) = @_;
+   $self->{title} = $title;
+   return;
+}
+
+sub set_columns {
+   my ( $self, @cols ) = @_;
+   my $min_hdr_wid = 0;  # check that header fits on line
+   my $used_width  = 0;
+   my @auto_width_cols;
+
+   for my $i ( 0..$#cols ) {
+      my $col      = $cols[$i];
+      my $col_name = $col->{name};
+      my $col_len  = length $col_name;
+      die "Column does not have a name" unless defined $col_name;
+
+      if ( $col->{width} ) {
+         $col->{width_pct} = ceil(($col->{width} * 100) / $self->{line_width});
+         PTDEBUG && _d('col:', $col_name, 'width:', $col->{width}, 'chars =',
+            $col->{width_pct}, '%');
+      }
+
+      if ( $col->{width_pct} ) {
+         $used_width += $col->{width_pct};
+      }
+      else {
+         PTDEBUG && _d('Auto width col:', $col_name);
+         $col->{auto_width} = 1;
+         push @auto_width_cols, $i;
+      }
+
+      $col->{truncate}        = 1 unless defined $col->{truncate};
+      $col->{truncate_mark}   = '...' unless defined $col->{truncate_mark};
+      $col->{truncate_side} ||= 'right';
+      $col->{undef_value}     = '' unless defined $col->{undef_value};
+
+      $col->{min_val} = 0;
+      $col->{max_val} = 0;
+
+      $min_hdr_wid        += $col_len;
+      $col->{header_width} = $col_len;
+
+      $col->{right_most} = 1 if $i == $#cols;
+
+      push @{$self->{cols}}, $col;
+   }
+
+   $self->{n_cols} = scalar @cols;
+
+   if ( ($used_width || 0) > 100 ) {
+      die "Total width_pct for all columns is >100%";
+   }
+
+   if ( @auto_width_cols ) {
+      my $wid_per_col = int((100 - $used_width) / scalar @auto_width_cols);
+      PTDEBUG && _d('Line width left:', (100-$used_width), '%;',
+         'each auto width col:', $wid_per_col, '%');
+      map { $self->{cols}->[$_]->{width_pct} = $wid_per_col } @auto_width_cols;
+   }
+
+   $min_hdr_wid += ($self->{n_cols} - 1) * length $self->{column_spacing};
+   PTDEBUG && _d('min header width:', $min_hdr_wid);
+   if ( $min_hdr_wid > $self->{line_width} ) {
+      PTDEBUG && _d('Will truncate headers because min header width',
+         $min_hdr_wid, '> line width', $self->{line_width});
+      $self->{truncate_headers} = 1;
+   }
+
+   return;
+}
+
+sub add_line {
+   my ( $self, @vals ) = @_;
+   my $n_vals = scalar @vals;
+   if ( $n_vals != $self->{n_cols} ) {
+      $self->_column_error("Number of values $n_vals does not match "
+         . "number of columns $self->{n_cols}");
+   }
+   for my $i ( 0..($n_vals-1) ) {
+      my $col   = $self->{cols}->[$i];
+      my $val   = defined $vals[$i] ? $vals[$i] : $col->{undef_value};
+      if ( $self->{strip_whitespace} ) {
+         $val =~ s/^\s+//g;
+         $val =~ s/\s+$//;
+         $vals[$i] = $val;
+      }
+      my $width = length $val;
+      $col->{min_val} = min($width, ($col->{min_val} || $width));
+      $col->{max_val} = max($width, ($col->{max_val} || $width));
+   }
+   push @{$self->{lines}}, \@vals;
+   return;
+}
+
+sub get_report {
+   my ( $self, %args ) = @_;
+
+   $self->_calculate_column_widths();
+   $self->_truncate_headers() if $self->{truncate_headers};
+   $self->_truncate_line_values(%args);
+
+   my @col_fmts = $self->_make_column_formats();
+   my $fmt      = ($self->{line_prefix} || '')
+                . join($self->{column_spacing}, @col_fmts);
+   PTDEBUG && _d('Format:', $fmt);
+
+   (my $hdr_fmt = $fmt) =~ s/%([^-])/%-$1/g;
+
+   my @lines;
+   push @lines, sprintf "$self->{line_prefix}$self->{title}" if $self->{title};
+   push @lines, $self->_truncate_line(
+         sprintf($hdr_fmt, map { $_->{name} } @{$self->{cols}}),
+         strip => 1,
+         mark  => '',
+   );
+
+   if ( $self->{underline_header} ) {
+      my @underlines = map { '=' x $_->{print_width} } @{$self->{cols}};
+      push @lines, $self->_truncate_line(
+         sprintf($fmt, map { $_ || '' } @underlines),
+         mark  => '',
+      );
+   }
+
+   push @lines, map {
+      my $vals = $_;
+      my $i    = 0;
+      my @vals = map {
+            my $val = defined $_ ? $_ : $self->{cols}->[$i++]->{undef_value};
+            $val = '' if !defined $val;
+            $val =~ s/\n/ /g;
+            $val;
+      } @$vals;
+      my $line = sprintf($fmt, @vals);
+      if ( $self->{extend_right} ) {
+         $line;
+      }
+      else {
+         $self->_truncate_line($line);
+      }
+   } @{$self->{lines}};
+
+   return join("\n", @lines) . "\n";
+}
+
+sub truncate_value {
+   my ( $self, $col, $val, $width, $side ) = @_;
+   return $val if length $val <= $width;
+   return $val if $col->{right_most} && $self->{extend_right};
+   $side  ||= $col->{truncate_side};
+   my $mark = $col->{truncate_mark};
+   if ( $side eq 'right' ) {
+      $val  = substr($val, 0, $width - length $mark);
+      $val .= $mark;
+   }
+   elsif ( $side eq 'left') {
+      $val = $mark . substr($val, -1 * $width + length $mark);
+   }
+   else {
+      PTDEBUG && _d("I don't know how to", $side, "truncate values");
+   }
+   return $val;
+}
+
+sub _calculate_column_widths {
+   my ( $self ) = @_;
+
+   my $extra_space = 0;
+   foreach my $col ( @{$self->{cols}} ) {
+      my $print_width = int($self->{line_width} * ($col->{width_pct} / 100));
+
+      PTDEBUG && _d('col:', $col->{name}, 'width pct:', $col->{width_pct},
+         'char width:', $print_width,
+         'min val:', $col->{min_val}, 'max val:', $col->{max_val});
+
+      if ( $col->{auto_width} ) {
+         if ( $col->{min_val} && $print_width < $col->{min_val} ) {
+            PTDEBUG && _d('Increased to min val width:', $col->{min_val});
+            $print_width = $col->{min_val};
+         }
+         elsif ( $col->{max_val} &&  $print_width > $col->{max_val} ) {
+            PTDEBUG && _d('Reduced to max val width:', $col->{max_val});
+            $extra_space += $print_width - $col->{max_val};
+            $print_width  = $col->{max_val};
+         }
+      }
+
+      $col->{print_width} = $print_width;
+      PTDEBUG && _d('print width:', $col->{print_width});
+   }
+
+   PTDEBUG && _d('Extra space:', $extra_space);
+   while ( $extra_space-- ) {
+      foreach my $col ( @{$self->{cols}} ) {
+         if (    $col->{auto_width}
+              && (    $col->{print_width} < $col->{max_val}
+                   || $col->{print_width} < $col->{header_width})
+         ) {
+            $col->{print_width}++;
+         }
+      }
+   }
+
+   return;
+}
+
+sub _truncate_headers {
+   my ( $self, $col ) = @_;
+   my $side = $self->{truncate_header_side};
+   foreach my $col ( @{$self->{cols}} ) {
+      my $col_name    = $col->{name};
+      my $print_width = $col->{print_width};
+      next if length $col_name <= $print_width;
+      $col->{name}  = $self->truncate_value($col, $col_name, $print_width, $side);
+      PTDEBUG && _d('Truncated hdr', $col_name, 'to', $col->{name},
+         'max width:', $print_width);
+   }
+   return;
+}
+
+sub _truncate_line_values {
+   my ( $self, %args ) = @_;
+   my $n_vals = $self->{n_cols} - 1;
+   foreach my $vals ( @{$self->{lines}} ) {
+      for my $i ( 0..$n_vals ) {
+         my $col   = $self->{cols}->[$i];
+         my $val   = defined $vals->[$i] ? $vals->[$i] : $col->{undef_value};
+         my $width = length $val;
+
+         if ( $col->{print_width} && $width > $col->{print_width} ) {
+            if ( !$col->{truncate} ) {
+               $self->_column_error("Value '$val' is too wide for column "
+                  . $col->{name});
+            }
+
+            my $callback    = $args{truncate_callback};
+            my $print_width = $col->{print_width};
+            $val = $callback ? $callback->($col, $val, $print_width)
+                 :             $self->truncate_value($col, $val, $print_width);
+            PTDEBUG && _d('Truncated val', $vals->[$i], 'to', $val,
+               '; max width:', $print_width);
+            $vals->[$i] = $val;
+         }
+      }
+   }
+   return;
+}
+
+sub _make_column_formats {
+   my ( $self ) = @_;
+   my @col_fmts;
+   my $n_cols = $self->{n_cols} - 1;
+   for my $i ( 0..$n_cols ) {
+      my $col = $self->{cols}->[$i];
+
+      my $width = $col->{right_most} && !$col->{right_justify} ? ''
+                : $col->{print_width};
+
+      my $col_fmt  = '%' . ($col->{right_justify} ? '' : '-') . $width . 's';
+      push @col_fmts, $col_fmt;
+   }
+   return @col_fmts;
+}
+
+sub _truncate_line {
+   my ( $self, $line, %args ) = @_;
+   my $mark = defined $args{mark} ? $args{mark} : $self->{truncate_line_mark};
+   if ( $line ) {
+      $line =~ s/\s+$// if $args{strip};
+      my $len  = length($line);
+      if ( $len > $self->{line_width} ) {
+         $line  = substr($line, 0, $self->{line_width} - length $mark);
+         $line .= $mark if $mark;
+      }
+   }
+   return $line;
+}
+
+sub _column_error {
+   my ( $self, $err ) = @_;
+   my $msg = "Column error: $err";
+   $self->{column_errors} eq 'die' ? die $msg : warn $msg;
+   return;
+}
+
+sub _d {
+   my ($package, undef, $line) = caller 0;
+   @_ = map { (my $temp = $_) =~ s/\n/\n# /g; $temp; }
+        map { defined $_ ? $_ : 'undef' }
+        @_;
+   print STDERR "# $package:$line $PID ", join(' ', @_), "\n";
+}
+
+1;
+}
+# ###########################################################################
+# End ReportFormatter package
+# ###########################################################################
+
 # ###########################################################################
 # Quoter package
 # This package is a copy without comments from the original.  The original
@@ -7197,12 +7551,16 @@ my @drop_trigger_sqls;
 $OUTPUT_AUTOFLUSH = 1;
 
 sub main {
-   # Reset global vars else tests will fail.
    local @ARGV        = @_;
+
+   # Reset global vars else tests will fail.
+   $exit_status       = 0;
    $oktorun           = 1;
    @drop_trigger_sqls = ();
 
-   $exit_status = 0;
+   my %stats = (
+      INSERT => 0,
+   );
 
    # ########################################################################
    # Get configuration information.
@@ -8123,6 +8481,7 @@ sub main {
             Retry        => $retry,
             Quoter       => $q,
             OptionParser => $o,
+            stats        => \%stats,
          );
          PTDEBUG && _d('Nibble time:', $tbl->{nibble_time});
 
@@ -8264,7 +8623,6 @@ sub main {
    }
    $orig_tbl->{copied} = 1;  # flag for cleanup tasks
 
-
    # XXX Auto-choose the alter fk method BEFORE swapping/renaming tables 
    # else everything will break because if drop_swap is chosen, then we
    # most NOT rename tables or drop the old table.
@@ -8343,6 +8701,7 @@ sub main {
                Quoter       => $q,
                Cxn          => $cxn,
                TableParser  => $tp,
+               stats        => \%stats,
             );
          }
          elsif ( $alter_fk_method eq 'drop_swap' ) {
@@ -8413,6 +8772,25 @@ sub main {
    $orig_tbl->{success} = 1;  # flag for cleanup tasks
    $cleanup = undef;          # exec cleanup tasks
 
+   if ( $o->get('statistics') ) {
+      my $report = new ReportFormatter(
+         line_width => 74,
+      );
+      $report->set_columns(
+         { name => 'Event',                    },
+         { name => 'Count', right_justify => 1 },
+      );
+
+      foreach my $event ( sort keys %stats ) {
+         $report->add_line(
+            $event,
+            $stats{$event},
+         );
+      }
+
+      print $report->get_report();
+   }
+
    return $exit_status;
 }
 
@@ -8831,12 +9209,12 @@ sub determine_alter_fk_method {
 
 sub rebuild_constraints {
    my ( %args ) = @_;
-   my @required_args = qw(orig_tbl old_tbl child_tables
+   my @required_args = qw(orig_tbl old_tbl child_tables stats
                           Cxn Quoter OptionParser TableParser);
    foreach my $arg ( @required_args ) {
       die "I need a $arg argument" unless $args{$arg};
    }
-   my ($orig_tbl, $old_tbl, $child_tables, $cxn, $q, $o, $tp)
+   my ($orig_tbl, $old_tbl, $child_tables, $stats, $cxn, $q, $o, $tp)
       = @args{@required_args};
 
    # MySQL has a "feature" where if the parent tbl is in the same db,
@@ -8913,6 +9291,7 @@ sub rebuild_constraints {
       if ( $o->get('execute') ) {
          PTDEBUG && _d($sql);
          $cxn->dbh()->do($sql);
+         $stats->{rebuilt_constraint}++;
       }
    }
 
@@ -9100,11 +9479,11 @@ sub drop_triggers {
 
 sub exec_nibble {
    my (%args) = @_;
-   my @required_args = qw(Cxn tbl NibbleIterator Retry Quoter OptionParser);
+   my @required_args = qw(Cxn tbl stats NibbleIterator Retry Quoter OptionParser);
    foreach my $arg ( @required_args ) {
       die "I need a $arg argument" unless $args{$arg};
    }
-   my ($cxn, $tbl, $nibble_iter, $retry, $q, $o)= @args{@required_args};
+   my ($cxn, $tbl, $stats, $nibble_iter, $retry, $q, $o)= @args{@required_args};
 
    my $dbh         = $cxn->dbh();
    my $sth         = $nibble_iter->statements();
@@ -9154,6 +9533,8 @@ sub exec_nibble {
          );
 
          my $t_end = time;
+         $stats->{INSERT}++;
+
          # ###################################################################
          # End timing the query.
          # ###################################################################
@@ -9169,6 +9550,7 @@ sub exec_nibble {
             my $code    = ($warning->{code} || 0);
             my $message = $warning->{message};
             if ( $ignore_code{$code} ) {
+               $stats->{"mysql_warning_$code"}++;
                PTDEBUG && _d('Ignoring warning:', $code, $message);
                next;
             }
@@ -9176,14 +9558,22 @@ sub exec_nibble {
                     && (!$warn_code{$code}->{pattern}
                         || $message =~ m/$warn_code{$code}->{pattern}/) )
             {
-               if ( !$tbl->{"warned_code_$code"} ) {  # warn once per table
+               if ( !$stats->{"mysql_warning_$code"}++ ) {  # warn once
-                  warn "Copying rows caused a MySQL error $code: "
+                  my $err
+                     = "Copying rows caused a MySQL error $code: "
                      . ($warn_code{$code}->{message}
                         ? $warn_code{$code}->{message}
                         : $message)
-                     . "\nThis MySQL error is being ignored and further "
+                     . "\nThis MySQL error is being ignored ";
-                     . "occurrences of it will not be reported.\n";
+                  if ( $o->get('statistics') ) {
-                  $tbl->{"warned_code_$code"} = 1;
+                     $err .= "but further occurrences will be reported "
+                           . "by --statistics when the tool finishes.\n";
+                  }
+                  else {
+                     $err .= "and further occurrences will not be reported.  "
+                           . "Specify --statistics to see a count of all "
+                           . "suppressed warnings and errors.\n";
+                  }
                }
             }
             else {
@@ -9204,6 +9594,7 @@ sub exec_nibble {
       fail => sub {
          my (%args) = @_;
          my $error = $args{error};
+         PTDEBUG && _d('Retry fail:', $error);
 
          # The query failed/caused an error.  If the error is one of these,
          # then we can possibly retry.
@@ -9213,17 +9604,30 @@ sub exec_nibble {
          ) {
             # These errors/warnings can be retried, so don't print
             # a warning yet; do that in final_fail.
+            my $event
+               = $error =~ m/Lock wait timeout/         ? 'lock_wait_timeout'
+               : $error =~ m/Deadlock found/            ? 'deadlock'
+               : $error =~ m/execution was interrupted/ ? 'query_killed'
+               :                                          'unknown1';
+            $stats->{$event}++;
             return 1;  # try again
          }
          elsif (   $error =~ m/MySQL server has gone away/
                 || $error =~ m/Lost connection to MySQL server/
          ) {
-            # The 2nd pattern means that MySQL itself died or was stopped.
+            # The 1st pattern means that MySQL itself died or was stopped.
-            # The 3rd pattern means that our cxn was killed (KILL <id>).
+            # The 2nd pattern means that our cxn was killed (KILL <id>).
+            my $event
+               = $error =~ m/server has gone away/ ? 'lost_connection'
+               : $error =~ m/Lost connection/      ? 'connection_killed'
+               :                                     'unknown2';
+            $stats->{$event}++;
             $dbh = $cxn->connect();  # connect or die trying
             return 1;  # reconnected, try again
          }
 
+         $stats->{retry_fail}++;
+
          # At this point, either the error/warning cannot be retried,
          # or we failed to reconnect.  Don't retry; call final_fail.
          return 0;
@@ -9416,8 +9820,16 @@ unless you specify L<"--alter-foreign-keys-method">.
 =head1 OUTPUT
 
 The tool prints information about its activities to STDOUT so that you can see
-what it is doing. During the data copy phase, it prints progress reports to
+what it is doing.  During the data copy phase, it prints L<"--progress">
-STDERR.  You can get additional information with the L<"--print"> option.
+reports to STDERR.  You can get additional information by specifying
+L<"--print">.
+
+If L<"--statistics"> is specified, a report of various internal event counts
+is printed at the end, like:
+
+   # Event  Count
+   # ====== =====
+   # INSERT     1
 
 =head1 OPTIONS
 
@@ -9975,6 +10387,11 @@ short form: -S; type: string
 
 Socket file to use for connection.
 
+=item --statistics
+
+Print statistics about internal counters.  This is useful to see how
+many warnings were suppressed compared to the number of INSERT.
+
 =item --[no]swap-tables
 
 default: yes

t/pt-online-schema-change/basics.t

@@ -32,9 +32,6 @@ if ( !$master_dbh ) {
 elsif ( !$slave_dbh ) {
    plan skip_all => 'Cannot connect to sandbox slave';
 }
-else {
-   plan tests => 119;
-}
 
 my $q      = new Quoter();
 my $tp     = new TableParser(Quoter => $q);
@@ -634,10 +631,38 @@ test_alter_table(
                   qw(--no-drop-new-table)],
 );
 
+# #############################################################################
+# --statistics
+# #############################################################################
+
+$sb->load_file('master', "$sample/bug_1045317.sql");
+
+ok(
+   no_diff(
+      sub { pt_online_schema_change::main(@args, "$dsn,D=bug_1045317,t=bits",
+         '--dry-run', '--statistics',
+         '--alter', "modify column val ENUM('M','E','H') NOT NULL")
+      },
+      "$sample/stats-dry-run.txt",
+   ),
+   "--statistics --dry-run"
+);
+
+ok(
+   no_diff(
+      sub { pt_online_schema_change::main(@args, "$dsn,D=bug_1045317,t=bits",
+         '--execute', '--statistics',
+         '--alter', "modify column val ENUM('M','E','H') NOT NULL")
+      },
+      "$sample/stats-execute.txt",
+   ),
+   "--statistics --execute"
+);
+
 # #############################################################################
 # Done.
 # #############################################################################
 $master_dbh->do("UPDATE mysql.proc SET created='2012-06-05 00:00:00', modified='2012-06-05 00:00:00'");
 $sb->wipe_clean($master_dbh);
 ok($sb->ok(), "Sandbox servers") or BAIL_OUT(__FILE__ . " broke the sandbox");
-exit;
+done_testing;

t/pt-online-schema-change/option_sanity.t

@@ -51,6 +51,12 @@ like(
    "--execute FALSE by default"
 );
 
+like(
+   $output,
+   qr/--statistics\s+FALSE/,
+   "--statistics is FALSE by default"
+);
+
 $output = `$cmd h=127.1,P=12345,u=msandbox,p=msandbox --alter-foreign-keys-method drop_swap --no-drop-new-table`;
 like(
    $output,

t/pt-online-schema-change/samples/bug_1045317.sql

@@ -0,0 +1,10 @@
+DROP DATABASE IF EXISTS bug_1045317;
+CREATE DATABASE bug_1045317;
+USE bug_1045317;
+CREATE TABLE `bits` (
+   `id` int,
+   `val` ENUM('M','E','H') NOT NULL,
+   PRIMARY KEY (`id`)
+);
+
+INSERT INTO `bits` VALUES (1, 'M'), (2, 'E'), (3, 'H');

t/pt-online-schema-change/samples/stats-dry-run.txt

@@ -0,0 +1,16 @@
+Starting a dry run.  `bug_1045317`.`bits` will not be altered.  Specify --execute instead of --dry-run to alter the table.
+Not dropping triggers because this is a dry run.
+Dropping new table...
+Dropped new table OK.
+Dry run complete.  `bug_1045317`.`bits` was not altered.
+Creating new table...
+Created new table bug_1045317._bits_new OK.
+Altering new table...
+Altered `bug_1045317`.`_bits_new` OK.
+Not creating triggers because this is a dry run.
+Not copying rows because this is a dry run.
+Not swapping tables because this is a dry run.
+Not dropping old table because this is a dry run.
+# Event  Count
+# ====== =====
+# INSERT     0

t/pt-online-schema-change/samples/stats-execute.txt

@@ -0,0 +1,19 @@
+Altering `bug_1045317`.`bits`...
+Dropping triggers...
+Dropped triggers OK.
+Successfully altered `bug_1045317`.`bits`.
+Creating new table...
+Created new table bug_1045317._bits_new OK.
+Altering new table...
+Altered `bug_1045317`.`_bits_new` OK.
+Creating triggers...
+Created triggers OK.
+Copying approximately 3 rows...
+Copied rows OK.
+Swapping tables...
+Swapped original and new tables OK.
+Dropping old table...
+Dropped old table `bug_1045317`.`_bits_old` OK.
+# Event  Count
+# ====== =====
+# INSERT     1