gh-ost: After copying is 100%: FATAL Timeout while waiting for events up to lock
Tried running a migration on master in RDS. Seemed to work fine until the cutover phase (I assume), when it looped over and over with “ERROR Timeout while waiting for events up to lock” until eventually it became FATAL.
Command:
./gh-ost --user="historical" --password="XXXXX" --host=XXXXX.rds.amazonaws.com --assume-rbr --hooks-path=hooks --database="historical" --table="raw_post_data" --verbose --alter="modify content longtext not null" --initially-drop-ghost-table --initially-drop-old-table --max-load=Threads_running=30 --chunk-size=500 --cut-over=default --allow-on-master --exact-rowcount --execute
First lines of output:
2017-01-26 12:25:13 INFO starting gh-ost 1.0.34
2017-01-26 12:25:13 INFO Migrating `historical`.`raw_post_data`
2017-01-26 12:25:14 INFO connection validated on XXXXX.rds.amazonaws.com:3306
2017-01-26 12:25:14 INFO User has REPLICATION CLIENT, REPLICATION SLAVE privileges, and has ALL privileges on `historical`.*
2017-01-26 12:25:14 INFO binary logs validated on XXXXX.rds.amazonaws.com:3306
2017-01-26 12:25:14 INFO Table found. Engine=InnoDB
2017-01-26 12:25:14 INFO Estimated number of rows via EXPLAIN: 344974
2017-01-26 12:25:14 INFO Recursively searching for replication master
2017-01-26 12:25:15 INFO Master found to be XXXXX
2017-01-26 12:25:15 INFO log_slave_updates validated on XXXXX.rds.amazonaws.com:3306
2017-01-26 12:25:15 INFO connection validated on XXXXX.rds.amazonaws.com:3306
2017-01-26 12:25:15 INFO Registering replica at XXXXX.rds.amazonaws.com:3306
2017-01-26 12:25:15 INFO Connecting binlog streamer at mysql-bin-changelog.134366:120
2017-01-26 12:25:15 INFO connection validated on XXXXX.rds.amazonaws.com:3306
2017-01-26 12:25:15 INFO rotate to next log name: mysql-bin-changelog.134366
2017-01-26 12:25:15 INFO connection validated on XXXXX.rds.amazonaws.com:3306
2017-01-26 12:25:15 INFO will use time_zone='UTC' on applier
2017-01-26 12:25:15 INFO Examining table structure on applier
2017-01-26 12:25:15 INFO Droppping table `historical`.`_raw_post_data_gho`
2017-01-26 12:25:15 INFO Table dropped
2017-01-26 12:25:15 INFO Droppping table `historical`.`_raw_post_data_del`
2017-01-26 12:25:15 INFO Table dropped
2017-01-26 12:25:15 INFO Droppping table `historical`.`_raw_post_data_ghc`
2017-01-26 12:25:15 INFO Table dropped
2017-01-26 12:25:15 INFO Creating changelog table `historical`.`_raw_post_data_ghc`
2017-01-26 12:25:15 INFO Changelog table created
2017-01-26 12:25:15 INFO Creating ghost table `historical`.`_raw_post_data_gho`
2017-01-26 12:25:16 INFO Ghost table created
2017-01-26 12:25:16 INFO Altering ghost table `historical`.`_raw_post_data_gho`
2017-01-26 12:25:16 INFO Ghost table altered
2017-01-26 12:25:16 INFO Intercepted changelog state GhostTableMigrated
2017-01-26 12:25:16 INFO Waiting for ghost table to be migrated. Current lag is 0s
2017-01-26 12:25:16 INFO Handled changelog state GhostTableMigrated
2017-01-26 12:25:16 INFO Chosen shared unique key is PRIMARY
2017-01-26 12:25:16 INFO Shared columns are id,content,created_at,updated_at,headers
2017-01-26 12:25:16 INFO Listening on unix socket file: /tmp/gh-ost.historical.raw_post_data.sock
2017-01-26 12:25:16 INFO As instructed, counting rows in the background; meanwhile I will use an estimated count, and will update it later on
2017-01-26 12:25:16 INFO As instructed, I'm issuing a SELECT COUNT(*) on the table. This may take a while
2017-01-26 12:25:16 INFO Migration min values: [1]
2017-01-26 12:25:16 INFO Migration max values: [351857]
2017-01-26 12:25:16 INFO Waiting for first throttle metrics to be collected
*#* Migrating `historical`.`raw_post_data`; Ghost table is `historical`.`_raw_post_data_gho`
*#* Migrating XXXXX; inspecting XXXXX; executing on XXXXX
*#* Migration started at Thu Jan 26 12:25:13 -0500 2017
*#* chunk-size: 500; max-lag-millis: 1500ms; max-load: Threads_running=30; critical-load: ; nice-ratio: 0.000000
*#* throttle-additional-flag-file: /tmp/gh-ost.throttle
*#* Serving on unix socket: /tmp/gh-ost.historical.raw_post_data.sock
Copy: 0/344974 0.0%; Applied: 0; Backlog: 0/100; Time: 3s(total), 0s(copy); streamer: mysql-bin-changelog.134366:3205; State: migrating; ETA: N/A
Copy: 0/344974 0.0%; Applied: 0; Backlog: 0/100; Time: 4s(total), 1s(copy); streamer: mysql-bin-changelog.134366:4648; State: migrating; ETA: N/A
After copying hits 100%:
Copy: 344500/344974 99.9%; Applied: 0; Backlog: 0/100; Time: 2h22m34s(total), 2h22m31s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: 11s
Copy: 344500/344974 99.9%; Applied: 0; Backlog: 0/100; Time: 2h22m33s(total), 2h22m30s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: 11s
Copy: 345500/344974 100.2%; Applied: 0; Backlog: 0/100; Time: 2h23m0s(total), 2h22m57s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
Copy: 346500/344974 100.4%; Applied: 0; Backlog: 0/100; Time: 2h23m30s(total), 2h23m27s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
Copy: 348000/344974 100.9%; Applied: 0; Backlog: 0/100; Time: 2h24m0s(total), 2h23m57s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
Copy: 349000/344974 101.2%; Applied: 0; Backlog: 0/100; Time: 2h24m30s(total), 2h24m27s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
Copy: 350000/344974 101.5%; Applied: 0; Backlog: 0/100; Time: 2h25m0s(total), 2h24m57s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
Copy: 351000/344974 101.7%; Applied: 0; Backlog: 0/100; Time: 2h25m30s(total), 2h25m27s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
2017-01-26 14:50:54 INFO Row copy complete
Copy: 351857/351857 100.0%; Applied: 0; Backlog: 0/100; Time: 2h25m40s(total), 2h25m37s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
2017-01-26 14:50:54 INFO Grabbing voluntary lock: gh-ost.5175.lock
2017-01-26 14:50:54 INFO Setting LOCK timeout as 6 seconds
2017-01-26 14:50:55 INFO Looking for magic cut-over table
2017-01-26 14:50:55 INFO Creating magic cut-over table `historical`.`_raw_post_data_del`
2017-01-26 14:50:57 INFO Magic cut-over table created
2017-01-26 14:50:57 INFO Locking `historical`.`raw_post_data`, `historical`.`_raw_post_data_del`
2017-01-26 14:50:57 INFO Tables locked
2017-01-26 14:50:57 INFO Session locking original & magic tables is 5175
2017-01-26 14:50:57 INFO Writing changelog state: AllEventsUpToLockProcessed:1485460257538913634
2017-01-26 14:50:57 INFO Waiting for events up to lock
Copy: 351857/351857 100.0%; Applied: 0; Backlog: 0/100; Time: 2h25m45s(total), 2h25m37s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
2017-01-26 14:51:00 ERROR Timeout while waiting for events up to lock
2017-01-26 14:51:00 ERROR 2017-01-26 14:51:00 ERROR Timeout while waiting for events up to lock
2017-01-26 14:51:00 INFO Looking for magic cut-over table
2017-01-26 14:51:00 INFO Will now proceed to drop magic table and unlock tables
Last lines of output:
2017-01-26 14:55:34 INFO Creating magic cut-over table historical._raw_post_data_del
2017-01-26 14:55:34 INFO Magic cut-over table created
2017-01-26 14:55:34 INFO Locking historical.raw_post_data, historical._raw_post_data_del
Copy: 351857/351857 100.0%; Applied: 0; Backlog: 0/100; Time: 2h30m20s(total), 2h25m37s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
2017-01-26 14:55:34 INFO Tables locked
2017-01-26 14:55:34 INFO Session locking original & magic tables is 5568
2017-01-26 14:55:34 INFO Writing changelog state: AllEventsUpToLockProcessed:1485460534390340333
2017-01-26 14:55:34 INFO Waiting for events up to lock
2017-01-26 14:55:37 ERROR Timeout while waiting for events up to lock
2017-01-26 14:55:37 ERROR 2017-01-26 14:55:37 ERROR Timeout while waiting for events up to lock
2017-01-26 14:55:37 INFO Looking for magic cut-over table
2017-01-26 14:55:37 INFO Will now proceed to drop magic table and unlock tables
2017-01-26 14:55:37 INFO Dropping magic cut-over table
2017-01-26 14:55:37 INFO Dropping magic cut-over table
2017-01-26 14:55:37 INFO Droppping table historical._raw_post_data_del
2017-01-26 14:55:37 INFO Releasing lock from historical.raw_post_data, historical._raw_post_data_del
2017-01-26 14:55:37 INFO Table dropped
2017-01-26 14:55:37 INFO Tables unlocked
2017-01-26 14:55:38 INFO Grabbing voluntary lock: gh-ost.5568.lock
2017-01-26 14:55:38 INFO Setting LOCK timeout as 6 seconds
2017-01-26 14:55:38 INFO Looking for magic cut-over table
2017-01-26 14:55:38 INFO Creating magic cut-over table historical._raw_post_data_del
2017-01-26 14:55:38 INFO Magic cut-over table created
2017-01-26 14:55:38 INFO Locking historical.raw_post_data, historical._raw_post_data_del
2017-01-26 14:55:38 INFO Tables locked
2017-01-26 14:55:38 INFO Session locking original & magic tables is 5568
2017-01-26 14:55:38 INFO Writing changelog state: AllEventsUpToLockProcessed:1485460538692532253
2017-01-26 14:55:38 INFO Waiting for events up to lock
Copy: 351857/351857 100.0%; Applied: 0; Backlog: 0/100; Time: 2h30m25s(total), 2h25m37s(copy); streamer: mysql-bin-changelog.134406:119471848; State: migrating; ETA: due
2017-01-26 14:55:41 ERROR Timeout while waiting for events up to lock
2017-01-26 14:55:41 ERROR 2017-01-26 14:55:41 ERROR Timeout while waiting for events up to lock
2017-01-26 14:55:41 INFO Looking for magic cut-over table
2017-01-26 14:55:41 INFO Will now proceed to drop magic table and unlock tables
2017-01-26 14:55:41 INFO Dropping magic cut-over table
2017-01-26 14:55:41 INFO Removing socket file: /tmp/gh-ost.historical.raw_post_data.sock
2017-01-26 14:55:41 FATAL 2017-01-26 14:55:41 ERROR Timeout while waiting for events up to lock
About this issue
- Original URL
- State: closed
- Created 7 years ago
- Comments: 57 (32 by maintainers)
Well, I will see it later.
@shlomi-noach Thank you! Yes I can test it and no -
POINT
column is not part ofPRIMARY KEY
in that table.Done. go-mysql #109
I can upgrade that replica to latest Percona MySQL 5.7.17 or to 5.7.14. I can’t downgrade that particular DB to 5.5, cause it’s uses 5.7 specific functionality.
@shlomi-noach Running with --dml-batch-size=1 ends with the same error.
grep ‘Intercepted changelog state’ screenlog.0 2017-02-06 09:33:55 INFO Intercepted changelog state GhostTableMigrated
@shlomi-noach Same server, same software versions: