gh-ost suddenly exited while waiting for cut over phase
- Dominant language
- Go
- Stars
- 13.6k
- Forks
- 1.4k
- Avg merge
- 2h 31m
- Merged PRs (30d)
- 4
Description
Hi,
We're trying to create partitions on heavy write server.
On the cut-over phase it kept failing with
```
2017-10-03 09:16:31 ERROR Timeout while waiting for events up to lock
2017-10-03 09:16:31 ERROR 2017-10-03 09:16:31 ERROR Timeout while waiting for events up to lock
```
after more failing attempts gh-ost just exited.
- gh-ost version: 1.0.42
- mysql version: 5.7.13
- using multi thread replication
log before exit
```
2017-10-03 09:16:19 INFO Tables unlocked
Copy: 315590599/315590599 100.0%; Applied: 205488336; Backlog: 1000/1000; Time: 55h33m40s(total), 54h51m39s(copy); streamer: mysqld-bin.013732:19061837; State: migrating; ETA: due
2017-10-03 09:16:20 INFO Grabbing voluntary lock: gh-ost.8863805.lock
2017-10-03 09:16:20 INFO Setting LOCK timeout as 6 seconds
2017-10-03 09:16:20 INFO Looking for magic cut-over table
2017-10-03 09:16:20 INFO Creating magic cut-over table `analytics`.`_daily_referer_page_del`
2017-10-03 09:16:20 INFO Magic cut-over table created
2017-10-03 09:16:20 INFO Locking `analytics`.`daily_referer_page`, `analytics`.`_daily_referer_page_del`
2017-10-03 09:16:20 INFO Tables locked
2017-10-03 09:16:20 INFO Session locking original & magic tables is 8863805
2017-10-03 09:16:20 INFO Writing changelog state: AllEventsUpToLockProcessed:1507036580240316507
2017-10-03 09:16:20 INFO Waiting for events up to lock
2017-10-03 09:16:23 ERROR Timeout while waiting for events up to lock
2017-10-03 09:16:23 ERROR 2017-10-03 09:16:23 ERROR Timeout while waiting for events up to lock
2017-10-03 09:16:23 INFO Looking for magic cut-over table
2017-10-03 09:16:23 INFO Will now proceed to drop magic table and unlock tables
2017-10-03 09:16:23 INFO Dropping magic cut-over table
2017-10-03 09:16:23 INFO Releasing lock from `analytics`.`daily_referer_page`, `analytics`.`_daily_referer_page_del`
2017-10-03 09:16:23 INFO Tables unlocked
2017-10-03 09:16:24 INFO Grabbing voluntary lock: gh-ost.8863808.lock
2017-10-03 09:16:24 INFO Setting LOCK timeout as 6 seconds
2017-10-03 09:16:24 INFO Looking for magic cut-over table
2017-10-03 09:16:24 INFO Creating magic cut-over table `analytics`.`_daily_referer_page_del`
2017-10-03 09:16:24 INFO Magic cut-over table created
2017-10-03 09:16:24 INFO Locking `analytics`.`daily_referer_page`, `analytics`.`_daily_referer_page_del`
2017-10-03 09:16:24 INFO Tables locked
2017-10-03 09:16:24 INFO Session locking original & magic tables is 8863808
2017-10-03 09:16:24 INFO Writing changelog state: AllEventsUpToLockProcessed:1507036584260833740
2017-10-03 09:16:24 INFO Waiting for events up to lock
Copy: 315590599/315590599 100.0%; Applied: 205495206; Backlog: 1000/1000; Time: 55h33m45s(total), 54h51m39s(copy); streamer: mysqld-bin.013732:22516279; State: migrating; ETA: due
2017-10-03 09:16:27 ERROR Timeout while waiting for events up to lock
2017-10-03 09:16:27 ERROR 2017-10-03 09:16:27 ERROR Timeout while waiting for events up to lock
2017-10-03 09:16:27 INFO Looking for magic cut-over table
2017-10-03 09:16:27 INFO Will now proceed to drop magic table and unlock tables
2017-10-03 09:16:27 INFO Dropping magic cut-over table
2017-10-03 09:16:27 INFO Releasing lock from `analytics`.`daily_referer_page`, `analytics`.`_daily_referer_page_del`
2017-10-03 09:16:27 INFO Tables unlocked
2017-10-03 09:16:28 INFO Grabbing voluntary lock: gh-ost.8863808.lock
2017-10-03 09:16:28 INFO Setting LOCK timeout as 6 seconds
2017-10-03 09:16:28 INFO Looking for magic cut-over table
2017-10-03 09:16:28 INFO Creating magic cut-over table `analytics`.`_daily_referer_page_del`
2017-10-03 09:16:28 INFO Magic cut-over table created
2017-10-03 09:16:28 INFO Locking `analytics`.`daily_referer_page`, `analytics`.`_daily_referer_page_del`
2017-10-03 09:16:28 INFO Tables locked
2017-10-03 09:16:28 INFO Session locking original & magic tables is 8863808
2017-10-03 09:16:28 INFO Writing changelog state: AllEventsUpToLockProcessed:1507036588282332194
2017-10-03 09:16:28 INFO Waiting for events up to lock
Copy: 315590599/315590599 100.0%; Applied: 205502276; Backlog: 1000/1000; Time: 55h33m50s(total), 54h51m39s(copy); streamer: mysqld-bin.013732:26317171; State: migrating; ETA: due
2017-10-03 09:16:31 ERROR Timeout while waiting for events up to lock
2017-10-03 09:16:31 ERROR 2017-10-03 09:16:31 ERROR Timeout while waiting for events up to lock
2017-10-03 09:16:31 INFO Looking for magic cut-over table
2017-10-03 09:16:31 INFO Will now proceed to drop magic table and unlock tables
2017-10-03 09:16:31 INFO Dropping magic cut-over table
2017-10-03 09:16:31 INFO Removing socket file: /tmp/gh-ost.analytics.daily_referer_page.sock
2017-10-03 09:16:31 FATAL 2017-10-03 09:16:31 ERROR Timeout while waiting for events up to lock
2017-10-03 09:16:31 INFO Releasing lock from `analytics`.`daily_referer_page`, `analytics`.`_daily_referer_page_del`
You have new mail in /var/mail/root
root@someserver:/opt#
```
Was the cut-phase didn't complete due to the fact it was behind in the binary log?
it was working on mysqld-bin.013732 while the slave binary current log was mysqld-bin.013740
```
Copy: 315590599/315590599 100.0%; Applied: 205502276; Backlog: 1000/1000; Time: 55h33m50s(total), 54h51m39s(copy); streamer: mysqld-bin.013732:26317171; State: migrating; ETA: due
```
was gh-ost panicked due to --default-retries=120 parameter? i'm not sure it reached 120 though.
my command was
```
./gh-ost --max-load=Threads_running=25 \
--critical-load=Threads_running=1000 \
--chunk-size=1000 \
--throttle-control-replicas="somereplica" \
--max-lag-millis=1500 \
--conf=/opt/ghost.cnf \
--host=127.0.0.1 \
--database="analytics" \
--table="daily_referer_page" \
--verbose \
--alter="PARTITION BY RANGE ( to_days(date)) (PARTITION daily_referer_page_2017_09_12 VALUES LESS THAN (736950) ENGINE = InnoDB,
PARTITION daily_referer_page_2017_09_13 VALUES LESS THAN (736951) ENGINE = InnoDB,
....
PARTITION daily_referer_page_2017_12_31 VALUES LESS THAN (737060) ENGINE = InnoDB,
PARTITION daily_referer_page_all VALUES LESS THAN MAXVALUE ENGINE = InnoDB)" \
--switch-to-rbr \
--allow-master-master \
--assume-master-host=somemaster \
--cut-over=default \
--exact-rowcount \
--concurrent-rowcount \
--default-retries=120 \
--panic-flag-file=/tmp/ghost.panic.flag \
--postpone-cut-over-flag-file=/tmp/ghost.postpone.flag \
--execute
```
Thanks for any help on this
Contributor guide
Assessment
This issue has not been assessed yet.