github / github/gh-ost

cut-over-lock-timeout-seconds not being respected

Open
#952 3 comments 0 reactions 0 assignees View on GitHub
Dominant language
Go
Stars
13.6k
Forks
1.4k
Avg merge
2h 31m
Merged PRs (30d)
4

Description

Ghost version:
```
./gh-ost --version
1.0.49
```
Migration command:

```
/gh-ost --port=6333 --critical-load-hibernate-seconds=360 --max-load=Threads_running=500 --critical-load=Threads_running=1000 --chunk-size=1000 --user="ghost" --password="xxxxxxxxx" --host=10.70.0.18 --database="core_prod_id" --table="orders" --verbose --alter="MODIFY COLUMN latest_inbound_scan_id BIGINT UNSIGNED DEFAULT NULL, MODIFY COLUMN latest_warehouse_sweep_id BIGINT UNSIGNED DEFAULT NULL" --assume-master-host=10.70.0.18:6333 --initially-drop-old-table --initially-drop-ghost-table --cut-over=default --cut-over-lock-timeout-seconds=180 --discard-foreign-keys --default-retries=120 --allow-on-master --exact-rowcount --concurrent-rowcount --ok-to-drop-table --throttle-control-replicas="10.70.255.43:6333" --max-lag-millis=100000 --execute
```

Specified cut over lock timeout as 180 seconds: "--cut-over-lock-timeout-seconds=180"

However when interactive command "unpostpone" is triggered, we still see the lock timeout defaulting to 6 seconds:

```
# Serving on unix socket: /tmp/gh-ost.core_prod_id.orders.sock
Copy: 279926016/279926016 100.0%; Applied: 150009146; Backlog: 11/1000; Time: 295h57m54s(total), 269h48m46s(copy); streamer: mysql-bin.078146:600751760; Lag: 0.00s, State: postponing cut-over; ETA: due
2021-04-04 21:40:23 INFO Grabbing voluntary lock: gh-ost.11906741.lock
2021-04-04 21:40:23 INFO Setting LOCK timeout as 6 seconds
2021-04-04 21:40:23 INFO Looking for magic cut-over table
2021-04-04 21:40:23 INFO Creating magic cut-over table `core_prod_id`.`_orders_del`
2021-04-04 21:40:23 INFO Magic cut-over table created
2021-04-04 21:40:23 INFO Locking `core_prod_id`.`orders`, `core_prod_id`.`_orders_del`
Copy: 279926016/279926016 100.0%; Applied: 150009146; Backlog: 27/1000; Time: 295h57m55s(total), 269h48m46s(copy); streamer: mysql-bin.078146:600961345; Lag: 0.00s, State: migrating; ETA: due
2021-04-04 21:40:23 INFO Magic cut-over table created
```

Mysql version:

`mysql --version
mysql Ver 14.14 Distrib 5.6.43-84.3, for Linux (x86_64) using 6.2`

Mysql release:
`Percona-XtraDB-Cluster-server-56.x86_64 1:5.6.43-28.32.1.el7 @percona-release-x86_64`

The default lock wait timeout is 50 seconds from our server timeout settings:

```
connect_timeout 10
delayed_insert_timeout 300
have_statement_timeout YES
innodb_flush_log_at_timeout 1
innodb_lock_wait_timeout 50
innodb_print_lock_wait_timeout_info OFF
innodb_rollback_on_timeout OFF
interactive_timeout 300
lock_wait_timeout 50
net_read_timeout 30
net_write_timeout 60
rpl_stop_slave_timeout 31536000
slave_net_timeout 3600
thread_pool_idle_timeout 60
wait_timeout 300
wsrep_RSU_commit_timeout 5000
```

Possible related issue?:

https://github.com/github/gh-ost/issues/773

We'll be trying out similar migration by disabling `--exact-rowcount`. We'll keep post our findings on this thread.

From the code it seems to be deriving 2 * CutOverLockTimeoutSeconds and cutOverLockTimeoutSeconds seems to be the correct setting:
```
cutOverLockTimeoutSeconds := flag.Int64("cut-over-lock-timeout-seconds", 3, "Max number of seconds to hold locks on tables while attempting to cut-over (retry attempted when lock exceeds timeout)")

tableLockTimeoutSeconds := this.migrationContext.CutOverLockTimeoutSeconds * 2
--
824 | this.migrationContext.Log.Infof("Setting LOCK timeout as %d seconds", tableLockTimeoutSeconds)
```

Happy to share more settings if needed.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.