search

github / gh-ost

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

binlogstreamer.go:47: [error] close sync with err: sync is been closing... #597

Open sky-9527-github opened 6 years ago

sky-9527-github commented 6 years ago

hello，shlomi-noach I am testing gh-ost latest GA version 1.0.45, still see: binlogstreamer.go:47: [error] close sync with err: sync is been closing... Check the issue list and notice that this issue is mentioned in #383, #388 and is fixed by #389 (no release yet) When will it be released? thank you very much

shlomi-noach commented 6 years ago

You may either use master right now, and hopefully a new release is made available next week.

sky-9527-github commented 6 years ago

thanks shlomi-noach

CoryPulm commented 6 years ago

It looks like v1.0.46 included this fix? I am still noticing this in our environment. I have been testing this on our replica with --test-on-replica. Version:

root@gh-ost01:~# gh-ost --version
1.0.46
root@gh-ost01:~#

Script:

gh-ost \
  --user="ghost" \
  --password="XXXXXXX" \
  --host=10.1.107.2 \
  --test-on-replica \
  --database="MasterDB" \
  --table="ServiceOutage" \
  --verbose \
  --alter="ADD COLUMN severity ENUM('warning', 'critical') DEFAULT 'critical';" \
  --initially-drop-ghost-table \
  --initially-drop-old-table \
  --max-load=Threads_running=30 \
  --switch-to-rbr \
  --chunk-size=1500 \
  --cut-over=default \
  --exact-rowcount \
  --concurrent-rowcount \
  --serve-socket-file=/tmp/gh-ost.test.sock \
  --panic-flag-file=/tmp/gh-ost.panic.flag \
  --postpone-cut-over-flag-file=/tmp/ghost.postpone.flag \
  --debug \
  --execute

Error:

2018-06-14 15:43:37 DEBUG ApplyDMLEventQueries() applied 1 events in one transaction
2018-06-14 15:43:37 DEBUG Getting nothing in the write queue. Sleeping...
2018-06-14 15:43:37 INFO Waiting for events up to lock: got AllEventsUpToLockProcessed:1528991017145673087
2018-06-14 15:43:37 INFO Done waiting for events up to lock; duration=531.178611ms
# Migrating `MasterDB`.`ServiceOutage`; Ghost table is `MasterDB`.`_ServiceOutage_gho`
# Migrating mysql-replica:3306; inspecting mysql-replica:3306; executing on gh-ost01
# Migration started at Thu Jun 14 15:11:49 +0000 2018
# chunk-size: 1500; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: Threads_running=30; critical-load: ; nice-r
atio: 0.000000   
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# throttle-control-replicas count: 1
# postpone-cut-over-flag-file: /tmp/ghost.postpone.flag
# panic-flag-file: /tmp/gh-ost.panic.flag
# Serving on unix socket: /tmp/gh-ost.test.sock
Copy: 10302979/10302979 100.0%; Applied: 7478; Backlog: 0/1000; Time: 31m48s(total), 23m26s(copy); streamer: mysql-bi
n.056497:30432317; State: migrating; ETA: due
2018-06-14 15:43:37 INFO Setting RENAME timeout as 3 seconds
2018-06-14 15:43:37 INFO Session renaming tables is 4570
2018-06-14 15:43:37 INFO Issuing and expecting this to block: rename /* gh-ost */ table `MasterDB`.`ServiceOutage` to
 `MasterDB`.`_ServiceOutage_del`, `MasterDB`.`_ServiceOutage_gho` to `MasterDB`.`ServiceOutage`
2018-06-14 15:43:37 INFO Found atomic RENAME to be blocking, as expected. Double checking the lock is still in place 
(though I don't strictly have to)
2018-06-14 15:43:37 INFO Checking session lock: gh-ost.4532.lock
2018-06-14 15:43:37 INFO Connection holding lock on original table still exists
2018-06-14 15:43:37 INFO Will now proceed to drop magic table and unlock tables
2018-06-14 15:43:37 INFO Dropping magic cut-over table
2018-06-14 15:43:37 ERROR replication not running; Slave_IO_Running=No, Slave_SQL_Running=No
2018-06-14 15:43:37 INFO Releasing lock from `MasterDB`.`ServiceOutage`, `MasterDB`.`_ServiceOutage_del`
2018-06-14 15:43:37 INFO Tables unlocked
2018-06-14 15:43:37 INFO Tables renamed
2018-06-14 15:43:37 INFO Lock & rename duration: 637.858685ms. During this time, queries on `ServiceOutage` were bloc
ked
2018-06-14 15:43:37 INFO Looking for magic cut-over table
2018-06-14 15:43:37 INFO Renaming back both tables
2018/06/14 15:43:37 binlogsyncer.go:107: [info] syncer is closing... 
2018-06-14 15:43:37 DEBUG done streaming events
2018-06-14 15:43:37 DEBUG Done streaming
2018/06/14 15:43:37 binlogstreamer.go:47: [error] close sync with err: sync is been closing...
2018/06/14 15:43:37 binlogsyncer.go:122: [info] syncer is closed 
2018-06-14 15:43:37 INFO Closed streamer connection. err=<nil>
2018-06-14 15:43:37 INFO Dropping table `MasterDB`.`_ServiceOutage_ghc`
2018-06-14 15:43:37 INFO Table dropped
2018-06-14 15:43:37 INFO Am not dropping old table because I want this operation to be as live as possible. If you in
sist I should do it, please add `--ok-to-drop-table` next time. But I prefer you do not. To drop the old table, issue
:
2018-06-14 15:43:37 INFO -- drop table `MasterDB`.`_ServiceOutage_del`
2018-06-14 15:43:37 INFO Done migrating `MasterDB`.`ServiceOutage`
2018-06-14 15:43:37 INFO Removing socket file: /tmp/gh-ost.test.sock
2018-06-14 15:43:37 INFO Tearing down inspector
2018-06-14 15:43:37 INFO Tearing down applier
2018-06-14 15:43:37 DEBUG Tearing down...
2018-06-14 15:43:37 INFO Tearing down streamer
2018-06-14 15:43:37 INFO Tearing down throttler
2018-06-14 15:43:37 DEBUG Tearing down...
# Done
sunashe commented 6 years ago

I am noticing this in our environment ... [ashe@ccc~]$ gh-ost --version 1.0.46

peppy commented 6 years ago

Can also reproduce this:

2018-10-15 07:34:36 INFO StreamEvents encountered unexpected error: EOF
2018-10-15 07:34:41 INFO Reconnecting... Will resume at :0
2018/10/15 07:34:41 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql x.x.x.x 3306 repl   false false <nil>}
2018-10-15 07:34:41 INFO Connecting binlog streamer at mysql-bin.000843:4
2018/10/15 07:34:41 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin.000843, 4)
2018/10/15 07:34:41 binlogsyncer.go:139: [info] register slave for master server x.x.x.x:3306
2018/10/15 07:34:41 binlogsyncer.go:573: [info] rotate to (mysql-bin.000843, 4)
2018-10-15 07:34:41 INFO rotate to next log name: mysql-bin.000843
2018/10/15 07:34:41 binlogstreamer.go:47: [error] close sync with err: EOF
2018-10-15 07:34:41 INFO StreamEvents encountered unexpected error: EOF
2018-10-15 07:34:46 INFO Reconnecting... Will resume at :0
2018/10/15 07:34:46 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql x.x.x.x 3306 repl   false false <nil>}
2018-10-15 07:34:46 INFO Connecting binlog streamer at mysql-bin.000843:4
2018/10/15 07:34:46 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin.000843, 4)
2018/10/15 07:34:46 binlogsyncer.go:139: [info] register slave for master server x.x.x.x:3306
2018/10/15 07:34:46 binlogsyncer.go:573: [info] rotate to (mysql-bin.000843, 4)
2018/10/15 07:34:46 binlogstreamer.go:47: [error] close sync with err: EOF
2018-10-15 07:34:46 INFO rotate to next log name: mysql-bin.000843
2018-10-15 07:34:46 INFO StreamEvents encountered unexpected error: EOF
2018-10-15 07:34:51 INFO Reconnecting... Will resume at :0
2018/10/15 07:34:51 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql x.x.x.x 3306 repl   false false <nil>}
2018-10-15 07:34:51 INFO Connecting binlog streamer at mysql-bin.000843:4
2018/10/15 07:34:51 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin.000843, 4)
2018/10/15 07:34:51 binlogsyncer.go:139: [info] register slave for master server x.x.x.x:3306
2018/10/15 07:34:51 binlogsyncer.go:573: [info] rotate to (mysql-bin.000843, 4)
2018/10/15 07:34:51 binlogstreamer.go:47: [error] close sync with err: EOF
2018-10-15 07:34:51 INFO rotate to next log name: mysql-bin.000843
2018-10-15 07:34:51 INFO StreamEvents encountered unexpected error: EOF
2018-10-15 07:34:56 INFO Reconnecting... Will resume at :0
2018/10/15 07:34:56 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql x.x.x.x 3306 repl   false false <nil>}
2018-10-15 07:34:56 INFO Connecting binlog streamer at mysql-bin.000843:4
2018/10/15 07:34:56 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin.000843, 4)
2018/10/15 07:34:56 binlogsyncer.go:139: [info] register slave for master server x.x.x.x:3306
2018/10/15 07:34:56 binlogsyncer.go:573: [info] rotate to (mysql-bin.000843, 4)
2018/10/15 07:34:56 binlogstreamer.go:47: [error] close sync with err: EOF
2018-10-15 07:34:56 INFO rotate to next log name: mysql-bin.000843
2018-10-15 07:34:56 INFO StreamEvents encountered unexpected error: EOF
shlomi-noach commented 6 years ago

This message is being printed by a 3rd party library gh-ost uses, and I have no control over the printing of the message. However, if gh-ost itself does not indicate an error (and in the logs provided by @CoryPulm and @peppy gh-ost does not indicate an error) then you may safely ignore it.

peppy commented 6 years ago

I see, thanks for the follow-up. I will try letting it run and see how it goes.

peppy commented 6 years ago

It seems to have eventually errored after leaving it to run:

2018/10/15 08:07:12 binlogstreamer.go:47: [error] close sync with err: EOF
2018-10-15 08:07:12 INFO rotate to next log name: mysql-bin.000844
2018-10-15 08:07:12 INFO StreamEvents encountered unexpected error: EOF
2018-10-15 08:07:17 FATAL 121 successive failures in streamer reconnect at coordinates mysql-bin.000844:4
shlomi-noach commented 6 years ago

@peppy which version are you running? and which MySQL version?

peppy commented 6 years ago 
> gh-ost --version
1.0.46
mysql> SELECT VERSION();
+-----------+
| VERSION() |
+-----------+
| 8.0.12    |
+-----------+
1 row in set (0.00 sec)
drogart commented 6 years ago

I'm seeing the exact same issue with gh-ost version 1.0.47 and mysql 8.0.11.

I have tested in both RDS and dbdeployer. Here's my command line and a log snippet for dbdeployer: $ gh-ost --chunk-size=1000 --user=ghost --password=SECRET --database=foo --table=foo --host=localhost --allow-on-master --switch-to-rbr --execute --port=20112 --alter="add index idx1 (b) invisible" --verbose 2018-10-26 15:27:19 INFO starting gh-ost 1.0.47 2018-10-26 15:27:19 INFO Migrating foo.foo 2018-10-26 15:27:19 INFO connection validated on localhost:20112 2018-10-26 15:27:19 INFO User has SUPER, REPLICATION SLAVE privileges, and has ALL privileges on foo.* 2018-10-26 15:27:19 INFO binary logs validated on localhost:20112 2018-10-26 15:27:19 INFO Restarting replication on localhost:20112 to make sure binlog settings apply to replication thread 2018-10-26 15:27:19 INFO Inspector initiated on drogart-us-la:20112, version 8.0.11 2018-10-26 15:27:19 INFO Table found. Engine=InnoDB 2018-10-26 15:27:19 INFO Estimated number of rows via EXPLAIN: 2 2018-10-26 15:27:19 INFO Recursively searching for replication master 2018-10-26 15:27:19 INFO Master found to be drogart-us-la:20112 2018-10-26 15:27:19 INFO log_slave_updates validated on localhost:20112 2018-10-26 15:27:19 INFO connection validated on localhost:20112 2018/10/26 15:27:19 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql localhost 20112 ghost false false } 2018-10-26 15:27:19 INFO Connecting binlog streamer at mysql-bin.000002:1465 2018/10/26 15:27:19 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin.000002, 1465) 2018/10/26 15:27:19 binlogsyncer.go:139: [info] register slave for master server localhost:20112 2018/10/26 15:27:19 binlogsyncer.go:573: [info] rotate to (mysql-bin.000002, 1465) 2018-10-26 15:27:19 INFO rotate to next log from mysql-bin.000002:0 to mysql-bin.000002 2018-10-26 15:27:19 INFO connection validated on localhost:20112 2018-10-26 15:27:19 INFO connection validated on localhost:20112 2018-10-26 15:27:19 INFO will use time_zone='SYSTEM' on applier 2018-10-26 15:27:19 INFO Examining table structure on applier 2018-10-26 15:27:19 INFO Applier initiated on drogart-us-la:20112, version 8.0.11 2018-10-26 15:27:19 INFO Dropping table foo._foo_ghc 2018-10-26 15:27:19 INFO Table dropped 2018-10-26 15:27:19 INFO Creating changelog table foo._foo_ghc 2018-10-26 15:27:19 INFO Changelog table created 2018-10-26 15:27:19 INFO Creating ghost table foo._foo_gho 2018-10-26 15:27:19 INFO Ghost table created 2018-10-26 15:27:19 INFO Altering ghost table foo._foo_gho 2018-10-26 15:27:19 INFO Ghost table altered 2018/10/26 15:27:19 binlogstreamer.go:47: [error] close sync with err: EOF 2018-10-26 15:27:19 INFO StreamEvents encountered unexpected error: EOF 2018-10-26 15:27:19 INFO Waiting for ghost table to be migrated. Current lag is 0s 2018-10-26 15:27:24 INFO Reconnecting... Will resume at :0 2018/10/26 15:27:24 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql localhost 20112 ghost false false } 2018-10-26 15:27:24 INFO Connecting binlog streamer at mysql-bin.000002:4 2018/10/26 15:27:24 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin.000002, 4) 2018/10/26 15:27:24 binlogsyncer.go:139: [info] register slave for master server localhost:20112 2018/10/26 15:27:24 binlogsyncer.go:573: [info] rotate to (mysql-bin.000002, 4) 2018-10-26 15:27:24 INFO rotate to next log from mysql-bin.000002:0 to mysql-bin.000002 2018/10/26 15:27:24 binlogstreamer.go:47: [error] close sync with err: EOF 2018-10-26 15:27:24 INFO StreamEvents encountered unexpected error: EOF 2018-10-26 15:27:29 INFO Reconnecting... Will resume at :0 [similar errors snipped, then...] 2018-10-26 15:32:25 FATAL 61 successive failures in streamer reconnect at coordinates mysql-bin.000002:4

The same gh-ost version and parameters work fine for mysql 5.7.x in both RDS and dbdeployer, so I think it must be something peculiar to mysql 8. I thought perhaps it might be the log_bin_use_v1_row_events setting, but I've tested with that either way with the same error(s).

Any other info I can provide to help troubleshoot this?

Thanks, Dan

shlomi-noach commented 6 years ago

I'm merely guessing that 8.0.* is where this is being seen (I'm not running 8.0 myself, nor is gh-ost tested on 8.0 in CI at this time). I'll need to look more deeply into this.

toddstoffel commented 5 years ago

Same error on 1.0.47:

[root@node1 vagrant]# gh-ost --version 1.0.47

gh-ost --user=root --database employees --table departments_copy --alter="engine=innodb" --allow-on-master --execute

2018/11/15 00:18:40 binlogsyncer.go:107: [info] syncer is closing... 2018/11/15 00:18:41 binlogstreamer.go:47: [error] close sync with err: sync is been closing...

luoxiaocai91 commented 5 years ago

Same error on 1.0.47 mysql:5.7.21-21-log Percona Server (GPL), Release 21, Revision 2a37e4e command: gh-ost \ --max-load=Threads_running=32 \ --critical-load=Threads_running=32 \ --chunk-size=1000 \ --throttle-control-replicas="$throttle_control_replicas" \ --max-lag-millis=1000 \ --initially-drop-old-table \ --initially-drop-ghost-table \ --conf="xxx" \ --host="$binlog_slave" \ --port="$port" \ --database="$database" \ --table="$table" \ --debug \ --alter="$sql" \ --switch-to-rbr \ --allow-master-master \ --cut-over=default \ --default-retries=3 \ --critical-load-interval-millis=3000 \ --panic-flag-file=/tmp/ghost.panic.flag \ --execute the log: 2018/11/22 21:21:58 binlogsyncer.go:107: ESC[0;37m[info] syncer is closing... ESC[0m 2018/11/22 21:21:58 binlogstreamer.go:47: ESC[0;31m[error] close sync with err: sync is been closing...ESC[0m 2018/11/22 21:21:58 binlogsyncer.go:122: ESC[0;37m[info] syncer is closed ESC[0m

peppy commented 5 years ago

Any updates on this issue?

shlomi-noach commented 5 years ago

No updates; unfortunately I do not have the spare cycles to investigate this right now.

peppy commented 5 years ago

Understandable, thanks for the update.

alextsui05 commented 5 years ago

I've ran into the same issues mentioned above and reproduced in an AWS environment (gist here): basically it does have something to do with MySQL 8 because MySQL 5.7 works.

Digging deeper, it seems that in the 1.0.47 version of gh-ost released in October 2018, the MySQL toolset (https://github.com/siddontang/go-mysql) used under the hood had some issues with MySQL 8 - handling the new default authentication for one, and possibly others.

However, there's been updates that were merged in December, and I presume that got pulled into this project at the beginning of the year (I'm new to Golang, but is there a way to see what specific version is vendored into this project? How are dependencies managed in this project/in general?). Building gh-ost from master and running a migration on MySQL 8 RDS seems to be working where the 1.0.47 release is failing with the EOF error.

shlomi-noach commented 5 years ago

Building gh-ost from master and running a migration on MySQL 8 RDS seems to be working where the 1.0.47 release is failing with the EOF error.

Thank you so much for testing this!

I'm new to Golang, but is there a way to see what specific version is vendored into this project? How are dependencies managed in this project/in general?

Ahem. I gave up on multiple vendoring/versioning approaches and right now vendoring is unversioned. To be clear, this is not the right way to go. Also, I'm yet to gain trust in a golang dependency manager.

shlomi-noach commented 5 years ago

I'll make a release shortly, I hope.

peppy commented 5 years ago

Hoping to give this a test-run today. Thanks for the investigation @alextsui05!

peppy commented 5 years ago

Confirming building from master works as expected (mysqld Ver 8.0.12 for Linux on x86_64 (MySQL Community Server - GPL).

Hitting a snag on obtaining a lock at the final stages of switching, but that is not relevant to this issue.

shlomi-noach commented 5 years ago

The release is a bit more of a hassle to generate, seeing that there is now CGO involved in the underlying go-mysql binary. I hope to deliver later today.

peppy commented 5 years ago

For what it's worth, I'm hitting a (likely) mysql 8 related issue here. Something weird going on with column statistics locks.

bingo711x commented 5 years ago

I try gh-ost 1.0.47 on mysql version 5.6.23 for the first time. the log is:

2019-02-15 10:32:13 INFO rotate to next log from mysql-bin.000239:0 to mysql-bin.000239 2019-02-15 10:32:13 INFO StreamEvents encountered unexpected error: EOF 2019-02-15 10:32:18 INFO Reconnecting... Will resume at :0 2019/02/15 10:32:18 binlogsyncer.go:79: [info] create BinlogSyncer with config {99999 mysql 127.0.0.1 3613 root false false } 2019-02-15 10:32:18 INFO Connecting binlog streamer at mysql-bin.000239:4 2019/02/15 10:32:18 binlogsyncer.go:246: [info] begin to sync binlog from position (mysql-bin.000239, 4) 2019/02/15 10:32:18 binlogsyncer.go:139: [info] register slave for master server 127.0.0.1:3613 2019/02/15 10:32:18 binlogsyncer.go:573: [info] rotate to (mysql-bin.000239, 4) 2019/02/15 10:32:18 binlogstreamer.go:47: [error] close sync with err: EOF

the error is about what? need some configure of mysql be changed ?@shlomi-noach

shlomi-noach commented 5 years ago

@bingo711x please try https://github.com/github/gh-ost/releases/tag/v1.0.48

drogart commented 5 years ago

I can confirm the 1.0.48 release resolves the binlogstreamer.go error with mysql 8.0.11 during my testing with dbdeployer.

I am however now hitting the cutover issue described here. I'll comment further on that thread...

Thanks much!

zhongyiio commented 5 years ago

Same error on 1.0.48

gh-ost: 1.0.48 MySQL: 5.7.25(AWS RDS)

ubuntu@host:/data$ gh-ost --host=$HOST     --user=root --password=$MYSQL_PASSWORD     --database=$DATABASE --table=$TABLE     --alter="
    add column $COL1 bigint NOT NULL DEFAULT 0, add column $COL2 bigint NOT NULL DEFAULT 0"     --allow-on-master --execute --initially-drop-old-table

[2019/07/31 07:52:28] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql $HOST 3306 root    false false <nil> false UTC true 0 0s 0s 0 false}
[2019/07/31 07:52:28] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin-changelog.028397, 6788161)
[2019/07/31 07:52:28] [info] binlogsyncer.go:203 register slave for master server $HOST:3306
[2019/07/31 07:52:28] [info] binlogsyncer.go:723 rotate to (mysql-bin-changelog.028397, 6788161)
# Migrating `$DATABASE`.`$TABLE`; Ghost table is `$DATABASE`.`_$TABLE_gho`
# Migrating ip-172-21-2-151:3306; inspecting ip-172-21-2-151:3306; executing on ip-10-0-1-190
# Migration started at Wed Jul 31 07:52:28 +0000 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# Serving on unix socket: /tmp/gh-ost.$DATABASE.$TABLE.sock
Copy: 0/1481583 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin-changelog.028397:6791220; State: migrating; ETA: N/A
Copy: 0/1481583 0.0%; Applied: 0; Backlog: 377/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin-changelog.028397:7002834; State: migrating; ETA: N/A
Copy: 33000/1481583 2.2%; Applied: 387; Backlog: 0/1000; Time: 2s(total), 2s(copy); streamer: mysql-bin-changelog.028397:11525040; State: migrating; ETA: 1m28s
Copy: 85000/1481583 5.7%; Applied: 387; Backlog: 0/1000; Time: 3s(total), 3s(copy); streamer: mysql-bin-changelog.028397:18648888; State: migrating; ETA: 49s
Copy: 124000/1481583 8.4%; Applied: 387; Backlog: 0/1000; Time: 4s(total), 4s(copy); streamer: mysql-bin-changelog.028397:23993390; State: migrating; ETA: 43s
Copy: 171000/1481583 11.5%; Applied: 387; Backlog: 0/1000; Time: 5s(total), 5s(copy); streamer: mysql-bin-changelog.028397:30432288; State: migrating; ETA: 38s
Copy: 214000/1481583 14.4%; Applied: 457; Backlog: 415/1000; Time: 6s(total), 6s(copy); streamer: mysql-bin-changelog.028397:36589787; State: migrating; ETA: 35s
Copy: 253000/1481583 17.1%; Applied: 882; Backlog: 0/1000; Time: 7s(total), 7s(copy); streamer: mysql-bin-changelog.028397:41936161; State: migrating; ETA: 34s
Copy: 296000/1481583 20.0%; Applied: 882; Backlog: 0/1000; Time: 8s(total), 8s(copy); streamer: mysql-bin-changelog.028397:47827867; State: migrating; ETA: 32s
Copy: 336000/1481583 22.7%; Applied: 882; Backlog: 0/1000; Time: 9s(total), 9s(copy); streamer: mysql-bin-changelog.028397:53308860; State: migrating; ETA: 30s
Copy: 386000/1481583 26.1%; Applied: 882; Backlog: 0/1000; Time: 10s(total), 10s(copy); streamer: mysql-bin-changelog.028397:60095589; State: migrating; ETA: 28s
Copy: 433000/1481583 29.2%; Applied: 882; Backlog: 0/1000; Time: 11s(total), 11s(copy); streamer: mysql-bin-changelog.028397:66598233; State: migrating; ETA: 26s
Copy: 475000/1481583 32.1%; Applied: 1293; Backlog: 0/1000; Time: 12s(total), 12s(copy); streamer: mysql-bin-changelog.028397:72572019; State: migrating; ETA: 25s
Copy: 525000/1481583 35.4%; Applied: 1293; Backlog: 0/1000; Time: 13s(total), 13s(copy); streamer: mysql-bin-changelog.028397:79422061; State: migrating; ETA: 23s
Copy: 572000/1481583 38.6%; Applied: 1293; Backlog: 0/1000; Time: 14s(total), 14s(copy); streamer: mysql-bin-changelog.028397:85861392; State: migrating; ETA: 22s
Copy: 626000/1481583 42.3%; Applied: 1293; Backlog: 0/1000; Time: 15s(total), 15s(copy); streamer: mysql-bin-changelog.028397:93258629; State: migrating; ETA: 20s
Copy: 678000/1481583 45.8%; Applied: 1293; Backlog: 0/1000; Time: 16s(total), 16s(copy); streamer: mysql-bin-changelog.028397:100382912; State: migrating; ETA: 18s
Copy: 719000/1481583 48.5%; Applied: 1736; Backlog: 0/1000; Time: 17s(total), 17s(copy); streamer: mysql-bin-changelog.028397:106239677; State: migrating; ETA: 18s
Copy: 768000/1481583 51.8%; Applied: 1736; Backlog: 0/1000; Time: 18s(total), 18s(copy); streamer: mysql-bin-changelog.028397:112952815; State: migrating; ETA: 16s
Copy: 818000/1481583 55.2%; Applied: 1736; Backlog: 0/1000; Time: 19s(total), 19s(copy); streamer: mysql-bin-changelog.028397:119802862; State: migrating; ETA: 15s
Copy: 872000/1481583 58.9%; Applied: 1736; Backlog: 0/1000; Time: 20s(total), 20s(copy); streamer: mysql-bin-changelog.028397:127200100; State: migrating; ETA: 13s
[2019/07/31 07:52:50] [info] binlogsyncer.go:723 rotate to (mysql-bin-changelog.028398, 4)
[2019/07/31 07:52:50] [info] binlogsyncer.go:723 rotate to (mysql-bin-changelog.028398, 4)
Copy: 923000/1481583 62.3%; Applied: 1736; Backlog: 0/1000; Time: 21s(total), 21s(copy); streamer: mysql-bin-changelog.028397:134324380; State: migrating; ETA: 12s
Copy: 965000/1481583 65.1%; Applied: 2054; Backlog: 0/1000; Time: 22s(total), 22s(copy); streamer: mysql-bin-changelog.028398:5788236; State: migrating; ETA: 11s
Copy: 1019000/1481583 68.8%; Applied: 2054; Backlog: 0/1000; Time: 23s(total), 23s(copy); streamer: mysql-bin-changelog.028398:13185900; State: migrating; ETA: 10s
Copy: 1070000/1481583 72.2%; Applied: 2054; Backlog: 0/1000; Time: 24s(total), 24s(copy); streamer: mysql-bin-changelog.028398:20172851; State: migrating; ETA: 9s
Copy: 1120000/1481583 75.6%; Applied: 2054; Backlog: 0/1000; Time: 25s(total), 25s(copy); streamer: mysql-bin-changelog.028398:27022889; State: migrating; ETA: 8s
Copy: 1173000/1481583 79.2%; Applied: 2054; Backlog: 0/1000; Time: 26s(total), 26s(copy); streamer: mysql-bin-changelog.028398:34283648; State: migrating; ETA: 6s
Copy: 1219000/1481583 82.3%; Applied: 2416; Backlog: 0/1000; Time: 27s(total), 27s(copy); streamer: mysql-bin-changelog.028398:40780772; State: migrating; ETA: 5s
Copy: 1272000/1481583 85.9%; Applied: 2416; Backlog: 0/1000; Time: 28s(total), 28s(copy); streamer: mysql-bin-changelog.028398:48041103; State: migrating; ETA: 4s
Copy: 1324000/1481583 89.4%; Applied: 2416; Backlog: 0/1000; Time: 29s(total), 29s(copy); streamer: mysql-bin-changelog.028398:55028055; State: migrating; ETA: 3s
Copy: 1375000/1481583 92.8%; Applied: 2416; Backlog: 0/1000; Time: 30s(total), 30s(copy); streamer: mysql-bin-changelog.028398:62151910; State: migrating; ETA: 2s
Copy: 1414000/1481583 95.4%; Applied: 2416; Backlog: 0/1000; Time: 31s(total), 31s(copy); streamer: mysql-bin-changelog.028398:67433113; State: migrating; ETA: 1s
Copy: 1459000/1481583 98.5%; Applied: 2792; Backlog: 0/1000; Time: 32s(total), 32s(copy); streamer: mysql-bin-changelog.028398:73864657; State: migrating; ETA: 0s
Copy: 1505000/1481583 101.6%; Applied: 2792; Backlog: 0/1000; Time: 33s(total), 33s(copy); streamer: mysql-bin-changelog.028398:80167082; State: migrating; ETA: due
Copy: 1505000/1481583 101.6%; Applied: 2792; Backlog: 0/1000; Time: 34s(total), 34s(copy); streamer: mysql-bin-changelog.028398:80171879; State: migrating; ETA: due
Copy: 1509998/1481583 101.9%; Applied: 2792; Backlog: 0/1000; Time: 35s(total), 35s(copy); streamer: mysql-bin-changelog.028398:80860931; State: migrating; ETA: due
Copy: 1509998/1481583 101.9%; Applied: 2792; Backlog: 0/1000; Time: 36s(total), 36s(copy); streamer: mysql-bin-changelog.028398:80865726; State: migrating; ETA: due
Copy: 1510998/1481583 102.0%; Applied: 3224; Backlog: 0/1000; Time: 37s(total), 37s(copy); streamer: mysql-bin-changelog.028398:81242591; State: migrating; ETA: due
Copy: 1510998/1481583 102.0%; Applied: 3224; Backlog: 0/1000; Time: 38s(total), 38s(copy); streamer: mysql-bin-changelog.028398:81247349; State: migrating; ETA: due
Copy: 1510998/1481583 102.0%; Applied: 3224; Backlog: 0/1000; Time: 39s(total), 39s(copy); streamer: mysql-bin-changelog.028398:81252099; State: migrating; ETA: due
Copy: 1510998/1481583 102.0%; Applied: 3224; Backlog: 0/1000; Time: 40s(total), 40s(copy); streamer: mysql-bin-changelog.028398:81256852; State: migrating; ETA: due
Copy: 1510998/1481583 102.0%; Applied: 3224; Backlog: 0/1000; Time: 41s(total), 41s(copy); streamer: mysql-bin-changelog.028398:81261593; State: migrating; ETA: due
Copy: 1537995/1481583 103.8%; Applied: 3565; Backlog: 0/1000; Time: 42s(total), 42s(copy); streamer: mysql-bin-changelog.028398:85151375; State: migrating; ETA: due
Copy: 1537995/1481583 103.8%; Applied: 3565; Backlog: 0/1000; Time: 43s(total), 43s(copy); streamer: mysql-bin-changelog.028398:85156172; State: migrating; ETA: due
Copy: 1537995/1481583 103.8%; Applied: 3565; Backlog: 0/1000; Time: 44s(total), 44s(copy); streamer: mysql-bin-changelog.028398:85160969; State: migrating; ETA: due
Copy: 1537995/1481583 103.8%; Applied: 3565; Backlog: 0/1000; Time: 45s(total), 45s(copy); streamer: mysql-bin-changelog.028398:85165766; State: migrating; ETA: due
Copy: 1537995/1481583 103.8%; Applied: 3565; Backlog: 0/1000; Time: 46s(total), 46s(copy); streamer: mysql-bin-changelog.028398:85170561; State: migrating; ETA: due
Copy: 1540995/1481583 104.0%; Applied: 3965; Backlog: 0/1000; Time: 47s(total), 47s(copy); streamer: mysql-bin-changelog.028398:85824681; State: migrating; ETA: due
Copy: 1540995/1481583 104.0%; Applied: 3965; Backlog: 0/1000; Time: 48s(total), 48s(copy); streamer: mysql-bin-changelog.028398:85829438; State: migrating; ETA: due
Copy: 1540995/1481583 104.0%; Applied: 3965; Backlog: 0/1000; Time: 49s(total), 49s(copy); streamer: mysql-bin-changelog.028398:85834187; State: migrating; ETA: due
Copy: 1540995/1481583 104.0%; Applied: 3965; Backlog: 0/1000; Time: 50s(total), 50s(copy); streamer: mysql-bin-changelog.028398:85838970; State: migrating; ETA: due
Copy: 1540995/1481583 104.0%; Applied: 3965; Backlog: 0/1000; Time: 51s(total), 51s(copy); streamer: mysql-bin-changelog.028398:85843342; State: migrating; ETA: due
Copy: 1543995/1481583 104.2%; Applied: 4404; Backlog: 0/1000; Time: 52s(total), 52s(copy); streamer: mysql-bin-changelog.028398:86544052; State: migrating; ETA: due
Copy: 1543995/1481583 104.2%; Applied: 4404; Backlog: 0/1000; Time: 53s(total), 53s(copy); streamer: mysql-bin-changelog.028398:86548811; State: migrating; ETA: due
Copy: 1543995/1481583 104.2%; Applied: 4404; Backlog: 0/1000; Time: 54s(total), 54s(copy); streamer: mysql-bin-changelog.028398:86553561; State: migrating; ETA: due
Copy: 1543995/1481583 104.2%; Applied: 4404; Backlog: 0/1000; Time: 55s(total), 55s(copy); streamer: mysql-bin-changelog.028398:86558317; State: migrating; ETA: due
Copy: 1543995/1481583 104.2%; Applied: 4404; Backlog: 0/1000; Time: 56s(total), 56s(copy); streamer: mysql-bin-changelog.028398:86563106; State: migrating; ETA: due
Copy: 1544995/1481583 104.3%; Applied: 4813; Backlog: 0/1000; Time: 57s(total), 57s(copy); streamer: mysql-bin-changelog.028398:87014180; State: migrating; ETA: due
Copy: 1544995/1481583 104.3%; Applied: 4813; Backlog: 0/1000; Time: 58s(total), 58s(copy); streamer: mysql-bin-changelog.028398:87018929; State: migrating; ETA: due
Copy: 1544995/1481583 104.3%; Applied: 4813; Backlog: 0/1000; Time: 59s(total), 59s(copy); streamer: mysql-bin-changelog.028398:87023685; State: migrating; ETA: due
Copy: 1544995/1481583 104.3%; Applied: 4813; Backlog: 0/1000; Time: 1m0s(total), 1m0s(copy); streamer: mysql-bin-changelog.028398:87028433; State: migrating; ETA: due
Copy: 1550423/1550423 100.0%; Applied: 5199; Backlog: 0/1000; Time: 1m2s(total), 1m2s(copy); streamer: mysql-bin-changelog.028398:88080344; State: migrating; ETA: due
Copy: 1550423/1550423 100.0%; Applied: 5199; Backlog: 0/1000; Time: 1m5s(total), 1m2s(copy); streamer: mysql-bin-changelog.028398:88093997; State: migrating; ETA: due
# Migrating `$DATABASE`.`$TABLE`; Ghost table is `$DATABASE`.`_$TABLE_gho`
# Migrating ip-172-21-2-151:3306; inspecting ip-172-21-2-151:3306; executing on ip-10-0-1-190
# Migration started at Wed Jul 31 07:52:28 +0000 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# Serving on unix socket: /tmp/gh-ost.$DATABASE.$TABLE.sock
Copy: 1550423/1550423 100.0%; Applied: 5695; Backlog: 0/1000; Time: 1m7s(total), 1m2s(copy); streamer: mysql-bin-changelog.028398:88577801; State: migrating; ETA: due
[2019/07/31 07:53:36] [info] binlogsyncer.go:164 syncer is closing...
[2019/07/31 07:53:36] [error] binlogstreamer.go:77 close sync with err: sync is been closing...
[2019/07/31 07:53:36] [info] binlogsyncer.go:179 syncer is closed
# Done
lydialyd0121 commented 5 years ago

Same error on 1.0.48 gh-ost: 1.0.48 MySQL：5.7.27


gh-ost --host=$HOST     --user=root --password=$MYSQL_PASSWORD     --database=$DATABASE --table=$TABLE     --alter=" add column integral int(11) NOT NULL default 0 comment 'xx' after column1;"     --allow-on-master --assume-rbr --initially-drop-ghost-table --initially-drop-old-table  -exact-rowcount  --approve-renamed-columns  --concurrent-rowcount=false --hooks-path=/tmp/hook 

[2019/08/29 02:02:57] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql 10.90.28.91 3311 incep_user false false false UTC true 0 0s 0s 0 false}
[2019/08/29 02:02:57] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.082465, 74695149)
[2019/08/29 02:02:57] [info] binlogsyncer.go:203 register slave for master server 10.90.28.91:3311
[2019/08/29 02:02:57] [info] binlogsyncer.go:723 rotate to (mysql-bin.082465, 74695149)
# Migrating `um`.`um_user_info_base`; Ghost table is `um`.`_um_user_info_base_gho`
# Migrating vcs1:3311; inspecting vcs1:3311; executing on sz080073
# Migration started at Thu Aug 29 02:02:56 +0800 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# Serving on unix socket: /tmp/gh-ost.um.um_user_info_base.sock
Copy: 0/4810499 0.0%; Applied: 0; Backlog: 0/1000; Time: 1s(total), 0s(copy); streamer: mysql-bin.082465:75134694; State: migrating; ETA: N/A
Copy: 0/4810499 0.0%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.082465:75524398; State: migrating; ETA: N/A
Copy: 11000/4810499 0.2%; Applied: 0; Backlog: 0/1000; Time: 3s(total), 2s(copy); streamer: mysql-bin.082465:76926452; State: migrating; ETA: N/A
Copy: 24000/4810499 0.5%; Applied: 0; Backlog: 0/1000; Time: 4s(total), 3s(copy); streamer: mysql-bin.082465:78486588; State: migrating; ETA: N/A
Copy: 37000/4810499 0.8%; Applied: 0; Backlog: 0/1000; Time: 5s(total), 4s(copy); streamer: mysql-bin.082465:79997881; State: migrating; ETA: N/A
Copy: 47000/4810500 1.0%; Applied: 2; Backlog: 0/1000; Time: 6s(total), 5s(copy); streamer: mysql-bin.082465:81430422; State: migrating; ETA: N/A
Copy: 59000/4810501 1.2%; Applied: 4; Backlog: 0/1000; Time: 7s(total), 6s(copy); streamer: mysql-bin.082465:82977427; State: migrating; ETA: 8m3s
Copy: 70000/4810501 1.5%; Applied: 4; Backlog: 0/1000; Time: 8s(total), 7s(copy); streamer: mysql-bin.082465:84310689; State: migrating; ETA: 7m54s
Copy: 81000/4810501 1.7%; Applied: 4; Backlog: 0/1000; Time: 9s(total), 8s(copy); streamer: mysql-bin.082465:85949642; State: migrating; ETA: 7m47s
Copy: 91000/4810501 1.9%; Applied: 4; Backlog: 0/1000; Time: 10s(total), 9s(copy); streamer: mysql-bin.082465:87255071; State: migrating; ETA: 7m46s
Copy: 102000/4810501 2.1%; Applied: 4; Backlog: 0/1000; Time: 11s(total), 10s(copy); streamer: mysql-bin.082465:88717004; State: migrating; ETA: 7m41s
Copy: 112000/4810501 2.3%; Applied: 4; Backlog: 0/1000; Time: 12s(total), 11s(copy); streamer: mysql-bin.082465:90137669; State: migrating; ETA: 7m41s
Copy: 124000/4810501 2.6%; Applied: 4; Backlog: 0/1000; Time: 13s(total), 12s(copy); streamer: mysql-bin.082465:91585554; State: migrating; ETA: 7m33s
Copy: 134000/4810501 2.8%; Applied: 4; Backlog: 0/1000; Time: 14s(total), 13s(copy); streamer: mysql-bin.082465:92910159; State: migrating; ETA: 7m33s
Copy: 144000/4810501 3.0%; Applied: 5; Backlog: 0/1000; Time: 15s(total), 14s(copy); streamer: mysql-bin.082465:94204307; State: migrating; ETA: 7m33s
Copy: 155000/4810501 3.2%; Applied: 5; Backlog: 0/1000; Time: 16s(total), 15s(copy); streamer: mysql-bin.082465:95647022; State: migrating; ETA: 7m30s
Copy: 165000/4810501 3.4%; Applied: 5; Backlog: 0/1000; Time: 17s(total), 16s(copy); streamer: mysql-bin.082465:97038992; State: migrating; ETA: 7m30s
Copy: 176000/4810501 3.7%; Applied: 5; Backlog: 0/1000; Time: 18s(total), 17s(copy); streamer: mysql-bin.082465:98508414; State: migrating; ETA: 7m27s
Copy: 186000/4810501 3.9%; Applied: 5; Backlog: 0/1000; Time: 19s(total), 18s(copy); streamer: mysql-bin.082465:99788526; State: migrating; ETA: 7m27s
Copy: 196000/4810501 4.1%; Applied: 5; Backlog: 0/1000; Time: 20s(total), 19s(copy); streamer: mysql-bin.082465:101243558; State: migrating; ETA: 7m27s
Copy: 206000/4810501 4.3%; Applied: 5; Backlog: 0/1000; Time: 21s(total), 20s(copy); streamer: mysql-bin.082465:102766541; State: migrating; ETA: 7m27s
Copy: 216000/4810501 4.5%; Applied: 5; Backlog: 0/1000; Time: 22s(total), 21s(copy); streamer: mysql-bin.082465:104162319; State: migrating; ETA: 7m26s
Copy: 227000/4810501 4.7%; Applied: 5; Backlog: 0/1000; Time: 23s(total), 22s(copy); streamer: mysql-bin.082465:105808010; State: migrating; ETA: 7m24s
Copy: 237000/4810501 4.9%; Applied: 7; Backlog: 0/1000; Time: 24s(total), 23s(copy); streamer: mysql-bin.082465:107433607; State: migrating; ETA: 7m23s
Copy: 247000/4810501 5.1%; Applied: 7; Backlog: 0/1000; Time: 25s(total), 24s(copy); streamer: mysql-bin.082465:108960307; State: migrating; ETA: 7m23s
Copy: 257000/4810501 5.3%; Applied: 7; Backlog: 0/1000; Time: 26s(total), 25s(copy); streamer: mysql-bin.082465:110533000; State: migrating; ETA: 7m23s
Copy: 267000/4810501 5.6%; Applied: 7; Backlog: 0/1000; Time: 27s(total), 26s(copy); streamer: mysql-bin.082465:112062789; State: migrating; ETA: 7m22s
Copy: 277000/4810501 5.8%; Applied: 7; Backlog: 0/1000; Time: 28s(total), 27s(copy); streamer: mysql-bin.082465:113639832; State: migrating; ETA: 7m21s
Copy: 285000/4810501 5.9%; Applied: 7; Backlog: 0/1000; Time: 29s(total), 28s(copy); streamer: mysql-bin.082465:114965872; State: migrating; ETA: 7m24s
Copy: 295000/4810501 6.1%; Applied: 7; Backlog: 0/1000; Time: 30s(total), 29s(copy); streamer: mysql-bin.082465:116526263; State: migrating; ETA: 7m23s
Copy: 304000/4810501 6.3%; Applied: 7; Backlog: 0/1000; Time: 31s(total), 30s(copy); streamer: mysql-bin.082465:118086150; State: migrating; ETA: 7m24s
Copy: 313000/4810501 6.5%; Applied: 7; Backlog: 0/1000; Time: 32s(total), 31s(copy); streamer: mysql-bin.082465:119532085; State: migrating; ETA: 7m25s
Copy: 322000/4810501 6.7%; Applied: 7; Backlog: 0/1000; Time: 33s(total), 32s(copy); streamer: mysql-bin.082465:121042067; State: migrating; ETA: 7m26s
Copy: 332000/4810501 6.9%; Applied: 7; Backlog: 0/1000; Time: 34s(total), 33s(copy); streamer: mysql-bin.082465:122535683; State: migrating; ETA: 7m25s
Copy: 342000/4810501 7.1%; Applied: 7; Backlog: 0/1000; Time: 35s(total), 34s(copy); streamer: mysql-bin.082465:124023456; State: migrating; ETA: 7m24s
Copy: 352000/4810501 7.3%; Applied: 7; Backlog: 0/1000; Time: 36s(total), 35s(copy); streamer: mysql-bin.082465:125581526; State: migrating; ETA: 7m23s
Copy: 362000/4810502 7.5%; Applied: 9; Backlog: 0/1000; Time: 37s(total), 36s(copy); streamer: mysql-bin.082465:127156522; State: migrating; ETA: 7m22s
Copy: 372000/4810502 7.7%; Applied: 9; Backlog: 0/1000; Time: 38s(total), 37s(copy); streamer: mysql-bin.082465:128767271; State: migrating; ETA: 7m21s
Copy: 382000/4810502 7.9%; Applied: 9; Backlog: 0/1000; Time: 39s(total), 38s(copy); streamer: mysql-bin.082465:130288750; State: migrating; ETA: 7m20s
Copy: 391000/4810502 8.1%; Applied: 9; Backlog: 0/1000; Time: 40s(total), 39s(copy); streamer: mysql-bin.082465:131792546; State: migrating; ETA: 7m20s
Copy: 401000/4810502 8.3%; Applied: 9; Backlog: 0/1000; Time: 41s(total), 40s(copy); streamer: mysql-bin.082465:133337900; State: migrating; ETA: 7m19s
Copy: 411000/4810502 8.5%; Applied: 9; Backlog: 0/1000; Time: 42s(total), 41s(copy); streamer: mysql-bin.082465:135076896; State: migrating; ETA: 7m18s
Copy: 420000/4810502 8.7%; Applied: 9; Backlog: 0/1000; Time: 43s(total), 42s(copy); streamer: mysql-bin.082465:136722576; State: migrating; ETA: 7m19s
Copy: 429000/4810502 8.9%; Applied: 9; Backlog: 0/1000; Time: 44s(total), 43s(copy); streamer: mysql-bin.082465:138255851; State: migrating; ETA: 7m19s
Copy: 439000/4810502 9.1%; Applied: 9; Backlog: 0/1000; Time: 45s(total), 44s(copy); streamer: mysql-bin.082465:139835619; State: migrating; ETA: 7m18s
Copy: 448000/4810502 9.3%; Applied: 9; Backlog: 0/1000; Time: 46s(total), 45s(copy); streamer: mysql-bin.082465:141463596; State: migrating; ETA: 7m18s
Copy: 458000/4810502 9.5%; Applied: 9; Backlog: 0/1000; Time: 47s(total), 46s(copy); streamer: mysql-bin.082465:143201272; State: migrating; ETA: 7m17s
Copy: 467000/4810502 9.7%; Applied: 9; Backlog: 0/1000; Time: 48s(total), 47s(copy); streamer: mysql-bin.082465:144766596; State: migrating; ETA: 7m17s
Copy: 477000/4810502 9.9%; Applied: 9; Backlog: 0/1000; Time: 49s(total), 48s(copy); streamer: mysql-bin.082465:146431747; State: migrating; ETA: 7m16s
Copy: 485000/4810502 10.1%; Applied: 10; Backlog: 0/1000; Time: 50s(total), 49s(copy); streamer: mysql-bin.082465:147855537; State: migrating; ETA: 7m17s
Copy: 494000/4810502 10.3%; Applied: 10; Backlog: 0/1000; Time: 51s(total), 50s(copy); streamer: mysql-bin.082465:149446917; State: migrating; ETA: 7m16s
Copy: 504000/4810502 10.5%; Applied: 10; Backlog: 0/1000; Time: 52s(total), 51s(copy); streamer: mysql-bin.082465:151126286; State: migrating; ETA: 7m15s
Copy: 513000/4810502 10.7%; Applied: 10; Backlog: 0/1000; Time: 53s(total), 52s(copy); streamer: mysql-bin.082465:152734743; State: migrating; ETA: 7m15s
Copy: 522000/4810502 10.9%; Applied: 10; Backlog: 0/1000; Time: 54s(total), 53s(copy); streamer: mysql-bin.082465:154247112; State: migrating; ETA: 7m15s
Copy: 531000/4810502 11.0%; Applied: 10; Backlog: 0/1000; Time: 55s(total), 54s(copy); streamer: mysql-bin.082465:155773167; State: migrating; ETA: 7m15s
Copy: 539000/4810502 11.2%; Applied: 10; Backlog: 0/1000; Time: 56s(total), 55s(copy); streamer: mysql-bin.082465:157282145; State: migrating; ETA: 7m15s
Copy: 548000/4810502 11.4%; Applied: 10; Backlog: 0/1000; Time: 57s(total), 56s(copy); streamer: mysql-bin.082465:158801094; State: migrating; ETA: 7m15s
Copy: 556000/4810502 11.6%; Applied: 10; Backlog: 0/1000; Time: 58s(total), 57s(copy); streamer: mysql-bin.082465:160368617; State: migrating; ETA: 7m16s
Copy: 565000/4810502 11.7%; Applied: 10; Backlog: 0/1000; Time: 59s(total), 58s(copy); streamer: mysql-bin.082465:161927333; State: migrating; ETA: 7m15s
Copy: 574000/4810502 11.9%; Applied: 11; Backlog: 0/1000; Time: 1m0s(total), 59s(copy); streamer: mysql-bin.082465:163489871; State: migrating; ETA: 7m15s
Copy: 618000/4810502 12.8%; Applied: 11; Backlog: 0/1000; Time: 1m5s(total), 1m4s(copy); streamer: mysql-bin.082465:171281422; State: migrating; ETA: 7m14s
Copy: 661000/4810502 13.7%; Applied: 11; Backlog: 0/1000; Time: 1m10s(total), 1m9s(copy); streamer: mysql-bin.082465:179059211; State: migrating; ETA: 7m13s
Copy: 706000/4810502 14.7%; Applied: 12; Backlog: 0/1000; Time: 1m15s(total), 1m14s(copy); streamer: mysql-bin.082465:186859080; State: migrating; ETA: 7m10s
Copy: 751000/4810502 15.6%; Applied: 12; Backlog: 0/1000; Time: 1m20s(total), 1m19s(copy); streamer: mysql-bin.082465:194501598; State: migrating; ETA: 7m7s
Copy: 795000/4810502 16.5%; Applied: 12; Backlog: 0/1000; Time: 1m25s(total), 1m24s(copy); streamer: mysql-bin.082465:201916164; State: migrating; ETA: 7m4s
Copy: 838000/4810502 17.4%; Applied: 14; Backlog: 0/1000; Time: 1m30s(total), 1m29s(copy); streamer: mysql-bin.082465:209475268; State: migrating; ETA: 7m1s
Copy: 881000/4810502 18.3%; Applied: 14; Backlog: 0/1000; Time: 1m35s(total), 1m34s(copy); streamer: mysql-bin.082465:216860080; State: migrating; ETA: 6m59s
Copy: 923000/4810503 19.2%; Applied: 16; Backlog: 0/1000; Time: 1m40s(total), 1m39s(copy); streamer: mysql-bin.082465:223872870; State: migrating; ETA: 6m56s
Copy: 967000/4810503 20.1%; Applied: 16; Backlog: 0/1000; Time: 1m45s(total), 1m44s(copy); streamer: mysql-bin.082465:231087183; State: migrating; ETA: 6m53s
Copy: 1010000/4810504 21.0%; Applied: 18; Backlog: 0/1000; Time: 1m50s(total), 1m49s(copy); streamer: mysql-bin.082465:238003407; State: migrating; ETA: 6m50s
Copy: 1051000/4810504 21.8%; Applied: 19; Backlog: 0/1000; Time: 1m55s(total), 1m54s(copy); streamer: mysql-bin.082465:244482012; State: migrating; ETA: 6m47s
Copy: 1094000/4810504 22.7%; Applied: 19; Backlog: 0/1000; Time: 2m0s(total), 1m59s(copy); streamer: mysql-bin.082465:251430834; State: migrating; ETA: 6m44s
Copy: 1133000/4810506 23.6%; Applied: 23; Backlog: 0/1000; Time: 2m5s(total), 2m4s(copy); streamer: mysql-bin.082465:257819912; State: migrating; ETA: 6m42s
Copy: 1172000/4810506 24.4%; Applied: 23; Backlog: 0/1000; Time: 2m10s(total), 2m9s(copy); streamer: mysql-bin.082465:264484024; State: migrating; ETA: 6m40s
[2019/08/29 02:05:10] [info] binlogsyncer.go:723 rotate to (mysql-bin.082466, 4)
[2019/08/29 02:05:10] [info] binlogsyncer.go:723 rotate to (mysql-bin.082466, 4)
Copy: 1213000/4810506 25.2%; Applied: 24; Backlog: 1/1000; Time: 2m15s(total), 2m14s(copy); streamer: mysql-bin.082466:2780470; State: migrating; ETA: 6m37s
Copy: 1255000/4810506 26.1%; Applied: 27; Backlog: 0/1000; Time: 2m20s(total), 2m19s(copy); streamer: mysql-bin.082466:9369272; State: migrating; ETA: 6m33s
Copy: 1296000/4810507 26.9%; Applied: 28; Backlog: 0/1000; Time: 2m25s(total), 2m24s(copy); streamer: mysql-bin.082466:16221238; State: migrating; ETA: 6m30s
Copy: 1335000/4810507 27.8%; Applied: 29; Backlog: 0/1000; Time: 2m30s(total), 2m29s(copy); streamer: mysql-bin.082466:22595393; State: migrating; ETA: 6m27s
Copy: 1376000/4810507 28.6%; Applied: 30; Backlog: 0/1000; Time: 2m35s(total), 2m34s(copy); streamer: mysql-bin.082466:28890289; State: migrating; ETA: 6m24s
Copy: 1417000/4810507 29.5%; Applied: 30; Backlog: 0/1000; Time: 2m40s(total), 2m39s(copy); streamer: mysql-bin.082466:35376440; State: migrating; ETA: 6m20s
Copy: 1458000/4810507 30.3%; Applied: 33; Backlog: 0/1000; Time: 2m45s(total), 2m44s(copy); streamer: mysql-bin.082466:41926569; State: migrating; ETA: 6m17s
Copy: 1500000/4810507 31.2%; Applied: 33; Backlog: 0/1000; Time: 2m50s(total), 2m49s(copy); streamer: mysql-bin.082466:50154650; State: migrating; ETA: 6m12s
Copy: 1542000/4810508 32.1%; Applied: 35; Backlog: 0/1000; Time: 2m55s(total), 2m54s(copy); streamer: mysql-bin.082466:56790396; State: migrating; ETA: 6m8s
Copy: 1583000/4810510 32.9%; Applied: 41; Backlog: 0/1000; Time: 3m0s(total), 2m59s(copy); streamer: mysql-bin.082466:63364377; State: migrating; ETA: 6m4s
Copy: 1832000/4810511 38.1%; Applied: 48; Backlog: 0/1000; Time: 3m30s(total), 3m29s(copy); streamer: mysql-bin.082466:103704104; State: migrating; ETA: 5m39s
Copy: 2079000/4810511 43.2%; Applied: 51; Backlog: 0/1000; Time: 4m0s(total), 3m59s(copy); streamer: mysql-bin.082466:144435410; State: migrating; ETA: 5m14s
Copy: 2324000/4810512 48.3%; Applied: 54; Backlog: 0/1000; Time: 4m30s(total), 4m29s(copy); streamer: mysql-bin.082466:186515484; State: migrating; ETA: 4m47s
Copy: 2565000/4810515 53.3%; Applied: 60; Backlog: 0/1000; Time: 5m0s(total), 4m59s(copy); streamer: mysql-bin.082466:229627469; State: migrating; ETA: 4m21s
[2019/08/29 02:08:25] [info] binlogsyncer.go:723 rotate to (mysql-bin.082467, 4)
[2019/08/29 02:08:25] [info] binlogsyncer.go:723 rotate to (mysql-bin.082467, 4)
Copy: 2807000/4810516 58.4%; Applied: 67; Backlog: 0/1000; Time: 5m30s(total), 5m29s(copy); streamer: mysql-bin.082467:2306266; State: migrating; ETA: 3m54s
Copy: 3046000/4810518 63.3%; Applied: 74; Backlog: 0/1000; Time: 6m0s(total), 5m59s(copy); streamer: mysql-bin.082467:43672090; State: migrating; ETA: 3m27s
Copy: 3278000/4810518 68.1%; Applied: 76; Backlog: 0/1000; Time: 6m30s(total), 6m29s(copy); streamer: mysql-bin.082467:84213750; State: migrating; ETA: 3m1s
Copy: 3316000/4810518 68.9%; Applied: 76; Backlog: 0/1000; Time: 6m35s(total), 6m34s(copy); streamer: mysql-bin.082467:91934226; State: migrating; ETA: 2m57s
Copy: 3355000/4810518 69.7%; Applied: 76; Backlog: 0/1000; Time: 6m40s(total), 6m39s(copy); streamer: mysql-bin.082467:97826595; State: migrating; ETA: 2m53s
Copy: 3394000/4810518 70.6%; Applied: 76; Backlog: 0/1000; Time: 6m45s(total), 6m44s(copy); streamer: mysql-bin.082467:104023808; State: migrating; ETA: 2m48s
Copy: 3435000/4810518 71.4%; Applied: 76; Backlog: 0/1000; Time: 6m50s(total), 6m49s(copy); streamer: mysql-bin.082467:110412146; State: migrating; ETA: 2m43s
Copy: 3475000/4810519 72.2%; Applied: 78; Backlog: 0/1000; Time: 6m55s(total), 6m54s(copy); streamer: mysql-bin.082467:116683637; State: migrating; ETA: 2m39s
Copy: 3514000/4810520 73.0%; Applied: 79; Backlog: 0/1000; Time: 7m0s(total), 6m59s(copy); streamer: mysql-bin.082467:122775939; State: migrating; ETA: 2m34s
Copy: 3553000/4810520 73.9%; Applied: 80; Backlog: 0/1000; Time: 7m5s(total), 7m4s(copy); streamer: mysql-bin.082467:129317682; State: migrating; ETA: 2m30s
Copy: 3591000/4810520 74.6%; Applied: 80; Backlog: 0/1000; Time: 7m10s(total), 7m9s(copy); streamer: mysql-bin.082467:136477550; State: migrating; ETA: 2m25s
Copy: 3629000/4810520 75.4%; Applied: 81; Backlog: 0/1000; Time: 7m15s(total), 7m14s(copy); streamer: mysql-bin.082467:142712636; State: migrating; ETA: 2m21s
Copy: 3669000/4810520 76.3%; Applied: 82; Backlog: 0/1000; Time: 7m20s(total), 7m19s(copy); streamer: mysql-bin.082467:148920521; State: migrating; ETA: 2m16s
Copy: 3708000/4810520 77.1%; Applied: 82; Backlog: 0/1000; Time: 7m25s(total), 7m24s(copy); streamer: mysql-bin.082467:155143294; State: migrating; ETA: 2m12s
Copy: 3748000/4810520 77.9%; Applied: 82; Backlog: 0/1000; Time: 7m30s(total), 7m29s(copy); streamer: mysql-bin.082467:161509564; State: migrating; ETA: 2m7s
Copy: 3788000/4810520 78.7%; Applied: 82; Backlog: 0/1000; Time: 7m35s(total), 7m34s(copy); streamer: mysql-bin.082467:167837442; State: migrating; ETA: 2m2s
Copy: 3828000/4810520 79.6%; Applied: 82; Backlog: 0/1000; Time: 7m40s(total), 7m39s(copy); streamer: mysql-bin.082467:174178242; State: migrating; ETA: 1m57s
Copy: 3867000/4810520 80.4%; Applied: 83; Backlog: 0/1000; Time: 7m45s(total), 7m44s(copy); streamer: mysql-bin.082467:180393185; State: migrating; ETA: 1m53s
Copy: 3905000/4810520 81.2%; Applied: 83; Backlog: 0/1000; Time: 7m50s(total), 7m49s(copy); streamer: mysql-bin.082467:186350747; State: migrating; ETA: 1m48s
Copy: 3944000/4810520 82.0%; Applied: 83; Backlog: 0/1000; Time: 7m55s(total), 7m54s(copy); streamer: mysql-bin.082467:192805463; State: migrating; ETA: 1m44s
Copy: 3984000/4810520 82.8%; Applied: 83; Backlog: 0/1000; Time: 8m0s(total), 7m59s(copy); streamer: mysql-bin.082467:199183173; State: migrating; ETA: 1m39s
Copy: 4024000/4810520 83.7%; Applied: 84; Backlog: 0/1000; Time: 8m5s(total), 8m4s(copy); streamer: mysql-bin.082467:205718077; State: migrating; ETA: 1m34s
Copy: 4064000/4810520 84.5%; Applied: 84; Backlog: 0/1000; Time: 8m10s(total), 8m9s(copy); streamer: mysql-bin.082467:214877467; State: migrating; ETA: 1m29s
Copy: 4101000/4810522 85.3%; Applied: 88; Backlog: 0/1000; Time: 8m15s(total), 8m14s(copy); streamer: mysql-bin.082467:221256293; State: migrating; ETA: 1m25s
Copy: 4142000/4810522 86.1%; Applied: 88; Backlog: 0/1000; Time: 8m20s(total), 8m19s(copy); streamer: mysql-bin.082467:227654974; State: migrating; ETA: 1m20s
Copy: 4181000/4810522 86.9%; Applied: 88; Backlog: 0/1000; Time: 8m25s(total), 8m24s(copy); streamer: mysql-bin.082467:235471594; State: migrating; ETA: 1m15s
Copy: 4221000/4810522 87.7%; Applied: 88; Backlog: 0/1000; Time: 8m30s(total), 8m29s(copy); streamer: mysql-bin.082467:242279998; State: migrating; ETA: 1m11s
Copy: 4260000/4810522 88.6%; Applied: 88; Backlog: 0/1000; Time: 8m35s(total), 8m34s(copy); streamer: mysql-bin.082467:248291538; State: migrating; ETA: 1m6s
Copy: 4298000/4810522 89.3%; Applied: 89; Backlog: 0/1000; Time: 8m40s(total), 8m39s(copy); streamer: mysql-bin.082467:254324508; State: migrating; ETA: 1m1s
Copy: 4314000/4810522 89.7%; Applied: 89; Backlog: 0/1000; Time: 8m42s(total), 8m41s(copy); streamer: mysql-bin.082467:256945531; State: migrating; ETA: 59s
Copy: 4321000/4810522 89.8%; Applied: 89; Backlog: 0/1000; Time: 8m43s(total), 8m42s(copy); streamer: mysql-bin.082467:258134975; State: migrating; ETA: 59s
Copy: 4327000/4810522 89.9%; Applied: 89; Backlog: 0/1000; Time: 8m44s(total), 8m43s(copy); streamer: mysql-bin.082467:259208035; State: migrating; ETA: 58s
Copy: 4335000/4810522 90.1%; Applied: 89; Backlog: 0/1000; Time: 8m45s(total), 8m44s(copy); streamer: mysql-bin.082467:260454564; State: migrating; ETA: 57s
Copy: 4343000/4810522 90.3%; Applied: 89; Backlog: 0/1000; Time: 8m46s(total), 8m45s(copy); streamer: mysql-bin.082467:261708621; State: migrating; ETA: 56s
Copy: 4351000/4810522 90.4%; Applied: 89; Backlog: 0/1000; Time: 8m47s(total), 8m46s(copy); streamer: mysql-bin.082467:262831932; State: migrating; ETA: 55s
Copy: 4359000/4810522 90.6%; Applied: 89; Backlog: 0/1000; Time: 8m48s(total), 8m47s(copy); streamer: mysql-bin.082467:264257297; State: migrating; ETA: 54s
Copy: 4367000/4810522 90.8%; Applied: 89; Backlog: 0/1000; Time: 8m49s(total), 8m48s(copy); streamer: mysql-bin.082467:265560781; State: migrating; ETA: 53s
Copy: 4374000/4810522 90.9%; Applied: 89; Backlog: 0/1000; Time: 8m50s(total), 8m49s(copy); streamer: mysql-bin.082467:266772963; State: migrating; ETA: 52s
Copy: 4382000/4810522 91.1%; Applied: 89; Backlog: 0/1000; Time: 8m51s(total), 8m50s(copy); streamer: mysql-bin.082467:268080503; State: migrating; ETA: 51s
[2019/08/29 02:11:48] [info] binlogsyncer.go:723 rotate to (mysql-bin.082468, 4)
[2019/08/29 02:11:48] [info] binlogsyncer.go:723 rotate to (mysql-bin.082468, 4)
Copy: 4390000/4810522 91.3%; Applied: 89; Backlog: 0/1000; Time: 8m52s(total), 8m51s(copy); streamer: mysql-bin.082468:943748; State: migrating; ETA: 50s
Copy: 4397000/4810522 91.4%; Applied: 89; Backlog: 0/1000; Time: 8m53s(total), 8m52s(copy); streamer: mysql-bin.082468:2113347; State: migrating; ETA: 50s
Copy: 4405000/4810522 91.6%; Applied: 89; Backlog: 0/1000; Time: 8m54s(total), 8m53s(copy); streamer: mysql-bin.082468:3426030; State: migrating; ETA: 49s
Copy: 4413000/4810522 91.7%; Applied: 89; Backlog: 0/1000; Time: 8m55s(total), 8m54s(copy); streamer: mysql-bin.082468:4716385; State: migrating; ETA: 48s
Copy: 4421000/4810522 91.9%; Applied: 89; Backlog: 0/1000; Time: 8m56s(total), 8m55s(copy); streamer: mysql-bin.082468:5897364; State: migrating; ETA: 47s
Copy: 4428000/4810522 92.0%; Applied: 89; Backlog: 0/1000; Time: 8m57s(total), 8m56s(copy); streamer: mysql-bin.082468:7072374; State: migrating; ETA: 46s
Copy: 4437000/4810522 92.2%; Applied: 89; Backlog: 0/1000; Time: 8m58s(total), 8m57s(copy); streamer: mysql-bin.082468:8418145; State: migrating; ETA: 45s
Copy: 4444000/4810522 92.4%; Applied: 89; Backlog: 0/1000; Time: 8m59s(total), 8m58s(copy); streamer: mysql-bin.082468:9576586; State: migrating; ETA: 44s
Copy: 4452000/4810523 92.5%; Applied: 91; Backlog: 0/1000; Time: 9m0s(total), 8m59s(copy); streamer: mysql-bin.082468:10887655; State: migrating; ETA: 43s
Copy: 4460000/4810523 92.7%; Applied: 91; Backlog: 0/1000; Time: 9m1s(total), 9m0s(copy); streamer: mysql-bin.082468:12105503; State: migrating; ETA: 42s
Copy: 4468000/4810523 92.9%; Applied: 91; Backlog: 0/1000; Time: 9m2s(total), 9m1s(copy); streamer: mysql-bin.082468:13370732; State: migrating; ETA: 41s
Copy: 4475000/4810523 93.0%; Applied: 91; Backlog: 0/1000; Time: 9m3s(total), 9m2s(copy); streamer: mysql-bin.082468:14609408; State: migrating; ETA: 40s
Copy: 4482000/4810523 93.2%; Applied: 91; Backlog: 0/1000; Time: 9m4s(total), 9m3s(copy); streamer: mysql-bin.082468:15863332; State: migrating; ETA: 39s
Copy: 4490000/4810523 93.3%; Applied: 92; Backlog: 0/1000; Time: 9m5s(total), 9m4s(copy); streamer: mysql-bin.082468:17133853; State: migrating; ETA: 38s
Copy: 4497000/4810523 93.5%; Applied: 92; Backlog: 0/1000; Time: 9m6s(total), 9m5s(copy); streamer: mysql-bin.082468:18267521; State: migrating; ETA: 37s
Copy: 4505000/4810523 93.6%; Applied: 92; Backlog: 0/1000; Time: 9m7s(total), 9m6s(copy); streamer: mysql-bin.082468:19493082; State: migrating; ETA: 37s
Copy: 4512000/4810523 93.8%; Applied: 92; Backlog: 0/1000; Time: 9m8s(total), 9m7s(copy); streamer: mysql-bin.082468:20808753; State: migrating; ETA: 36s
Copy: 4520000/4810523 94.0%; Applied: 92; Backlog: 0/1000; Time: 9m9s(total), 9m8s(copy); streamer: mysql-bin.082468:21987810; State: migrating; ETA: 35s
Copy: 4528000/4810523 94.1%; Applied: 92; Backlog: 0/1000; Time: 9m10s(total), 9m9s(copy); streamer: mysql-bin.082468:23314769; State: migrating; ETA: 34s
Copy: 4536000/4810523 94.3%; Applied: 92; Backlog: 0/1000; Time: 9m11s(total), 9m10s(copy); streamer: mysql-bin.082468:24559028; State: migrating; ETA: 33s
Copy: 4544000/4810523 94.5%; Applied: 92; Backlog: 0/1000; Time: 9m12s(total), 9m11s(copy); streamer: mysql-bin.082468:25752062; State: migrating; ETA: 32s
Copy: 4551000/4810524 94.6%; Applied: 94; Backlog: 0/1000; Time: 9m13s(total), 9m12s(copy); streamer: mysql-bin.082468:26894510; State: migrating; ETA: 31s
Copy: 4558000/4810524 94.8%; Applied: 94; Backlog: 0/1000; Time: 9m14s(total), 9m13s(copy); streamer: mysql-bin.082468:28169982; State: migrating; ETA: 30s
Copy: 4566000/4810525 94.9%; Applied: 96; Backlog: 0/1000; Time: 9m15s(total), 9m14s(copy); streamer: mysql-bin.082468:29514179; State: migrating; ETA: 29s
Copy: 4574000/4810525 95.1%; Applied: 96; Backlog: 0/1000; Time: 9m16s(total), 9m15s(copy); streamer: mysql-bin.082468:33622649; State: migrating; ETA: 28s
Copy: 4581000/4810525 95.2%; Applied: 96; Backlog: 0/1000; Time: 9m17s(total), 9m16s(copy); streamer: mysql-bin.082468:34704122; State: migrating; ETA: 27s
Copy: 4588000/4810525 95.4%; Applied: 96; Backlog: 0/1000; Time: 9m18s(total), 9m17s(copy); streamer: mysql-bin.082468:35858804; State: migrating; ETA: 27s
Copy: 4596000/4810525 95.5%; Applied: 96; Backlog: 0/1000; Time: 9m19s(total), 9m18s(copy); streamer: mysql-bin.082468:37072923; State: migrating; ETA: 26s
Copy: 4604000/4810525 95.7%; Applied: 96; Backlog: 0/1000; Time: 9m20s(total), 9m19s(copy); streamer: mysql-bin.082468:38288491; State: migrating; ETA: 25s
Copy: 4613000/4810525 95.9%; Applied: 96; Backlog: 0/1000; Time: 9m21s(total), 9m20s(copy); streamer: mysql-bin.082468:39665373; State: migrating; ETA: 23s
Copy: 4620000/4810525 96.0%; Applied: 96; Backlog: 0/1000; Time: 9m22s(total), 9m21s(copy); streamer: mysql-bin.082468:40709916; State: migrating; ETA: 23s
Copy: 4628000/4810526 96.2%; Applied: 97; Backlog: 0/1000; Time: 9m23s(total), 9m22s(copy); streamer: mysql-bin.082468:42037742; State: migrating; ETA: 22s
Copy: 4637000/4810526 96.4%; Applied: 97; Backlog: 0/1000; Time: 9m24s(total), 9m23s(copy); streamer: mysql-bin.082468:43365137; State: migrating; ETA: 21s
Copy: 4644000/4810526 96.5%; Applied: 97; Backlog: 0/1000; Time: 9m25s(total), 9m24s(copy); streamer: mysql-bin.082468:44498820; State: migrating; ETA: 20s
Copy: 4651000/4810526 96.7%; Applied: 98; Backlog: 0/1000; Time: 9m26s(total), 9m25s(copy); streamer: mysql-bin.082468:45737354; State: migrating; ETA: 19s
Copy: 4658000/4810526 96.8%; Applied: 98; Backlog: 0/1000; Time: 9m27s(total), 9m26s(copy); streamer: mysql-bin.082468:46889186; State: migrating; ETA: 18s
Copy: 4666000/4810526 97.0%; Applied: 98; Backlog: 0/1000; Time: 9m28s(total), 9m27s(copy); streamer: mysql-bin.082468:48238463; State: migrating; ETA: 17s
Copy: 4674000/4810526 97.2%; Applied: 98; Backlog: 0/1000; Time: 9m29s(total), 9m28s(copy); streamer: mysql-bin.082468:49527948; State: migrating; ETA: 16s
Copy: 4682000/4810526 97.3%; Applied: 98; Backlog: 0/1000; Time: 9m30s(total), 9m29s(copy); streamer: mysql-bin.082468:50718677; State: migrating; ETA: 15s
Copy: 4690000/4810526 97.5%; Applied: 98; Backlog: 0/1000; Time: 9m31s(total), 9m30s(copy); streamer: mysql-bin.082468:52059475; State: migrating; ETA: 14s
Copy: 4698000/4810526 97.7%; Applied: 98; Backlog: 0/1000; Time: 9m32s(total), 9m31s(copy); streamer: mysql-bin.082468:53115678; State: migrating; ETA: 13s
Copy: 4705000/4810526 97.8%; Applied: 98; Backlog: 0/1000; Time: 9m33s(total), 9m32s(copy); streamer: mysql-bin.082468:54374590; State: migrating; ETA: 12s
Copy: 4714000/4810526 98.0%; Applied: 99; Backlog: 0/1000; Time: 9m34s(total), 9m33s(copy); streamer: mysql-bin.082468:55700634; State: migrating; ETA: 11s
Copy: 4722000/4810526 98.2%; Applied: 99; Backlog: 0/1000; Time: 9m35s(total), 9m34s(copy); streamer: mysql-bin.082468:56879179; State: migrating; ETA: 10s
Copy: 4730000/4810526 98.3%; Applied: 99; Backlog: 0/1000; Time: 9m36s(total), 9m35s(copy); streamer: mysql-bin.082468:58125764; State: migrating; ETA: 9s
Copy: 4738000/4810526 98.5%; Applied: 99; Backlog: 0/1000; Time: 9m37s(total), 9m36s(copy); streamer: mysql-bin.082468:59339605; State: migrating; ETA: 8s
Copy: 4745000/4810526 98.6%; Applied: 99; Backlog: 0/1000; Time: 9m38s(total), 9m37s(copy); streamer: mysql-bin.082468:60474255; State: migrating; ETA: 7s
Copy: 4753000/4810526 98.8%; Applied: 99; Backlog: 0/1000; Time: 9m39s(total), 9m38s(copy); streamer: mysql-bin.082468:61642527; State: migrating; ETA: 6s
Copy: 4761000/4810526 99.0%; Applied: 99; Backlog: 0/1000; Time: 9m40s(total), 9m39s(copy); streamer: mysql-bin.082468:62857250; State: migrating; ETA: 6s
Copy: 4768000/4810526 99.1%; Applied: 99; Backlog: 0/1000; Time: 9m41s(total), 9m40s(copy); streamer: mysql-bin.082468:64101454; State: migrating; ETA: 5s
Copy: 4776000/4810526 99.3%; Applied: 100; Backlog: 0/1000; Time: 9m42s(total), 9m41s(copy); streamer: mysql-bin.082468:65321366; State: migrating; ETA: 4s
Copy: 4784000/4810526 99.4%; Applied: 100; Backlog: 0/1000; Time: 9m43s(total), 9m42s(copy); streamer: mysql-bin.082468:66476078; State: migrating; ETA: 3s
Copy: 4791000/4810526 99.6%; Applied: 100; Backlog: 0/1000; Time: 9m44s(total), 9m43s(copy); streamer: mysql-bin.082468:67488864; State: migrating; ETA: 2s
Copy: 4797000/4810527 99.7%; Applied: 102; Backlog: 0/1000; Time: 9m45s(total), 9m44s(copy); streamer: mysql-bin.082468:68688693; State: migrating; ETA: 1s
Copy: 4805000/4810527 99.9%; Applied: 102; Backlog: 0/1000; Time: 9m46s(total), 9m45s(copy); streamer: mysql-bin.082468:69905675; State: migrating; ETA: 0s
Copy: 4810499/4810499 100.0%; Applied: 102; Backlog: 0/1000; Time: 9m47s(total), 9m45s(copy); streamer: mysql-bin.082468:70779044; State: migrating; ETA: due
# Migrating `um`.`um_user_info_base`; Ghost table is `um`.`_um_user_info_base_gho`
# Migrating vcs1:3311; inspecting vcs1:3311; executing on sz080073
# Migration started at Thu Aug 29 02:02:56 +0800 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle 
# Serving on unix socket: /tmp/gh-ost.um.um_user_info_base.sock
Copy: 4810499/4810499 100.0%; Applied: 102; Backlog: 0/1000; Time: 9m48s(total), 9m45s(copy); streamer: mysql-bin.082468:71176154; State: migrating; ETA: due
[2019/08/29 02:12:45] [info] binlogsyncer.go:164 syncer is closing...
[2019/08/29 02:12:45] [error] binlogstreamer.go:77 close sync with err: sync is been closing...
[2019/08/29 02:12:45] [info] binlogsyncer.go:179 syncer is closed
# Done
chulkilee commented 2 years ago

This is happening in 1.1.4 which uses old version of mysql library. binlogsyncer.go:164 is at https://github.com/github/gh-ost/blob/v1.1.4/vendor/github.com/siddontang/go-mysql/replication/binlogsyncer.go#L164

I'm not sure the upgrade would fix it.. but can we get a new release with that change?

SungTien commented 2 years ago

MySQL [test]> select version(); +------------+ | version() | +------------+ | 5.7.35-log | +------------+ 1 row in set (0.00 sec)

MySQL [test]> show create table rds_table_01 \G 1. row Table: rds_table_01 Create Table: CREATE TABLE rds_table_01 ( id bigint(20) NOT NULL AUTO_INCREMENT, name varchar(200) CHARACTER SET utf16 COLLATE utf16_bin NOT NULL DEFAULT '' COMMENT 'fdsfff', created_time datetime(3) DEFAULT CURRENT_TIMESTAMP(3), address1 varchar(100) DEFAULT ' ' COMMENT '地址1', a10 decimal(16,4) NOT NULL DEFAULT '1000.0100' COMMENT 'a10', PRIMARY KEY (id), KEY name (name(50),address1) USING BTREE ) ENGINE=InnoDB AUTO_INCREMENT=7 DEFAULT CHARSET=utf8mb4 1 row in set (0.00 sec)

gh-ost --version

1.1.1

execute shell : gh-ost --user='xxx' --password='xxxxx' --host=172.xx.x.x --port=30xx --database='test' --table='rds_table_01' --alter="ADD COLUMN age INT(11) NOT NULL DEFAULT '18' COMMENT 'age'" \ --max-load=Threads_connected=150 --critical-load=Threads_connected=200 --chunk-size=1000 \ --initially-drop-ghost-table --initially-drop-old-table --initially-drop-socket-file \ --allow-on-master --ok-to-drop-table --execute --assume-rbr

log: [2022/05/19 19:55:11] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql 172.xx.x.x 30xx dba false false false UTC true 0 0s 0s 0 false} [2022/05/19 19:55:11] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.000036, 6755) [2022/05/19 19:55:11] [info] binlogsyncer.go:203 register slave for master server 172.xx.x.x:30xx [2022/05/19 19:55:11] [info] binlogsyncer.go:723 rotate to (mysql-bin.000036, 6755)

Migrating test.rds_table_01; Ghost table is test._rds_table_01_gho

Migrating xxxxxxxx; inspecting xxxxx:30xx; executing on xxx-transfer-01

Migration started at Thu May 19 19:55:00 +0800 2022

chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: Threads_connected=150; critical-load: Threads_connected=200; nice-ratio: 0.000000

throttle-additional-flag-file: /tmp/gh-ost.throttle

Serving on unix socket: /tmp/gh-ost.test.rds_table_01.sock

Copy: 0/1 0.0%; Applied: 0; Backlog: 0/1000; Time: 11s(total), 0s(copy); streamer: mysql-bin.000036:9315; Lag: 0.03s, State: migrating; ETA: N/A Copy: 0/1 0.0%; Applied: 0; Backlog: 0/1000; Time: 12s(total), 1s(copy); streamer: mysql-bin.000036:13777; Lag: 0.03s, State: migrating; ETA: N/A Copy: 1/1 100.0%; Applied: 0; Backlog: 0/1000; Time: 12s(total), 1s(copy); streamer: mysql-bin.000036:14564; Lag: 0.03s, State: migrating; ETA: due Copy: 1/1 100.0%; Applied: 0; Backlog: 1/1000; Time: 13s(total), 1s(copy); streamer: mysql-bin.000036:20066; Lag: 0.03s, State: migrating; ETA: due

Migrating test.rds_table_01; Ghost table is test._rds_table_01_gho

Migrating ; inspecting xxx:xxx; executing on tv2-db-transfer-01

Migration started at Thu May 19 19:55:00 +0800 2022

chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: Threads_connected=150; critical-load: Threads_connected=200; nice-ratio: 0.000000

throttle-additional-flag-file: /tmp/gh-ost.throttle

Serving on unix socket: /tmp/gh-ost.test.rds_table_01.sock

Copy: 1/1 100.0%; Applied: 0; Backlog: 0/1000; Time: 13s(total), 1s(copy); streamer: mysql-bin.000036:20538; Lag: 0.03s, State: migrating; ETA: due Copy: 1/1 100.0%; Applied: 0; Backlog: 0/1000; Time: 14s(total), 1s(copy); streamer: mysql-bin.000036:25202; Lag: 0.03s, State: migrating; ETA: due [2022/05/19 19:55:14] [info] binlogsyncer.go:164 syncer is closing... [2022/05/19 19:55:14] [error] binlogstreamer.go:77 close sync with err: sync is been closing... [2022/05/19 19:55:14] [info] binlogsyncer.go:179 syncer is closed

Done

table : MySQL [test]> desc rds_table_01; +--------------+---------------+------+-----+----------------------+----------------+ | Field | Type | Null | Key | Default | Extra | +--------------+---------------+------+-----+----------------------+----------------+ | id | bigint(20) | NO | PRI | NULL | auto_increment | | name | varchar(200) | NO | MUL | | | | created_time | datetime(3) | YES | | CURRENT_TIMESTAMP(3) | | | address1 | varchar(100) | YES | | | | | a10 | decimal(16,4) | NO | | 1000.0100 | | | age | int(11) | NO | | 18 | | +--------------+---------------+------+-----+----------------------+----------------+ 6 rows in set (0.00 sec)

the table rds_table_01 succeed to add column, but An error was reported in the gh-osc log。