search

github / gh-ost

GitHub's Online Schema-migration Tool for MySQL
MIT License
12.44k stars 1.26k forks source link

concurrent migration issue #439

Open cenkore opened 7 years ago

cenkore commented 7 years ago

Gh-ost version : 1.0.30

**gh-ost was designed with having multiple concurrent migration running in parallel** in triggerless-design.md

BUT I fond gh-ost could not concurrent migration actually , one task wolud be quit with error "ERROR Timeout while waiting for events up to lock" , another would be OK .

execute script: Task 1.

gh-ost --host=10.28.77.43 --database=ghostdb --table=test1g --port=55944 --alter="add column addcol05 int default 0" --concurrent-rowcount --conf=/usr/local/gh-ost.cnf --throttle-flag-file="/tmp/gh-ost.ghostdb.test1g.throttle" --postpone-cut-over-flag-file="/tmp/gh-ost.ghostdb.test1g.postpone" --hooks-path="/tmp" --max-load="Threads_connected=5000,Threads_running=5000" --initially-drop-old-table --initially-drop-ghost-table --initially-drop-socket-file --verbose --execute

Task 2.

gh-ost --host=10.28.77.43 --database=ghostdb --table=test10g --port=55944 --alter="add column addcol05 int default 0" --concurrent-rowcount --conf=/usr/local/gh-ost.cnf --throttle-flag-file="/tmp/gh-ost.ghostdb.test10g.throttle" --postpone-cut-over-flag-file="/tmp/gh-ost.ghostdb.test10g.postpone" --hooks-path="/tmp" --max-load="Threads_connected=5000,Threads_running=5000" --initially-drop-old-table --initially-drop-ghost-table --initially-drop-socket-file --verbose --execute

Task 1's log

2017-07-04 14:50:33 INFO Looking for magic cut-over table
2017-07-04 14:50:33 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 14:50:33 INFO Dropping magic cut-over table
2017-07-04 14:50:33 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 14:50:33 INFO Tables unlocked
2017-07-04 14:50:34 INFO Grabbing voluntary lock: gh-ost.2447063.lock
2017-07-04 14:50:34 INFO Setting LOCK timeout as 6 seconds
2017-07-04 14:50:34 INFO Looking for magic cut-over table
2017-07-04 14:50:34 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 14:50:34 INFO Magic cut-over table created
2017-07-04 14:50:34 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 14:50:34 INFO Tables locked
2017-07-04 14:50:34 INFO Session locking original & magic tables is 2447063
2017-07-04 14:50:34 INFO Writing changelog state: AllEventsUpToLockProcessed:1499151034706034765
2017-07-04 14:50:34 INFO Waiting for events up to lock
2017-07-04 14:50:35 INFO StreamEvents encountered unexpected error: ERROR 1236 (HY000): A slave with the same server_uuid/server_id as this slave has connected to the master; the first event 'SVR14883DE630-bin.001315' at 4, the last event read from './SVR14883DE630-bin.001315' at 187061838, the last byte read from './SVR14883DE630-bin.001315' at 187061838.
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 6m10s(total), 2m9s(copy); streamer: SVR14883DE630-bin.001315:187061838; State: migrating; ETA: due
2017-07-04 14:50:37 ERROR Timeout while waiting for events up to lock
2017-07-04 14:50:37 ERROR 2017-07-04 14:50:37 ERROR Timeout while waiting for events up to lock
2017-07-04 14:50:37 INFO Looking for magic cut-over table
2017-07-04 14:50:37 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 14:50:37 INFO Dropping magic cut-over table
2017-07-04 14:50:37 INFO Removing socket file: /tmp/gh-ost.ghostdb.test1g.sock
2017-07-04 14:50:37 INFO executing gh-ost-on-failure hook: /tmp/gh-ost-on-failure.hook
**2017-07-04 14:50:37 FATAL 2017-07-04 14:50:37 ERROR Timeout while waiting for events up to lock**

Task 2's log

2017-07-04 14:55:15 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1499151314500641336
2017-07-04 14:55:15 INFO Done waiting for events up to lock; duration=993.440857ms
Copy: 18898698/18898698 100.0%; Applied: 0; Backlog: 0/100; Time: 10m53s(total), 10m50s(copy); streamer: SVR14883DE630-bin.001323:668568927; State: migrating; ETA: due
2017-07-04 14:55:15 INFO Setting RENAME timeout as 3 seconds
2017-07-04 14:55:15 INFO Session renaming tables is 2447290
2017-07-04 14:55:15 INFO Issuing and expecting this to block: rename /* gh-ost */ table `ghostdb`.`test10g` to `ghostdb`.`_test10g_del`, `ghostdb`.`_test10g_gho` to `ghostdb`.`test10g`
2017-07-04 14:55:15 INFO Found atomic RENAME to be blocking, as expected. Double checking the lock is still in place (though I don't strictly have to)
2017-07-04 14:55:15 INFO Checking session lock: gh-ost.2446665.lock
2017-07-04 14:55:15 INFO Connection holding lock on original table still exists
2017-07-04 14:55:15 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 14:55:15 INFO Dropping magic cut-over table
2017-07-04 14:55:15 INFO Releasing lock from `ghostdb`.`test10g`, `ghostdb`.`_test10g_del`
2017-07-04 14:55:15 INFO Tables unlocked
2017-07-04 14:55:15 INFO Tables renamed
2017-07-04 14:55:15 INFO Lock & rename duration: 1.041417629s. During this time, queries on `test10g` were blocked
2017-07-04 14:55:15 INFO Looking for magic cut-over table
2017-07-04 14:55:16 INFO Closed streamer connection. err=<nil>
2017-07-04 14:55:16 INFO Droppping table `ghostdb`.`_test10g_ghc`
2017-07-04 14:55:16 INFO StreamEvents encountered unexpected error: sync is been closing...
2017-07-04 14:55:16 INFO Table dropped
2017-07-04 14:55:16 INFO Am not dropping old table because I want this operation to be as live as possible. If you insist I should do it, please add `--ok-to-drop-table` next time. But I prefer you do not. To drop the old table, issue:
2017-07-04 14:55:16 INFO -- drop table `ghostdb`.`_test10g_del`
2017-07-04 14:55:16 INFO executing gh-ost-on-success hook: /tmp/gh-ost-on-success.hook

BTW , gh-ost-on-failure hook can not work normally in this condition.

2017-07-04 14:50:37 INFO executing gh-ost-on-failure hook: /tmp/gh-ost-on-failure.hook

Thank you!

shlomi-noach commented 7 years ago

Thank you for this report.

My understanding right now is that the bug is different than described. What I see is one migration bailing out on 2017-07-04 14:50:37. It shouldn't -- the timeout is legit, but gh-ost should enter a retry-cycle.

The second migration only completes at 2017-07-04 14:55:16, five minutes later.

My suspicion is that the two are unrelated. That is, unless you tell me this reproduces for you, and more so the error reproduces on two concurrent migrations, and does not reproduce on single migration.

shlomi-noach commented 7 years ago

I also suspect the log is too truncated. How many times did task 1 run "Looking for magic cut-over table" ?

cenkore commented 7 years ago

Yes , sorry for that i truncated the log . I reproduces the issue as follows . Full log Task 1's log:

2017-07-04 16:16:58 INFO starting gh-ost 1.0.30
2017-07-04 16:16:58 INFO Migrating `ghostdb`.`test1g`
2017-07-04 16:16:58 INFO executing gh-ost-on-startup hook: /tmp/gh-ost-on-startup.hook

2017-07-04 16:16:58 INFO connection validated on 10.28.77.43:55944
2017-07-04 16:16:58 INFO User has ALL privileges
2017-07-04 16:16:58 INFO binary logs validated on 10.28.77.43:55944
2017-07-04 16:16:58 INFO Restarting replication on 10.28.77.43:55944 to make sure binlog settings apply to replication thread
2017-07-04 16:16:58 INFO Table found. Engine=InnoDB
2017-07-04 16:16:58 INFO Estimated number of rows via EXPLAIN: 4339016
2017-07-04 16:16:58 INFO Recursively searching for replication master
2017-07-04 16:16:58 INFO Master found to be 10.28.77.42:55944
2017-07-04 16:16:58 INFO log_slave_updates validated on 10.28.77.43:55944
2017-07-04 16:16:58 INFO connection validated on 10.28.77.43:55944
2017-07-04 16:16:58 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:16:58 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:974840650
2017-07-04 16:16:58 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:16:58 INFO connection validated on 10.28.77.42:55944
2017-07-04 16:16:58 INFO connection validated on 10.28.77.42:55944
2017-07-04 16:16:58 INFO will use time_zone='SYSTEM' on applier
2017-07-04 16:16:58 INFO Examining table structure on applier
2017-07-04 16:16:58 INFO Droppping table `ghostdb`.`_test1g_gho`
2017-07-04 16:16:59 INFO Table dropped
2017-07-04 16:16:59 INFO Droppping table `ghostdb`.`_test1g_del`
2017-07-04 16:16:59 INFO Table dropped
2017-07-04 16:16:59 INFO Droppping table `ghostdb`.`_test1g_ghc`
2017-07-04 16:16:59 INFO Table dropped
2017-07-04 16:16:59 INFO Creating changelog table `ghostdb`.`_test1g_ghc`
2017-07-04 16:16:59 INFO Changelog table created
2017-07-04 16:16:59 INFO Creating ghost table `ghostdb`.`_test1g_gho`
2017-07-04 16:16:59 INFO Ghost table created
2017-07-04 16:16:59 INFO Altering ghost table `ghostdb`.`_test1g_gho`
2017-07-04 16:16:59 INFO Ghost table altered
2017-07-04 16:16:59 INFO Waiting for ghost table to be migrated. Current lag is 0s
2017-07-04 16:17:00 INFO Intercepted changelog state GhostTableMigrated
2017-07-04 16:17:00 INFO Handled changelog state GhostTableMigrated
2017-07-04 16:17:00 INFO Chosen shared unique key is PRIMARY
2017-07-04 16:17:00 INFO Shared columns are id,machine_name,host_name,dbname,username,sid,rolename,create_date,addcol,collection_time,insert_timestamp,addcol2,addcol10,addcol11,addcol12,addcol21,addcol20,addcol03,addcol06
2017-07-04 16:17:00 INFO Listening on unix socket file: /tmp/gh-ost.ghostdb.test1g.sock
2017-07-04 16:17:00 INFO Migration min values: [1,2017-06-12 18:00:42,a]
2017-07-04 16:17:00 INFO Migration max values: [183758439,2017-05-29 05:20:04,SVR10039DE920]
2017-07-04 16:17:00 INFO Waiting for first throttle metrics to be collected
# Migrating `ghostdb`.`test1g`; Ghost table is `ghostdb`.`_test1g_gho`
# Migrating SVR14306DE630:55944; inspecting SVR14883DE630:55944; executing on SVR14883DE630
# Migration started at Tue Jul 04 16:16:58 +0800 2017
# chunk-size: 1000; max-lag-millis: 1500ms; max-load: Threads_connected=5000,Threads_running=5000; critical-load: ; nice-ratio: 0.000000
# throttle-flag-file: /tmp/gh-ost.ghostdb.test1g.throttle 
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# postpone-cut-over-flag-file: /tmp/gh-ost.ghostdb.test1g.postpone 
# Serving on unix socket: /tmp/gh-ost.ghostdb.test1g.sock
Copy: 0/4339016 0.0%; Applied: 0; Backlog: 0/100; Time: 2s(total), 0s(copy); streamer: SVR14883DE630-bin.001333:978872926; State: migrating; ETA: N/A
Copy: 0/4339016 0.0%; Applied: 0; Backlog: 0/100; Time: 3s(total), 1s(copy); streamer: SVR14883DE630-bin.001333:995620200; State: migrating; ETA: N/A
Copy: 38000/4339016 0.9%; Applied: 0; Backlog: 0/100; Time: 4s(total), 2s(copy); streamer: SVR14883DE630-bin.001333:1010989176; State: migrating; ETA: N/A
last event read from './SVR14883DE630-bin.001333' at 1024346933, the last byte read from './SVR14883DE630-bin.001333' at 1024346933.
Copy: 78000/4339016 1.8%; Applied: 0; Backlog: 0/100; Time: 5s(total), 3s(copy); streamer: SVR14883DE630-bin.001333:1024346902; State: migrating; ETA: 2m43s
Copy: 113000/4339016 2.6%; Applied: 0; Backlog: 0/100; Time: 6s(total), 4s(copy); streamer: SVR14883DE630-bin.001333:1024346902; State: migrating; ETA: 2m29s
Copy: 155000/4339016 3.6%; Applied: 0; Backlog: 0/100; Time: 7s(total), 5s(copy); streamer: SVR14883DE630-bin.001333:1024346902; State: migrating; ETA: 2m15s
Copy: 197000/4339016 4.5%; Applied: 0; Backlog: 0/100; Time: 8s(total), 6s(copy); streamer: SVR14883DE630-bin.001333:1024346902; State: migrating; ETA: 2m6s
Copy: 239000/4339016 5.5%; Applied: 0; Backlog: 0/100; Time: 9s(total), 7s(copy); streamer: SVR14883DE630-bin.001333:1024346902; State: migrating; ETA: 2m0s
2017-07-04 16:17:08 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:17:08 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:08 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:08 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 276000/4339016 6.4%; Applied: 0; Backlog: 0/100; Time: 10s(total), 8s(copy); streamer: SVR14883DE630-bin.001333:7440115; State: migrating; ETA: 1m57s
Copy: 317000/4339016 7.3%; Applied: 0; Backlog: 0/100; Time: 11s(total), 9s(copy); streamer: SVR14883DE630-bin.001333:75042978; State: migrating; ETA: 1m54s
Copy: 360000/4339016 8.3%; Applied: 0; Backlog: 0/100; Time: 12s(total), 10s(copy); streamer: SVR14883DE630-bin.001333:146127568; State: migrating; ETA: 1m50s
Copy: 403000/4339016 9.3%; Applied: 0; Backlog: 0/100; Time: 13s(total), 11s(copy); streamer: SVR14883DE630-bin.001333:237193124; State: migrating; ETA: 1m47s
Copy: 404000/4339016 9.3%; Applied: 0; Backlog: 0/100; Time: 14s(total), 12s(copy); streamer: SVR14883DE630-bin.001333:336358197; State: throttled, lag=1.767786s; ETA: 1m56s
nt read from './SVR14883DE630-bin.001333' at 424187156, the last byte read from './SVR14883DE630-bin.001333' at 424187156.
Copy: 404000/4339016 9.3%; Applied: 0; Backlog: 0/100; Time: 15s(total), 13s(copy); streamer: SVR14883DE630-bin.001333:424187156; State: throttled, lag=1.767705s; ETA: 2m6s
Copy: 439000/4339016 10.1%; Applied: 0; Backlog: 0/100; Time: 16s(total), 14s(copy); streamer: SVR14883DE630-bin.001333:424187156; State: migrating; ETA: 2m4s
Copy: 481000/4339016 11.1%; Applied: 0; Backlog: 0/100; Time: 17s(total), 15s(copy); streamer: SVR14883DE630-bin.001333:424187156; State: migrating; ETA: 2m0s
Copy: 522000/4339016 12.0%; Applied: 0; Backlog: 0/100; Time: 18s(total), 16s(copy); streamer: SVR14883DE630-bin.001333:424187156; State: migrating; ETA: 1m57s
Copy: 561000/4339016 12.9%; Applied: 0; Backlog: 0/100; Time: 19s(total), 17s(copy); streamer: SVR14883DE630-bin.001333:424187156; State: migrating; ETA: 1m54s
2017-07-04 16:17:18 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:17:18 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:18 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:18 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 597000/4339016 13.8%; Applied: 0; Backlog: 0/100; Time: 20s(total), 18s(copy); streamer: SVR14883DE630-bin.001333:4767473; State: migrating; ETA: 1m52s
Copy: 639000/4339016 14.7%; Applied: 0; Backlog: 0/100; Time: 21s(total), 19s(copy); streamer: SVR14883DE630-bin.001333:73625607; State: migrating; ETA: 1m50s
Copy: 681000/4339016 15.7%; Applied: 0; Backlog: 0/100; Time: 22s(total), 20s(copy); streamer: SVR14883DE630-bin.001333:144077883; State: migrating; ETA: 1m47s
Copy: 722000/4339016 16.6%; Applied: 0; Backlog: 0/100; Time: 23s(total), 21s(copy); streamer: SVR14883DE630-bin.001333:235082640; State: migrating; ETA: 1m45s
Copy: 744000/4339016 17.1%; Applied: 0; Backlog: 0/100; Time: 24s(total), 22s(copy); streamer: SVR14883DE630-bin.001333:332598761; State: throttled, lag=1.767791s; ETA: 1m46s
nt read from './SVR14883DE630-bin.001333' at 422677768, the last byte read from './SVR14883DE630-bin.001333' at 422677768.
Copy: 744000/4339016 17.1%; Applied: 0; Backlog: 0/100; Time: 25s(total), 23s(copy); streamer: SVR14883DE630-bin.001333:422677768; State: throttled, lag=1.767766s; ETA: 1m51s
Copy: 764000/4339016 17.6%; Applied: 0; Backlog: 0/100; Time: 26s(total), 24s(copy); streamer: SVR14883DE630-bin.001333:422677768; State: migrating; ETA: 1m52s
Copy: 806000/4339016 18.6%; Applied: 0; Backlog: 0/100; Time: 27s(total), 25s(copy); streamer: SVR14883DE630-bin.001333:422677768; State: migrating; ETA: 1m49s
Copy: 848000/4339016 19.5%; Applied: 0; Backlog: 0/100; Time: 28s(total), 26s(copy); streamer: SVR14883DE630-bin.001333:422677768; State: migrating; ETA: 1m47s
Copy: 892000/4339016 20.6%; Applied: 0; Backlog: 0/100; Time: 29s(total), 27s(copy); streamer: SVR14883DE630-bin.001333:422677768; State: migrating; ETA: 1m44s
2017-07-04 16:17:28 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:17:28 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:28 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:28 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 928000/4339016 21.4%; Applied: 0; Backlog: 0/100; Time: 30s(total), 28s(copy); streamer: SVR14883DE630-bin.001333:1137435; State: migrating; ETA: 1m42s
Copy: 968000/4339016 22.3%; Applied: 0; Backlog: 0/100; Time: 31s(total), 29s(copy); streamer: SVR14883DE630-bin.001333:69429688; State: migrating; ETA: 1m40s
Copy: 1010000/4339016 23.3%; Applied: 0; Backlog: 0/100; Time: 32s(total), 30s(copy); streamer: SVR14883DE630-bin.001333:136489096; State: migrating; ETA: 1m38s
Copy: 1051000/4339016 24.2%; Applied: 0; Backlog: 0/100; Time: 33s(total), 31s(copy); streamer: SVR14883DE630-bin.001333:223145828; State: migrating; ETA: 1m36s
Copy: 1088000/4339016 25.1%; Applied: 0; Backlog: 0/100; Time: 34s(total), 32s(copy); streamer: SVR14883DE630-bin.001333:317714352; State: migrating; ETA: 1m35s
Copy: 1110000/4339016 25.6%; Applied: 0; Backlog: 0/100; Time: 35s(total), 33s(copy); streamer: SVR14883DE630-bin.001333:411648483; State: throttled, lag=1.767868s; ETA: 1m36s
nt read from './SVR14883DE630-bin.001333' at 414297915, the last byte read from './SVR14883DE630-bin.001333' at 414297915.
Copy: 1110000/4339016 25.6%; Applied: 0; Backlog: 0/100; Time: 36s(total), 34s(copy); streamer: SVR14883DE630-bin.001333:414297915; State: throttled, lag=1.768003s; ETA: 1m38s
Copy: 1130000/4339016 26.0%; Applied: 0; Backlog: 0/100; Time: 37s(total), 35s(copy); streamer: SVR14883DE630-bin.001333:414297915; State: migrating; ETA: 1m39s
Copy: 1172000/4339016 27.0%; Applied: 0; Backlog: 0/100; Time: 38s(total), 36s(copy); streamer: SVR14883DE630-bin.001333:414297915; State: migrating; ETA: 1m37s
Copy: 1213000/4339016 28.0%; Applied: 0; Backlog: 0/100; Time: 39s(total), 37s(copy); streamer: SVR14883DE630-bin.001333:414297915; State: migrating; ETA: 1m35s
Copy: 1251000/4339016 28.8%; Applied: 0; Backlog: 0/100; Time: 40s(total), 38s(copy); streamer: SVR14883DE630-bin.001333:414297915; State: migrating; ETA: 1m33s
2017-07-04 16:17:38 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:17:38 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:38 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:38 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 1292000/4339016 29.8%; Applied: 0; Backlog: 0/100; Time: 41s(total), 39s(copy); streamer: SVR14883DE630-bin.001333:65708664; State: migrating; ETA: 1m31s
Copy: 1334000/4339016 30.7%; Applied: 0; Backlog: 0/100; Time: 42s(total), 40s(copy); streamer: SVR14883DE630-bin.001333:134779626; State: migrating; ETA: 1m30s
Copy: 1376000/4339016 31.7%; Applied: 0; Backlog: 0/100; Time: 43s(total), 41s(copy); streamer: SVR14883DE630-bin.001333:221157360; State: migrating; ETA: 1m28s
Copy: 1413000/4339016 32.6%; Applied: 0; Backlog: 0/100; Time: 44s(total), 42s(copy); streamer: SVR14883DE630-bin.001333:313797912; State: migrating; ETA: 1m26s
Copy: 1414000/4339016 32.6%; Applied: 0; Backlog: 0/100; Time: 45s(total), 43s(copy); streamer: SVR14883DE630-bin.001333:409182322; State: throttled, lag=1.767771s; ETA: 1m28s
nt read from './SVR14883DE630-bin.001333' at 416683896, the last byte read from './SVR14883DE630-bin.001333' at 416683896.
Copy: 1435000/4339016 33.1%; Applied: 0; Backlog: 0/100; Time: 46s(total), 44s(copy); streamer: SVR14883DE630-bin.001333:416683896; State: migrating; ETA: 1m29s
Copy: 1474000/4339016 34.0%; Applied: 0; Backlog: 0/100; Time: 47s(total), 45s(copy); streamer: SVR14883DE630-bin.001333:416683896; State: migrating; ETA: 1m27s
Copy: 1515000/4339016 34.9%; Applied: 0; Backlog: 0/100; Time: 48s(total), 46s(copy); streamer: SVR14883DE630-bin.001333:416683896; State: migrating; ETA: 1m25s
Copy: 1550000/4339016 35.7%; Applied: 0; Backlog: 0/100; Time: 49s(total), 47s(copy); streamer: SVR14883DE630-bin.001333:416683896; State: migrating; ETA: 1m24s
Copy: 1592000/4339016 36.7%; Applied: 0; Backlog: 0/100; Time: 50s(total), 48s(copy); streamer: SVR14883DE630-bin.001333:416683896; State: migrating; ETA: 1m22s
2017-07-04 16:17:48 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:17:48 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:48 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:48 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 1633000/4339016 37.6%; Applied: 0; Backlog: 0/100; Time: 51s(total), 49s(copy); streamer: SVR14883DE630-bin.001333:62863001; State: migrating; ETA: 1m21s
Copy: 1675000/4339016 38.6%; Applied: 0; Backlog: 0/100; Time: 52s(total), 50s(copy); streamer: SVR14883DE630-bin.001333:132942604; State: migrating; ETA: 1m19s
Copy: 1691000/4339016 39.0%; Applied: 0; Backlog: 0/100; Time: 53s(total), 51s(copy); streamer: SVR14883DE630-bin.001333:220764330; State: throttled, lag=1.767917s; ETA: 1m19s
Copy: 1691000/4339016 39.0%; Applied: 0; Backlog: 0/100; Time: 54s(total), 52s(copy); streamer: SVR14883DE630-bin.001333:314688011; State: throttled, lag=1.767841s; ETA: 1m21s
Copy: 1711000/4339016 39.4%; Applied: 0; Backlog: 0/100; Time: 55s(total), 53s(copy); streamer: SVR14883DE630-bin.001333:411579645; State: migrating; ETA: 1m21s
nt read from './SVR14883DE630-bin.001333' at 422710566, the last byte read from './SVR14883DE630-bin.001333' at 422710566.
Copy: 1751000/4339016 40.4%; Applied: 0; Backlog: 0/100; Time: 56s(total), 54s(copy); streamer: SVR14883DE630-bin.001333:422710566; State: migrating; ETA: 1m19s
Copy: 1793000/4339016 41.3%; Applied: 0; Backlog: 0/100; Time: 57s(total), 55s(copy); streamer: SVR14883DE630-bin.001333:422710566; State: migrating; ETA: 1m18s
Copy: 1828000/4339016 42.1%; Applied: 0; Backlog: 0/100; Time: 58s(total), 56s(copy); streamer: SVR14883DE630-bin.001333:422710566; State: migrating; ETA: 1m16s
Copy: 1870000/4339016 43.1%; Applied: 0; Backlog: 0/100; Time: 59s(total), 57s(copy); streamer: SVR14883DE630-bin.001333:422710566; State: migrating; ETA: 1m15s
Copy: 1911000/4339016 44.0%; Applied: 0; Backlog: 0/100; Time: 1m0s(total), 58s(copy); streamer: SVR14883DE630-bin.001333:422710566; State: migrating; ETA: 1m13s
2017-07-04 16:17:58 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:17:58 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:58 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:58 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 2103000/4339016 48.5%; Applied: 0; Backlog: 0/100; Time: 1m5s(total), 1m3s(copy); streamer: SVR14883DE630-bin.001333:411859867; State: migrating; ETA: 1m6s
nt read from './SVR14883DE630-bin.001333' at 427262458, the last byte read from './SVR14883DE630-bin.001333' at 427262458.
Copy: 2225000/4339016 51.3%; Applied: 0; Backlog: 0/100; Time: 1m10s(total), 1m8s(copy); streamer: SVR14883DE630-bin.001333:427262458; State: migrating; ETA: 1m4s
2017-07-04 16:18:08 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:18:08 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:08 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:08 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 2381000/4339016 54.9%; Applied: 0; Backlog: 0/100; Time: 1m14s(total), 1m12s(copy); streamer: SVR14883DE630-bin.001333:293832199; State: migrating; ETA: 59s
Copy: 2422000/4339016 55.8%; Applied: 0; Backlog: 0/100; Time: 1m15s(total), 1m13s(copy); streamer: SVR14883DE630-bin.001333:389655529; State: migrating; ETA: 57s
nt read from './SVR14883DE630-bin.001333' at 409298791, the last byte read from './SVR14883DE630-bin.001333' at 409298791.
Copy: 2458000/4339016 56.6%; Applied: 0; Backlog: 0/100; Time: 1m16s(total), 1m14s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: migrating; ETA: 56s
Copy: 2494000/4339016 57.5%; Applied: 0; Backlog: 0/100; Time: 1m17s(total), 1m15s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: migrating; ETA: 55s
Copy: 2533000/4339016 58.4%; Applied: 0; Backlog: 0/100; Time: 1m18s(total), 1m16s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: migrating; ETA: 54s
Copy: 2572000/4339016 59.3%; Applied: 0; Backlog: 0/100; Time: 1m19s(total), 1m17s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: migrating; ETA: 52s
Copy: 2574000/4339016 59.3%; Applied: 0; Backlog: 0/100; Time: 1m20s(total), 1m18s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: throttled, lag=1.767892s; ETA: 53s
2017-07-04 16:18:18 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:18:18 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:18 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:18 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 2574000/4339016 59.3%; Applied: 0; Backlog: 0/100; Time: 1m21s(total), 1m19s(copy); streamer: SVR14883DE630-bin.001333:51558374; State: throttled, lag=1.767776s; ETA: 54s
Copy: 2611000/4339016 60.2%; Applied: 0; Backlog: 0/100; Time: 1m22s(total), 1m20s(copy); streamer: SVR14883DE630-bin.001333:119765974; State: migrating; ETA: 52s
Copy: 2649000/4339016 61.1%; Applied: 0; Backlog: 0/100; Time: 1m23s(total), 1m21s(copy); streamer: SVR14883DE630-bin.001333:203555677; State: migrating; ETA: 51s
Copy: 2690000/4339016 62.0%; Applied: 0; Backlog: 0/100; Time: 1m24s(total), 1m22s(copy); streamer: SVR14883DE630-bin.001333:295332380; State: migrating; ETA: 50s
Copy: 2724000/4339016 62.8%; Applied: 0; Backlog: 0/100; Time: 1m25s(total), 1m23s(copy); streamer: SVR14883DE630-bin.001333:392958821; State: migrating; ETA: 49s
nt read from './SVR14883DE630-bin.001333' at 417114362, the last byte read from './SVR14883DE630-bin.001333' at 417114362.
Copy: 2764000/4339016 63.7%; Applied: 0; Backlog: 0/100; Time: 1m26s(total), 1m24s(copy); streamer: SVR14883DE630-bin.001333:417114362; State: migrating; ETA: 47s
Copy: 2803000/4339016 64.6%; Applied: 0; Backlog: 0/100; Time: 1m27s(total), 1m25s(copy); streamer: SVR14883DE630-bin.001333:417114362; State: migrating; ETA: 46s
Copy: 2837000/4339016 65.4%; Applied: 0; Backlog: 0/100; Time: 1m28s(total), 1m26s(copy); streamer: SVR14883DE630-bin.001333:417114362; State: migrating; ETA: 45s
Copy: 2877000/4339016 66.3%; Applied: 0; Backlog: 0/100; Time: 1m29s(total), 1m27s(copy); streamer: SVR14883DE630-bin.001333:417114362; State: migrating; ETA: 44s
Copy: 2915000/4339016 67.2%; Applied: 0; Backlog: 0/100; Time: 1m30s(total), 1m28s(copy); streamer: SVR14883DE630-bin.001333:417114362; State: migrating; ETA: 42s
2017-07-04 16:18:28 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:18:28 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:28 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:28 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 2956000/4339016 68.1%; Applied: 0; Backlog: 0/100; Time: 1m31s(total), 1m29s(copy); streamer: SVR14883DE630-bin.001333:48379715; State: migrating; ETA: 41s
Copy: 2991000/4339016 68.9%; Applied: 0; Backlog: 0/100; Time: 1m32s(total), 1m30s(copy); streamer: SVR14883DE630-bin.001333:117436064; State: migrating; ETA: 40s
Copy: 3033000/4339016 69.9%; Applied: 0; Backlog: 0/100; Time: 1m33s(total), 1m31s(copy); streamer: SVR14883DE630-bin.001333:199916692; State: migrating; ETA: 39s
Copy: 3074000/4339016 70.8%; Applied: 0; Backlog: 0/100; Time: 1m34s(total), 1m32s(copy); streamer: SVR14883DE630-bin.001333:289980979; State: migrating; ETA: 37s
Copy: 3100000/4339016 71.4%; Applied: 0; Backlog: 0/100; Time: 1m35s(total), 1m33s(copy); streamer: SVR14883DE630-bin.001333:388481867; State: throttled, lag=1.768052s; ETA: 37s
nt read from './SVR14883DE630-bin.001333' at 418372395, the last byte read from './SVR14883DE630-bin.001333' at 418372395.
Copy: 3100000/4339016 71.4%; Applied: 0; Backlog: 0/100; Time: 1m36s(total), 1m34s(copy); streamer: SVR14883DE630-bin.001333:418372395; State: throttled, lag=1.768043s; ETA: 37s
Copy: 3116000/4339016 71.8%; Applied: 0; Backlog: 0/100; Time: 1m37s(total), 1m35s(copy); streamer: SVR14883DE630-bin.001333:418372395; State: migrating; ETA: 37s
Copy: 3154000/4339016 72.7%; Applied: 0; Backlog: 0/100; Time: 1m38s(total), 1m36s(copy); streamer: SVR14883DE630-bin.001333:418372395; State: migrating; ETA: 36s
Copy: 3195000/4339016 73.6%; Applied: 0; Backlog: 0/100; Time: 1m39s(total), 1m37s(copy); streamer: SVR14883DE630-bin.001333:418372395; State: migrating; ETA: 34s
Copy: 3236000/4339016 74.6%; Applied: 0; Backlog: 0/100; Time: 1m40s(total), 1m38s(copy); streamer: SVR14883DE630-bin.001333:418372395; State: migrating; ETA: 33s
2017-07-04 16:18:38 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:18:38 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:38 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:38 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 3275000/4339016 75.5%; Applied: 0; Backlog: 0/100; Time: 1m41s(total), 1m39s(copy); streamer: SVR14883DE630-bin.001333:43977330; State: migrating; ETA: 32s
Copy: 3315000/4339016 76.4%; Applied: 0; Backlog: 0/100; Time: 1m42s(total), 1m40s(copy); streamer: SVR14883DE630-bin.001333:112001473; State: migrating; ETA: 30s
Copy: 3352000/4339016 77.3%; Applied: 0; Backlog: 0/100; Time: 1m43s(total), 1m41s(copy); streamer: SVR14883DE630-bin.001333:193201519; State: migrating; ETA: 29s
Copy: 3392000/4339016 78.2%; Applied: 0; Backlog: 0/100; Time: 1m44s(total), 1m42s(copy); streamer: SVR14883DE630-bin.001333:280128120; State: migrating; ETA: 28s
Copy: 3430000/4339016 79.1%; Applied: 0; Backlog: 0/100; Time: 1m45s(total), 1m43s(copy); streamer: SVR14883DE630-bin.001333:375252664; State: migrating; ETA: 27s
nt read from './SVR14883DE630-bin.001333' at 409790672, the last byte read from './SVR14883DE630-bin.001333' at 409790672.
Copy: 3471000/4339016 80.0%; Applied: 0; Backlog: 0/100; Time: 1m46s(total), 1m44s(copy); streamer: SVR14883DE630-bin.001333:409783229; State: migrating; ETA: 26s
Copy: 3507000/4339016 80.8%; Applied: 0; Backlog: 0/100; Time: 1m47s(total), 1m45s(copy); streamer: SVR14883DE630-bin.001333:409783229; State: migrating; ETA: 24s
Copy: 3508000/4339016 80.8%; Applied: 0; Backlog: 0/100; Time: 1m48s(total), 1m46s(copy); streamer: SVR14883DE630-bin.001333:409783229; State: throttled, lag=1.767888s; ETA: 25s
Copy: 3508000/4339016 80.8%; Applied: 0; Backlog: 0/100; Time: 1m49s(total), 1m47s(copy); streamer: SVR14883DE630-bin.001333:409783229; State: throttled, lag=1.767827s; ETA: 25s
Copy: 3548000/4339016 81.8%; Applied: 0; Backlog: 0/100; Time: 1m50s(total), 1m48s(copy); streamer: SVR14883DE630-bin.001333:409783229; State: migrating; ETA: 24s
2017-07-04 16:18:49 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:18:49 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:49 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:49 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 3589000/4339016 82.7%; Applied: 0; Backlog: 0/100; Time: 1m51s(total), 1m49s(copy); streamer: SVR14883DE630-bin.001333:40704778; State: migrating; ETA: 22s
Copy: 3629000/4339016 83.6%; Applied: 0; Backlog: 0/100; Time: 1m52s(total), 1m50s(copy); streamer: SVR14883DE630-bin.001333:106989677; State: migrating; ETA: 21s
Copy: 3670000/4339016 84.6%; Applied: 0; Backlog: 0/100; Time: 1m53s(total), 1m51s(copy); streamer: SVR14883DE630-bin.001333:186778936; State: migrating; ETA: 20s
Copy: 3707000/4339016 85.4%; Applied: 0; Backlog: 0/100; Time: 1m54s(total), 1m52s(copy); streamer: SVR14883DE630-bin.001333:273653010; State: migrating; ETA: 19s
Copy: 3749000/4339016 86.4%; Applied: 0; Backlog: 0/100; Time: 1m55s(total), 1m53s(copy); streamer: SVR14883DE630-bin.001333:369721622; State: migrating; ETA: 17s
nt read from './SVR14883DE630-bin.001333' at 409298791, the last byte read from './SVR14883DE630-bin.001333' at 409298791.
Copy: 3790000/4339016 87.3%; Applied: 0; Backlog: 0/100; Time: 1m56s(total), 1m54s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: migrating; ETA: 16s
Copy: 3831000/4339016 88.3%; Applied: 0; Backlog: 0/100; Time: 1m57s(total), 1m55s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: migrating; ETA: 15s
Copy: 3852000/4339016 88.8%; Applied: 0; Backlog: 0/100; Time: 1m58s(total), 1m56s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: throttled, lag=1.767910s; ETA: 14s
Copy: 3852000/4339016 88.8%; Applied: 0; Backlog: 0/100; Time: 1m59s(total), 1m57s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: throttled, lag=1.767754s; ETA: 14s
Copy: 3867000/4339016 89.1%; Applied: 0; Backlog: 0/100; Time: 2m0s(total), 1m58s(copy); streamer: SVR14883DE630-bin.001333:409298791; State: migrating; ETA: 14s
2017-07-04 16:18:59 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:18:59 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:59 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:59 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 3905000/4339016 90.0%; Applied: 0; Backlog: 0/100; Time: 2m1s(total), 1m59s(copy); streamer: SVR14883DE630-bin.001333:36834369; State: migrating; ETA: 13s
Copy: 3942000/4339016 90.9%; Applied: 0; Backlog: 0/100; Time: 2m2s(total), 2m0s(copy); streamer: SVR14883DE630-bin.001333:103769856; State: migrating; ETA: 12s
Copy: 3983000/4339016 91.8%; Applied: 0; Backlog: 0/100; Time: 2m3s(total), 2m1s(copy); streamer: SVR14883DE630-bin.001333:182353863; State: migrating; ETA: 10s
Copy: 4024000/4339016 92.7%; Applied: 0; Backlog: 0/100; Time: 2m4s(total), 2m2s(copy); streamer: SVR14883DE630-bin.001333:270831138; State: migrating; ETA: 9s
Copy: 4060000/4339016 93.6%; Applied: 0; Backlog: 0/100; Time: 2m5s(total), 2m3s(copy); streamer: SVR14883DE630-bin.001333:365371065; State: migrating; ETA: 8s
nt read from './SVR14883DE630-bin.001333' at 410694552, the last byte read from './SVR14883DE630-bin.001333' at 410694552.
Copy: 4101000/4339016 94.5%; Applied: 0; Backlog: 0/100; Time: 2m6s(total), 2m4s(copy); streamer: SVR14883DE630-bin.001333:410694552; State: migrating; ETA: 7s
Copy: 4142000/4339016 95.5%; Applied: 0; Backlog: 0/100; Time: 2m7s(total), 2m5s(copy); streamer: SVR14883DE630-bin.001333:410694552; State: migrating; ETA: 5s
Copy: 4183000/4339016 96.4%; Applied: 0; Backlog: 0/100; Time: 2m8s(total), 2m6s(copy); streamer: SVR14883DE630-bin.001333:410694552; State: migrating; ETA: 4s
Copy: 4223000/4339016 97.3%; Applied: 0; Backlog: 0/100; Time: 2m9s(total), 2m7s(copy); streamer: SVR14883DE630-bin.001333:410694552; State: migrating; ETA: 3s
Copy: 4238000/4339016 97.7%; Applied: 0; Backlog: 0/100; Time: 2m10s(total), 2m8s(copy); streamer: SVR14883DE630-bin.001333:410694552; State: throttled, lag=1.767809s; ETA: 3s
2017-07-04 16:19:09 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:19:09 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:09 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:09 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 4238000/4339016 97.7%; Applied: 0; Backlog: 0/100; Time: 2m11s(total), 2m9s(copy); streamer: SVR14883DE630-bin.001333:34131393; State: throttled, lag=1.767829s; ETA: 3s
Copy: 4258000/4339016 98.1%; Applied: 0; Backlog: 0/100; Time: 2m12s(total), 2m10s(copy); streamer: SVR14883DE630-bin.001333:102154358; State: migrating; ETA: 2s
Copy: 4300000/4339016 99.1%; Applied: 0; Backlog: 0/100; Time: 2m13s(total), 2m11s(copy); streamer: SVR14883DE630-bin.001333:180554109; State: migrating; ETA: 1s
2017-07-04 16:19:13 INFO Row copy complete
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m15s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:359007030; State: migrating; ETA: due
2017-07-04 16:19:13 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:19:13 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:13 INFO Looking for magic cut-over table
2017-07-04 16:19:13 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:13 INFO Magic cut-over table created
2017-07-04 16:19:13 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:13 INFO Tables locked
2017-07-04 16:19:13 INFO Session locking original & magic tables is 2453584
2017-07-04 16:19:13 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156353550615078
2017-07-04 16:19:13 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m15s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:364724070; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 413938889, the last byte read from './SVR14883DE630-bin.001333' at 413938889.
2017-07-04 16:19:16 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:16 ERROR 2017-07-04 16:19:16 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:16 INFO Looking for magic cut-over table
2017-07-04 16:19:16 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:16 INFO Dropping magic cut-over table
2017-07-04 16:19:16 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:16 INFO Tables unlocked
2017-07-04 16:19:17 INFO Grabbing voluntary lock: gh-ost.2453607.lock
2017-07-04 16:19:17 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:17 INFO Looking for magic cut-over table
2017-07-04 16:19:17 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:17 INFO Magic cut-over table created
2017-07-04 16:19:17 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:17 INFO Tables locked
2017-07-04 16:19:17 INFO Session locking original & magic tables is 2453607
2017-07-04 16:19:17 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156357569519766
2017-07-04 16:19:17 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m20s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:413938889; State: migrating; ETA: due
2017-07-04 16:19:19 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:19:19 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:19 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:19 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:19:20 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:20 ERROR 2017-07-04 16:19:20 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:20 INFO Looking for magic cut-over table
2017-07-04 16:19:20 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:20 INFO Dropping magic cut-over table
2017-07-04 16:19:20 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:20 INFO Tables unlocked
2017-07-04 16:19:21 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:19:21 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:21 INFO Looking for magic cut-over table
2017-07-04 16:19:21 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:21 INFO Magic cut-over table created
2017-07-04 16:19:21 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:21 INFO Tables locked
2017-07-04 16:19:21 INFO Session locking original & magic tables is 2453584
2017-07-04 16:19:21 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156361578184889
2017-07-04 16:19:21 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m25s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:360854824; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 415290358, the last byte read from './SVR14883DE630-bin.001333' at 415290358.
2017-07-04 16:19:24 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:24 ERROR 2017-07-04 16:19:24 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:24 INFO Looking for magic cut-over table
2017-07-04 16:19:24 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:24 INFO Dropping magic cut-over table
2017-07-04 16:19:24 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:24 INFO Tables unlocked
2017-07-04 16:19:25 INFO Grabbing voluntary lock: gh-ost.2453607.lock
2017-07-04 16:19:25 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:25 INFO Looking for magic cut-over table
2017-07-04 16:19:25 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:25 INFO Magic cut-over table created
2017-07-04 16:19:25 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:25 INFO Tables locked
2017-07-04 16:19:25 INFO Session locking original & magic tables is 2453607
2017-07-04 16:19:25 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156365586126120
2017-07-04 16:19:25 INFO Waiting for events up to lock
2017-07-04 16:19:28 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:28 ERROR 2017-07-04 16:19:28 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:28 INFO Looking for magic cut-over table
2017-07-04 16:19:28 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:28 INFO Dropping magic cut-over table
2017-07-04 16:19:28 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:28 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m30s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:415290358; State: migrating; ETA: due
2017-07-04 16:19:29 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:19:29 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:29 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:29 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:19:29 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:19:29 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:29 INFO Looking for magic cut-over table
2017-07-04 16:19:29 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:29 INFO Magic cut-over table created
2017-07-04 16:19:29 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:29 INFO Tables locked
2017-07-04 16:19:29 INFO Session locking original & magic tables is 2453584
2017-07-04 16:19:29 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156369592473251
2017-07-04 16:19:29 INFO Waiting for events up to lock
2017-07-04 16:19:32 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:32 ERROR 2017-07-04 16:19:32 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:32 INFO Looking for magic cut-over table
2017-07-04 16:19:32 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:32 INFO Dropping magic cut-over table
2017-07-04 16:19:32 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:32 INFO Tables unlocked
2017-07-04 16:19:33 INFO Grabbing voluntary lock: gh-ost.2453607.lock
2017-07-04 16:19:33 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:33 INFO Looking for magic cut-over table
2017-07-04 16:19:33 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:33 INFO Magic cut-over table created
2017-07-04 16:19:33 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:33 INFO Tables locked
2017-07-04 16:19:33 INFO Session locking original & magic tables is 2453607
2017-07-04 16:19:33 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156373602335017
2017-07-04 16:19:33 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m35s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:352433145; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 412917574, the last byte read from './SVR14883DE630-bin.001333' at 412917574.
2017-07-04 16:19:36 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:36 ERROR 2017-07-04 16:19:36 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:36 INFO Looking for magic cut-over table
2017-07-04 16:19:36 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:36 INFO Dropping magic cut-over table
2017-07-04 16:19:36 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:36 INFO Tables unlocked
2017-07-04 16:19:37 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:19:37 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:37 INFO Looking for magic cut-over table
2017-07-04 16:19:37 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:37 INFO Magic cut-over table created
2017-07-04 16:19:37 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:37 INFO Tables locked
2017-07-04 16:19:37 INFO Session locking original & magic tables is 2453584
2017-07-04 16:19:37 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156377609069734
2017-07-04 16:19:37 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m40s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:412917574; State: migrating; ETA: due
2017-07-04 16:19:39 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:19:39 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:39 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:39 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:19:40 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:40 ERROR 2017-07-04 16:19:40 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:40 INFO Looking for magic cut-over table
2017-07-04 16:19:40 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:40 INFO Dropping magic cut-over table
2017-07-04 16:19:40 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:40 INFO Tables unlocked
2017-07-04 16:19:41 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:19:41 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:41 INFO Looking for magic cut-over table
2017-07-04 16:19:41 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:41 INFO Magic cut-over table created
2017-07-04 16:19:41 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:41 INFO Tables locked
2017-07-04 16:19:41 INFO Session locking original & magic tables is 2453679
2017-07-04 16:19:41 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156381631598895
2017-07-04 16:19:41 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m45s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:342010435; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 409336449, the last byte read from './SVR14883DE630-bin.001333' at 409336449.
2017-07-04 16:19:44 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:44 ERROR 2017-07-04 16:19:44 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:44 INFO Looking for magic cut-over table
2017-07-04 16:19:44 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:44 INFO Dropping magic cut-over table
2017-07-04 16:19:44 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:44 INFO Tables unlocked
2017-07-04 16:19:45 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:19:45 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:45 INFO Looking for magic cut-over table
2017-07-04 16:19:45 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:45 INFO Magic cut-over table created
2017-07-04 16:19:45 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:45 INFO Tables locked
2017-07-04 16:19:45 INFO Session locking original & magic tables is 2453584
2017-07-04 16:19:45 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156385639145462
2017-07-04 16:19:45 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m50s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:409336449; State: migrating; ETA: due
2017-07-04 16:19:48 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:48 ERROR 2017-07-04 16:19:48 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:48 INFO Looking for magic cut-over table
2017-07-04 16:19:48 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:48 INFO Dropping magic cut-over table
2017-07-04 16:19:48 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:48 INFO Tables unlocked
2017-07-04 16:19:49 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:19:49 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:49 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:49 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:19:49 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:19:49 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:49 INFO Looking for magic cut-over table
2017-07-04 16:19:49 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:49 INFO Magic cut-over table created
2017-07-04 16:19:49 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:49 INFO Tables locked
2017-07-04 16:19:49 INFO Session locking original & magic tables is 2453679
2017-07-04 16:19:49 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156389664808015
2017-07-04 16:19:49 INFO Waiting for events up to lock
2017-07-04 16:19:52 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:52 ERROR 2017-07-04 16:19:52 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:52 INFO Looking for magic cut-over table
2017-07-04 16:19:52 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:52 INFO Dropping magic cut-over table
2017-07-04 16:19:52 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:52 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 2m55s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:344804285; State: migrating; ETA: due
2017-07-04 16:19:53 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:19:53 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:53 INFO Looking for magic cut-over table
2017-07-04 16:19:53 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:53 INFO Magic cut-over table created
2017-07-04 16:19:53 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:53 INFO Tables locked
2017-07-04 16:19:53 INFO Session locking original & magic tables is 2453584
2017-07-04 16:19:53 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156393683688720
2017-07-04 16:19:53 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 416651590, the last byte read from './SVR14883DE630-bin.001333' at 416651590.
2017-07-04 16:19:56 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:56 ERROR 2017-07-04 16:19:56 ERROR Timeout while waiting for events up to lock
2017-07-04 16:19:56 INFO Looking for magic cut-over table
2017-07-04 16:19:56 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:19:56 INFO Dropping magic cut-over table
2017-07-04 16:19:56 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:56 INFO Tables unlocked
2017-07-04 16:19:57 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:19:57 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:19:57 INFO Looking for magic cut-over table
2017-07-04 16:19:57 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:19:57 INFO Magic cut-over table created
2017-07-04 16:19:57 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:19:57 INFO Tables locked
2017-07-04 16:19:57 INFO Session locking original & magic tables is 2453679
2017-07-04 16:19:57 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156397693895855
2017-07-04 16:19:57 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m0s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:416651590; State: migrating; ETA: due
2017-07-04 16:19:59 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:19:59 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:59 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:59 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:20:00 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:00 ERROR 2017-07-04 16:20:00 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:00 INFO Looking for magic cut-over table
2017-07-04 16:20:00 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:00 INFO Dropping magic cut-over table
2017-07-04 16:20:00 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:00 INFO Tables unlocked
2017-07-04 16:20:01 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:20:01 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:01 INFO Looking for magic cut-over table
2017-07-04 16:20:01 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:01 INFO Magic cut-over table created
2017-07-04 16:20:01 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:01 INFO Tables locked
2017-07-04 16:20:01 INFO Session locking original & magic tables is 2453584
2017-07-04 16:20:01 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156401704678848
2017-07-04 16:20:01 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m5s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:334253472; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 410481292, the last byte read from './SVR14883DE630-bin.001333' at 410481292.
2017-07-04 16:20:04 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:04 ERROR 2017-07-04 16:20:04 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:04 INFO Looking for magic cut-over table
2017-07-04 16:20:04 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:04 INFO Dropping magic cut-over table
2017-07-04 16:20:04 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:04 INFO Tables unlocked
2017-07-04 16:20:05 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:20:05 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:05 INFO Looking for magic cut-over table
2017-07-04 16:20:05 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:05 INFO Magic cut-over table created
2017-07-04 16:20:05 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:05 INFO Tables locked
2017-07-04 16:20:05 INFO Session locking original & magic tables is 2453679
2017-07-04 16:20:05 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156405720938325
2017-07-04 16:20:05 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m10s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:410481292; State: migrating; ETA: due
2017-07-04 16:20:08 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:08 ERROR 2017-07-04 16:20:08 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:08 INFO Looking for magic cut-over table
2017-07-04 16:20:08 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:08 INFO Dropping magic cut-over table
2017-07-04 16:20:08 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:08 INFO Tables unlocked
2017-07-04 16:20:09 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:20:09 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:09 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:09 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:20:09 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:20:09 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:09 INFO Looking for magic cut-over table
2017-07-04 16:20:09 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:09 INFO Magic cut-over table created
2017-07-04 16:20:09 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:09 INFO Tables locked
2017-07-04 16:20:09 INFO Session locking original & magic tables is 2453584
2017-07-04 16:20:09 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156409733576909
2017-07-04 16:20:09 INFO Waiting for events up to lock
2017-07-04 16:20:12 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:12 ERROR 2017-07-04 16:20:12 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:12 INFO Looking for magic cut-over table
2017-07-04 16:20:12 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:12 INFO Dropping magic cut-over table
2017-07-04 16:20:12 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:12 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m15s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:333547175; State: migrating; ETA: due
2017-07-04 16:20:13 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:20:13 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:13 INFO Looking for magic cut-over table
2017-07-04 16:20:13 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:13 INFO Magic cut-over table created
2017-07-04 16:20:13 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:13 INFO Tables locked
2017-07-04 16:20:13 INFO Session locking original & magic tables is 2453679
2017-07-04 16:20:13 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156413741719618
2017-07-04 16:20:13 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 414166555, the last byte read from './SVR14883DE630-bin.001333' at 414166555.
2017-07-04 16:20:16 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:16 ERROR 2017-07-04 16:20:16 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:16 INFO Looking for magic cut-over table
2017-07-04 16:20:16 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:16 INFO Dropping magic cut-over table
2017-07-04 16:20:16 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:16 INFO Tables unlocked
2017-07-04 16:20:17 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:20:17 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:17 INFO Looking for magic cut-over table
2017-07-04 16:20:17 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:17 INFO Magic cut-over table created
2017-07-04 16:20:17 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:17 INFO Tables locked
2017-07-04 16:20:17 INFO Session locking original & magic tables is 2453584
2017-07-04 16:20:17 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156417748200072
2017-07-04 16:20:17 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m20s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:414166555; State: migrating; ETA: due
2017-07-04 16:20:19 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:20:19 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:19 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:19 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:20:20 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:20 ERROR 2017-07-04 16:20:20 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:20 INFO Looking for magic cut-over table
2017-07-04 16:20:20 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:20 INFO Dropping magic cut-over table
2017-07-04 16:20:20 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:20 INFO Tables unlocked
2017-07-04 16:20:21 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:20:21 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:21 INFO Looking for magic cut-over table
2017-07-04 16:20:21 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:21 INFO Magic cut-over table created
2017-07-04 16:20:21 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:21 INFO Tables locked
2017-07-04 16:20:21 INFO Session locking original & magic tables is 2453679
2017-07-04 16:20:21 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156421828407901
2017-07-04 16:20:21 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m25s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:332322021; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 416570822, the last byte read from './SVR14883DE630-bin.001333' at 416570822.
2017-07-04 16:20:24 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:24 ERROR 2017-07-04 16:20:24 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:24 INFO Looking for magic cut-over table
2017-07-04 16:20:24 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:24 INFO Dropping magic cut-over table
2017-07-04 16:20:24 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:24 INFO Tables unlocked
2017-07-04 16:20:25 INFO Grabbing voluntary lock: gh-ost.2453584.lock
2017-07-04 16:20:25 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:25 INFO Looking for magic cut-over table
2017-07-04 16:20:25 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:25 INFO Magic cut-over table created
2017-07-04 16:20:25 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:25 INFO Tables locked
2017-07-04 16:20:25 INFO Session locking original & magic tables is 2453584
2017-07-04 16:20:25 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156425836078689
2017-07-04 16:20:25 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m30s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:416570822; State: migrating; ETA: due
2017-07-04 16:20:28 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:28 ERROR 2017-07-04 16:20:28 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:28 INFO Looking for magic cut-over table
2017-07-04 16:20:28 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:28 INFO Dropping magic cut-over table
2017-07-04 16:20:28 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:28 INFO Tables unlocked
2017-07-04 16:20:29 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:20:29 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:29 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:29 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:20:29 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:20:29 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:29 INFO Looking for magic cut-over table
2017-07-04 16:20:29 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:29 INFO Magic cut-over table created
2017-07-04 16:20:29 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:29 INFO Tables locked
2017-07-04 16:20:29 INFO Session locking original & magic tables is 2453679
2017-07-04 16:20:29 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156429842284856
2017-07-04 16:20:29 INFO Waiting for events up to lock
2017-07-04 16:20:32 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:32 ERROR 2017-07-04 16:20:32 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:32 INFO Looking for magic cut-over table
2017-07-04 16:20:32 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:32 INFO Dropping magic cut-over table
2017-07-04 16:20:32 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:32 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m35s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:324915092; State: migrating; ETA: due
2017-07-04 16:20:33 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:20:33 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:33 INFO Looking for magic cut-over table
2017-07-04 16:20:33 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:33 INFO Magic cut-over table created
2017-07-04 16:20:33 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:33 INFO Tables locked
2017-07-04 16:20:33 INFO Session locking original & magic tables is 2453749
2017-07-04 16:20:33 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156433862236065
2017-07-04 16:20:33 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 414855511, the last byte read from './SVR14883DE630-bin.001333' at 414855511.
2017-07-04 16:20:36 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:36 ERROR 2017-07-04 16:20:36 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:36 INFO Looking for magic cut-over table
2017-07-04 16:20:36 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:36 INFO Dropping magic cut-over table
2017-07-04 16:20:36 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:36 INFO Tables unlocked
2017-07-04 16:20:37 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:20:37 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:37 INFO Looking for magic cut-over table
2017-07-04 16:20:37 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:37 INFO Magic cut-over table created
2017-07-04 16:20:37 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:37 INFO Tables locked
2017-07-04 16:20:37 INFO Session locking original & magic tables is 2453679
2017-07-04 16:20:37 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156437870548775
2017-07-04 16:20:37 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m40s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:414855511; State: migrating; ETA: due
2017-07-04 16:20:39 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:20:39 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:39 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:39 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:20:40 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:40 ERROR 2017-07-04 16:20:40 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:40 INFO Looking for magic cut-over table
2017-07-04 16:20:40 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:40 INFO Dropping magic cut-over table
2017-07-04 16:20:40 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:40 INFO Tables unlocked
2017-07-04 16:20:41 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:20:41 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:41 INFO Looking for magic cut-over table
2017-07-04 16:20:41 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:41 INFO Magic cut-over table created
2017-07-04 16:20:41 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:41 INFO Tables locked
2017-07-04 16:20:41 INFO Session locking original & magic tables is 2453749
2017-07-04 16:20:41 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156441876837319
2017-07-04 16:20:41 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m45s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:318791669; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 413916122, the last byte read from './SVR14883DE630-bin.001333' at 413916122.
2017-07-04 16:20:44 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:44 ERROR 2017-07-04 16:20:44 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:44 INFO Looking for magic cut-over table
2017-07-04 16:20:44 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:44 INFO Dropping magic cut-over table
2017-07-04 16:20:44 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:44 INFO Tables unlocked
2017-07-04 16:20:45 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:20:45 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:45 INFO Looking for magic cut-over table
2017-07-04 16:20:45 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:45 INFO Magic cut-over table created
2017-07-04 16:20:45 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:45 INFO Tables locked
2017-07-04 16:20:45 INFO Session locking original & magic tables is 2453679
2017-07-04 16:20:45 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156445883368162
2017-07-04 16:20:45 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m50s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:413916122; State: migrating; ETA: due
2017-07-04 16:20:48 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:48 ERROR 2017-07-04 16:20:48 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:48 INFO Looking for magic cut-over table
2017-07-04 16:20:48 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:48 INFO Dropping magic cut-over table
2017-07-04 16:20:48 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:48 INFO Tables unlocked
2017-07-04 16:20:49 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:20:49 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:49 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:49 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:20:49 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:20:49 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:49 INFO Looking for magic cut-over table
2017-07-04 16:20:49 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:49 INFO Magic cut-over table created
2017-07-04 16:20:49 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:49 INFO Tables locked
2017-07-04 16:20:49 INFO Session locking original & magic tables is 2453749
2017-07-04 16:20:49 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156449891681925
2017-07-04 16:20:49 INFO Waiting for events up to lock
2017-07-04 16:20:52 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:52 ERROR 2017-07-04 16:20:52 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:52 INFO Looking for magic cut-over table
2017-07-04 16:20:52 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:52 INFO Dropping magic cut-over table
2017-07-04 16:20:52 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:52 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 3m55s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:313366248; State: migrating; ETA: due
2017-07-04 16:20:53 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:20:53 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:53 INFO Looking for magic cut-over table
2017-07-04 16:20:53 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:53 INFO Magic cut-over table created
2017-07-04 16:20:53 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:53 INFO Tables locked
2017-07-04 16:20:53 INFO Session locking original & magic tables is 2453679
2017-07-04 16:20:53 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156453899029727
2017-07-04 16:20:53 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 415820692, the last byte read from './SVR14883DE630-bin.001333' at 415820692.
2017-07-04 16:20:56 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:56 ERROR 2017-07-04 16:20:56 ERROR Timeout while waiting for events up to lock
2017-07-04 16:20:56 INFO Looking for magic cut-over table
2017-07-04 16:20:56 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:20:56 INFO Dropping magic cut-over table
2017-07-04 16:20:56 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:56 INFO Tables unlocked
2017-07-04 16:20:57 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:20:57 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:20:57 INFO Looking for magic cut-over table
2017-07-04 16:20:57 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:20:57 INFO Magic cut-over table created
2017-07-04 16:20:57 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:20:57 INFO Tables locked
2017-07-04 16:20:57 INFO Session locking original & magic tables is 2453749
2017-07-04 16:20:57 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156457906246684
2017-07-04 16:20:57 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m0s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:415820692; State: migrating; ETA: due
2017-07-04 16:20:59 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:20:59 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:59 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:59 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:21:00 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:00 ERROR 2017-07-04 16:21:00 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:00 INFO Looking for magic cut-over table
2017-07-04 16:21:00 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:00 INFO Dropping magic cut-over table
2017-07-04 16:21:00 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:00 INFO Tables unlocked
2017-07-04 16:21:01 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:21:01 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:01 INFO Looking for magic cut-over table
2017-07-04 16:21:01 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:01 INFO Magic cut-over table created
2017-07-04 16:21:01 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:01 INFO Tables locked
2017-07-04 16:21:01 INFO Session locking original & magic tables is 2453679
2017-07-04 16:21:01 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156461912377541
2017-07-04 16:21:01 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m5s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:310393115; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 418997074, the last byte read from './SVR14883DE630-bin.001333' at 418997074.
2017-07-04 16:21:04 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:04 ERROR 2017-07-04 16:21:04 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:04 INFO Looking for magic cut-over table
2017-07-04 16:21:04 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:04 INFO Dropping magic cut-over table
2017-07-04 16:21:04 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:04 INFO Tables unlocked
2017-07-04 16:21:05 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:21:05 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:05 INFO Looking for magic cut-over table
2017-07-04 16:21:05 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:05 INFO Magic cut-over table created
2017-07-04 16:21:05 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:05 INFO Tables locked
2017-07-04 16:21:05 INFO Session locking original & magic tables is 2453749
2017-07-04 16:21:05 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156465919298817
2017-07-04 16:21:05 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m10s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:418989054; State: migrating; ETA: due
2017-07-04 16:21:08 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:08 ERROR 2017-07-04 16:21:08 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:08 INFO Looking for magic cut-over table
2017-07-04 16:21:08 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:08 INFO Dropping magic cut-over table
2017-07-04 16:21:08 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:08 INFO Tables unlocked
2017-07-04 16:21:09 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:21:09 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:09 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:09 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:21:09 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:21:09 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:09 INFO Looking for magic cut-over table
2017-07-04 16:21:09 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:09 INFO Magic cut-over table created
2017-07-04 16:21:09 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:09 INFO Tables locked
2017-07-04 16:21:09 INFO Session locking original & magic tables is 2453679
2017-07-04 16:21:09 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156469927526701
2017-07-04 16:21:09 INFO Waiting for events up to lock
2017-07-04 16:21:12 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:12 ERROR 2017-07-04 16:21:12 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:12 INFO Looking for magic cut-over table
2017-07-04 16:21:12 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:12 INFO Dropping magic cut-over table
2017-07-04 16:21:12 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:12 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m15s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:308511401; State: migrating; ETA: due
2017-07-04 16:21:13 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:21:13 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:13 INFO Looking for magic cut-over table
2017-07-04 16:21:13 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:13 INFO Magic cut-over table created
2017-07-04 16:21:13 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:13 INFO Tables locked
2017-07-04 16:21:13 INFO Session locking original & magic tables is 2453749
2017-07-04 16:21:13 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156473933607533
2017-07-04 16:21:13 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 421560788, the last byte read from './SVR14883DE630-bin.001333' at 421560788.
2017-07-04 16:21:16 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:16 ERROR 2017-07-04 16:21:16 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:16 INFO Looking for magic cut-over table
2017-07-04 16:21:16 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:16 INFO Dropping magic cut-over table
2017-07-04 16:21:16 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:16 INFO Tables unlocked
2017-07-04 16:21:17 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:21:17 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:17 INFO Looking for magic cut-over table
2017-07-04 16:21:17 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:17 INFO Magic cut-over table created
2017-07-04 16:21:17 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:17 INFO Tables locked
2017-07-04 16:21:17 INFO Session locking original & magic tables is 2453679
2017-07-04 16:21:17 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156477939474616
2017-07-04 16:21:17 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m20s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:421560788; State: migrating; ETA: due
2017-07-04 16:21:19 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:21:19 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:19 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:19 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:21:20 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:20 ERROR 2017-07-04 16:21:20 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:20 INFO Looking for magic cut-over table
2017-07-04 16:21:20 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:20 INFO Dropping magic cut-over table
2017-07-04 16:21:20 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:20 INFO Tables unlocked
2017-07-04 16:21:21 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:21:21 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:21 INFO Looking for magic cut-over table
2017-07-04 16:21:21 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:21 INFO Magic cut-over table created
2017-07-04 16:21:21 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:21 INFO Tables locked
2017-07-04 16:21:21 INFO Session locking original & magic tables is 2453749
2017-07-04 16:21:21 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156481946000657
2017-07-04 16:21:21 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m25s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:298584905; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 416586978, the last byte read from './SVR14883DE630-bin.001333' at 416586978.
2017-07-04 16:21:24 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:24 ERROR 2017-07-04 16:21:24 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:24 INFO Looking for magic cut-over table
2017-07-04 16:21:24 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:24 INFO Dropping magic cut-over table
2017-07-04 16:21:24 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:24 INFO Tables unlocked
2017-07-04 16:21:25 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:21:25 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:25 INFO Looking for magic cut-over table
2017-07-04 16:21:25 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:25 INFO Magic cut-over table created
2017-07-04 16:21:25 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:25 INFO Tables locked
2017-07-04 16:21:25 INFO Session locking original & magic tables is 2453679
2017-07-04 16:21:25 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156485952074801
2017-07-04 16:21:25 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m30s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:416586978; State: migrating; ETA: due
2017-07-04 16:21:28 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:28 ERROR 2017-07-04 16:21:28 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:28 INFO Looking for magic cut-over table
2017-07-04 16:21:28 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:28 INFO Dropping magic cut-over table
2017-07-04 16:21:28 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:28 INFO Tables unlocked
2017-07-04 16:21:29 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:21:29 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:29 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:29 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:21:29 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:21:29 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:29 INFO Looking for magic cut-over table
2017-07-04 16:21:29 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:29 INFO Magic cut-over table created
2017-07-04 16:21:29 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:29 INFO Tables locked
2017-07-04 16:21:29 INFO Session locking original & magic tables is 2453749
2017-07-04 16:21:29 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156489961063389
2017-07-04 16:21:29 INFO Waiting for events up to lock
2017-07-04 16:21:32 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:32 ERROR 2017-07-04 16:21:32 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:32 INFO Looking for magic cut-over table
2017-07-04 16:21:32 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:32 INFO Dropping magic cut-over table
2017-07-04 16:21:32 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:32 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m35s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:288025772; State: migrating; ETA: due
2017-07-04 16:21:33 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:21:33 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:33 INFO Looking for magic cut-over table
2017-07-04 16:21:33 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:33 INFO Magic cut-over table created
2017-07-04 16:21:33 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:33 INFO Tables locked
2017-07-04 16:21:33 INFO Session locking original & magic tables is 2453679
2017-07-04 16:21:33 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156493966672455
2017-07-04 16:21:33 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 410709029, the last byte read from './SVR14883DE630-bin.001333' at 410709029.
2017-07-04 16:21:36 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:36 ERROR 2017-07-04 16:21:36 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:36 INFO Looking for magic cut-over table
2017-07-04 16:21:36 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:36 INFO Dropping magic cut-over table
2017-07-04 16:21:36 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:36 INFO Tables unlocked
2017-07-04 16:21:37 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:21:37 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:37 INFO Looking for magic cut-over table
2017-07-04 16:21:37 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:37 INFO Magic cut-over table created
2017-07-04 16:21:37 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:37 INFO Tables locked
2017-07-04 16:21:37 INFO Session locking original & magic tables is 2453749
2017-07-04 16:21:37 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156497976074007
2017-07-04 16:21:37 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m40s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:410709029; State: migrating; ETA: due
2017-07-04 16:21:39 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:21:39 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:39 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:39 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:21:40 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:40 ERROR 2017-07-04 16:21:40 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:40 INFO Looking for magic cut-over table
2017-07-04 16:21:40 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:40 INFO Dropping magic cut-over table
2017-07-04 16:21:40 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:40 INFO Tables unlocked
2017-07-04 16:21:41 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:21:41 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:41 INFO Looking for magic cut-over table
2017-07-04 16:21:41 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:41 INFO Magic cut-over table created
2017-07-04 16:21:41 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:41 INFO Tables locked
2017-07-04 16:21:41 INFO Session locking original & magic tables is 2453679
2017-07-04 16:21:41 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156501983025702
2017-07-04 16:21:41 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m45s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:289029778; State: migrating; ETA: due
nt read from './SVR14883DE630-bin.001333' at 413492187, the last byte read from './SVR14883DE630-bin.001333' at 413492187.
2017-07-04 16:21:44 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:44 ERROR 2017-07-04 16:21:44 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:44 INFO Looking for magic cut-over table
2017-07-04 16:21:44 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:44 INFO Dropping magic cut-over table
2017-07-04 16:21:44 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:44 INFO Tables unlocked
2017-07-04 16:21:45 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:21:45 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:45 INFO Looking for magic cut-over table
2017-07-04 16:21:45 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:45 INFO Magic cut-over table created
2017-07-04 16:21:45 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:45 INFO Tables locked
2017-07-04 16:21:45 INFO Session locking original & magic tables is 2453749
2017-07-04 16:21:45 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156505989204036
2017-07-04 16:21:45 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m50s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:413492187; State: migrating; ETA: due
2017-07-04 16:21:48 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:48 ERROR 2017-07-04 16:21:48 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:48 INFO Looking for magic cut-over table
2017-07-04 16:21:48 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:48 INFO Dropping magic cut-over table
2017-07-04 16:21:48 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:48 INFO Tables unlocked
2017-07-04 16:21:49 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:21:49 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:49 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:49 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:21:49 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:21:49 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:49 INFO Looking for magic cut-over table
2017-07-04 16:21:49 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:49 INFO Magic cut-over table created
2017-07-04 16:21:49 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:49 INFO Tables locked
2017-07-04 16:21:49 INFO Session locking original & magic tables is 2453679
2017-07-04 16:21:49 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156509995128035
2017-07-04 16:21:49 INFO Waiting for events up to lock
2017-07-04 16:21:52 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:52 ERROR 2017-07-04 16:21:52 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:52 INFO Looking for magic cut-over table
2017-07-04 16:21:52 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:52 INFO Dropping magic cut-over table
2017-07-04 16:21:53 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:53 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 4m55s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:282327089; State: migrating; ETA: due
2017-07-04 16:21:53 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:21:53 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:53 INFO Looking for magic cut-over table
2017-07-04 16:21:53 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:54 INFO Magic cut-over table created
2017-07-04 16:21:54 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:54 INFO Tables locked
2017-07-04 16:21:54 INFO Session locking original & magic tables is 2453749
2017-07-04 16:21:54 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156514001966300
2017-07-04 16:21:54 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 415800093, the last byte read from './SVR14883DE630-bin.001333' at 415800093.
2017-07-04 16:21:57 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:57 ERROR 2017-07-04 16:21:57 ERROR Timeout while waiting for events up to lock
2017-07-04 16:21:57 INFO Looking for magic cut-over table
2017-07-04 16:21:57 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:21:57 INFO Dropping magic cut-over table
2017-07-04 16:21:57 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:57 INFO Tables unlocked
2017-07-04 16:21:58 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:21:58 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:21:58 INFO Looking for magic cut-over table
2017-07-04 16:21:58 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:21:58 INFO Magic cut-over table created
2017-07-04 16:21:58 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:21:58 INFO Tables locked
2017-07-04 16:21:58 INFO Session locking original & magic tables is 2453679
2017-07-04 16:21:58 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156518010061087
2017-07-04 16:21:58 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m0s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:415800093; State: migrating; ETA: due
2017-07-04 16:22:00 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:22:00 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:00 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:00 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:22:01 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:01 ERROR 2017-07-04 16:22:01 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:01 INFO Looking for magic cut-over table
2017-07-04 16:22:01 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:01 INFO Dropping magic cut-over table
2017-07-04 16:22:01 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:01 INFO Tables unlocked
2017-07-04 16:22:02 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:22:02 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:02 INFO Looking for magic cut-over table
2017-07-04 16:22:02 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:02 INFO Magic cut-over table created
2017-07-04 16:22:02 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:02 INFO Tables locked
2017-07-04 16:22:02 INFO Session locking original & magic tables is 2453749
2017-07-04 16:22:02 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156522017540619
2017-07-04 16:22:02 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m5s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:276841212; State: migrating; ETA: due
2017-07-04 16:22:05 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:05 ERROR 2017-07-04 16:22:05 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:05 INFO Looking for magic cut-over table
2017-07-04 16:22:05 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:05 INFO Dropping magic cut-over table
2017-07-04 16:22:05 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:05 INFO Tables unlocked
nt read from './SVR14883DE630-bin.001333' at 410643768, the last byte read from './SVR14883DE630-bin.001333' at 410643768.
2017-07-04 16:22:06 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:22:06 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:06 INFO Looking for magic cut-over table
2017-07-04 16:22:06 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:06 INFO Magic cut-over table created
2017-07-04 16:22:06 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:06 INFO Tables locked
2017-07-04 16:22:06 INFO Session locking original & magic tables is 2453679
2017-07-04 16:22:06 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156526023123163
2017-07-04 16:22:06 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m10s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:410631291; State: migrating; ETA: due
2017-07-04 16:22:09 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:09 ERROR 2017-07-04 16:22:09 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:09 INFO Looking for magic cut-over table
2017-07-04 16:22:09 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:09 INFO Dropping magic cut-over table
2017-07-04 16:22:09 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:09 INFO Tables unlocked
2017-07-04 16:22:10 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:22:10 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:10 INFO Looking for magic cut-over table
2017-07-04 16:22:10 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:10 INFO Magic cut-over table created
2017-07-04 16:22:10 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:10 INFO Tables locked
2017-07-04 16:22:10 INFO Session locking original & magic tables is 2453749
2017-07-04 16:22:10 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156530031300523
2017-07-04 16:22:10 INFO Waiting for events up to lock
2017-07-04 16:22:10 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:22:10 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:10 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:10 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:22:13 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:13 ERROR 2017-07-04 16:22:13 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:13 INFO Looking for magic cut-over table
2017-07-04 16:22:13 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:13 INFO Dropping magic cut-over table
2017-07-04 16:22:13 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:13 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m15s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:272882630; State: migrating; ETA: due
2017-07-04 16:22:14 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:22:14 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:14 INFO Looking for magic cut-over table
2017-07-04 16:22:14 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:14 INFO Magic cut-over table created
2017-07-04 16:22:14 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:14 INFO Tables locked
2017-07-04 16:22:14 INFO Session locking original & magic tables is 2453679
2017-07-04 16:22:14 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156534039817071
2017-07-04 16:22:14 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 413771357, the last byte read from './SVR14883DE630-bin.001333' at 413771357.
2017-07-04 16:22:17 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:17 ERROR 2017-07-04 16:22:17 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:17 INFO Looking for magic cut-over table
2017-07-04 16:22:17 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:17 INFO Dropping magic cut-over table
2017-07-04 16:22:17 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:17 INFO Tables unlocked
2017-07-04 16:22:18 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:22:18 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:18 INFO Looking for magic cut-over table
2017-07-04 16:22:18 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:18 INFO Magic cut-over table created
2017-07-04 16:22:18 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:18 INFO Tables locked
2017-07-04 16:22:18 INFO Session locking original & magic tables is 2453749
2017-07-04 16:22:18 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156538046132555
2017-07-04 16:22:18 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m20s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:413771357; State: migrating; ETA: due
2017-07-04 16:22:20 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:22:20 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:20 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:20 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:22:21 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:21 ERROR 2017-07-04 16:22:21 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:21 INFO Looking for magic cut-over table
2017-07-04 16:22:21 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:21 INFO Dropping magic cut-over table
2017-07-04 16:22:21 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:21 INFO Tables unlocked
2017-07-04 16:22:22 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:22:22 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:22 INFO Looking for magic cut-over table
2017-07-04 16:22:22 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:22 INFO Magic cut-over table created
2017-07-04 16:22:22 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:22 INFO Tables locked
2017-07-04 16:22:22 INFO Session locking original & magic tables is 2453679
2017-07-04 16:22:22 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156542053288839
2017-07-04 16:22:22 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m25s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:268510184; State: migrating; ETA: due
2017-07-04 16:22:25 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:25 ERROR 2017-07-04 16:22:25 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:25 INFO Looking for magic cut-over table
2017-07-04 16:22:25 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:25 INFO Dropping magic cut-over table
2017-07-04 16:22:25 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:25 INFO Tables unlocked
nt read from './SVR14883DE630-bin.001333' at 413508279, the last byte read from './SVR14883DE630-bin.001333' at 413508279.
2017-07-04 16:22:26 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:22:26 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:26 INFO Looking for magic cut-over table
2017-07-04 16:22:26 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:26 INFO Magic cut-over table created
2017-07-04 16:22:26 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:26 INFO Tables locked
2017-07-04 16:22:26 INFO Session locking original & magic tables is 2453749
2017-07-04 16:22:26 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156546060729156
2017-07-04 16:22:26 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m30s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:413508279; State: migrating; ETA: due
2017-07-04 16:22:29 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:29 ERROR 2017-07-04 16:22:29 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:29 INFO Looking for magic cut-over table
2017-07-04 16:22:29 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:29 INFO Dropping magic cut-over table
2017-07-04 16:22:29 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:29 INFO Tables unlocked
2017-07-04 16:22:30 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:22:30 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:30 INFO Looking for magic cut-over table
2017-07-04 16:22:30 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:30 INFO Magic cut-over table created
2017-07-04 16:22:30 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:30 INFO Tables locked
2017-07-04 16:22:30 INFO Session locking original & magic tables is 2453679
2017-07-04 16:22:30 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156550082658114
2017-07-04 16:22:30 INFO Waiting for events up to lock
2017-07-04 16:22:30 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:22:30 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:30 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:30 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:22:33 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:33 ERROR 2017-07-04 16:22:33 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:33 INFO Looking for magic cut-over table
2017-07-04 16:22:33 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:33 INFO Dropping magic cut-over table
2017-07-04 16:22:33 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:33 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m35s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:263266079; State: migrating; ETA: due
2017-07-04 16:22:34 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:22:34 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:34 INFO Looking for magic cut-over table
2017-07-04 16:22:34 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:34 INFO Magic cut-over table created
2017-07-04 16:22:34 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:34 INFO Tables locked
2017-07-04 16:22:34 INFO Session locking original & magic tables is 2453749
2017-07-04 16:22:34 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156554089546239
2017-07-04 16:22:34 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 414050715, the last byte read from './SVR14883DE630-bin.001333' at 414050715.
2017-07-04 16:22:37 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:37 ERROR 2017-07-04 16:22:37 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:37 INFO Looking for magic cut-over table
2017-07-04 16:22:37 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:37 INFO Dropping magic cut-over table
2017-07-04 16:22:37 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:37 INFO Tables unlocked
2017-07-04 16:22:38 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:22:38 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:38 INFO Looking for magic cut-over table
2017-07-04 16:22:38 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:38 INFO Magic cut-over table created
2017-07-04 16:22:38 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:38 INFO Tables locked
2017-07-04 16:22:38 INFO Session locking original & magic tables is 2453679
2017-07-04 16:22:38 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156558095370338
2017-07-04 16:22:38 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m40s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:414050715; State: migrating; ETA: due
2017-07-04 16:22:40 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:22:40 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:40 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:40 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:22:41 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:41 ERROR 2017-07-04 16:22:41 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:41 INFO Looking for magic cut-over table
2017-07-04 16:22:41 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:41 INFO Dropping magic cut-over table
2017-07-04 16:22:41 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:41 INFO Tables unlocked
2017-07-04 16:22:42 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:22:42 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:42 INFO Looking for magic cut-over table
2017-07-04 16:22:42 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:42 INFO Magic cut-over table created
2017-07-04 16:22:42 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:42 INFO Tables locked
2017-07-04 16:22:42 INFO Session locking original & magic tables is 2453749
2017-07-04 16:22:42 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156562102540948
2017-07-04 16:22:42 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m45s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:258545604; State: migrating; ETA: due
2017-07-04 16:22:45 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:45 ERROR 2017-07-04 16:22:45 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:45 INFO Looking for magic cut-over table
2017-07-04 16:22:45 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:45 INFO Dropping magic cut-over table
2017-07-04 16:22:45 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:45 INFO Tables unlocked
nt read from './SVR14883DE630-bin.001333' at 411118339, the last byte read from './SVR14883DE630-bin.001333' at 411118339.
2017-07-04 16:22:46 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:22:46 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:46 INFO Looking for magic cut-over table
2017-07-04 16:22:46 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:46 INFO Magic cut-over table created
2017-07-04 16:22:46 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:46 INFO Tables locked
2017-07-04 16:22:46 INFO Session locking original & magic tables is 2453679
2017-07-04 16:22:46 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156566109802615
2017-07-04 16:22:46 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m50s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:411118339; State: migrating; ETA: due
2017-07-04 16:22:49 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:49 ERROR 2017-07-04 16:22:49 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:49 INFO Looking for magic cut-over table
2017-07-04 16:22:49 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:49 INFO Dropping magic cut-over table
2017-07-04 16:22:49 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:49 INFO Tables unlocked
2017-07-04 16:22:50 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:22:50 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:50 INFO Looking for magic cut-over table
2017-07-04 16:22:50 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:50 INFO Magic cut-over table created
2017-07-04 16:22:50 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:50 INFO Tables locked
2017-07-04 16:22:50 INFO Session locking original & magic tables is 2453749
2017-07-04 16:22:50 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156570116519571
2017-07-04 16:22:50 INFO Waiting for events up to lock
2017-07-04 16:22:50 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:22:50 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:50 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:50 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:22:53 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:53 ERROR 2017-07-04 16:22:53 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:53 INFO Looking for magic cut-over table
2017-07-04 16:22:53 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:53 INFO Dropping magic cut-over table
2017-07-04 16:22:53 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:53 INFO Tables unlocked
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 5m55s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:250712520; State: migrating; ETA: due
2017-07-04 16:22:54 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:22:54 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:54 INFO Looking for magic cut-over table
2017-07-04 16:22:54 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:54 INFO Magic cut-over table created
2017-07-04 16:22:54 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:54 INFO Tables locked
2017-07-04 16:22:54 INFO Session locking original & magic tables is 2453679
2017-07-04 16:22:54 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156574122077066
2017-07-04 16:22:54 INFO Waiting for events up to lock
nt read from './SVR14883DE630-bin.001333' at 410679086, the last byte read from './SVR14883DE630-bin.001333' at 410679086.
2017-07-04 16:22:57 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:57 ERROR 2017-07-04 16:22:57 ERROR Timeout while waiting for events up to lock
2017-07-04 16:22:57 INFO Looking for magic cut-over table
2017-07-04 16:22:57 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:22:57 INFO Dropping magic cut-over table
2017-07-04 16:22:57 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:57 INFO Tables unlocked
2017-07-04 16:22:58 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:22:58 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:22:58 INFO Looking for magic cut-over table
2017-07-04 16:22:58 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:22:58 INFO Magic cut-over table created
2017-07-04 16:22:58 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:22:58 INFO Tables locked
2017-07-04 16:22:58 INFO Session locking original & magic tables is 2453749
2017-07-04 16:22:58 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156578137516280
2017-07-04 16:22:58 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 6m0s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:410679086; State: migrating; ETA: due
2017-07-04 16:23:00 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:23:00 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:23:00 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:23:00 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:23:01 ERROR Timeout while waiting for events up to lock
2017-07-04 16:23:01 ERROR 2017-07-04 16:23:01 ERROR Timeout while waiting for events up to lock
2017-07-04 16:23:01 INFO Looking for magic cut-over table
2017-07-04 16:23:01 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:23:01 INFO Dropping magic cut-over table
2017-07-04 16:23:01 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:23:01 INFO Tables unlocked
2017-07-04 16:23:02 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:23:02 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:23:02 INFO Looking for magic cut-over table
2017-07-04 16:23:02 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:23:02 INFO Magic cut-over table created
2017-07-04 16:23:02 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:23:02 INFO Tables locked
2017-07-04 16:23:02 INFO Session locking original & magic tables is 2453679
2017-07-04 16:23:02 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156582145771664
2017-07-04 16:23:02 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 6m5s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:248519671; State: migrating; ETA: due
2017-07-04 16:23:05 ERROR Timeout while waiting for events up to lock
2017-07-04 16:23:05 ERROR 2017-07-04 16:23:05 ERROR Timeout while waiting for events up to lock
2017-07-04 16:23:05 INFO Looking for magic cut-over table
2017-07-04 16:23:05 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:23:05 INFO Dropping magic cut-over table
2017-07-04 16:23:05 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:23:05 INFO Tables unlocked
nt read from './SVR14883DE630-bin.001333' at 410694552, the last byte read from './SVR14883DE630-bin.001333' at 410694552.
2017-07-04 16:23:06 INFO Grabbing voluntary lock: gh-ost.2453749.lock
2017-07-04 16:23:06 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:23:06 INFO Looking for magic cut-over table
2017-07-04 16:23:06 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:23:06 INFO Magic cut-over table created
2017-07-04 16:23:06 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:23:06 INFO Tables locked
2017-07-04 16:23:06 INFO Session locking original & magic tables is 2453749
2017-07-04 16:23:06 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156586162091297
2017-07-04 16:23:06 INFO Waiting for events up to lock
Copy: 4378153/4378153 100.0%; Applied: 0; Backlog: 0/100; Time: 6m10s(total), 2m12s(copy); streamer: SVR14883DE630-bin.001333:410694552; State: migrating; ETA: due
2017-07-04 16:23:09 ERROR Timeout while waiting for events up to lock
2017-07-04 16:23:09 ERROR 2017-07-04 16:23:09 ERROR Timeout while waiting for events up to lock
2017-07-04 16:23:09 INFO Looking for magic cut-over table
2017-07-04 16:23:09 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:23:09 INFO Dropping magic cut-over table
2017-07-04 16:23:09 INFO Releasing lock from `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:23:09 INFO Tables unlocked
2017-07-04 16:23:10 INFO Grabbing voluntary lock: gh-ost.2453679.lock
2017-07-04 16:23:10 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:23:10 INFO Looking for magic cut-over table
2017-07-04 16:23:10 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-04 16:23:10 INFO Magic cut-over table created
2017-07-04 16:23:10 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
2017-07-04 16:23:10 INFO Tables locked
2017-07-04 16:23:10 INFO Session locking original & magic tables is 2453679
2017-07-04 16:23:10 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156590175307362
2017-07-04 16:23:10 INFO Waiting for events up to lock
2017-07-04 16:23:10 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:1024346902
2017-07-04 16:23:10 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:23:10 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:23:10 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:23:13 ERROR Timeout while waiting for events up to lock
2017-07-04 16:23:13 ERROR 2017-07-04 16:23:13 ERROR Timeout while waiting for events up to lock
2017-07-04 16:23:13 INFO Looking for magic cut-over table
2017-07-04 16:23:13 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:23:13 INFO Dropping magic cut-over table
2017-07-04 16:23:13 INFO Removing socket file: /tmp/gh-ost.ghostdb.test1g.sock
2017-07-04 16:23:13 INFO executing gh-ost-on-failure hook: /tmp/gh-ost-on-failure.hook
2017-07-04 16:23:13 FATAL 2017-07-04 16:23:13 ERROR Timeout while waiting for events up to lock

Task 2's log:

2017-07-04 16:14:54 INFO starting gh-ost 1.0.30
2017-07-04 16:14:54 INFO Migrating `ghostdb`.`test10g`
2017-07-04 16:14:54 INFO executing gh-ost-on-startup hook: /tmp/gh-ost-on-startup.hook

2017-07-04 16:14:54 INFO connection validated on 10.28.77.43:55944
2017-07-04 16:14:54 INFO User has ALL privileges
2017-07-04 16:14:54 INFO binary logs validated on 10.28.77.43:55944
2017-07-04 16:14:54 INFO Restarting replication on 10.28.77.43:55944 to make sure binlog settings apply to replication thread
2017-07-04 16:14:54 INFO Table found. Engine=InnoDB
2017-07-04 16:14:54 INFO Estimated number of rows via EXPLAIN: 17919072
2017-07-04 16:14:54 INFO Recursively searching for replication master
2017-07-04 16:14:54 INFO Master found to be 10.28.77.42:55944
2017-07-04 16:14:54 INFO log_slave_updates validated on 10.28.77.43:55944
2017-07-04 16:14:54 INFO connection validated on 10.28.77.43:55944
2017-07-04 16:14:54 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:14:54 INFO Connecting binlog streamer at SVR14883DE630-bin.001332:875140569
2017-07-04 16:14:54 INFO rotate to next log name: SVR14883DE630-bin.001332
2017-07-04 16:14:54 INFO connection validated on 10.28.77.42:55944
2017-07-04 16:14:54 INFO connection validated on 10.28.77.42:55944
2017-07-04 16:14:54 INFO will use time_zone='SYSTEM' on applier
2017-07-04 16:14:54 INFO Examining table structure on applier
2017-07-04 16:14:54 INFO Droppping table `ghostdb`.`_test10g_gho`
2017-07-04 16:14:55 INFO Table dropped
2017-07-04 16:14:55 INFO Droppping table `ghostdb`.`_test10g_del`
2017-07-04 16:14:55 INFO Table dropped
2017-07-04 16:14:55 INFO Droppping table `ghostdb`.`_test10g_ghc`
2017-07-04 16:14:55 INFO Table dropped
2017-07-04 16:14:55 INFO Creating changelog table `ghostdb`.`_test10g_ghc`
2017-07-04 16:14:55 INFO Changelog table created
2017-07-04 16:14:55 INFO Creating ghost table `ghostdb`.`_test10g_gho`
2017-07-04 16:14:56 INFO Ghost table created
2017-07-04 16:14:56 INFO Altering ghost table `ghostdb`.`_test10g_gho`
2017-07-04 16:14:56 INFO Ghost table altered
2017-07-04 16:14:56 INFO Waiting for ghost table to be migrated. Current lag is 0s
2017-07-04 16:14:56 INFO Intercepted changelog state GhostTableMigrated
2017-07-04 16:14:56 INFO Handled changelog state GhostTableMigrated
2017-07-04 16:14:56 INFO Chosen shared unique key is PRIMARY
2017-07-04 16:14:56 INFO Shared columns are id,service_name,machine_name,host_name,logdate,processinfo,text,warn_level,insert_timestamp,addcol1,addcol20,addcol03,addcol05
2017-07-04 16:14:56 INFO Listening on unix socket file: /tmp/gh-ost.ghostdb.test10g.sock
2017-07-04 16:14:56 INFO Migration min values: [2936835671,2017-04-14 00:00:13]
2017-07-04 16:14:56 INFO Migration max values: [2955788520,2017-06-11 23:10:04]
2017-07-04 16:14:56 INFO Waiting for first throttle metrics to be collected
# Migrating `ghostdb`.`test10g`; Ghost table is `ghostdb`.`_test10g_gho`
# Migrating SVR14306DE630:55944; inspecting SVR14883DE630:55944; executing on SVR14883DE630
# Migration started at Tue Jul 04 16:14:54 +0800 2017
# chunk-size: 1000; max-lag-millis: 1500ms; max-load: Threads_connected=5000,Threads_running=5000; critical-load: ; nice-ratio: 0.000000
# throttle-flag-file: /tmp/gh-ost.ghostdb.test10g.throttle 
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# postpone-cut-over-flag-file: /tmp/gh-ost.ghostdb.test10g.postpone 
# Serving on unix socket: /tmp/gh-ost.ghostdb.test10g.sock
Copy: 0/17919072 0.0%; Applied: 0; Backlog: 0/100; Time: 1s(total), 0s(copy); streamer: SVR14883DE630-bin.001332:875143782; State: migrating; ETA: N/A
Copy: 0/17919072 0.0%; Applied: 0; Backlog: 0/100; Time: 2s(total), 1s(copy); streamer: SVR14883DE630-bin.001332:875145881; State: migrating; ETA: N/A
Copy: 7000/17919072 0.0%; Applied: 0; Backlog: 0/100; Time: 3s(total), 2s(copy); streamer: SVR14883DE630-bin.001332:876759248; State: migrating; ETA: N/A
Copy: 24000/17919072 0.1%; Applied: 0; Backlog: 0/100; Time: 4s(total), 3s(copy); streamer: SVR14883DE630-bin.001332:881418090; State: migrating; ETA: N/A
Copy: 53000/17919072 0.3%; Applied: 0; Backlog: 0/100; Time: 5s(total), 4s(copy); streamer: SVR14883DE630-bin.001332:888376412; State: migrating; ETA: N/A
Copy: 83000/17919072 0.5%; Applied: 0; Backlog: 0/100; Time: 6s(total), 5s(copy); streamer: SVR14883DE630-bin.001332:896988862; State: migrating; ETA: N/A
Copy: 117000/17919072 0.7%; Applied: 0; Backlog: 0/100; Time: 7s(total), 6s(copy); streamer: SVR14883DE630-bin.001332:904804884; State: migrating; ETA: N/A
Copy: 149000/17919072 0.8%; Applied: 0; Backlog: 0/100; Time: 8s(total), 7s(copy); streamer: SVR14883DE630-bin.001332:913874784; State: migrating; ETA: N/A
Copy: 181000/17919072 1.0%; Applied: 0; Backlog: 0/100; Time: 9s(total), 8s(copy); streamer: SVR14883DE630-bin.001332:921786706; State: migrating; ETA: 13m4s
Copy: 212000/17919072 1.2%; Applied: 0; Backlog: 0/100; Time: 10s(total), 9s(copy); streamer: SVR14883DE630-bin.001332:930419531; State: migrating; ETA: 12m31s
Copy: 243000/17919072 1.4%; Applied: 0; Backlog: 0/100; Time: 11s(total), 10s(copy); streamer: SVR14883DE630-bin.001332:938495404; State: migrating; ETA: 12m7s
Copy: 271000/17919072 1.5%; Applied: 0; Backlog: 0/100; Time: 12s(total), 11s(copy); streamer: SVR14883DE630-bin.001332:945013955; State: migrating; ETA: 11m56s
Copy: 302000/17919072 1.7%; Applied: 0; Backlog: 0/100; Time: 13s(total), 12s(copy); streamer: SVR14883DE630-bin.001332:953658932; State: migrating; ETA: 11m40s
Copy: 334000/17919072 1.9%; Applied: 0; Backlog: 0/100; Time: 14s(total), 13s(copy); streamer: SVR14883DE630-bin.001332:961900881; State: migrating; ETA: 11m24s
Copy: 367000/17919072 2.0%; Applied: 0; Backlog: 0/100; Time: 15s(total), 14s(copy); streamer: SVR14883DE630-bin.001332:969943403; State: migrating; ETA: 11m9s
Copy: 398000/17919072 2.2%; Applied: 0; Backlog: 0/100; Time: 16s(total), 15s(copy); streamer: SVR14883DE630-bin.001332:978310249; State: migrating; ETA: 11m0s
Copy: 430000/17919072 2.4%; Applied: 0; Backlog: 0/100; Time: 17s(total), 16s(copy); streamer: SVR14883DE630-bin.001332:986512079; State: migrating; ETA: 10m50s
Copy: 463000/17919072 2.6%; Applied: 0; Backlog: 0/100; Time: 18s(total), 17s(copy); streamer: SVR14883DE630-bin.001332:994769786; State: migrating; ETA: 10m40s
Copy: 495000/17919072 2.8%; Applied: 0; Backlog: 0/100; Time: 19s(total), 18s(copy); streamer: SVR14883DE630-bin.001332:1003011134; State: migrating; ETA: 10m33s
Copy: 523000/17919072 2.9%; Applied: 0; Backlog: 0/100; Time: 20s(total), 19s(copy); streamer: SVR14883DE630-bin.001332:1010274143; State: migrating; ETA: 10m32s
Copy: 556000/17919072 3.1%; Applied: 0; Backlog: 0/100; Time: 21s(total), 20s(copy); streamer: SVR14883DE630-bin.001332:1018579134; State: migrating; ETA: 10m24s
Copy: 589000/17919072 3.3%; Applied: 0; Backlog: 0/100; Time: 22s(total), 21s(copy); streamer: SVR14883DE630-bin.001332:1027470066; State: migrating; ETA: 10m17s
Copy: 622000/17919072 3.5%; Applied: 0; Backlog: 0/100; Time: 23s(total), 22s(copy); streamer: SVR14883DE630-bin.001332:1035605224; State: migrating; ETA: 10m11s
Copy: 656000/17919072 3.7%; Applied: 0; Backlog: 0/100; Time: 24s(total), 23s(copy); streamer: SVR14883DE630-bin.001332:1044139263; State: migrating; ETA: 10m5s
Copy: 688000/17919072 3.8%; Applied: 0; Backlog: 0/100; Time: 25s(total), 24s(copy); streamer: SVR14883DE630-bin.001332:1052076006; State: migrating; ETA: 10m1s
Copy: 721000/17919072 4.0%; Applied: 0; Backlog: 0/100; Time: 26s(total), 25s(copy); streamer: SVR14883DE630-bin.001332:1060245870; State: migrating; ETA: 9m56s
Copy: 753000/17919072 4.2%; Applied: 0; Backlog: 0/100; Time: 27s(total), 26s(copy); streamer: SVR14883DE630-bin.001332:1068526361; State: migrating; ETA: 9m52s
2017-07-04 16:15:23 INFO rotate to next log name: SVR14883DE630-bin.001333
2017-07-04 16:15:23 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 782000/17919072 4.4%; Applied: 0; Backlog: 0/100; Time: 28s(total), 27s(copy); streamer: SVR14883DE630-bin.001333:1716494; State: migrating; ETA: 9m51s
Copy: 814000/17919072 4.5%; Applied: 0; Backlog: 0/100; Time: 29s(total), 28s(copy); streamer: SVR14883DE630-bin.001333:9536037; State: migrating; ETA: 9m48s
Copy: 846000/17919072 4.7%; Applied: 0; Backlog: 0/100; Time: 30s(total), 29s(copy); streamer: SVR14883DE630-bin.001333:18289700; State: migrating; ETA: 9m45s
Copy: 879000/17919072 4.9%; Applied: 0; Backlog: 0/100; Time: 31s(total), 30s(copy); streamer: SVR14883DE630-bin.001333:26340342; State: migrating; ETA: 9m41s
Copy: 911000/17919072 5.1%; Applied: 0; Backlog: 0/100; Time: 32s(total), 31s(copy); streamer: SVR14883DE630-bin.001333:34327398; State: migrating; ETA: 9m38s
Copy: 943000/17919072 5.3%; Applied: 0; Backlog: 0/100; Time: 33s(total), 32s(copy); streamer: SVR14883DE630-bin.001333:42602984; State: migrating; ETA: 9m36s
Copy: 974000/17919072 5.4%; Applied: 0; Backlog: 0/100; Time: 34s(total), 33s(copy); streamer: SVR14883DE630-bin.001333:50119715; State: migrating; ETA: 9m34s
Copy: 1007000/17919072 5.6%; Applied: 0; Backlog: 0/100; Time: 35s(total), 34s(copy); streamer: SVR14883DE630-bin.001333:58422701; State: migrating; ETA: 9m31s
Copy: 1040000/17919072 5.8%; Applied: 0; Backlog: 0/100; Time: 36s(total), 35s(copy); streamer: SVR14883DE630-bin.001333:66224973; State: migrating; ETA: 9m28s
Copy: 1070000/17919072 6.0%; Applied: 0; Backlog: 0/100; Time: 37s(total), 36s(copy); streamer: SVR14883DE630-bin.001333:74090063; State: migrating; ETA: 9m26s
Copy: 1103000/17919072 6.2%; Applied: 0; Backlog: 0/100; Time: 38s(total), 37s(copy); streamer: SVR14883DE630-bin.001333:83329774; State: migrating; ETA: 9m24s
Copy: 1136000/17919072 6.3%; Applied: 0; Backlog: 0/100; Time: 39s(total), 38s(copy); streamer: SVR14883DE630-bin.001333:91175494; State: migrating; ETA: 9m21s
Copy: 1168000/17919072 6.5%; Applied: 0; Backlog: 0/100; Time: 40s(total), 39s(copy); streamer: SVR14883DE630-bin.001333:99581249; State: migrating; ETA: 9m19s
Copy: 1202000/17919072 6.7%; Applied: 0; Backlog: 0/100; Time: 41s(total), 40s(copy); streamer: SVR14883DE630-bin.001333:107544341; State: migrating; ETA: 9m16s
Copy: 1234000/17919072 6.9%; Applied: 0; Backlog: 0/100; Time: 42s(total), 41s(copy); streamer: SVR14883DE630-bin.001333:115578142; State: migrating; ETA: 9m14s
Copy: 1266000/17919072 7.1%; Applied: 0; Backlog: 0/100; Time: 43s(total), 42s(copy); streamer: SVR14883DE630-bin.001333:124465266; State: migrating; ETA: 9m12s
Copy: 1298000/17919072 7.2%; Applied: 0; Backlog: 0/100; Time: 44s(total), 43s(copy); streamer: SVR14883DE630-bin.001333:132940740; State: migrating; ETA: 9m10s
Copy: 1326000/17919072 7.4%; Applied: 0; Backlog: 0/100; Time: 45s(total), 44s(copy); streamer: SVR14883DE630-bin.001333:140074445; State: migrating; ETA: 9m10s
Copy: 1357000/17919072 7.6%; Applied: 0; Backlog: 0/100; Time: 46s(total), 45s(copy); streamer: SVR14883DE630-bin.001333:150391851; State: migrating; ETA: 9m9s
Copy: 1388000/17919072 7.7%; Applied: 0; Backlog: 0/100; Time: 47s(total), 46s(copy); streamer: SVR14883DE630-bin.001333:162170938; State: migrating; ETA: 9m7s
Copy: 1417000/17919072 7.9%; Applied: 0; Backlog: 0/100; Time: 48s(total), 47s(copy); streamer: SVR14883DE630-bin.001333:174129564; State: migrating; ETA: 9m7s
Copy: 1448000/17919072 8.1%; Applied: 0; Backlog: 0/100; Time: 49s(total), 48s(copy); streamer: SVR14883DE630-bin.001333:183833769; State: migrating; ETA: 9m6s
Copy: 1477000/17919072 8.2%; Applied: 0; Backlog: 0/100; Time: 50s(total), 49s(copy); streamer: SVR14883DE630-bin.001333:194212485; State: migrating; ETA: 9m5s
Copy: 1501000/17919072 8.4%; Applied: 0; Backlog: 0/100; Time: 51s(total), 50s(copy); streamer: SVR14883DE630-bin.001333:202569249; State: migrating; ETA: 9m6s
Copy: 1533000/17919072 8.6%; Applied: 0; Backlog: 0/100; Time: 52s(total), 51s(copy); streamer: SVR14883DE630-bin.001333:212046176; State: migrating; ETA: 9m5s
Copy: 1564000/17919072 8.7%; Applied: 0; Backlog: 0/100; Time: 53s(total), 52s(copy); streamer: SVR14883DE630-bin.001333:223197642; State: migrating; ETA: 9m3s
Copy: 1595000/17919072 8.9%; Applied: 0; Backlog: 0/100; Time: 54s(total), 53s(copy); streamer: SVR14883DE630-bin.001333:234345959; State: migrating; ETA: 9m2s
Copy: 1626000/17919072 9.1%; Applied: 0; Backlog: 0/100; Time: 55s(total), 54s(copy); streamer: SVR14883DE630-bin.001333:246008320; State: migrating; ETA: 9m1s
Copy: 1657000/17919072 9.2%; Applied: 0; Backlog: 0/100; Time: 56s(total), 55s(copy); streamer: SVR14883DE630-bin.001333:257796988; State: migrating; ETA: 8m59s
Copy: 1688000/17919072 9.4%; Applied: 0; Backlog: 0/100; Time: 57s(total), 56s(copy); streamer: SVR14883DE630-bin.001333:268581293; State: migrating; ETA: 8m58s
Copy: 1714000/17919072 9.6%; Applied: 0; Backlog: 0/100; Time: 58s(total), 57s(copy); streamer: SVR14883DE630-bin.001333:278170291; State: migrating; ETA: 8m58s
Copy: 1745000/17919072 9.7%; Applied: 0; Backlog: 0/100; Time: 59s(total), 58s(copy); streamer: SVR14883DE630-bin.001333:289947009; State: migrating; ETA: 8m57s
Copy: 1776000/17919072 9.9%; Applied: 0; Backlog: 0/100; Time: 1m0s(total), 59s(copy); streamer: SVR14883DE630-bin.001333:301783492; State: migrating; ETA: 8m56s
Copy: 1920000/17919072 10.7%; Applied: 0; Backlog: 0/100; Time: 1m5s(total), 1m4s(copy); streamer: SVR14883DE630-bin.001333:359473486; State: migrating; ETA: 8m53s
Copy: 2066000/17919072 11.5%; Applied: 0; Backlog: 0/100; Time: 1m10s(total), 1m9s(copy); streamer: SVR14883DE630-bin.001333:413394006; State: migrating; ETA: 8m49s
Copy: 2223000/17919072 12.4%; Applied: 0; Backlog: 0/100; Time: 1m15s(total), 1m14s(copy); streamer: SVR14883DE630-bin.001333:471712151; State: migrating; ETA: 8m42s
Copy: 2377000/17919072 13.3%; Applied: 0; Backlog: 0/100; Time: 1m20s(total), 1m19s(copy); streamer: SVR14883DE630-bin.001333:529687460; State: migrating; ETA: 8m36s
Copy: 2531000/17919072 14.1%; Applied: 0; Backlog: 0/100; Time: 1m25s(total), 1m24s(copy); streamer: SVR14883DE630-bin.001333:585167116; State: migrating; ETA: 8m30s
Copy: 2681000/17919072 15.0%; Applied: 0; Backlog: 0/100; Time: 1m30s(total), 1m29s(copy); streamer: SVR14883DE630-bin.001333:633006679; State: migrating; ETA: 8m25s
Copy: 2832000/17919072 15.8%; Applied: 0; Backlog: 0/100; Time: 1m35s(total), 1m34s(copy); streamer: SVR14883DE630-bin.001333:688952949; State: migrating; ETA: 8m20s
Copy: 2987000/17919072 16.7%; Applied: 0; Backlog: 0/100; Time: 1m40s(total), 1m39s(copy); streamer: SVR14883DE630-bin.001333:745670241; State: migrating; ETA: 8m14s
Copy: 3138000/17919072 17.5%; Applied: 0; Backlog: 0/100; Time: 1m45s(total), 1m44s(copy); streamer: SVR14883DE630-bin.001333:798174945; State: migrating; ETA: 8m9s
Copy: 3284000/17919072 18.3%; Applied: 0; Backlog: 0/100; Time: 1m50s(total), 1m49s(copy); streamer: SVR14883DE630-bin.001333:844766835; State: migrating; ETA: 8m5s
Copy: 3435000/17919072 19.2%; Applied: 0; Backlog: 0/100; Time: 1m55s(total), 1m54s(copy); streamer: SVR14883DE630-bin.001333:895192548; State: migrating; ETA: 8m0s
Copy: 3588000/17919072 20.0%; Applied: 0; Backlog: 0/100; Time: 2m0s(total), 1m59s(copy); streamer: SVR14883DE630-bin.001333:947914655; State: migrating; ETA: 7m55s
last event read from './SVR14883DE630-bin.001333' at 974840650, the last byte read from './SVR14883DE630-bin.001333' at 974840650.
Copy: 3706000/17919072 20.7%; Applied: 0; Backlog: 0/100; Time: 2m5s(total), 2m4s(copy); streamer: SVR14883DE630-bin.001333:974840650; State: migrating; ETA: 7m55s
2017-07-04 16:17:03 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:17:03 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:03 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:03 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 3844000/17919072 21.5%; Applied: 0; Backlog: 0/100; Time: 2m10s(total), 2m9s(copy); streamer: SVR14883DE630-bin.001333:169104047; State: migrating; ETA: 7m52s
nt read from './SVR14883DE630-bin.001333' at 417601381, the last byte read from './SVR14883DE630-bin.001333' at 417601381.
Copy: 3979000/17919072 22.2%; Applied: 0; Backlog: 0/100; Time: 2m15s(total), 2m14s(copy); streamer: SVR14883DE630-bin.001333:417601381; State: migrating; ETA: 7m49s
2017-07-04 16:17:13 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:17:13 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:13 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:13 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 4079000/17919072 22.8%; Applied: 0; Backlog: 0/100; Time: 2m20s(total), 2m19s(copy); streamer: SVR14883DE630-bin.001333:169300897; State: migrating; ETA: 7m51s
nt read from './SVR14883DE630-bin.001333' at 421384913, the last byte read from './SVR14883DE630-bin.001333' at 421384913.
Copy: 4223000/17919072 23.6%; Applied: 0; Backlog: 0/100; Time: 2m25s(total), 2m24s(copy); streamer: SVR14883DE630-bin.001333:421384913; State: migrating; ETA: 7m47s
2017-07-04 16:17:23 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:17:23 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:23 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:23 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 4311000/17919072 24.1%; Applied: 0; Backlog: 0/100; Time: 2m30s(total), 2m29s(copy); streamer: SVR14883DE630-bin.001333:160269175; State: migrating; ETA: 7m50s
nt read from './SVR14883DE630-bin.001333' at 413954983, the last byte read from './SVR14883DE630-bin.001333' at 413954983.
Copy: 4452000/17919072 24.8%; Applied: 0; Backlog: 0/100; Time: 2m35s(total), 2m34s(copy); streamer: SVR14883DE630-bin.001333:413954983; State: migrating; ETA: 7m45s
2017-07-04 16:17:33 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:17:33 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:33 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:33 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 4551000/17919072 25.4%; Applied: 0; Backlog: 0/100; Time: 2m40s(total), 2m39s(copy); streamer: SVR14883DE630-bin.001333:158541184; State: migrating; ETA: 7m47s
nt read from './SVR14883DE630-bin.001333' at 415687590, the last byte read from './SVR14883DE630-bin.001333' at 415687590.
Copy: 4691000/17919072 26.2%; Applied: 0; Backlog: 0/100; Time: 2m45s(total), 2m44s(copy); streamer: SVR14883DE630-bin.001333:415687590; State: migrating; ETA: 7m42s
2017-07-04 16:17:43 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:17:43 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:43 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:43 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 4807000/17919072 26.8%; Applied: 0; Backlog: 0/100; Time: 2m50s(total), 2m49s(copy); streamer: SVR14883DE630-bin.001333:147976820; State: migrating; ETA: 7m40s
nt read from './SVR14883DE630-bin.001333' at 414871614, the last byte read from './SVR14883DE630-bin.001333' at 414871614.
Copy: 4953000/17919072 27.6%; Applied: 0; Backlog: 0/100; Time: 2m55s(total), 2m54s(copy); streamer: SVR14883DE630-bin.001333:414871614; State: migrating; ETA: 7m35s
2017-07-04 16:17:53 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:17:53 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:17:53 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:17:53 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 5053000/17919072 28.2%; Applied: 0; Backlog: 0/100; Time: 3m0s(total), 2m59s(copy); streamer: SVR14883DE630-bin.001333:143160956; State: migrating; ETA: 7m35s
nt read from './SVR14883DE630-bin.001333' at 409747487, the last byte read from './SVR14883DE630-bin.001333' at 409747487.
Copy: 5191000/17919072 29.0%; Applied: 0; Backlog: 0/100; Time: 3m5s(total), 3m4s(copy); streamer: SVR14883DE630-bin.001333:409747487; State: migrating; ETA: 7m31s
2017-07-04 16:18:03 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:18:03 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:03 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:03 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 5306000/17919072 29.6%; Applied: 0; Backlog: 0/100; Time: 3m10s(total), 3m9s(copy); streamer: SVR14883DE630-bin.001333:141326471; State: throttled, lag=1.808490s; ETA: 7m29s
nt read from './SVR14883DE630-bin.001333' at 413047729, the last byte read from './SVR14883DE630-bin.001333' at 413047729.
Copy: 5423000/17919072 30.3%; Applied: 0; Backlog: 0/100; Time: 3m15s(total), 3m14s(copy); streamer: SVR14883DE630-bin.001333:413047729; State: migrating; ETA: 7m27s
2017-07-04 16:18:13 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:18:13 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:13 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:13 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 5571000/17919072 31.1%; Applied: 0; Backlog: 0/100; Time: 3m20s(total), 3m19s(copy); streamer: SVR14883DE630-bin.001333:137036765; State: migrating; ETA: 7m21s
nt read from './SVR14883DE630-bin.001333' at 408239544, the last byte read from './SVR14883DE630-bin.001333' at 408239544.
Copy: 5661000/17919072 31.6%; Applied: 0; Backlog: 0/100; Time: 3m25s(total), 3m24s(copy); streamer: SVR14883DE630-bin.001333:408239544; State: migrating; ETA: 7m21s
2017-07-04 16:18:23 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:18:23 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:23 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:23 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 5790000/17919072 32.3%; Applied: 0; Backlog: 0/100; Time: 3m30s(total), 3m29s(copy); streamer: SVR14883DE630-bin.001333:133798775; State: migrating; ETA: 7m17s
nt read from './SVR14883DE630-bin.001333' at 413706840, the last byte read from './SVR14883DE630-bin.001333' at 413706840.
Copy: 5935000/17919072 33.1%; Applied: 0; Backlog: 0/100; Time: 3m35s(total), 3m34s(copy); streamer: SVR14883DE630-bin.001333:413706840; State: migrating; ETA: 7m12s
2017-07-04 16:18:33 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:18:33 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:33 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:33 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 6047000/17919072 33.7%; Applied: 0; Backlog: 0/100; Time: 3m40s(total), 3m39s(copy); streamer: SVR14883DE630-bin.001333:129195827; State: migrating; ETA: 7m9s
nt read from './SVR14883DE630-bin.001333' at 409762567, the last byte read from './SVR14883DE630-bin.001333' at 409762567.
Copy: 6212000/17919072 34.7%; Applied: 0; Backlog: 0/100; Time: 3m45s(total), 3m44s(copy); streamer: SVR14883DE630-bin.001333:409762567; State: migrating; ETA: 7m2s
2017-07-04 16:18:43 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:18:43 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:43 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:43 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 6366000/17919072 35.5%; Applied: 0; Backlog: 0/100; Time: 3m50s(total), 3m49s(copy); streamer: SVR14883DE630-bin.001333:126465143; State: migrating; ETA: 6m55s
nt read from './SVR14883DE630-bin.001333' at 413690748, the last byte read from './SVR14883DE630-bin.001333' at 413690748.
Copy: 6454000/17919072 36.0%; Applied: 0; Backlog: 0/100; Time: 3m55s(total), 3m54s(copy); streamer: SVR14883DE630-bin.001333:413690748; State: migrating; ETA: 6m55s
2017-07-04 16:18:54 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:18:54 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:18:54 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:18:54 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 6605000/17919072 36.9%; Applied: 0; Backlog: 0/100; Time: 4m0s(total), 3m59s(copy); streamer: SVR14883DE630-bin.001333:121868598; State: migrating; ETA: 6m49s
nt read from './SVR14883DE630-bin.001333' at 412950006, the last byte read from './SVR14883DE630-bin.001333' at 412950006.
Copy: 6702000/17919072 37.4%; Applied: 0; Backlog: 0/100; Time: 4m5s(total), 4m4s(copy); streamer: SVR14883DE630-bin.001333:412950006; State: migrating; ETA: 6m48s
2017-07-04 16:19:04 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:19:04 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:04 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:04 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 6846000/17919072 38.2%; Applied: 0; Backlog: 0/100; Time: 4m10s(total), 4m9s(copy); streamer: SVR14883DE630-bin.001333:118372868; State: migrating; ETA: 6m42s
nt read from './SVR14883DE630-bin.001333' at 406534991, the last byte read from './SVR14883DE630-bin.001333' at 406534991.
Copy: 6948000/17919072 38.8%; Applied: 0; Backlog: 0/100; Time: 4m15s(total), 4m14s(copy); streamer: SVR14883DE630-bin.001333:406534991; State: migrating; ETA: 6m41s
2017-07-04 16:19:14 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:19:14 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:14 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:14 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 7096000/17919072 39.6%; Applied: 0; Backlog: 0/100; Time: 4m20s(total), 4m19s(copy); streamer: SVR14883DE630-bin.001333:119081564; State: migrating; ETA: 6m35s
nt read from './SVR14883DE630-bin.001333' at 423625600, the last byte read from './SVR14883DE630-bin.001333' at 423625600.
Copy: 7261000/17919072 40.5%; Applied: 0; Backlog: 0/100; Time: 4m25s(total), 4m24s(copy); streamer: SVR14883DE630-bin.001333:423625600; State: migrating; ETA: 6m27s
2017-07-04 16:19:24 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:19:24 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:24 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:24 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 7426000/17919072 41.4%; Applied: 0; Backlog: 0/100; Time: 4m30s(total), 4m29s(copy); streamer: SVR14883DE630-bin.001333:114414363; State: migrating; ETA: 6m20s
nt read from './SVR14883DE630-bin.001333' at 413835727, the last byte read from './SVR14883DE630-bin.001333' at 413835727.
Copy: 7588000/17919072 42.3%; Applied: 0; Backlog: 0/100; Time: 4m35s(total), 4m34s(copy); streamer: SVR14883DE630-bin.001333:413835727; State: migrating; ETA: 6m13s
2017-07-04 16:19:34 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:19:34 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:34 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:34 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 7730000/17919072 43.1%; Applied: 0; Backlog: 0/100; Time: 4m40s(total), 4m39s(copy); streamer: SVR14883DE630-bin.001333:109341396; State: migrating; ETA: 6m7s
nt read from './SVR14883DE630-bin.001333' at 415833279, the last byte read from './SVR14883DE630-bin.001333' at 415833279.
Copy: 7872000/17919072 43.9%; Applied: 0; Backlog: 0/100; Time: 4m45s(total), 4m44s(copy); streamer: SVR14883DE630-bin.001333:415827067; State: migrating; ETA: 6m2s
2017-07-04 16:19:44 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:19:44 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:44 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:44 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 8015000/17919072 44.7%; Applied: 0; Backlog: 0/100; Time: 4m50s(total), 4m49s(copy); streamer: SVR14883DE630-bin.001333:103777880; State: migrating; ETA: 5m57s
nt read from './SVR14883DE630-bin.001333' at 412933814, the last byte read from './SVR14883DE630-bin.001333' at 412933814.
Copy: 8150000/17919072 45.5%; Applied: 0; Backlog: 0/100; Time: 4m55s(total), 4m54s(copy); streamer: SVR14883DE630-bin.001333:412933814; State: migrating; ETA: 5m52s
2017-07-04 16:19:54 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:19:54 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:19:54 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:19:54 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 8290000/17919072 46.3%; Applied: 0; Backlog: 0/100; Time: 5m0s(total), 4m59s(copy); streamer: SVR14883DE630-bin.001333:104181954; State: migrating; ETA: 5m47s
nt read from './SVR14883DE630-bin.001333' at 419730823, the last byte read from './SVR14883DE630-bin.001333' at 419730823.
Copy: 8440000/17919072 47.1%; Applied: 0; Backlog: 0/100; Time: 5m5s(total), 5m4s(copy); streamer: SVR14883DE630-bin.001333:419730823; State: migrating; ETA: 5m41s
2017-07-04 16:20:04 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:20:04 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:04 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:04 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 8617000/17919072 48.1%; Applied: 0; Backlog: 0/100; Time: 5m10s(total), 5m9s(copy); streamer: SVR14883DE630-bin.001333:98403055; State: migrating; ETA: 5m33s
nt read from './SVR14883DE630-bin.001333' at 414887770, the last byte read from './SVR14883DE630-bin.001333' at 414887770.
Copy: 8788000/17919072 49.0%; Applied: 0; Backlog: 0/100; Time: 5m15s(total), 5m14s(copy); streamer: SVR14883DE630-bin.001333:414887770; State: migrating; ETA: 5m26s
2017-07-04 16:20:14 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:20:14 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:14 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:14 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 8944000/17919072 49.9%; Applied: 0; Backlog: 0/100; Time: 5m20s(total), 5m19s(copy); streamer: SVR14883DE630-bin.001333:94312378; State: migrating; ETA: 5m20s
nt read from './SVR14883DE630-bin.001333' at 415374151, the last byte read from './SVR14883DE630-bin.001333' at 415374151.
Copy: 9105000/17919072 50.8%; Applied: 0; Backlog: 0/100; Time: 5m25s(total), 5m24s(copy); streamer: SVR14883DE630-bin.001333:415374151; State: migrating; ETA: 5m13s
2017-07-04 16:20:24 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:20:24 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:24 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:24 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 9260000/17919072 51.7%; Applied: 0; Backlog: 0/100; Time: 5m30s(total), 5m29s(copy); streamer: SVR14883DE630-bin.001333:91663110; State: migrating; ETA: 5m7s
nt read from './SVR14883DE630-bin.001333' at 412933814, the last byte read from './SVR14883DE630-bin.001333' at 412933814.
Copy: 9420000/17919072 52.6%; Applied: 0; Backlog: 0/100; Time: 5m35s(total), 5m34s(copy); streamer: SVR14883DE630-bin.001333:412933814; State: migrating; ETA: 5m1s
2017-07-04 16:20:34 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:20:34 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:34 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:34 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 9583000/17919072 53.5%; Applied: 0; Backlog: 0/100; Time: 5m40s(total), 5m39s(copy); streamer: SVR14883DE630-bin.001333:86739777; State: migrating; ETA: 4m54s
nt read from './SVR14883DE630-bin.001333' at 415618756, the last byte read from './SVR14883DE630-bin.001333' at 415618756.
Copy: 9764000/17919072 54.5%; Applied: 0; Backlog: 0/100; Time: 5m45s(total), 5m44s(copy); streamer: SVR14883DE630-bin.001333:415618756; State: migrating; ETA: 4m47s
2017-07-04 16:20:44 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:20:44 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:44 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:44 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 9939000/17919072 55.5%; Applied: 0; Backlog: 0/100; Time: 5m50s(total), 5m49s(copy); streamer: SVR14883DE630-bin.001333:80974852; State: migrating; ETA: 4m40s
nt read from './SVR14883DE630-bin.001333' at 413524373, the last byte read from './SVR14883DE630-bin.001333' at 413524373.
Copy: 10110000/17919072 56.4%; Applied: 0; Backlog: 0/100; Time: 5m55s(total), 5m54s(copy); streamer: SVR14883DE630-bin.001333:413524373; State: migrating; ETA: 4m33s
2017-07-04 16:20:54 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:20:54 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:20:54 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:20:54 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 10286000/17919072 57.4%; Applied: 0; Backlog: 0/100; Time: 6m0s(total), 5m59s(copy); streamer: SVR14883DE630-bin.001333:79177840; State: migrating; ETA: 4m26s
nt read from './SVR14883DE630-bin.001333' at 417617477, the last byte read from './SVR14883DE630-bin.001333' at 417617477.
Copy: 10455000/17919072 58.3%; Applied: 0; Backlog: 0/100; Time: 6m5s(total), 6m4s(copy); streamer: SVR14883DE630-bin.001333:417617477; State: migrating; ETA: 4m19s
2017-07-04 16:21:04 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:21:04 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:04 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:04 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 10625000/17919072 59.3%; Applied: 0; Backlog: 0/100; Time: 6m10s(total), 6m9s(copy); streamer: SVR14883DE630-bin.001333:75034900; State: migrating; ETA: 4m13s
nt read from './SVR14883DE630-bin.001333' at 409747487, the last byte read from './SVR14883DE630-bin.001333' at 409747487.
Copy: 10797000/17919072 60.3%; Applied: 0; Backlog: 0/100; Time: 6m15s(total), 6m14s(copy); streamer: SVR14883DE630-bin.001333:409747487; State: migrating; ETA: 4m6s
2017-07-04 16:21:14 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:21:14 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:14 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:14 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 10972000/17919072 61.2%; Applied: 0; Backlog: 0/100; Time: 6m20s(total), 6m19s(copy); streamer: SVR14883DE630-bin.001333:72338860; State: migrating; ETA: 3m59s
nt read from './SVR14883DE630-bin.001333' at 417681851, the last byte read from './SVR14883DE630-bin.001333' at 417681851.
Copy: 11146000/17919072 62.2%; Applied: 0; Backlog: 0/100; Time: 6m25s(total), 6m24s(copy); streamer: SVR14883DE630-bin.001333:417681851; State: migrating; ETA: 3m53s
2017-07-04 16:21:24 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:21:24 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:24 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:24 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 11323000/17919072 63.2%; Applied: 0; Backlog: 0/100; Time: 6m30s(total), 6m29s(copy); streamer: SVR14883DE630-bin.001333:69269880; State: migrating; ETA: 3m46s
nt read from './SVR14883DE630-bin.001333' at 423312364, the last byte read from './SVR14883DE630-bin.001333' at 423312364.
Copy: 11498000/17919072 64.2%; Applied: 0; Backlog: 0/100; Time: 6m35s(total), 6m34s(copy); streamer: SVR14883DE630-bin.001333:423299796; State: migrating; ETA: 3m40s
2017-07-04 16:21:34 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:21:34 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:34 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:34 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 11670000/17919072 65.1%; Applied: 0; Backlog: 0/100; Time: 6m40s(total), 6m39s(copy); streamer: SVR14883DE630-bin.001333:66078364; State: migrating; ETA: 3m33s
nt read from './SVR14883DE630-bin.001333' at 421579525, the last byte read from './SVR14883DE630-bin.001333' at 421579525.
Copy: 11841000/17919072 66.1%; Applied: 0; Backlog: 0/100; Time: 6m45s(total), 6m44s(copy); streamer: SVR14883DE630-bin.001333:421560788; State: migrating; ETA: 3m27s
2017-07-04 16:21:44 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:21:44 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:44 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:44 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 12008000/17919072 67.0%; Applied: 0; Backlog: 0/100; Time: 6m50s(total), 6m49s(copy); streamer: SVR14883DE630-bin.001333:63175022; State: migrating; ETA: 3m21s
nt read from './SVR14883DE630-bin.001333' at 423721965, the last byte read from './SVR14883DE630-bin.001333' at 423721965.
Copy: 12179000/17919072 68.0%; Applied: 0; Backlog: 0/100; Time: 6m55s(total), 6m54s(copy); streamer: SVR14883DE630-bin.001333:423714152; State: migrating; ETA: 3m15s
2017-07-04 16:21:54 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:21:54 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:21:54 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:21:54 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 12346000/17919072 68.9%; Applied: 0; Backlog: 0/100; Time: 7m0s(total), 6m59s(copy); streamer: SVR14883DE630-bin.001333:58505427; State: migrating; ETA: 3m9s
nt read from './SVR14883DE630-bin.001333' at 422926870, the last byte read from './SVR14883DE630-bin.001333' at 422926870.
Copy: 12483000/17919072 69.7%; Applied: 0; Backlog: 0/100; Time: 7m5s(total), 7m4s(copy); streamer: SVR14883DE630-bin.001333:422926870; State: migrating; ETA: 3m4s
2017-07-04 16:22:05 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:22:05 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:05 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:05 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 12621000/17919072 70.4%; Applied: 0; Backlog: 0/100; Time: 7m10s(total), 7m9s(copy); streamer: SVR14883DE630-bin.001333:54714295; State: migrating; ETA: 3m0s
nt read from './SVR14883DE630-bin.001333' at 416764658, the last byte read from './SVR14883DE630-bin.001333' at 416764658.
Copy: 12761000/17919072 71.2%; Applied: 0; Backlog: 0/100; Time: 7m15s(total), 7m14s(copy); streamer: SVR14883DE630-bin.001333:416764658; State: migrating; ETA: 2m55s
2017-07-04 16:22:15 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:22:15 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:15 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:15 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 12907000/17919072 72.0%; Applied: 0; Backlog: 0/100; Time: 7m20s(total), 7m19s(copy); streamer: SVR14883DE630-bin.001333:50765799; State: migrating; ETA: 2m50s
nt read from './SVR14883DE630-bin.001333' at 415161374, the last byte read from './SVR14883DE630-bin.001333' at 415161374.
Copy: 13031000/17919072 72.7%; Applied: 0; Backlog: 0/100; Time: 7m25s(total), 7m24s(copy); streamer: SVR14883DE630-bin.001333:415161374; State: migrating; ETA: 2m46s
2017-07-04 16:22:25 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:22:25 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:25 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:25 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 13156000/17919072 73.4%; Applied: 0; Backlog: 0/100; Time: 7m30s(total), 7m29s(copy); streamer: SVR14883DE630-bin.001333:48091759; State: migrating; ETA: 2m42s
nt read from './SVR14883DE630-bin.001333' at 416082076, the last byte read from './SVR14883DE630-bin.001333' at 416082076.
Copy: 13287000/17919072 74.2%; Applied: 0; Backlog: 0/100; Time: 7m35s(total), 7m34s(copy); streamer: SVR14883DE630-bin.001333:416082076; State: migrating; ETA: 2m38s
2017-07-04 16:22:35 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:22:35 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:35 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:35 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 13426000/17919072 74.9%; Applied: 0; Backlog: 0/100; Time: 7m40s(total), 7m39s(copy); streamer: SVR14883DE630-bin.001333:44558615; State: migrating; ETA: 2m33s
nt read from './SVR14883DE630-bin.001333' at 400952011, the last byte read from './SVR14883DE630-bin.001333' at 400952011.
Copy: 13550000/17919072 75.6%; Applied: 0; Backlog: 0/100; Time: 7m45s(total), 7m44s(copy); streamer: SVR14883DE630-bin.001333:400952011; State: migrating; ETA: 2m29s
2017-07-04 16:22:45 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:22:45 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:45 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:45 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 13676000/17919072 76.3%; Applied: 0; Backlog: 0/100; Time: 7m50s(total), 7m49s(copy); streamer: SVR14883DE630-bin.001333:40192669; State: migrating; ETA: 2m25s
nt read from './SVR14883DE630-bin.001333' at 408806562, the last byte read from './SVR14883DE630-bin.001333' at 408806562.
Copy: 13803000/17919072 77.0%; Applied: 0; Backlog: 0/100; Time: 7m55s(total), 7m54s(copy); streamer: SVR14883DE630-bin.001333:408806562; State: migrating; ETA: 2m21s
2017-07-04 16:22:55 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:22:55 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:22:55 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:22:55 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 13932000/17919072 77.7%; Applied: 0; Backlog: 0/100; Time: 8m0s(total), 7m59s(copy); streamer: SVR14883DE630-bin.001333:36745020; State: migrating; ETA: 2m17s
nt read from './SVR14883DE630-bin.001333' at 409674803, the last byte read from './SVR14883DE630-bin.001333' at 409674803.
Copy: 14057000/17919072 78.4%; Applied: 0; Backlog: 0/100; Time: 8m5s(total), 8m4s(copy); streamer: SVR14883DE630-bin.001333:409674803; State: migrating; ETA: 2m12s
2017-07-04 16:23:05 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:23:05 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:23:05 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:23:05 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 14172000/17919072 79.1%; Applied: 0; Backlog: 0/100; Time: 8m10s(total), 8m9s(copy); streamer: SVR14883DE630-bin.001333:33783504; State: migrating; ETA: 2m9s
nt read from './SVR14883DE630-bin.001333' at 405157851, the last byte read from './SVR14883DE630-bin.001333' at 405157851.
Copy: 14292000/17919072 79.8%; Applied: 0; Backlog: 0/100; Time: 8m15s(total), 8m14s(copy); streamer: SVR14883DE630-bin.001333:405157851; State: migrating; ETA: 2m5s
2017-07-04 16:23:15 INFO Reconnecting... Will resume at SVR14883DE630-bin.001333:974840619
2017-07-04 16:23:15 INFO Registering replica at 10.28.77.43:55944
2017-07-04 16:23:15 INFO Connecting binlog streamer at SVR14883DE630-bin.001333:4
2017-07-04 16:23:15 INFO rotate to next log name: SVR14883DE630-bin.001333
Copy: 14420000/17919072 80.5%; Applied: 0; Backlog: 0/100; Time: 8m20s(total), 8m19s(copy); streamer: SVR14883DE630-bin.001333:30987756; State: migrating; ETA: 2m1s
Copy: 14549000/17919072 81.2%; Applied: 0; Backlog: 0/100; Time: 8m25s(total), 8m24s(copy); streamer: SVR14883DE630-bin.001333:454293995; State: migrating; ETA: 1m56s
Copy: 14672000/17919072 81.9%; Applied: 0; Backlog: 0/100; Time: 8m30s(total), 8m29s(copy); streamer: SVR14883DE630-bin.001333:893793365; State: migrating; ETA: 1m52s
2017-07-04 16:23:28 INFO rotate to next log name: SVR14883DE630-bin.001334
2017-07-04 16:23:28 INFO rotate to next log name: SVR14883DE630-bin.001334
Copy: 14800000/17919072 82.6%; Applied: 0; Backlog: 0/100; Time: 8m35s(total), 8m34s(copy); streamer: SVR14883DE630-bin.001334:113723795; State: migrating; ETA: 1m48s
Copy: 14941000/17919072 83.4%; Applied: 0; Backlog: 0/100; Time: 8m40s(total), 8m39s(copy); streamer: SVR14883DE630-bin.001334:369465650; State: migrating; ETA: 1m43s
Copy: 15068000/17919072 84.1%; Applied: 0; Backlog: 0/100; Time: 8m45s(total), 8m44s(copy); streamer: SVR14883DE630-bin.001334:625473963; State: migrating; ETA: 1m39s
Copy: 15194000/17919072 84.8%; Applied: 0; Backlog: 0/100; Time: 8m50s(total), 8m49s(copy); streamer: SVR14883DE630-bin.001334:881717687; State: migrating; ETA: 1m34s
2017-07-04 16:23:49 INFO rotate to next log name: SVR14883DE630-bin.001335
2017-07-04 16:23:49 INFO rotate to next log name: SVR14883DE630-bin.001335
Copy: 15323000/17919072 85.5%; Applied: 0; Backlog: 0/100; Time: 8m55s(total), 8m54s(copy); streamer: SVR14883DE630-bin.001335:111788896; State: migrating; ETA: 1m30s
Copy: 15475000/17919072 86.4%; Applied: 0; Backlog: 0/100; Time: 9m0s(total), 8m59s(copy); streamer: SVR14883DE630-bin.001335:331635887; State: migrating; ETA: 1m25s
Copy: 15613000/17919072 87.1%; Applied: 0; Backlog: 0/100; Time: 9m5s(total), 9m4s(copy); streamer: SVR14883DE630-bin.001335:548240536; State: migrating; ETA: 1m20s
Copy: 15759000/17919072 87.9%; Applied: 0; Backlog: 0/100; Time: 9m10s(total), 9m9s(copy); streamer: SVR14883DE630-bin.001335:808856730; State: migrating; ETA: 1m15s
2017-07-04 16:24:08 INFO rotate to next log name: SVR14883DE630-bin.001336
2017-07-04 16:24:08 INFO rotate to next log name: SVR14883DE630-bin.001336
Copy: 15898000/17919072 88.7%; Applied: 0; Backlog: 0/100; Time: 9m15s(total), 9m14s(copy); streamer: SVR14883DE630-bin.001336:199168681; State: migrating; ETA: 1m10s
Copy: 16048000/17919072 89.6%; Applied: 0; Backlog: 0/100; Time: 9m20s(total), 9m19s(copy); streamer: SVR14883DE630-bin.001336:551187824; State: migrating; ETA: 1m5s
Copy: 16193000/17919072 90.4%; Applied: 0; Backlog: 0/100; Time: 9m25s(total), 9m24s(copy); streamer: SVR14883DE630-bin.001336:814666720; State: migrating; ETA: 1m0s
Copy: 16222000/17919072 90.5%; Applied: 0; Backlog: 0/100; Time: 9m26s(total), 9m25s(copy); streamer: SVR14883DE630-bin.001336:867198494; State: migrating; ETA: 59s
Copy: 16257000/17919072 90.7%; Applied: 0; Backlog: 0/100; Time: 9m27s(total), 9m26s(copy); streamer: SVR14883DE630-bin.001336:926498151; State: migrating; ETA: 57s
Copy: 16278000/17919072 90.8%; Applied: 0; Backlog: 0/100; Time: 9m28s(total), 9m27s(copy); streamer: SVR14883DE630-bin.001336:985846989; State: migrating; ETA: 57s
Copy: 16304000/17919072 91.0%; Applied: 0; Backlog: 0/100; Time: 9m29s(total), 9m28s(copy); streamer: SVR14883DE630-bin.001336:1044191053; State: migrating; ETA: 56s
2017-07-04 16:24:25 INFO rotate to next log name: SVR14883DE630-bin.001337
2017-07-04 16:24:25 INFO rotate to next log name: SVR14883DE630-bin.001337
Copy: 16328000/17919072 91.1%; Applied: 0; Backlog: 0/100; Time: 9m30s(total), 9m29s(copy); streamer: SVR14883DE630-bin.001337:65193572; State: migrating; ETA: 55s
Copy: 16356000/17919072 91.3%; Applied: 0; Backlog: 0/100; Time: 9m31s(total), 9m30s(copy); streamer: SVR14883DE630-bin.001337:172480225; State: migrating; ETA: 54s
Copy: 16387000/17919072 91.5%; Applied: 0; Backlog: 0/100; Time: 9m32s(total), 9m31s(copy); streamer: SVR14883DE630-bin.001337:278342348; State: migrating; ETA: 53s
Copy: 16420000/17919072 91.6%; Applied: 0; Backlog: 0/100; Time: 9m33s(total), 9m32s(copy); streamer: SVR14883DE630-bin.001337:395799199; State: migrating; ETA: 52s
Copy: 16449000/17919072 91.8%; Applied: 0; Backlog: 0/100; Time: 9m34s(total), 9m33s(copy); streamer: SVR14883DE630-bin.001337:527618245; State: migrating; ETA: 51s
Copy: 16475000/17919072 91.9%; Applied: 0; Backlog: 0/100; Time: 9m35s(total), 9m34s(copy); streamer: SVR14883DE630-bin.001337:642994336; State: migrating; ETA: 50s
Copy: 16499000/17919072 92.1%; Applied: 0; Backlog: 0/100; Time: 9m36s(total), 9m35s(copy); streamer: SVR14883DE630-bin.001337:765300100; State: migrating; ETA: 49s
Copy: 16519000/17919072 92.2%; Applied: 0; Backlog: 0/100; Time: 9m37s(total), 9m36s(copy); streamer: SVR14883DE630-bin.001337:895267769; State: migrating; ETA: 48s
Copy: 16549000/17919072 92.4%; Applied: 0; Backlog: 0/100; Time: 9m38s(total), 9m37s(copy); streamer: SVR14883DE630-bin.001337:1015827381; State: migrating; ETA: 47s
2017-07-04 16:24:34 INFO rotate to next log name: SVR14883DE630-bin.001338
2017-07-04 16:24:34 INFO rotate to next log name: SVR14883DE630-bin.001338
Copy: 16577000/17919072 92.5%; Applied: 0; Backlog: 0/100; Time: 9m39s(total), 9m38s(copy); streamer: SVR14883DE630-bin.001338:65843071; State: migrating; ETA: 46s
Copy: 16603000/17919072 92.7%; Applied: 0; Backlog: 0/100; Time: 9m40s(total), 9m39s(copy); streamer: SVR14883DE630-bin.001338:194404527; State: migrating; ETA: 45s
Copy: 16624000/17919072 92.8%; Applied: 0; Backlog: 0/100; Time: 9m41s(total), 9m40s(copy); streamer: SVR14883DE630-bin.001338:320344117; State: migrating; ETA: 45s
Copy: 16648000/17919072 92.9%; Applied: 0; Backlog: 0/100; Time: 9m42s(total), 9m41s(copy); streamer: SVR14883DE630-bin.001338:443745720; State: migrating; ETA: 44s
Copy: 16674000/17919072 93.1%; Applied: 0; Backlog: 0/100; Time: 9m43s(total), 9m42s(copy); streamer: SVR14883DE630-bin.001338:542685478; State: migrating; ETA: 43s
Copy: 16702000/17919072 93.2%; Applied: 0; Backlog: 0/100; Time: 9m44s(total), 9m43s(copy); streamer: SVR14883DE630-bin.001338:674829110; State: migrating; ETA: 42s
Copy: 16729000/17919072 93.4%; Applied: 0; Backlog: 0/100; Time: 9m45s(total), 9m44s(copy); streamer: SVR14883DE630-bin.001338:789011046; State: migrating; ETA: 41s
Copy: 16752000/17919072 93.5%; Applied: 0; Backlog: 0/100; Time: 9m46s(total), 9m45s(copy); streamer: SVR14883DE630-bin.001338:877472608; State: migrating; ETA: 40s
Copy: 16775000/17919072 93.6%; Applied: 0; Backlog: 0/100; Time: 9m47s(total), 9m46s(copy); streamer: SVR14883DE630-bin.001338:974709828; State: migrating; ETA: 39s
Copy: 16801000/17919072 93.8%; Applied: 0; Backlog: 0/100; Time: 9m48s(total), 9m47s(copy); streamer: SVR14883DE630-bin.001338:1067143905; State: migrating; ETA: 39s
2017-07-04 16:24:43 INFO rotate to next log name: SVR14883DE630-bin.001339
2017-07-04 16:24:43 INFO rotate to next log name: SVR14883DE630-bin.001339
Copy: 16825000/17919072 93.9%; Applied: 0; Backlog: 0/100; Time: 9m49s(total), 9m48s(copy); streamer: SVR14883DE630-bin.001339:93561858; State: migrating; ETA: 38s
Copy: 16853000/17919072 94.1%; Applied: 0; Backlog: 0/100; Time: 9m50s(total), 9m49s(copy); streamer: SVR14883DE630-bin.001339:199082404; State: migrating; ETA: 37s
Copy: 16878000/17919072 94.2%; Applied: 0; Backlog: 0/100; Time: 9m51s(total), 9m50s(copy); streamer: SVR14883DE630-bin.001339:333657297; State: migrating; ETA: 36s
Copy: 16900000/17919072 94.3%; Applied: 0; Backlog: 0/100; Time: 9m52s(total), 9m51s(copy); streamer: SVR14883DE630-bin.001339:460702098; State: migrating; ETA: 35s
Copy: 16921000/17919072 94.4%; Applied: 0; Backlog: 0/100; Time: 9m53s(total), 9m52s(copy); streamer: SVR14883DE630-bin.001339:531090305; State: migrating; ETA: 34s
Copy: 16951000/17919072 94.6%; Applied: 0; Backlog: 0/100; Time: 9m54s(total), 9m53s(copy); streamer: SVR14883DE630-bin.001339:544549846; State: migrating; ETA: 33s
Copy: 16979000/17919072 94.8%; Applied: 0; Backlog: 0/100; Time: 9m55s(total), 9m54s(copy); streamer: SVR14883DE630-bin.001339:560097315; State: migrating; ETA: 32s
Copy: 17005000/17919072 94.9%; Applied: 0; Backlog: 0/100; Time: 9m56s(total), 9m55s(copy); streamer: SVR14883DE630-bin.001339:576861042; State: migrating; ETA: 31s
Copy: 17026000/17919072 95.0%; Applied: 0; Backlog: 0/100; Time: 9m57s(total), 9m56s(copy); streamer: SVR14883DE630-bin.001339:595635283; State: migrating; ETA: 31s
Copy: 17050000/17919072 95.2%; Applied: 0; Backlog: 0/100; Time: 9m58s(total), 9m57s(copy); streamer: SVR14883DE630-bin.001339:617285808; State: migrating; ETA: 30s
Copy: 17077000/17919072 95.3%; Applied: 0; Backlog: 0/100; Time: 9m59s(total), 9m58s(copy); streamer: SVR14883DE630-bin.001339:631818141; State: migrating; ETA: 29s
# Migrating `ghostdb`.`test10g`; Ghost table is `ghostdb`.`_test10g_gho`
# Migrating SVR14306DE630:55944; inspecting SVR14883DE630:55944; executing on SVR14883DE630
# Migration started at Tue Jul 04 16:14:54 +0800 2017
# chunk-size: 1000; max-lag-millis: 1500ms; max-load: Threads_connected=5000,Threads_running=5000; critical-load: ; nice-ratio: 0.000000
# throttle-flag-file: /tmp/gh-ost.ghostdb.test10g.throttle 
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# postpone-cut-over-flag-file: /tmp/gh-ost.ghostdb.test10g.postpone 
# Serving on unix socket: /tmp/gh-ost.ghostdb.test10g.sock
Copy: 17106000/17919072 95.5%; Applied: 0; Backlog: 0/100; Time: 10m0s(total), 9m59s(copy); streamer: SVR14883DE630-bin.001339:646682627; State: migrating; ETA: 28s
Copy: 17131000/17919072 95.6%; Applied: 0; Backlog: 0/100; Time: 10m1s(total), 10m0s(copy); streamer: SVR14883DE630-bin.001339:660674624; State: migrating; ETA: 27s
Copy: 17156000/17919072 95.7%; Applied: 0; Backlog: 0/100; Time: 10m2s(total), 10m1s(copy); streamer: SVR14883DE630-bin.001339:680552321; State: migrating; ETA: 26s
Copy: 17179000/17919072 95.9%; Applied: 0; Backlog: 0/100; Time: 10m3s(total), 10m2s(copy); streamer: SVR14883DE630-bin.001339:701010641; State: migrating; ETA: 25s
Copy: 17204000/17919072 96.0%; Applied: 0; Backlog: 0/100; Time: 10m4s(total), 10m3s(copy); streamer: SVR14883DE630-bin.001339:718523656; State: migrating; ETA: 25s
Copy: 17230000/17919072 96.2%; Applied: 0; Backlog: 0/100; Time: 10m5s(total), 10m4s(copy); streamer: SVR14883DE630-bin.001339:730795342; State: migrating; ETA: 24s
Copy: 17255000/17919072 96.3%; Applied: 0; Backlog: 0/100; Time: 10m6s(total), 10m5s(copy); streamer: SVR14883DE630-bin.001339:744080298; State: migrating; ETA: 23s
Copy: 17281000/17919072 96.4%; Applied: 0; Backlog: 0/100; Time: 10m7s(total), 10m6s(copy); streamer: SVR14883DE630-bin.001339:761672154; State: migrating; ETA: 22s
Copy: 17304000/17919072 96.6%; Applied: 0; Backlog: 0/100; Time: 10m8s(total), 10m7s(copy); streamer: SVR14883DE630-bin.001339:781302139; State: migrating; ETA: 21s
Copy: 17326000/17919072 96.7%; Applied: 0; Backlog: 0/100; Time: 10m9s(total), 10m8s(copy); streamer: SVR14883DE630-bin.001339:800001674; State: migrating; ETA: 20s
Copy: 17352000/17919072 96.8%; Applied: 0; Backlog: 0/100; Time: 10m10s(total), 10m9s(copy); streamer: SVR14883DE630-bin.001339:814206744; State: migrating; ETA: 19s
Copy: 17380000/17919072 97.0%; Applied: 0; Backlog: 0/100; Time: 10m11s(total), 10m10s(copy); streamer: SVR14883DE630-bin.001339:828625263; State: migrating; ETA: 18s
Copy: 17407000/17919072 97.1%; Applied: 0; Backlog: 0/100; Time: 10m12s(total), 10m11s(copy); streamer: SVR14883DE630-bin.001339:844232217; State: migrating; ETA: 17s
Copy: 17429000/17919072 97.3%; Applied: 0; Backlog: 0/100; Time: 10m13s(total), 10m12s(copy); streamer: SVR14883DE630-bin.001339:862115058; State: migrating; ETA: 17s
Copy: 17456000/17919072 97.4%; Applied: 0; Backlog: 0/100; Time: 10m14s(total), 10m13s(copy); streamer: SVR14883DE630-bin.001339:878451668; State: migrating; ETA: 16s
Copy: 17481000/17919072 97.6%; Applied: 0; Backlog: 0/100; Time: 10m15s(total), 10m14s(copy); streamer: SVR14883DE630-bin.001339:898364539; State: migrating; ETA: 15s
Copy: 17509000/17919072 97.7%; Applied: 0; Backlog: 0/100; Time: 10m16s(total), 10m15s(copy); streamer: SVR14883DE630-bin.001339:911792717; State: migrating; ETA: 14s
Copy: 17536000/17919072 97.9%; Applied: 0; Backlog: 0/100; Time: 10m17s(total), 10m16s(copy); streamer: SVR14883DE630-bin.001339:927306650; State: migrating; ETA: 13s
Copy: 17561000/17919072 98.0%; Applied: 0; Backlog: 0/100; Time: 10m18s(total), 10m17s(copy); streamer: SVR14883DE630-bin.001339:941902878; State: migrating; ETA: 12s
Copy: 17584000/17919072 98.1%; Applied: 0; Backlog: 0/100; Time: 10m19s(total), 10m18s(copy); streamer: SVR14883DE630-bin.001339:963064299; State: migrating; ETA: 11s
Copy: 17607000/17919072 98.3%; Applied: 0; Backlog: 0/100; Time: 10m20s(total), 10m19s(copy); streamer: SVR14883DE630-bin.001339:983621168; State: migrating; ETA: 10s
Copy: 17631000/17919072 98.4%; Applied: 0; Backlog: 0/100; Time: 10m21s(total), 10m20s(copy); streamer: SVR14883DE630-bin.001339:996978551; State: migrating; ETA: 10s
Copy: 17660000/17919072 98.6%; Applied: 0; Backlog: 0/100; Time: 10m22s(total), 10m21s(copy); streamer: SVR14883DE630-bin.001339:1011898490; State: migrating; ETA: 9s
Copy: 17688000/17919072 98.7%; Applied: 0; Backlog: 0/100; Time: 10m23s(total), 10m22s(copy); streamer: SVR14883DE630-bin.001339:1027546617; State: migrating; ETA: 8s
Copy: 17713000/17919072 98.8%; Applied: 0; Backlog: 0/100; Time: 10m24s(total), 10m23s(copy); streamer: SVR14883DE630-bin.001339:1046577661; State: migrating; ETA: 7s
Copy: 17735000/17919072 99.0%; Applied: 0; Backlog: 0/100; Time: 10m25s(total), 10m24s(copy); streamer: SVR14883DE630-bin.001339:1065975183; State: migrating; ETA: 6s
2017-07-04 16:25:21 INFO rotate to next log name: SVR14883DE630-bin.001340
2017-07-04 16:25:21 INFO rotate to next log name: SVR14883DE630-bin.001340
Copy: 17761000/17919072 99.1%; Applied: 0; Backlog: 0/100; Time: 10m26s(total), 10m25s(copy); streamer: SVR14883DE630-bin.001340:9448349; State: migrating; ETA: 5s
Copy: 17794000/17919072 99.3%; Applied: 0; Backlog: 0/100; Time: 10m27s(total), 10m26s(copy); streamer: SVR14883DE630-bin.001340:19313030; State: migrating; ETA: 4s
Copy: 17827000/17919072 99.5%; Applied: 0; Backlog: 0/100; Time: 10m28s(total), 10m27s(copy); streamer: SVR14883DE630-bin.001340:30467990; State: migrating; ETA: 3s
Copy: 17861000/17919072 99.7%; Applied: 0; Backlog: 0/100; Time: 10m29s(total), 10m28s(copy); streamer: SVR14883DE630-bin.001340:41993105; State: migrating; ETA: 2s
Copy: 17893000/17919072 99.9%; Applied: 0; Backlog: 0/100; Time: 10m30s(total), 10m29s(copy); streamer: SVR14883DE630-bin.001340:53232230; State: migrating; ETA: 0s
Copy: 18693000/17919072 104.3%; Applied: 0; Backlog: 0/100; Time: 11m0s(total), 10m59s(copy); streamer: SVR14883DE630-bin.001340:526829260; State: migrating; ETA: due
2017-07-04 16:26:04 INFO Row copy complete
Copy: 18898698/18898698 100.0%; Applied: 0; Backlog: 0/100; Time: 11m9s(total), 11m7s(copy); streamer: SVR14883DE630-bin.001340:677806295; State: migrating; ETA: due
2017-07-04 16:26:04 INFO Grabbing voluntary lock: gh-ost.2453319.lock
2017-07-04 16:26:04 INFO Setting LOCK timeout as 6 seconds
2017-07-04 16:26:04 INFO Looking for magic cut-over table
2017-07-04 16:26:04 INFO Creating magic cut-over table `ghostdb`.`_test10g_del`
2017-07-04 16:26:04 INFO Magic cut-over table created
2017-07-04 16:26:04 INFO Locking `ghostdb`.`test10g`, `ghostdb`.`_test10g_del`
2017-07-04 16:26:04 INFO Tables locked
2017-07-04 16:26:04 INFO Session locking original & magic tables is 2453319
2017-07-04 16:26:04 INFO Writing changelog state: AllEventsUpToLockProcessed:1499156764337638905
2017-07-04 16:26:04 INFO Waiting for events up to lock
2017-07-04 16:26:04 INFO Intercepted changelog state AllEventsUpToLockProcessed
2017-07-04 16:26:04 INFO Handled changelog state AllEventsUpToLockProcessed
2017-07-04 16:26:05 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1499156764337638905
2017-07-04 16:26:05 INFO Done waiting for events up to lock; duration=993.455861ms
# Migrating `ghostdb`.`test10g`; Ghost table is `ghostdb`.`_test10g_gho`
# Migrating SVR14306DE630:55944; inspecting SVR14883DE630:55944; executing on SVR14883DE630
# Migration started at Tue Jul 04 16:14:54 +0800 2017
# chunk-size: 1000; max-lag-millis: 1500ms; max-load: Threads_connected=5000,Threads_running=5000; critical-load: ; nice-ratio: 0.000000
# throttle-flag-file: /tmp/gh-ost.ghostdb.test10g.throttle 
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# postpone-cut-over-flag-file: /tmp/gh-ost.ghostdb.test10g.postpone 
# Serving on unix socket: /tmp/gh-ost.ghostdb.test10g.sock
Copy: 18898698/18898698 100.0%; Applied: 0; Backlog: 0/100; Time: 11m10s(total), 11m7s(copy); streamer: SVR14883DE630-bin.001340:678416155; State: migrating; ETA: due
2017-07-04 16:26:05 INFO Setting RENAME timeout as 3 seconds
2017-07-04 16:26:05 INFO Session renaming tables is 2453316
2017-07-04 16:26:05 INFO Issuing and expecting this to block: rename /* gh-ost */ table `ghostdb`.`test10g` to `ghostdb`.`_test10g_del`, `ghostdb`.`_test10g_gho` to `ghostdb`.`test10g`
2017-07-04 16:26:05 INFO Found atomic RENAME to be blocking, as expected. Double checking the lock is still in place (though I don't strictly have to)
2017-07-04 16:26:05 INFO Checking session lock: gh-ost.2453319.lock
2017-07-04 16:26:05 INFO Connection holding lock on original table still exists
2017-07-04 16:26:05 INFO Will now proceed to drop magic table and unlock tables
2017-07-04 16:26:05 INFO Dropping magic cut-over table
2017-07-04 16:26:05 INFO Releasing lock from `ghostdb`.`test10g`, `ghostdb`.`_test10g_del`
2017-07-04 16:26:05 INFO Tables unlocked
2017-07-04 16:26:05 INFO Tables renamed
2017-07-04 16:26:05 INFO Lock & rename duration: 1.041543645s. During this time, queries on `test10g` were blocked
2017-07-04 16:26:05 INFO Looking for magic cut-over table
Copy: 18898698/18898698 100.0%; Applied: 0; Backlog: 0/100; Time: 11m10s(total), 11m7s(copy); streamer: SVR14883DE630-bin.001340:678418138; State: migrating; ETA: due
2017-07-04 16:26:05 INFO StreamEvents encountered unexpected error: connection was bad
2017-07-04 16:26:05 INFO Closed streamer connection. err=<nil>
2017-07-04 16:26:05 INFO Droppping table `ghostdb`.`_test10g_ghc`
2017-07-04 16:26:06 INFO Table dropped
2017-07-04 16:26:06 INFO Am not dropping old table because I want this operation to be as live as possible. If you insist I should do it, please add `--ok-to-drop-table` next time. But I prefer you do not. To drop the old table, issue:
2017-07-04 16:26:06 INFO -- drop table `ghostdb`.`_test10g_del`
2017-07-04 16:26:06 INFO executing gh-ost-on-success hook: /tmp/gh-ost-on-success.hook

2017-07-04 16:26:06 INFO Done migrating `ghostdb`.`test10g`
2017-07-04 16:26:06 INFO Removing socket file: /tmp/gh-ost.ghostdb.test10g.sock
2017-07-04 16:26:06 INFO Done
cenkore commented 7 years ago

Q:How many times did task 1 run "Looking for magic cut-over table" ?

A:120

shlomi-noach commented 7 years ago

Thank you for the complete log. I still suspect the problem is completely different. I'm looking now at an alarming number of times you get Reconnecting... Will resume at messages. To be exact, this happens exactly every 10 seconds. I'm wondering if you have some cronjob or daemon (pt-kill?) that kills idle connections after 10 seconds? Or perhaps this is your wait_timeout? More information on this would be helpful.

And now I'm also looking at the fact you have Applied: 0 throughout the migration. Seems like nothing comes through. Is this table not receiving writes?

Which MySQL version are you using?

What is the table structure?

cenkore commented 7 years ago

  1. I think the Reconnecting... Will resume at messages have relation with 2017-07-04 16:17:28 INFO StreamEvents encountered unexpected error: ERROR 1236 (HY000): A slave with the same server_uuid/server_id as this slave has connected to the master; the first event 'SVR14883DE630-bin.001333' at 4, the last event read from './SVR14883DE630-bin.001333' at 413954983, the last byte read from './SVR14883DE630-bin.001333' at 413954983. And there is no cronjob or pt-kill ,and so on..

  2. Yes , this machine is just for test ,so there is no other writes.

  3. MySQL version: 5.7.18

  4. table structure: task 1's:

    CREATE TABLE `test1g` (
`id` bigint(20) NOT NULL AUTO_INCREMENT,
`machine_name` varchar(128) NOT NULL DEFAULT '',
`host_name` varchar(128) NOT NULL,
`dbname` varchar(128) DEFAULT NULL,
`username` varchar(128) DEFAULT NULL,
`sid` varbinary(85) DEFAULT NULL,
`rolename` varchar(128) DEFAULT NULL,
`create_date` datetime DEFAULT NULL,
`addcol` varchar(255) DEFAULT NULL COMMENT '添加普通列测试',
`collection_time` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
`insert_timestamp` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP,
`addcol2` int(11) DEFAULT '0',
`addcol10` int(11) DEFAULT '0',
`addcol11` int(11) DEFAULT '0',
`addcol12` int(11) DEFAULT '0',
`addcol21` int(11) DEFAULT '0',
`addcol20` int(11) DEFAULT '0',
`addcol03` int(11) DEFAULT '0',
`addcol06` int(11) DEFAULT '0',
PRIMARY KEY (`id`,`collection_time`,`host_name`),
UNIQUE KEY `u_i` (`id`,`collection_time`),
KEY `idx_1` (`collection_time`,`host_name`),
KEY `idx_c` (`addcol`)
) ENGINE=InnoDB AUTO_INCREMENT=183758440 DEFAULT CHARSET=utf8mb4
/*!50500 PARTITION BY RANGE  COLUMNS(collection_time)
(PARTITION p20170529 VALUES LESS THAN ('2017-05-30') ENGINE = InnoDB,
PARTITION p20170530 VALUES LESS THAN ('2017-05-31') ENGINE = InnoDB,
PARTITION p20170531 VALUES LESS THAN ('2017-06-01') ENGINE = InnoDB,
PARTITION p20170601 VALUES LESS THAN ('2017-06-02') ENGINE = InnoDB,
PARTITION p20170602 VALUES LESS THAN ('2017-06-03') ENGINE = InnoDB,
PARTITION p20170603 VALUES LESS THAN ('2017-06-04') ENGINE = InnoDB,
PARTITION p20170604 VALUES LESS THAN ('2017-06-05') ENGINE = InnoDB,
PARTITION p20170605 VALUES LESS THAN ('2017-06-06') ENGINE = InnoDB,
PARTITION p20170606 VALUES LESS THAN ('2017-06-07') ENGINE = InnoDB,
PARTITION p20170607 VALUES LESS THAN ('2017-06-08') ENGINE = InnoDB,
PARTITION p20170608 VALUES LESS THAN ('2017-06-09') ENGINE = InnoDB,
PARTITION p20170609 VALUES LESS THAN ('2017-06-10') ENGINE = InnoDB,
PARTITION p20170610 VALUES LESS THAN ('2017-06-11') ENGINE = InnoDB,
PARTITION p20170611 VALUES LESS THAN ('2017-06-12') ENGINE = InnoDB,
PARTITION p20170612 VALUES LESS THAN ('2017-06-13') ENGINE = InnoDB,
PARTITION p20170613 VALUES LESS THAN ('2017-06-14') ENGINE = InnoDB,
PARTITION p20170614 VALUES LESS THAN ('2017-06-15') ENGINE = InnoDB,
PARTITION p20170615 VALUES LESS THAN ('2017-06-16') ENGINE = InnoDB,
PARTITION p20170616 VALUES LESS THAN ('2017-06-17') ENGINE = InnoDB,
PARTITION p20170617 VALUES LESS THAN ('2017-06-18') ENGINE = InnoDB,
PARTITION p20170618 VALUES LESS THAN ('2017-06-19') ENGINE = InnoDB,
PARTITION p20170619 VALUES LESS THAN ('2017-06-20') ENGINE = InnoDB,
PARTITION pmaxvalue VALUES LESS THAN (MAXVALUE) ENGINE = InnoDB) */

    task 2's:

    CREATE TABLE `test10g` (
`id` bigint(20) NOT NULL AUTO_INCREMENT,
`service_name` varchar(128) NOT NULL,
`machine_name` varchar(128) NOT NULL DEFAULT '',
`host_name` varchar(128) NOT NULL,
`logdate` datetime NOT NULL,
`processinfo` varchar(128) DEFAULT NULL,
`text` varchar(4000) DEFAULT NULL,
`warn_level` int(11) DEFAULT NULL,
`insert_timestamp` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP,
`addcol1` int(11) DEFAULT '0',
`addcol20` int(11) DEFAULT '0',
`addcol03` int(11) DEFAULT '0',
`addcol05` int(11) DEFAULT '0',
`addcol07` int(11) DEFAULT '0',
PRIMARY KEY (`id`,`logdate`),
KEY `idx1` (`service_name`,`logdate`),
KEY `idx2` (`host_name`,`logdate`)
) ENGINE=InnoDB AUTO_INCREMENT=2955788521 DEFAULT CHARSET=utf8mb4
/*!50500 PARTITION BY RANGE  COLUMNS(logdate)
(PARTITION p20170414 VALUES LESS THAN ('2017-04-15') ENGINE = InnoDB,
PARTITION p20170415 VALUES LESS THAN ('2017-04-16') ENGINE = InnoDB,
PARTITION p20170416 VALUES LESS THAN ('2017-04-17') ENGINE = InnoDB,
PARTITION p20170417 VALUES LESS THAN ('2017-04-18') ENGINE = InnoDB,
PARTITION p20170418 VALUES LESS THAN ('2017-04-19') ENGINE = InnoDB,
PARTITION p20170419 VALUES LESS THAN ('2017-04-20') ENGINE = InnoDB,
PARTITION p20170420 VALUES LESS THAN ('2017-04-21') ENGINE = InnoDB,
PARTITION p20170421 VALUES LESS THAN ('2017-04-22') ENGINE = InnoDB,
PARTITION p20170422 VALUES LESS THAN ('2017-04-23') ENGINE = InnoDB,
PARTITION p20170423 VALUES LESS THAN ('2017-04-24') ENGINE = InnoDB,
PARTITION p20170424 VALUES LESS THAN ('2017-04-25') ENGINE = InnoDB,
PARTITION p20170425 VALUES LESS THAN ('2017-04-26') ENGINE = InnoDB,
PARTITION p20170426 VALUES LESS THAN ('2017-04-27') ENGINE = InnoDB,
PARTITION p20170427 VALUES LESS THAN ('2017-04-28') ENGINE = InnoDB,
PARTITION p20170428 VALUES LESS THAN ('2017-04-29') ENGINE = InnoDB,
PARTITION p20170429 VALUES LESS THAN ('2017-04-30') ENGINE = InnoDB,
PARTITION p20170430 VALUES LESS THAN ('2017-05-01') ENGINE = InnoDB,
PARTITION p20170501 VALUES LESS THAN ('2017-05-02') ENGINE = InnoDB,
PARTITION p20170502 VALUES LESS THAN ('2017-05-03') ENGINE = InnoDB,
PARTITION p20170503 VALUES LESS THAN ('2017-05-04') ENGINE = InnoDB,
PARTITION p20170504 VALUES LESS THAN ('2017-05-05') ENGINE = InnoDB,
PARTITION p20170505 VALUES LESS THAN ('2017-05-06') ENGINE = InnoDB,
PARTITION p20170506 VALUES LESS THAN ('2017-05-07') ENGINE = InnoDB,
PARTITION p20170507 VALUES LESS THAN ('2017-05-08') ENGINE = InnoDB,
PARTITION p20170508 VALUES LESS THAN ('2017-05-09') ENGINE = InnoDB,
PARTITION p20170509 VALUES LESS THAN ('2017-05-10') ENGINE = InnoDB,
PARTITION p20170510 VALUES LESS THAN ('2017-05-11') ENGINE = InnoDB,
PARTITION p20170511 VALUES LESS THAN ('2017-05-12') ENGINE = InnoDB,
PARTITION p20170512 VALUES LESS THAN ('2017-05-13') ENGINE = InnoDB,
PARTITION p20170513 VALUES LESS THAN ('2017-05-14') ENGINE = InnoDB,
PARTITION p20170514 VALUES LESS THAN ('2017-05-15') ENGINE = InnoDB,
PARTITION p20170515 VALUES LESS THAN ('2017-05-16') ENGINE = InnoDB,
PARTITION p20170516 VALUES LESS THAN ('2017-05-17') ENGINE = InnoDB,
PARTITION p20170517 VALUES LESS THAN ('2017-05-18') ENGINE = InnoDB,
PARTITION p20170518 VALUES LESS THAN ('2017-05-19') ENGINE = InnoDB,
PARTITION p20170519 VALUES LESS THAN ('2017-05-20') ENGINE = InnoDB,
PARTITION p20170520 VALUES LESS THAN ('2017-05-21') ENGINE = InnoDB,
PARTITION p20170521 VALUES LESS THAN ('2017-05-22') ENGINE = InnoDB,
PARTITION p20170522 VALUES LESS THAN ('2017-05-23') ENGINE = InnoDB,
PARTITION p20170523 VALUES LESS THAN ('2017-05-24') ENGINE = InnoDB,
PARTITION p20170524 VALUES LESS THAN ('2017-05-25') ENGINE = InnoDB,
PARTITION p20170525 VALUES LESS THAN ('2017-05-26') ENGINE = InnoDB,
PARTITION p20170526 VALUES LESS THAN ('2017-05-27') ENGINE = InnoDB,
PARTITION p20170527 VALUES LESS THAN ('2017-05-28') ENGINE = InnoDB,
PARTITION p20170528 VALUES LESS THAN ('2017-05-29') ENGINE = InnoDB,
PARTITION p20170529 VALUES LESS THAN ('2017-05-30') ENGINE = InnoDB,
PARTITION p20170530 VALUES LESS THAN ('2017-05-31') ENGINE = InnoDB,
PARTITION p20170531 VALUES LESS THAN ('2017-06-01') ENGINE = InnoDB,
PARTITION p20170601 VALUES LESS THAN ('2017-06-02') ENGINE = InnoDB,
PARTITION p20170602 VALUES LESS THAN ('2017-06-03') ENGINE = InnoDB,
PARTITION p20170603 VALUES LESS THAN ('2017-06-04') ENGINE = InnoDB,
PARTITION p20170604 VALUES LESS THAN ('2017-06-05') ENGINE = InnoDB,
PARTITION p20170605 VALUES LESS THAN ('2017-06-06') ENGINE = InnoDB,
PARTITION p20170606 VALUES LESS THAN ('2017-06-07') ENGINE = InnoDB,
PARTITION p20170607 VALUES LESS THAN ('2017-06-08') ENGINE = InnoDB,
PARTITION p20170608 VALUES LESS THAN ('2017-06-09') ENGINE = InnoDB,
PARTITION p20170609 VALUES LESS THAN ('2017-06-10') ENGINE = InnoDB,
PARTITION p20170610 VALUES LESS THAN ('2017-06-11') ENGINE = InnoDB,
PARTITION p20170611 VALUES LESS THAN ('2017-06-12') ENGINE = InnoDB,
PARTITION p20170612 VALUES LESS THAN ('2017-06-13') ENGINE = InnoDB,
PARTITION p20170613 VALUES LESS THAN ('2017-06-14') ENGINE = InnoDB,
PARTITION p20170614 VALUES LESS THAN ('2017-06-15') ENGINE = InnoDB,
PARTITION p20170615 VALUES LESS THAN ('2017-06-16') ENGINE = InnoDB,
PARTITION p20170616 VALUES LESS THAN ('2017-06-17') ENGINE = InnoDB,
PARTITION p20170617 VALUES LESS THAN ('2017-06-18') ENGINE = InnoDB,
PARTITION p20170618 VALUES LESS THAN ('2017-06-19') ENGINE = InnoDB,
PARTITION p20170619 VALUES LESS THAN ('2017-06-20') ENGINE = InnoDB,
PARTITION pmaxvalue VALUES LESS THAN (MAXVALUE) ENGINE = InnoDB) */

    At the end , I think it is gh-ost's expect behavior. In magrator.go: // Inject the "AllEventsUpToLockProcessed" state hint, wait for it to appear in the binary logs, // make sure the queue is drained. func (this *Migrator) waitForEventsUpToLock() (err error) {

shlomi-noach commented 7 years ago

I believe this is it:

1.  I think the `Reconnecting... Will resume at` messages have relation with 
`2017-07-04 16:17:28 INFO StreamEvents encountered unexpected error: ERROR 1236 (HY000): A slave with the same server_uuid/server_id as this slave has connected to the master; the first event 'SVR14883DE630-bin.001333' at 4, the last event read from './SVR14883DE630-bin.001333' at 413954983, the last byte read from './SVR14883DE630-bin.001333' at 413954983.`
And there is no cronjob or pt-kill ,and so on..

So what happens is that another (a different gh-ost?) client has same server Id, which means binlog entries get lost.

Can you please add --replica-server-id=9991 and --replica-server-id=9992 to your concurrent migrations, and see if this reproduces?

shlomi-noach commented 7 years ago

related: https://github.com/github/gh-ost/pull/349

cenkore commented 7 years ago

Yes , It did not reproduced after add --replica-server-id . But I find one row log about binlogsyncer.go , It will print config information with my account and password .. Its NOT safety .

func NewBinlogSyncer(cfg *BinlogSyncerConfig) *BinlogSyncer {
    if cfg.LogLevel == "" {
        cfg.LogLevel = "info"
    }
    log.SetLevelByString(cfg.LogLevel)

    **log.Infof("create BinlogSyncer with config %v", cfg)**

LOG binlogsyncer.go:75: [info] create BinlogSyncer with config &{9992 mysql 10.28.77.43 55944 gh-ost 123456 false false <nil>}

shlomi-noach commented 7 years ago

But I find one row log about binlogsyncer.go , It will print config information with my account and password .. Its NOT safety .

Will you kindly report that on https://github.com/siddontang/go-mysql/, since this is a 3rd party library?

cenkore commented 7 years ago

Yes , I have reported it . Thanks a lot !

shlomi-noach commented 7 years ago

Thank you.

I'm just wondering right now whether gh-ost would be able to detect another gh-ost execution (via show processlist) and identify the server-id used by the other migration, and implicitly use a different one.

cenkore commented 7 years ago

It seems like that every migration process would create private binlogsyncer with server-id. binlogsyncer struct consists of server-id , host ,user , password , and so on.So it would not conflict between migration process . task 1:

2017/07/05 13:54:43 binlogsyncer.go:241: [info] begin to sync binlog from position (SVR14883DE630-bin.001340, 965191215)
2017/07/05 13:54:43 binlogsyncer.go:134: [info] register slave for master server 10.28.77.43:55944
2017/07/05 13:54:43 binlogsyncer.go:568: [info] rotate to (SVR14883DE630-bin.001340, 965191215)
...

task 2:

binlogsyncer.go:75: [info] create BinlogSyncer with config &{9991 mysql 10.28.77.43 55944 gh-ost 123456 false false <nil>}
2017/07/05 13:53:59 binlogsyncer.go:241: [info] begin to sync binlog from position (SVR14883DE630-bin.001340, 679515408)
2017/07/05 13:53:59 binlogsyncer.go:134: [info] register slave for master server 10.28.77.43:55944
2017/07/05 13:53:59 binlogsyncer.go:568: [info] rotate to (SVR14883DE630-bin.001340, 679515408)
...
shlomi-noach commented 7 years ago

So it would not conflict between migration process .

I'm not sure I follow you. It did conflict. How do you mean "it would not conflict"?

cenkore commented 7 years ago

Yes , It did not conflict after identify --replica-server-id in my test . I guess , Even different binglogsyncer read the same binlog entry , but they are independent , and they have their own position .