gh-ost: Hang in `throttled` state

I create MariaDB(version 10.1.28) master-slave instances by Docker container, when I run command

./gh-ost \
--port=33092 \
--user="root" \
--database="ghost" \
--table="test_2" \
--alter="engine=innodb" \
--initially-drop-ghost-table \
--max-load=Threads_running=25 \
--critical-load=Threads_running=1000 \
--debug \
--execute

it seems hang in throttled state

2017-10-23 12:11:07 INFO starting gh-ost 1.0.42
2017-10-23 12:11:07 INFO Migrating `ghost`.`test_2`
2017-10-23 12:11:07 INFO connection validated on 127.0.0.1:33092
2017-10-23 12:11:07 INFO User has ALL privileges
2017-10-23 12:11:07 INFO binary logs validated on 127.0.0.1:33092
2017-10-23 12:11:07 INFO Restarting replication on 127.0.0.1:33092 to make sure binlog settings apply to replication thread
2017-10-23 12:11:07 DEBUG Replication restarted
2017-10-23 12:11:07 INFO Inspector initiated on eb154ec93e94:33092, version 10.1.28-MariaDB
2017-10-23 12:11:07 INFO Table found. Engine=InnoDB
2017-10-23 12:11:07 DEBUG Estimated number of rows via STATUS: 784080
2017-10-23 12:11:07 DEBUG Validated no foreign keys exist on table
2017-10-23 12:11:07 DEBUG Validated no triggers exist on table
2017-10-23 12:11:07 INFO Estimated number of rows via EXPLAIN: 784080
2017-10-23 12:11:07 DEBUG Potential unique keys in test_2: [PRIMARY (auto_increment): [id]; has nullable: false]
2017-10-23 12:11:07 INFO Recursively searching for replication master
2017-10-23 12:11:07 DEBUG Looking for master on 127.0.0.1:33092
2017-10-23 12:11:07 DEBUG Master of 127.0.0.1:33092 is master:33091
2017-10-23 12:11:07 DEBUG Looking for master on master:33091
2017-10-23 12:11:07 INFO Master found to be master:33091
2017-10-23 12:11:07 INFO log_slave_updates validated on 127.0.0.1:33092
2017-10-23 12:11:07 INFO connection validated on 127.0.0.1:33092
2017-10-23 12:11:07 DEBUG Streamer binlog coordinates: mysql-bin.000002:37435135
2017/10/23 12:11:07 binlogsyncer.go:75: [info] create BinlogSyncer with config &{99999 mysql 127.0.0.1 33092 root   false false <nil>}
2017-10-23 12:11:07 INFO Connecting binlog streamer at mysql-bin.000002:37435135
2017/10/23 12:11:07 binlogsyncer.go:241: [info] begin to sync binlog from position (mysql-bin.000002, 37435135)
2017/10/23 12:11:07 binlogsyncer.go:134: [info] register slave for master server 127.0.0.1:33092
2017-10-23 12:11:07 DEBUG Beginning streaming
2017/10/23 12:11:07 binlogsyncer.go:568: [info] rotate to (mysql-bin.000002, 37435135)
2017-10-23 12:11:07 INFO rotate to next log name: mysql-bin.000002
2017-10-23 12:11:07 INFO connection validated on master:33091
2017-10-23 12:11:07 INFO connection validated on master:33091
2017-10-23 12:11:07 INFO will use time_zone='SYSTEM' on applier
2017-10-23 12:11:07 INFO Examining table structure on applier
2017-10-23 12:11:07 INFO Applier initiated on 64716996105b:33091, version 10.1.28-MariaDB
2017-10-23 12:11:07 INFO Droppping table `ghost`.`_test_2_gho`
2017-10-23 12:11:07 INFO Table dropped
2017-10-23 12:11:07 INFO Droppping table `ghost`.`_test_2_ghc`
2017-10-23 12:11:08 INFO Table dropped
2017-10-23 12:11:08 INFO Creating changelog table `ghost`.`_test_2_ghc`
2017-10-23 12:11:08 INFO Changelog table created
2017-10-23 12:11:08 INFO Creating ghost table `ghost`.`_test_2_gho`
2017-10-23 12:11:08 INFO Ghost table created
2017-10-23 12:11:08 INFO Altering ghost table `ghost`.`_test_2_gho`
2017-10-23 12:11:08 DEBUG ALTER statement: alter /* gh-ost */ table `ghost`.`_test_2_gho` engine=innodb
2017-10-23 12:11:09 INFO Ghost table altered
2017-10-23 12:11:09 INFO Waiting for ghost table to be migrated. Current lag is 0s
2017-10-23 12:11:09 INFO Intercepted changelog state GhostTableMigrated
2017-10-23 12:11:09 INFO Handled changelog state GhostTableMigrated
2017-10-23 12:11:09 DEBUG ghost table migrated
2017-10-23 12:11:09 DEBUG Potential unique keys in _test_2_gho: [PRIMARY (auto_increment): [id]; has nullable: false]
2017-10-23 12:11:09 INFO Chosen shared unique key is PRIMARY
2017-10-23 12:11:09 INFO Shared columns are id,key,key1,key2,update_time
2017-10-23 12:11:09 INFO Listening on unix socket file: /tmp/gh-ost.ghost.test_2.sock
2017-10-23 12:11:09 DEBUG Reading migration range according to key: PRIMARY
2017-10-23 12:11:09 INFO Migration min values: [23752]
2017-10-23 12:11:09 DEBUG Reading migration range according to key: PRIMARY
2017-10-23 12:11:09 INFO Migration max values: [6669079]
2017-10-23 12:11:09 INFO Waiting for first throttle metrics to be collected
2017-10-23 12:11:09 ERROR parsing time "" as "2006-01-02T15:04:05.999999999Z07:00": cannot parse "" as "2006"
2017-10-23 12:11:09 INFO First throttle metrics collected
2017-10-23 12:11:09 DEBUG Operating until row copy is complete
2017-10-23 12:11:09 DEBUG Getting nothing in the write queue. Sleeping...
# Migrating `ghost`.`test_2`; Ghost table is `ghost`.`_test_2_gho`
# Migrating 64716996105b:33091; inspecting eb154ec93e94:33092; executing on nears-MacBook-Pro.local
# Migration started at Mon Oct 23 12:11:07 +0800 2017
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: Threads_running=25; critical-load: Threads_running=1000; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# Serving on unix socket: /tmp/gh-ost.ghost.test_2.sock
Copy: 0/784080 0.0%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 0s(copy); streamer: mysql-bin.000002:37436417; State: migrating; ETA: N/A
2017-10-23 12:11:09 ERROR parsing time "" as "2006-01-02T15:04:05.999999999Z07:00": cannot parse "" as "2006"
2017-10-23 12:11:10 DEBUG Issued INSERT on range: [23752]..[24751]; iteration: 0; chunk-size: 1000
Copy: 0/784080 0.0%; Applied: 0; Backlog: 0/1000; Time: 3s(total), 1s(copy); streamer: mysql-bin.000002:37440129; State: migrating; ETA: N/A
2017-10-23 12:11:10 DEBUG Issued INSERT on range: [24751]..[25751]; iteration: 1; chunk-size: 1000
2017-10-23 12:11:11 DEBUG Issued INSERT on range: [25751]..[26751]; iteration: 2; chunk-size: 1000
2017-10-23 12:11:11 DEBUG Issued INSERT on range: [26751]..[27751]; iteration: 3; chunk-size: 1000
2017-10-23 12:11:11 DEBUG Issued INSERT on range: [27751]..[28751]; iteration: 4; chunk-size: 1000
2017-10-23 12:11:11 DEBUG Issued INSERT on range: [28751]..[29751]; iteration: 5; chunk-size: 1000
Copy: 6000/784080 0.8%; Applied: 0; Backlog: 0/1000; Time: 4s(total), 2s(copy); streamer: mysql-bin.000002:37510090; State: migrating; ETA: N/A
2017-10-23 12:11:11 DEBUG Issued INSERT on range: [29751]..[30751]; iteration: 6; chunk-size: 1000
2017-10-23 12:11:11 DEBUG Issued INSERT on range: [30751]..[31751]; iteration: 7; chunk-size: 1000
2017-10-23 12:11:12 DEBUG Issued INSERT on range: [31751]..[32751]; iteration: 8; chunk-size: 1000
2017-10-23 12:11:12 DEBUG Issued INSERT on range: [32751]..[33751]; iteration: 9; chunk-size: 1000
2017-10-23 12:11:12 DEBUG Issued INSERT on range: [33751]..[34751]; iteration: 10; chunk-size: 1000
Copy: 11000/784080 1.4%; Applied: 0; Backlog: 0/1000; Time: 5s(total), 3s(copy); streamer: mysql-bin.000002:37557222; State: migrating; ETA: 3m36s
2017-10-23 12:11:12 DEBUG Issued INSERT on range: [34751]..[35751]; iteration: 11; chunk-size: 1000
2017-10-23 12:11:13 DEBUG Issued INSERT on range: [35751]..[36751]; iteration: 12; chunk-size: 1000
Copy: 13000/784080 1.7%; Applied: 0; Backlog: 0/1000; Time: 6s(total), 4s(copy); streamer: mysql-bin.000002:37603892; State: throttled, lag=1.501912s; ETA: 4m2s
2017-10-23 12:11:13 DEBUG Issued INSERT on range: [36751]..[37751]; iteration: 13; chunk-size: 1000
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 7s(total), 5s(copy); streamer: mysql-bin.000002:37650488; State: throttled, lag=2.203634s; ETA: 4m39s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 8s(total), 6s(copy); streamer: mysql-bin.000002:37720458; State: throttled, lag=2.713891s; ETA: 5m35s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 9s(total), 7s(copy); streamer: mysql-bin.000002:37745013; State: throttled, lag=3.186269s; ETA: 6m29s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 10s(total), 8s(copy); streamer: mysql-bin.000002:37768962; State: throttled, lag=3.643499s; ETA: 7m25s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 11s(total), 9s(copy); streamer: mysql-bin.000002:37771411; State: throttled, lag=4.031085s; ETA: 8m19s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 12s(total), 10s(copy); streamer: mysql-bin.000002:37774203; State: throttled, lag=4.471950s; ETA: 9m14s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 13s(total), 11s(copy); streamer: mysql-bin.000002:37777092; State: throttled, lag=4.898709s; ETA: 10m9s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 14s(total), 12s(copy); streamer: mysql-bin.000002:37780156; State: throttled, lag=5.165900s; ETA: 11m4s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 15s(total), 13s(copy); streamer: mysql-bin.000002:37782203; State: throttled, lag=5.652501s; ETA: 11m59s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 16s(total), 14s(copy); streamer: mysql-bin.000002:37784156; State: throttled, lag=6.267008s; ETA: 12m54s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 17s(total), 15s(copy); streamer: mysql-bin.000002:37787448; State: throttled, lag=6.741759s; ETA: 13m49s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 18s(total), 16s(copy); streamer: mysql-bin.000002:37789839; State: throttled, lag=7.160522s; ETA: 14m44s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 19s(total), 17s(copy); streamer: mysql-bin.000002:37792919; State: throttled, lag=7.602088s; ETA: 15m39s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 20s(total), 18s(copy); streamer: mysql-bin.000002:37795354; State: throttled, lag=7.905196s; ETA: 16m35s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 21s(total), 19s(copy); streamer: mysql-bin.000002:37798435; State: throttled, lag=8.302424s; ETA: 17m30s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 22s(total), 20s(copy); streamer: mysql-bin.000002:37801288; State: throttled, lag=8.801842s; ETA: 18m24s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 23s(total), 21s(copy); streamer: mysql-bin.000002:37803455; State: throttled, lag=9.203401s; ETA: 19m20s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 24s(total), 22s(copy); streamer: mysql-bin.000002:37806038; State: throttled, lag=9.892248s; ETA: 20m15s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 25s(total), 23s(copy); streamer: mysql-bin.000002:37808699; State: throttled, lag=10.064135s; ETA: 21m10s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 26s(total), 24s(copy); streamer: mysql-bin.000002:37811070; State: throttled, lag=10.352151s; ETA: 22m4s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 27s(total), 25s(copy); streamer: mysql-bin.000002:37814306; State: throttled, lag=10.771618s; ETA: 22m59s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 28s(total), 26s(copy); streamer: mysql-bin.000002:37817022; State: throttled, lag=11.173454s; ETA: 23m54s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 29s(total), 27s(copy); streamer: mysql-bin.000002:37818708; State: throttled, lag=11.598983s; ETA: 24m50s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 30s(total), 28s(copy); streamer: mysql-bin.000002:37820047; State: throttled, lag=12.501022s; ETA: 25m44s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 31s(total), 29s(copy); streamer: mysql-bin.000002:37821237; State: throttled, lag=13.142864s; ETA: 26m40s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 32s(total), 30s(copy); streamer: mysql-bin.000002:37822442; State: throttled, lag=13.382003s; ETA: 27m34s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 33s(total), 31s(copy); streamer: mysql-bin.000002:37824264; State: throttled, lag=14.573279s; ETA: 28m30s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 34s(total), 32s(copy); streamer: mysql-bin.000002:37826005; State: throttled, lag=14.999559s; ETA: 29m24s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 35s(total), 33s(copy); streamer: mysql-bin.000002:37827195; State: throttled, lag=15.901134s; ETA: 30m20s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 36s(total), 34s(copy); streamer: mysql-bin.000002:37828400; State: throttled, lag=16.197906s; ETA: 31m15s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 37s(total), 35s(copy); streamer: mysql-bin.000002:37829741; State: throttled, lag=17.443810s; ETA: 32m10s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 38s(total), 36s(copy); streamer: mysql-bin.000002:37830986; State: throttled, lag=17.932967s; ETA: 33m5s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 39s(total), 37s(copy); streamer: mysql-bin.000002:37832176; State: throttled, lag=18.673887s; ETA: 34m0s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 40s(total), 38s(copy); streamer: mysql-bin.000002:37833517; State: throttled, lag=19.799566s; ETA: 34m54s
Copy: 14000/784080 1.8%; Applied: 0; Backlog: 0/1000; Time: 41s(total), 39s(copy); streamer: mysql-bin.000002:37834762; State: throttled, lag=20.298345s; ETA: 35m50s
^C

table schema of test_2

CREATE TABLE `test_2` (
  `id` int(10) NOT NULL AUTO_INCREMENT,
  `key` mediumtext CHARACTER SET ucs2,
  `key1` int(11) NOT NULL,
  `key2` varchar(128) CHARACTER SET ucs2 DEFAULT '0',
  `update_time` timestamp NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=6669080 DEFAULT CHARSET=utf8

I recur this issue both release 1.0.42 and build by myself with go1.8.3 in macOS 10.13.

About this issue

  • Original URL
  • State: closed
  • Created 7 years ago
  • Comments: 28 (14 by maintainers)

Most upvoted comments

It seems a problem with disk I/O performance. The test server is a xen virtual machine with some other vms on the host. So, not sure. I tried another free physical machine and itโ€™s about 39 /s. My macbook with ssd reaches around 180 /s. ๐Ÿ˜†