pt-online-schema-change 2.1.1 doesn't choose the PRIMARY KEY

Hi
 I am using pt-online-schema-change 2.1.1 to alter a table
Create Table: CREATE TABLE `CityPopularity` (
  `ufi` int(11) NOT NULL,
  `guest_language` char(2) NOT NULL,
  `guest_country` char(2) NOT NULL,
  `score` int(10) unsigned NOT NULL,
  PRIMARY KEY (`ufi`,`guest_language`,`guest_country`),
  KEY `guest_language` (`guest_language`,`guest_country`,`score`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

Here is the complete output:

[root@server-03 app]# PTDEBUG=1 pt-online-schema-change --alter "add guy char(2)" --execute D=app,t=CityPopularity
# /usr/bin/perl 5.008008
# Linux server-03 2.6.18-238.el5 #1 SMP Thu Jan 13 15:51:15 EST 2011 x86_64 x86_64 x86_64 GNU/Linux
# Arguments: _[--alter]_ _[add guy char(2)]_ _[--execute]_ _[D=app,t=CityPopularity]_
# OptionParser:190 14514 Option rule: --dry-run and --execute are mutually exclusive.
# OptionParser:190 14514 Option rule: This tool accepts additional command-line arguments. Refer to the SYNOPSIS and usage information for details.
# OptionParser:199 14514 =item --alter
# OptionParser:226 14514 Short help: The schema modification, without the ALTER TABLE keywords
# OptionParser:199 14514 =item --alter-foreign-keys-method
# OptionParser:226 14514 Short help: How to modify foreign keys so they reference the new table
# OptionParser:199 14514 =item --ask-pass
# OptionParser:218 14514 Option has no attributes
# OptionParser:226 14514 Short help: Prompt for a password when connecting to MySQL
# OptionParser:199 14514 =item --charset
# OptionParser:226 14514 Short help: Default character set
# OptionParser:199 14514 =item --check-interval
# OptionParser:226 14514 Short help: Sleep time between checks for --max-lag
# OptionParser:199 14514 =item --[no]check-replication-filters
# OptionParser:226 14514 Short help: Abort if any replication filter is set on any server
# OptionParser:199 14514 =item --check-slave-lag
# OptionParser:226 14514 Short help: Pause the data copy until this replica's lag is less than --max-lag
# OptionParser:199 14514 =item --chunk-index
# OptionParser:226 14514 Short help: Prefer this index for chunking tables
# OptionParser:199 14514 =item --chunk-size
# OptionParser:226 14514 Short help: Number of rows to select for each chunk copied
# OptionParser:199 14514 =item --chunk-size-limit
# OptionParser:226 14514 Short help: Do not copy chunks this much larger than the desired chunk size
# OptionParser:199 14514 =item --chunk-time
# OptionParser:226 14514 Short help: Adjust the chunk size dynamically so each data-copy query takes this long to execute
# OptionParser:199 14514 =item --config
# OptionParser:226 14514 Short help: Read this comma-separated list of config files; if specified, this must be the first option on the command line
# OptionParser:199 14514 =item --critical-load
# OptionParser:226 14514 Short help: Examine SHOW GLOBAL STATUS after every chunk, and abort if the load is too high
# OptionParser:199 14514 =item --defaults-file
# OptionParser:226 14514 Short help: Only read mysql options from the given file
# OptionParser:199 14514 =item --[no]drop-old-table
# OptionParser:226 14514 Short help: Drop the original table after renaming it
# OptionParser:199 14514 =item --dry-run
# OptionParser:218 14514 Option has no attributes
# OptionParser:226 14514 Short help: Create and alter the new table, but do not create triggers, copy data, or replace the original table
# OptionParser:199 14514 =item --execute
# OptionParser:218 14514 Option has no attributes
# OptionParser:226 14514 Short help: Indicate that you have read the documentation and want to alter the table
# OptionParser:199 14514 =item --help
# OptionParser:218 14514 Option has no attributes
# OptionParser:226 14514 Short help: Show help and exit
# OptionParser:199 14514 =item --host
# OptionParser:226 14514 Short help: Connect to host
# OptionParser:199 14514 =item --lock-wait-timeout
# OptionParser:226 14514 Short help: Set the session value of innodb_lock_wait_timeout
# OptionParser:199 14514 =item --max-lag
# OptionParser:226 14514 Short help: Pause the data copy until all replicas' lag is less than this value
# OptionParser:199 14514 =item --max-load
# OptionParser:226 14514 Short help: Examine SHOW GLOBAL STATUS after every chunk, and pause if any status variables are higher than their thresholds
# OptionParser:199 14514 =item --password
# OptionParser:226 14514 Short help: Password to use when connecting
# OptionParser:199 14514 =item --pid
# OptionParser:226 14514 Short help: Create the given PID file
# OptionParser:199 14514 =item --port
# OptionParser:226 14514 Short help: Port number to use for connection
# OptionParser:199 14514 =item --print
# OptionParser:218 14514 Option has no attributes
# OptionParser:226 14514 Short help: Print SQL statements to STDOUT
# OptionParser:199 14514 =item --progress
# OptionParser:226 14514 Short help: Print progress reports to STDERR while copying rows
# OptionParser:199 14514 =item --quiet
# OptionParser:226 14514 Short help: Do not print messages to STDOUT
# OptionParser:199 14514 =item --recurse
# OptionParser:226 14514 Short help: Number of levels to recurse in the hierarchy when discovering replicas
# OptionParser:199 14514 =item --recursion-method
# OptionParser:226 14514 Short help: Preferred recursion method for discovering replicas
# OptionParser:199 14514 =item --retries
# OptionParser:226 14514 Short help: Retry a chunk this many times when there is a nonfatal error
# OptionParser:199 14514 =item --set-vars
# OptionParser:226 14514 Short help: Set these MySQL variables
# OptionParser:199 14514 =item --socket
# OptionParser:226 14514 Short help: Socket file to use for connection
# OptionParser:199 14514 =item --[no]swap-tables
# OptionParser:226 14514 Short help: Swap the original table and the new, altered table
# OptionParser:199 14514 =item --user
# OptionParser:226 14514 Short help: User for login if not current user
# OptionParser:199 14514 =item --version
# OptionParser:218 14514 Option has no attributes
# OptionParser:226 14514 Short help: Show version and exit
# OptionParser:265 14514 Parsing opt spec: group => default spec => alter=s desc => The schema modification, without the ALTER TABLE keywords
# OptionParser:303 14514 alter type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => alter-foreign-keys-method=s desc => How to modify foreign keys so they reference the new table
# OptionParser:303 14514 alter-foreign-keys-method type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => ask-pass desc => Prompt for a password when connecting to MySQL
# OptionParser:303 14514 ask-pass type: undef
# OptionParser:265 14514 Parsing opt spec: group => default spec => charset|A=s desc => Default character set
# OptionParser:303 14514 charset type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => check-interval=m desc => Sleep time between checks for --max-lag (default 1)
# OptionParser:303 14514 check-interval type: m
# OptionParser:310 14514 check-interval default: 1
# OptionParser:265 14514 Parsing opt spec: group => default spec => check-replication-filters! desc => Abort if any replication filter is set on any server (default yes)
# OptionParser:303 14514 check-replication-filters type: undef
# OptionParser:310 14514 check-replication-filters default: yes
# OptionParser:265 14514 Parsing opt spec: group => default spec => check-slave-lag=s desc => Pause the data copy until this replica's lag is less than --max-lag
# OptionParser:303 14514 check-slave-lag type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => chunk-index=s desc => Prefer this index for chunking tables
# OptionParser:303 14514 chunk-index type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => chunk-size=z desc => Number of rows to select for each chunk copied (default 1000)
# OptionParser:303 14514 chunk-size type: z
# OptionParser:310 14514 chunk-size default: 1000
# OptionParser:265 14514 Parsing opt spec: group => default spec => chunk-size-limit=f desc => Do not copy chunks this much larger than the desired chunk size (default 4.0)
# OptionParser:303 14514 chunk-size-limit type: f
# OptionParser:310 14514 chunk-size-limit default: 4.0
# OptionParser:265 14514 Parsing opt spec: group => default spec => chunk-time=f desc => Adjust the chunk size dynamically so each data-copy query takes this long to execute (default 0.5)
# OptionParser:303 14514 chunk-time type: f
# OptionParser:310 14514 chunk-time default: 0.5
# OptionParser:265 14514 Parsing opt spec: group => default spec => config=A desc => Read this comma-separated list of config files; if specified, this must be the first option on the command line
# OptionParser:303 14514 config type: A
# OptionParser:265 14514 Parsing opt spec: group => default spec => critical-load=A desc => Examine SHOW GLOBAL STATUS after every chunk, and abort if the load is too high (default Threads_running=50)
# OptionParser:303 14514 critical-load type: A
# OptionParser:310 14514 critical-load default: Threads_running=50
# OptionParser:265 14514 Parsing opt spec: group => default spec => defaults-file|F=s desc => Only read mysql options from the given file
# OptionParser:303 14514 defaults-file type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => drop-old-table! desc => Drop the original table after renaming it (default yes)
# OptionParser:303 14514 drop-old-table type: undef
# OptionParser:310 14514 drop-old-table default: yes
# OptionParser:265 14514 Parsing opt spec: group => default spec => dry-run desc => Create and alter the new table, but do not create triggers, copy data, or replace the original table
# OptionParser:303 14514 dry-run type: undef
# OptionParser:265 14514 Parsing opt spec: group => default spec => execute desc => Indicate that you have read the documentation and want to alter the table
# OptionParser:303 14514 execute type: undef
# OptionParser:265 14514 Parsing opt spec: group => default spec => help desc => Show help and exit
# OptionParser:303 14514 help type: undef
# OptionParser:265 14514 Parsing opt spec: group => default spec => host|h=s desc => Connect to host
# OptionParser:303 14514 host type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => lock-wait-timeout=i desc => Set the session value of innodb_lock_wait_timeout (default 1)
# OptionParser:303 14514 lock-wait-timeout type: i
# OptionParser:310 14514 lock-wait-timeout default: 1
# OptionParser:265 14514 Parsing opt spec: group => default spec => max-lag=m desc => Pause the data copy until all replicas' lag is less than this value (default 1s)
# OptionParser:303 14514 max-lag type: m
# OptionParser:310 14514 max-lag default: 1s
# OptionParser:265 14514 Parsing opt spec: group => default spec => max-load=A desc => Examine SHOW GLOBAL STATUS after every chunk, and pause if any status variables are higher than their thresholds (default Threads_running=25)
# OptionParser:303 14514 max-load type: A
# OptionParser:310 14514 max-load default: Threads_running=25
# OptionParser:265 14514 Parsing opt spec: group => default spec => password|p=s desc => Password to use when connecting
# OptionParser:303 14514 password type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => pid=s desc => Create the given PID file
# OptionParser:303 14514 pid type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => port|P=i desc => Port number to use for connection
# OptionParser:303 14514 port type: i
# OptionParser:265 14514 Parsing opt spec: group => default spec => print desc => Print SQL statements to STDOUT
# OptionParser:303 14514 print type: undef
# OptionParser:265 14514 Parsing opt spec: group => default spec => progress=a desc => Print progress reports to STDERR while copying rows (default time,30)
# OptionParser:303 14514 progress type: a
# OptionParser:310 14514 progress default: time,30
# OptionParser:265 14514 Parsing opt spec: group => default spec => quiet|q desc => Do not print messages to STDOUT
# OptionParser:303 14514 quiet type: undef
# OptionParser:265 14514 Parsing opt spec: group => default spec => recurse=i desc => Number of levels to recurse in the hierarchy when discovering replicas
# OptionParser:303 14514 recurse type: i
# OptionParser:265 14514 Parsing opt spec: group => default spec => recursion-method=s desc => Preferred recursion method for discovering replicas
# OptionParser:303 14514 recursion-method type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => retries=i desc => Retry a chunk this many times when there is a nonfatal error (default 3)
# OptionParser:303 14514 retries type: i
# OptionParser:310 14514 retries default: 3
# OptionParser:265 14514 Parsing opt spec: group => default spec => set-vars=s desc => Set these MySQL variables (default wait_timeout=10000)
# OptionParser:303 14514 set-vars type: s
# OptionParser:310 14514 set-vars default: wait_timeout=10000
# OptionParser:265 14514 Parsing opt spec: group => default spec => socket|S=s desc => Socket file to use for connection
# OptionParser:303 14514 socket type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => swap-tables! desc => Swap the original table and the new, altered table (default yes)
# OptionParser:303 14514 swap-tables type: undef
# OptionParser:310 14514 swap-tables default: yes
# OptionParser:265 14514 Parsing opt spec: group => default spec => user|u=s desc => User for login if not current user
# OptionParser:303 14514 user type: s
# OptionParser:265 14514 Parsing opt spec: group => default spec => version desc => Show version and exit
# OptionParser:303 14514 version type: undef
# OptionParser:325 14514 Parsing rule: --dry-run and --execute are mutually exclusive.
# OptionParser:381 14514 Participants for --dry-run and --execute are mutually exclusive. : dry-run execute
# OptionParser:333 14514 dry-run execute are mutually exclusive
# OptionParser:325 14514 Parsing rule: This tool accepts additional command-line arguments. Refer to the SYNOPSIS and usage information for details.
# OptionParser:381 14514 Participants for This tool accepts additional command-line arguments. Refer to the SYNOPSIS and usage information for details. :
# OptionParser:357 14514 Strict mode disabled by rule
# OptionParser:109 14514 Parsing DSN OPTIONS
# OptionParser:199 14514 =item * A
# OptionParser:226 14514 Short help: Default character set
# OptionParser:199 14514 =item * D
# OptionParser:226 14514 Short help: Database for the old and new table
# OptionParser:199 14514 =item * F
# OptionParser:226 14514 Short help: Only read default options from the given file
# OptionParser:199 14514 =item * h
# OptionParser:226 14514 Short help: Connect to host
# OptionParser:199 14514 =item * p
# OptionParser:226 14514 Short help: Password to use when connecting
# OptionParser:199 14514 =item * P
# OptionParser:226 14514 Short help: Port number to use for connection
# OptionParser:199 14514 =item * S
# OptionParser:226 14514 Short help: Socket file to use for connection
# OptionParser:199 14514 =item * t
# OptionParser:226 14514 Short help: Table to alter
# OptionParser:199 14514 =item * u
# OptionParser:226 14514 Short help: User for login if not current user
# DSNParser:1158 14514 DSN option: copy=1, dsn=charset, desc=Default character set, key=A
# DSNParser:1158 14514 DSN option: copy=1, dsn=database, desc=Database for the old and new table, key=D
# DSNParser:1158 14514 DSN option: copy=1, dsn=mysql_read_default_file, desc=Only read default options from the given file, key=F
# DSNParser:1158 14514 DSN option: copy=1, dsn=host, desc=Connect to host, key=h
# DSNParser:1158 14514 DSN option: copy=1, dsn=password, desc=Password to use when connecting, key=p
# DSNParser:1158 14514 DSN option: copy=1, dsn=port, desc=Port number to use for connection, key=P
# DSNParser:1158 14514 DSN option: copy=1, dsn=mysql_socket, desc=Socket file to use for connection, key=S
# DSNParser:1158 14514 DSN option: copy=, dsn=table, desc=Table to alter, key=t
# DSNParser:1158 14514 DSN option: copy=1, dsn=user, desc=User for login if not current user, key=u
# OptionParser:153 14514 pt-online-schema-change 2.1.1
# OptionParser:465 14514 Cannot open /etc/percona-toolkit/percona-toolkit.conf: No such file or directory
#
# OptionParser:465 14514 Cannot open /etc/percona-toolkit/pt-online-schema-change.conf: No such file or directory
#
# OptionParser:465 14514 Cannot open /root/.percona-toolkit.conf: No such file or directory
#
# OptionParser:465 14514 Cannot open /root/.pt-online-schema-change.conf: No such file or directory
#
# OptionParser:433 14514 Got option alter = add guy char(2)
# OptionParser:433 14514 Got option execute = 1
# OptionParser:643 14514 Parsing option chunk-size as a size value
# OptionParser:653 14514 Nothing to validate for option recursion-method type s value undef
# OptionParser:653 14514 Nothing to validate for option check-slave-lag type s value undef
# OptionParser:653 14514 Nothing to validate for option chunk-index type s value undef
# OptionParser:653 14514 Nothing to validate for option password type s value undef
# OptionParser:653 14514 Nothing to validate for option pid type s value undef
# OptionParser:653 14514 Nothing to validate for option user type s value undef
# OptionParser:653 14514 Nothing to validate for option alter type s value add guy char(2)
# OptionParser:653 14514 Nothing to validate for option chunk-time type f value 0.5
# OptionParser:653 14514 Nothing to validate for option alter-foreign-keys-method type s value undef
# OptionParser:653 14514 Nothing to validate for option charset type s value undef
# OptionParser:653 14514 Nothing to validate for option set-vars type s value wait_timeout=10000
# OptionParser:653 14514 Nothing to validate for option port type i value undef
# OptionParser:653 14514 Nothing to validate for option socket type s value undef
# OptionParser:653 14514 Nothing to validate for option lock-wait-timeout type i value 1
# OptionParser:604 14514 Parsing option check-interval as a time value
# OptionParser:609 14514 No suffix given; using s for check-interval (value: 1 )
# OptionParser:618 14514 Setting option check-interval to 1
# OptionParser:653 14514 Nothing to validate for option recurse type i value undef
# OptionParser:604 14514 Parsing option max-lag as a time value
# OptionParser:618 14514 Setting option max-lag to 1
# OptionParser:653 14514 Nothing to validate for option retries type i value 3
# OptionParser:653 14514 Nothing to validate for option chunk-size-limit type f value 4.0
# OptionParser:653 14514 Nothing to validate for option defaults-file type s value undef
# OptionParser:653 14514 Nothing to validate for option host type s value undef
# DSNParser:1174 14514 Setting set-vars property
# DSNParser:1245 14514 DSN string made from options:
# DSNParser:1183 14514 No DSN to parse
# DSNParser:1186 14514 Parsing D=app,t=CityPopularity
# DSNParser:1204 14514 Finding value for S
# DSNParser:1214 14514 Copying value for S from defaults
# DSNParser:1204 14514 Finding value for F
# DSNParser:1214 14514 Copying value for F from defaults
# DSNParser:1204 14514 Finding value for A
# DSNParser:1214 14514 Copying value for A from defaults
# DSNParser:1204 14514 Finding value for P
# DSNParser:1214 14514 Copying value for P from defaults
# DSNParser:1204 14514 Finding value for p
# DSNParser:1214 14514 Copying value for p from defaults
# DSNParser:1204 14514 Finding value for u
# DSNParser:1214 14514 Copying value for u from defaults
# DSNParser:1204 14514 Finding value for h
# DSNParser:1214 14514 Copying value for h from defaults
# DSNParser:1204 14514 Finding value for D
# DSNParser:1204 14514 Finding value for t
# OptionParser:727 14514 Getting description and usage from SYNOPSIS in /usr/bin/pt-online-schema-change
# OptionParser:980 14514 Parsing SYNOPSIS in /usr/bin/pt-online-schema-change
# OptionParser:993 14514 Raw SYNOPSIS text: Usage: pt-online-schema-change [OPTIONS] DSN
#
# pt-online-schema-change alters a table's structure without blocking reads or
# writes. Specify the database and table in the DSN. Do not use this tool before
# reading its documentation and checking your backups carefully.
#
#
# OptionParser:731 14514 Description: pt-online-schema-change alters a table's structure without blocking reads or writes. Specify the database and table in the DSN. Do not use this tool before reading its documentation and checking your backups carefully.
# Usage: pt-online-schema-change [OPTIONS] DSN
# DSNParser:1245 14514 DSN string made from options:
# DSNParser:1183 14514 No DSN to parse
# DSNParser:1297 14514 DBI:mysql:app;;mysql_read_default_group=client
# DSNParser:1343 14514 DBI:mysql:app;;mysql_read_default_group=client undef undef mysql_enable_utf8=>0, ShowErrorStatement=>1, AutoCommit=>1, RaiseError=>1, PrintError=>0
# DSNParser:1352 14514 DBI::db=HASH(0x1b1af0b0) SELECT @@SQL_MODE
# DSNParser:1359 14514 DBI::db=HASH(0x1b1af0b0) SET @@SQL_QUOTE_SHOW_CREATE = 1/*!40101, @@SQL_MODE='NO_AUTO_VALUE_ON_ZERO,NO_AUTO_VALUE_ON_ZERO,STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION'*/
# DSNParser:1378 14514 DBI::db=HASH(0x1b1af0b0) : SET wait_timeout=10000
# DSNParser:1404 14514 DBH info: DBI::db=HASH(0x1b1af0b0) $VAR1 = {
# '@@hostname' => 'server',
# 'CONNECTION_ID()' => '24807',
# 'DATABASE()' => 'app',
# 'VERSION()' => '5.5.16-log'
# };
# Connection info: Localhost via UNIX socket Character set info: $VAR1 = [
# {
# Value => 'latin1',
# Variable_name => 'character_set_client'
# },
# {
# Value => 'latin1',
# Variable_name => 'character_set_connection'
# },
# {
# Value => 'utf8',
# Variable_name => 'character_set_database'
# },
# {
# Value => 'binary',
# Variable_name => 'character_set_filesystem'
# },
# {
# Value => 'latin1',
# Variable_name => 'character_set_results'
# },
# {
# Value => 'utf8',
# Variable_name => 'character_set_server'
# },
# {
# Value => 'utf8',
# Variable_name => 'character_set_system'
# },
# {
# Value => '/usr/share/mysql/charsets/',
# Variable_name => 'character_sets_dir'
# }
# ];
# $DBD::mysql::VERSION: 4.010 $DBI::VERSION: 1.609
# Cxn:2766 14514 DBI::db=HASH(0x1b1af0b0) Connected dbh to undef
# Cxn:2779 14514 DBI::db=HASH(0x1b1af0b0) Setting dbh
# Cxn:2784 14514 DBI::db=HASH(0x1b1af0b0) SELECT @@hostname, @@server_id
# Cxn:2786 14514 DBI::db=HASH(0x1b1af0b0) hostname: server 149207190
# pt_online_schema_change:5004 14514 SET SESSION innodb_lock_wait_timeout=1
# VersionParser:1060 14514 5.5.16-log parses to 005005016
# VersionParser:1060 14514 5.0.10 parses to 005000010
# VersionParser:1071 14514 005005016 ge 5.0.10 : 1
# MasterSlave:2874 14514 Slave recursion method: undef
# MasterSlave:2922 14514 Connected to D=app,t=CityPopularity
# MasterSlave:2931 14514 SELECT @@SERVER_ID
# MasterSlave:2933 14514 Working on server ID 149207190
# MasterSlave:2977 14514 Looking for slaves on D=app,t=CityPopularity using methods processlist hosts
# MasterSlave:2984 14514 Finding slaves with _find_slaves_by_processlist
# MasterSlave:3051 14514 DBI::db=HASH(0x1b1af0b0) SHOW GRANTS FOR CURRENT_USER()
# MasterSlave:3081 14514 DBI::db=HASH(0x1b1af0b0) SHOW PROCESSLIST
# MasterSlave:2984 14514 Finding slaves with _find_slaves_by_hosts
# MasterSlave:3018 14514 DBI::db=HASH(0x1b1af0b0) SHOW SLAVE HOSTS
# MasterSlave:2989 14514 Found 0 slaves
# pt_online_schema_change:5087 14514 0 slaves found
# pt_online_schema_change:5098 14514 Will check slave lag on all slaves
# pt_online_schema_change:5106 14514 Checking slave replication filters
# MySQLStatusWaiter:3692 14514 Parsing spec for max thresholds
# MySQLStatusWaiter:3737 14514 Wait if Threads_running >= 25
# MySQLStatusWaiter:3699 14514 Parsing spec for critical thresholds
# MySQLStatusWaiter:3737 14514 Wait if Threads_running >= 50
# TableParser:2261 14514 Checking `app`.`CityPopularity`
# TableParser:2265 14514 SHOW TABLES FROM `app` LIKE 'CityPopularity'
# TableParser:2279 14514 Table exists; no privs to check
# pt_online_schema_change:6150 14514 SHOW TRIGGERS FROM `app` LIKE 'CityPopularity'
# TableParser:2090 14514 /*!40101 SET @OLD_SQL_MODE := @@SQL_MODE, @@SQL_MODE := REPLACE(REPLACE(@@SQL_MODE, 'ANSI_QUOTES', ''), ',,', ','), @OLD_QUOTE := @@SQL_QUOTE_SHOW_CREATE, @@SQL_QUOTE_SHOW_CREATE := 1 */
# TableParser:2095 14514 DBI::db=HASH(0x1b1af0b0) USE `app`
# TableParser:2099 14514 SHOW CREATE TABLE `app`.`CityPopularity`
# TableParser:2111 14514 /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
# TableParser:2320 14514 Storage engine: InnoDB
# TableParser:2141 14514 Table cols: `ufi`, `guest_language`, `guest_country`, `score`
# TableParser:2320 14514 Storage engine: InnoDB
# TableParser:2336 14514 Parsed key: PRIMARY KEY (`ufi`,`guest_language`,`guest_country`),
# TableParser:2362 14514 PRIMARY key cols: `ufi`, `guest_language`, `guest_country`
# TableParser:2384 14514 This key is the clustered key
# TableParser:2336 14514 Parsed key: KEY `guest_language` (`guest_language`,`guest_country`,`score`)
# TableParser:2362 14514 guest_language key cols: `guest_language`, `guest_country`, `score`
# NibbleIterator:4392 14514 EXPLAIN SELECT * FROM `app`.`CityPopularity` WHERE 1=1
# NibbleIterator:4394 14514 $VAR1 = {
# extra => 'Using index',
# id => '1',
# key => 'guest_language',
# key_len => '8',
# possible_keys => undef,
# ref => undef,
# rows => '24947869',
# select_type => 'SIMPLE',
# table => 'CityPopularity',
# type => 'index'
# };
#
# NibbleIterator:4269 14514 One nibble: no
# NibbleIterator:4307 14514 MySQL wants to use index guest_language
# NibbleIterator:4319 14514 Wanted index is a possible index
# NibbleIterator:4337 14514 No PRIMARY or unique indexes; will use index with highest cardinality
# NibbleIterator:4368 14514 SHOW INDEXES FROM `app`.`CityPopularity` WHERE Key_name = 'guest_language'
# NibbleIterator:4378 14514 Index guest_language cardinality: 125366
# NibbleIterator:4357 14514 Best index: guest_language
# TableParser:2202 14514 Indexes sorted best-first: PRIMARY, guest_language
# pt_online_schema_change:6187 14514 Delete trigger index: $VAR1 = 'PRIMARY';
#
# pt_online_schema_change:6208 14514 Finding child tables
# pt_online_schema_change:6214 14514 SELECT table_schema, table_name FROM information_schema.key_column_usage WHERE constraint_schema='app' AND referenced_table_name='CityPopularity'
# pt_online_schema_change:6217 14514 No child tables found
Altering `app`.`CityPopularity`...
# CleanupTask:4856 14514 Created cleanup task CODE(0x1b68ebe0)
# TableParser:2090 14514 /*!40101 SET @OLD_SQL_MODE := @@SQL_MODE, @@SQL_MODE := REPLACE(REPLACE(@@SQL_MODE, 'ANSI_QUOTES', ''), ',,', ','), @OLD_QUOTE := @@SQL_QUOTE_SHOW_CREATE, @@SQL_QUOTE_SHOW_CREATE := 1 */
# TableParser:2095 14514 DBI::db=HASH(0x1b1af0b0) USE `app`
# TableParser:2099 14514 SHOW CREATE TABLE `app`.`CityPopularity`
# TableParser:2111 14514 /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
Creating new table...
# pt_online_schema_change:6032 14514 CREATE TABLE `app`.`_CityPopularity_new` (
# `ufi` int(11) NOT NULL,
# `guest_language` char(2) NOT NULL,
# `guest_country` char(2) NOT NULL,
# `score` int(10) unsigned NOT NULL,
# PRIMARY KEY (`ufi`,`guest_language`,`guest_country`),
# KEY `guest_language` (`guest_language`,`guest_country`,`score`)
# ) ENGINE=InnoDB DEFAULT CHARSET=latin1
# pt_online_schema_change:6032 14514 CREATE TABLE `app`.`__CityPopularity_new` (
# `ufi` int(11) NOT NULL,
# `guest_language` char(2) NOT NULL,
# `guest_country` char(2) NOT NULL,
# `score` int(10) unsigned NOT NULL,
# PRIMARY KEY (`ufi`,`guest_language`,`guest_country`),
# KEY `guest_language` (`guest_language`,`guest_country`,`score`)
# ) ENGINE=InnoDB DEFAULT CHARSET=latin1
# pt_online_schema_change:6032 14514 CREATE TABLE `app`.`___CityPopularity_new` (
# `ufi` int(11) NOT NULL,
# `guest_language` char(2) NOT NULL,
# `guest_country` char(2) NOT NULL,
# `score` int(10) unsigned NOT NULL,
# PRIMARY KEY (`ufi`,`guest_language`,`guest_country`),
# KEY `guest_language` (`guest_language`,`guest_country`,`score`)
# ) ENGINE=InnoDB DEFAULT CHARSET=latin1
Created new table app.___CityPopularity_new OK.
Altering new table...
# pt_online_schema_change:5436 14514 ALTER TABLE `app`.`___CityPopularity_new` add guy char(2)
Altered `app`.`___CityPopularity_new` OK.
# TableParser:2090 14514 /*!40101 SET @OLD_SQL_MODE := @@SQL_MODE, @@SQL_MODE := REPLACE(REPLACE(@@SQL_MODE, 'ANSI_QUOTES', ''), ',,', ','), @OLD_QUOTE := @@SQL_QUOTE_SHOW_CREATE, @@SQL_QUOTE_SHOW_CREATE := 1 */
# TableParser:2095 14514 DBI::db=HASH(0x1b1af0b0) USE `app`
# TableParser:2099 14514 SHOW CREATE TABLE `app`.`___CityPopularity_new`
# TableParser:2111 14514 /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */
# TableParser:2320 14514 Storage engine: InnoDB
# TableParser:2141 14514 Table cols: `ufi`, `guest_language`, `guest_country`, `score`, `guy`
# TableParser:2320 14514 Storage engine: InnoDB
# TableParser:2336 14514 Parsed key: PRIMARY KEY (`ufi`,`guest_language`,`guest_country`),
# TableParser:2362 14514 PRIMARY key cols: `ufi`, `guest_language`, `guest_country`
# TableParser:2384 14514 This key is the clustered key
# TableParser:2336 14514 Parsed key: KEY `guest_language` (`guest_language`,`guest_country`,`score`)
# TableParser:2362 14514 guest_language key cols: `guest_language`, `guest_country`, `score`
# pt_online_schema_change:5471 14514 Common columns ufi guest_language guest_country score
Creating triggers...
# pt_online_schema_change:6476 14514 CREATE TRIGGER `pt_osc_app_CityPopularity_del` AFTER DELETE ON `app`.`CityPopularity` FOR EACH ROW DELETE IGNORE FROM `app`.`___CityPopularity_new` WHERE `app`.`___CityPopularity_new`.`ufi` <=> OLD.`ufi` AND `app`.`___CityPopularity_new`.`guest_language` <=> OLD.`guest_language` AND `app`.`___CityPopularity_new`.`guest_country` <=> OLD.`guest_country`
# pt_online_schema_change:6476 14514 CREATE TRIGGER `pt_osc_app_CityPopularity_upd` AFTER UPDATE ON `app`.`CityPopularity` FOR EACH ROW REPLACE INTO `app`.`___CityPopularity_new` (`ufi`, `guest_language`, `guest_country`, `score`) VALUES (NEW.`ufi`, NEW.`guest_language`, NEW.`guest_country`, NEW.`score`)
# pt_online_schema_change:6476 14514 CREATE TRIGGER `pt_osc_app_CityPopularity_ins` AFTER INSERT ON `app`.`CityPopularity` FOR EACH ROW REPLACE INTO `app`.`___CityPopularity_new` (`ufi`, `guest_language`, `guest_country`, `score`) VALUES (NEW.`ufi`, NEW.`guest_language`, NEW.`guest_country`, NEW.`score`)
Created triggers OK.
# NibbleIterator:4392 14514 EXPLAIN SELECT * FROM `app`.`CityPopularity` WHERE 1=1
# NibbleIterator:4394 14514 $VAR1 = {
# extra => 'Using index',
# id => '1',
# key => 'guest_language',
# key_len => '8',
# possible_keys => undef,
# ref => undef,
# rows => '24947869',
# select_type => 'SIMPLE',
# table => 'CityPopularity',
# type => 'index'
# };
#
# NibbleIterator:4269 14514 One nibble: no
# NibbleIterator:4307 14514 MySQL wants to use index guest_language
# NibbleIterator:4319 14514 Wanted index is a possible index
# NibbleIterator:4337 14514 No PRIMARY or unique indexes; will use index with highest cardinality
# NibbleIterator:4368 14514 SHOW INDEXES FROM `app`.`CityPopularity` WHERE Key_name = 'guest_language'
# NibbleIterator:4378 14514 Index guest_language cardinality: 125366
# NibbleIterator:4357 14514 Best index: guest_language
# TableNibbler:1824 14514 Will ascend index guest_language
# TableNibbler:1831 14514 Will ascend columns guest_language, guest_country, score
# TableNibbler:1842 14514 Will ascend, in ordinal position: 1, 2, 3
# NibbleIterator:3990 14514 Ascend params: $VAR1 = {
# boundaries => {
# '<' => '((`guest_language` < ?) OR (`guest_language` = ? AND `guest_country` < ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` < ?))',
# '<=' => '((`guest_language` < ?) OR (`guest_language` = ? AND `guest_country` < ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` <= ?))',
# '>' => '((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` > ?))',
# '>=' => '((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?))'
# },
# cols => [
# 'ufi',
# 'guest_language',
# 'guest_country',
# 'score'
# ],
# index => 'guest_language',
# scols => [
# 'guest_language',
# 'guest_language',
# 'guest_country',
# 'guest_language',
# 'guest_country',
# 'score'
# ],
# slice => [
# 1,
# 1,
# 2,
# 1,
# 2,
# 3
# ],
# where => '((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` > ?))'
# };
#
# NibbleIterator:4003 14514 First lower boundary statement: SELECT /*!40001 SQL_NO_CACHE */ `guest_language`, `guest_language`, `guest_country`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) ORDER BY `guest_language`, `guest_country`, `score` LIMIT 1 /*first lower boundary*/
# NibbleIterator:4028 14514 Last upper boundary statement: SELECT /*!40001 SQL_NO_CACHE */ `guest_language`, `guest_language`, `guest_country`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) ORDER BY `guest_language` DESC, `guest_country` DESC, `score` DESC LIMIT 1 /*last upper boundary*/
# NibbleIterator:4039 14514 Upper boundary statement: SELECT /*!40001 SQL_NO_CACHE */ `guest_language`, `guest_language`, `guest_country`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) WHERE ((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?)) ORDER BY `guest_language`, `guest_country`, `score` LIMIT ?, 2 /*next chunk boundary*/
# NibbleIterator:4051 14514 Nibble statement: INSERT LOW_PRIORITY IGNORE INTO `app`.`___CityPopularity_new` (`ufi`, `guest_language`, `guest_country`, `score`) SELECT `ufi`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) WHERE ((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?)) AND ((`guest_language` < ?) OR (`guest_language` = ? AND `guest_country` < ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` <= ?)) /*pt-online-schema-change 14514 copy nibble*/
# NibbleIterator:4063 14514 Explain nibble statement: EXPLAIN SELECT `ufi`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) WHERE ((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?)) AND ((`guest_language` < ?) OR (`guest_language` = ? AND `guest_country` < ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` <= ?)) /*explain pt-online-schema-change 14514 copy nibble*/
# NibbleIterator:4066 14514 Initial chunk size (LIMIT): 999
# NibbleIterator:4400 14514 Preparing statement handles
# NibbleIterator:4428 14514 First lower boundary: $VAR1 = [
# 'ar',
# 'ar',
# 'ae',
# 'ar',
# 'ae',
# '7'
# ];
#
# NibbleIterator:4444 14514 Next lower boundary: $VAR1 = [
# 'ar',
# 'ar',
# 'ae',
# 'ar',
# 'ae',
# '7'
# ];
#
Copying approximately 24947869 rows...
# NibbleIterator:4117 14514 init callback returned 1
# pt_online_schema_change:6700 14514 EXPLAIN SELECT /*!40001 SQL_NO_CACHE */ `guest_language`, `guest_language`, `guest_country`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) WHERE ((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?)) ORDER BY `guest_language`, `guest_country`, `score` LIMIT ?, 2 /*next chunk boundary*/ params: ar ar ae ar ae 7 1000
# pt_online_schema_change:6709 14514 EXPLAIN plan: $VAR1 = {
# extra => 'Using where; Using index',
# id => '1',
# key => 'guest_language',
# key_len => '8',
# possible_keys => 'guest_language',
# ref => undef,
# rows => '13715894',
# select_type => 'SIMPLE',
# table => 'CityPopularity',
# type => 'range'
# };
#
# NibbleIterator:4498 14514 next_boundaries callback returned 1
# NibbleIterator:4506 14514 SELECT /*!40001 SQL_NO_CACHE */ `guest_language`, `guest_language`, `guest_country`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) WHERE ((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?)) ORDER BY `guest_language`, `guest_country`, `score` LIMIT ?, 2 /*next chunk boundary*/ params: ar, ar, ae, ar, ae, 7 999
# NibbleIterator:4509 14514 Next boundary: $VAR1 = [
# [
# 'ar',
# 'ar',
# 'ae',
# 'ar',
# 'ae',
# '7'
# ],
# [
# 'ar',
# 'ar',
# 'ae',
# 'ar',
# 'ae',
# '7'
# ]
# ];
#
# NibbleIterator:4130 14514 INSERT LOW_PRIORITY IGNORE INTO `app`.`___CityPopularity_new` (`ufi`, `guest_language`, `guest_country`, `score`) SELECT `ufi`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) WHERE ((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?)) AND ((`guest_language` < ?) OR (`guest_language` = ? AND `guest_country` < ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` <= ?)) /*pt-online-schema-change 14514 copy nibble*/ params: ar, ar, ae, ar, ae, 7, ar, ar, ae, ar, ae, 7
# pt_online_schema_change:6700 14514 EXPLAIN SELECT `ufi`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) WHERE ((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?)) AND ((`guest_language` < ?) OR (`guest_language` = ? AND `guest_country` < ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` <= ?)) /*explain pt-online-schema-change 14514 copy nibble*/ params: ar ar ae ar ae 7 ar ar ae ar ae 7
# pt_online_schema_change:6709 14514 EXPLAIN plan: $VAR1 = {
# extra => 'Using where; Using index',
# id => '1',
# key => 'guest_language',
# key_len => '8',
# possible_keys => 'guest_language',
# ref => undef,
# rows => '2853',
# select_type => 'SIMPLE',
# table => 'CityPopularity',
# type => 'range'
# };
#
# Retry:2659 14514 Try 1 of 3
# pt_online_schema_change:6589 14514 INSERT LOW_PRIORITY IGNORE INTO `app`.`___CityPopularity_new` (`ufi`, `guest_language`, `guest_country`, `score`) SELECT `ufi`, `guest_language`, `guest_country`, `score` FROM `app`.`CityPopularity` FORCE INDEX(`guest_language`) WHERE ((`guest_language` > ?) OR (`guest_language` = ? AND `guest_country` > ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` >= ?)) AND ((`guest_language` < ?) OR (`guest_language` = ? AND `guest_country` < ?) OR (`guest_language` = ? AND `guest_country` = ? AND `score` <= ?)) /*pt-online-schema-change 14514 copy nibble*/ lower boundary: ar ar ae ar ae 7 upper boundary: ar ar ae ar ae 7
# pt_online_schema_change:6606 14514 SHOW WARNINGS
# Retry:2676 14514 Try code succeeded
# pt_online_schema_change:5706 14514 Nibble time: 0.042794942855835
# NibbleIterator:4138 14514 0 rows in nibble 1
# NibbleIterator:4150 14514 No rows in nibble or nibble skipped
# pt_online_schema_change:5729 14514 Average copy rate (rows/s): 66690
# WeightedAvgRate:3867 14514 Master op time: 2854 n / 0.042794942855835 s
# WeightedAvgRate:3879 14514 Initial avg rate: 66690.1229337864 n/s
# WeightedAvgRate:3883 14514 Adjust n to 33345
# NibbleIterator:4233 14514 Set new chunk size (LIMIT): 33345
# ReplicaLagWaiter:3651 14514 All slaves caught up
# MySQLStatusWaiter:3784 14514 Checking status variables
# pt_online_schema_change:5185 14514 SHOW GLOBAL STATUS LIKE ? Threads_running
# MySQLStatusWaiter:3787 14514 Threads_running = 1
# MySQLStatusWaiter:3814 14514 All var vals are low enough
# NibbleIterator:4474 14514 Infinite loop detected
Error copying rows from `app`.`CityPopularity` to `app`.`___CityPopularity_new`: Possible infinite loop detected! The lower boundary for chunk 1 is <ar, ar, ae, ar, ae, 7> and the lower boundary for chunk 2 is also <ar, ar, ae, ar, ae, 7>. This usually happens when using a non-unique single column index. The current chunk index for table app.CityPopularity is guest_language which is not unique and covers 3 columns.

# NibbleIterator:4556 14514 Finish nibble_sth
# NibbleIterator:4556 14514 Finish ub_sth
# NibbleIterator:4556 14514 Finish explain_nibble_sth
# NibbleIterator:4556 14514 Finish explain_ub_sth
# CleanupTask:4863 14514 Calling cleanup task CODE(0x1b68ebe0)
# pt_online_schema_change:5482 14514 Clean up triggers
Dropping triggers...
# pt_online_schema_change:6516 14514 DROP TRIGGER IF EXISTS `app`.`pt_osc_app_CityPopularity_del`;
# pt_online_schema_change:6516 14514 DROP TRIGGER IF EXISTS `app`.`pt_osc_app_CityPopularity_upd`;
# pt_online_schema_change:6516 14514 DROP TRIGGER IF EXISTS `app`.`pt_osc_app_CityPopularity_ins`;
Dropped triggers OK.
Error cleaning up: Undefined subroutine &main::_ called at /usr/bin/pt-online-schema-change line 5390.

# pt_online_schema_change:5339 14514 Clean up done, report if orig table was altered
`app`.`CityPopularity` was not altered.
# Cxn:2819 14514 Disconnecting dbh DBI::db=HASH(0x1b1af0b0) undef