FATAL ERROR Timeout while waiting for events up to lock
- Dominant language
- Go
- Stars
- 13.6k
- Forks
- 1.4k
- Avg merge
- 2h 31m
- Merged PRs (30d)
- 4
Description
Doing migration on gh-ost-1.0.48-1.x86_64 on CentOS Linux release 7.3.1611 (Core) with working against MySQL Server version: 5.7.19-log MySQL Community Server (GPL), after two days of work, with throttling for replication lags, the utility failed in the last switch between the modified table and the active table.
**Questions:**
**1. Is it really a bug ?**
**2. Is there a way to control/avoid this issue with some params tuning ? timeout threshold tuning? retry count number change ?**
**The command executed (machines, db's and table name changed for privacy):**
```
nohup /usr/bin/gh-ost \
--max-load='Threads_running=500' \
--critical-load='Threads_running=1000' \
--initially-drop-ghost-table \
--chunk-size=600 \
--assume-master-host=db-mysql0a.96.prod.net \
--max-lag-millis=6000 \
--user="db_user" --password=XXXXXX \
--throttle-control-replicas="db-mysql0a.42.prod.net" \
--host=db-mysql1b.96.prod.net \
--database="dbx" \
--table="tablex" \
--verbose \
--alter="ADD (col1 VARCHAR(1024), col2 BINARY(32) UNIQUE KEY )" \
--assume-rbr \
--allow-master-master \
--cut-over=default \
--concurrent-rowcount \
--default-retries=120 \
--panic-flag-file=/tmp/ghost.panic.flag \
--postpone-cut-over-flag-file=/tmp/ghost.postpone.flag \
--execute &
```
**The final log lines in the nohup.log file are:**
```
2019-05-29 18:36:15 INFO Locking `dbx`.`tablex`, `dbx`.`_tablex_del`
2019-05-29 18:36:15 INFO Tables locked
2019-05-29 18:36:15 INFO Session locking original & magic tables is 105362438
2019-05-29 18:36:15 INFO Writing changelog state: AllEventsUpToLockProcessed:1559154975732861793
2019-05-29 18:36:15 INFO Waiting for events up to lock
2019-05-29 18:36:18 ERROR Timeout while waiting for events up to lock
2019-05-29 18:36:18 ERROR 2019-05-29 18:36:18 ERROR Timeout while waiting for events up to lock
2019-05-29 18:36:18 INFO Looking for magic cut-over table
2019-05-29 18:36:18 INFO Will now proceed to drop magic table and unlock tables
2019-05-29 18:36:18 INFO Dropping magic cut-over table
2019-05-29 18:36:18 INFO Releasing lock from `dbx`.`tablex`, `dbx`.`_tablex_del`
2019-05-29 18:36:18 INFO Tables unlocked
Copy: 155973962/155973962 100.0%; Applied: 42; Backlog: 0/1000; Time: 35h50m25s(total), 35h42m16s(copy); streamer: mysql-bin.000021:478319749; State: migrating; ETA: due
2019-05-29 18:36:19 INFO Grabbing voluntary lock: gh-ost.105362438.lock
2019-05-29 18:36:19 INFO Setting LOCK timeout as 6 seconds
2019-05-29 18:36:19 INFO Looking for magic cut-over table
2019-05-29 18:36:19 INFO Creating magic cut-over table `dbx`.`_tablex_del`
2019-05-29 18:36:19 INFO Magic cut-over table created
2019-05-29 18:36:19 INFO Locking `dbx`.`tablex`, `dbx`.`_tablex_del`
2019-05-29 18:36:19 INFO Tables locked
2019-05-29 18:36:19 INFO Session locking original & magic tables is 105362438
2019-05-29 18:36:19 INFO Writing changelog state: AllEventsUpToLockProcessed:1559154979789624396
2019-05-29 18:36:19 INFO Waiting for events up to lock
2019-05-29 18:36:22 ERROR Timeout while waiting for events up to lock
2019-05-29 18:36:22 ERROR 2019-05-29 18:36:22 ERROR Timeout while waiting for events up to lock
2019-05-29 18:36:22 INFO Looking for magic cut-over table
2019-05-29 18:36:22 INFO Will now proceed to drop magic table and unlock tables
2019-05-29 18:36:22 INFO Dropping magic cut-over table
2019-05-29 18:36:22 INFO Releasing lock from `dbx`.`tablex`, `dbx`.`_tablex_del`
2019-05-29 18:36:22 INFO Tables unlocked
2019-05-29 18:36:23 INFO Grabbing voluntary lock: gh-ost.105362439.lock
2019-05-29 18:36:23 INFO Setting LOCK timeout as 6 seconds
2019-05-29 18:36:23 INFO Looking for magic cut-over table
2019-05-29 18:36:23 INFO Creating magic cut-over table `dbx`.`_tablex_del`
2019-05-29 18:36:23 INFO Magic cut-over table created
2019-05-29 18:36:23 INFO Locking `dbx`.`tablex`, `dbx`.`_tablex_del`
2019-05-29 18:36:23 INFO Tables locked
2019-05-29 18:36:23 INFO Session locking original & magic tables is 105362439
2019-05-29 18:36:23 INFO Writing changelog state: AllEventsUpToLockProcessed:1559154983853734460
2019-05-29 18:36:23 INFO Waiting for events up to lock
Copy: 155973962/155973962 100.0%; Applied: 42; Backlog: 0/1000; Time: 35h50m30s(total), 35h42m16s(copy); streamer: mysql-bin.000021:478319749; State: migrating; ETA: due
2019-05-29 18:36:26 ERROR Timeout while waiting for events up to lock
2019-05-29 18:36:26 ERROR 2019-05-29 18:36:26 ERROR Timeout while waiting for events up to lock
2019-05-29 18:36:26 INFO Looking for magic cut-over table
2019-05-29 18:36:26 INFO Will now proceed to drop magic table and unlock tables
2019-05-29 18:36:26 INFO Dropping magic cut-over table
2019-05-29 18:36:26 INFO Removing socket file: /tmp/gh-ost.dbx.tablex.sock
**2019-05-29 18:36:26 FATAL 2019-05-29 18:36:26 ERROR Timeout while waiting for events up to lock**
2019-05-29 18:36:26 INFO Tearing down inspector
```
Contributor guide
Assessment
This issue has not been assessed yet.