github / github/gh-ost

lock table issue

Open
#443 4 comments 0 reactions 1 assignee Claimed by @shlomi-noach View on GitHub
Dominant language
Go
Stars
13.6k
Forks
1.4k
Avg merge
2h 31m
Merged PRs (30d)
4

Description

In my follow test , I lock the original table firstly and then run the gh-ost command. It shows that could not row-copy BUT print `INFO Row copy complete` . then , Even i release the lock after the `INFO Row copy complete` information ,it still could not row-copy and print `Error 1205: Lock wait timeout exceeded; try restarting transaction` .

step 1:
`begin;
update test1g set addcol=1 where id=1;`

step 2:
`[op1@SVR14883DE630 ~]$ gh-ost --host=10.28.77.43 --database=ghostdb --table=test1g --replica-server-id=7778 --port=55944 --alter="add column addcoltest int default 0" --concurrent-rowcount --conf=/usr/local/gh-ost.cnf --throttle-flag-file="/tmp/gh-ost.ghostdb.test50g.throttle" --postpone-cut-over-flag-file="/tmp/gh-ost.ghostdb.test50g.postpone" --hooks-path="/tmp" --max-load="Threads_connected=5000,Threads_running=5000" --initially-drop-old-table --initially-drop-ghost-table --initially-drop-socket-file --nice-ratio=0.2 --verbose --execute
`
**log**
```
2017-07-10 15:37:51 INFO starting gh-ost 1.0.36
2017-07-10 15:37:51 INFO Migrating `ghostdb`.`test1g`
2017-07-10 15:37:51 INFO executing gh-ost-on-startup hook: /tmp/gh-ost-on-startup.hook

2017-07-10 15:37:51 INFO connection validated on 10.28.77.43:55944
2017-07-10 15:37:51 INFO User has ALL privileges
2017-07-10 15:37:51 INFO binary logs validated on 10.28.77.43:55944
2017-07-10 15:37:51 INFO Restarting replication on 10.28.77.43:55944 to make sure binlog settings apply to replication thread
2017-07-10 15:37:52 INFO Inspector initiated on SVR14883DE630:55944, version 5.7.18-ctrip-log
2017-07-10 15:37:52 INFO Table found. Engine=InnoDB
2017-07-10 15:37:52 INFO Estimated number of rows via EXPLAIN: 4330416
2017-07-10 15:37:52 INFO Recursively searching for replication master
2017-07-10 15:37:52 INFO Master found to be 10.28.77.42:55944
2017-07-10 15:37:52 INFO log_slave_updates validated on 10.28.77.43:55944
2017-07-10 15:37:52 INFO connection validated on 10.28.77.43:55944
2017/07/10 15:37:52 binlogsyncer.go:75: [info] create BinlogSyncer with config [replica-server-id:7778] 10.28.77.43:55944
2017-07-10 15:37:52 INFO Connecting binlog streamer at SVR14883DE630-bin.001682:397064763
2017/07/10 15:37:52 binlogsyncer.go:241: [info] begin to sync binlog from position (SVR14883DE630-bin.001682, 397064763)
2017/07/10 15:37:52 binlogsyncer.go:134: [info] register slave for master server 10.28.77.43:55944
2017/07/10 15:37:52 binlogsyncer.go:568: [info] rotate to (SVR14883DE630-bin.001682, 397064763)
2017-07-10 15:37:52 INFO rotate to next log name: SVR14883DE630-bin.001682
2017-07-10 15:37:52 INFO connection validated on 10.28.77.42:55944
2017-07-10 15:37:52 INFO connection validated on 10.28.77.42:55944
2017-07-10 15:37:52 INFO will use time_zone='SYSTEM' on applier
2017-07-10 15:37:52 INFO Examining table structure on applier
2017-07-10 15:37:52 INFO Applier initiated on SVR14306DE630:55944, version 5.7.18-ctrip-log
2017-07-10 15:37:52 INFO Droppping table `ghostdb`.`_test1g_gho`
2017-07-10 15:37:52 INFO Table dropped
2017-07-10 15:37:52 INFO Droppping table `ghostdb`.`_test1g_del`
2017-07-10 15:37:52 INFO Table dropped
2017-07-10 15:37:52 INFO Droppping table `ghostdb`.`_test1g_ghc`
2017-07-10 15:37:52 INFO Table dropped
2017-07-10 15:37:52 INFO Creating changelog table `ghostdb`.`_test1g_ghc`
2017-07-10 15:37:52 INFO Changelog table created
2017-07-10 15:37:52 INFO Creating ghost table `ghostdb`.`_test1g_gho`
2017-07-10 15:37:53 INFO Ghost table created
2017-07-10 15:37:53 INFO Altering ghost table `ghostdb`.`_test1g_gho`
2017-07-10 15:37:53 INFO Ghost table altered
2017-07-10 15:37:53 INFO Waiting for ghost table to be migrated. Current lag is 0s
2017-07-10 15:37:53 INFO Intercepted changelog state GhostTableMigrated
2017-07-10 15:37:53 INFO Handled changelog state GhostTableMigrated
2017-07-10 15:37:53 INFO Chosen shared unique key is PRIMARY
2017-07-10 15:37:53 INFO Shared columns are id,machine_name,host_name,dbname,username,sid,rolename,create_date,addcol,collection_time,insert_timestamp,addcol2,addcol10,addcol11,addcol12,addcol21,addcol20,addcol03,addcol06,addcol08,addcol13,addcoltest1
2017-07-10 15:37:53 INFO Listening on unix socket file: /tmp/gh-ost.ghostdb.test1g.sock
2017-07-10 15:37:53 INFO Migration min values: [1,2017-06-12 18:00:42,a]
2017-07-10 15:37:53 INFO Migration max values: [183758439,2017-05-29 05:20:04,SVR10039DE920]
2017-07-10 15:37:53 INFO Waiting for first throttle metrics to be collected
2017-07-10 15:37:53 INFO First throttle metrics collected
# Migrating `ghostdb`.`test1g`; Ghost table is `ghostdb`.`_test1g_gho`
# Migrating SVR14306DE630:55944; inspecting SVR14883DE630:55944; executing on SVR14883DE630
# Migration started at Mon Jul 10 15:37:51 +0800 2017
# chunk-size: 1000; max-lag-millis: 1500ms; max-load: Threads_connected=5000,Threads_running=5000; critical-load: ; nice-ratio: 0.200000
# throttle-flag-file: /tmp/gh-ost.ghostdb.test50g.throttle
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# postpone-cut-over-flag-file: /tmp/gh-ost.ghostdb.test50g.postpone
# Serving on unix socket: /tmp/gh-ost.ghostdb.test1g.sock
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 1s(total), 0s(copy); streamer: SVR14883DE630-bin.001682:397070473; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 2s(total), 1s(copy); streamer: SVR14883DE630-bin.001682:397077574; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 3s(total), 2s(copy); streamer: SVR14883DE630-bin.001682:397084678; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 4s(total), 3s(copy); streamer: SVR14883DE630-bin.001682:397091785; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 5s(total), 4s(copy); streamer: SVR14883DE630-bin.001682:397098889; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 6s(total), 5s(copy); streamer: SVR14883DE630-bin.001682:397105990; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 7s(total), 6s(copy); streamer: SVR14883DE630-bin.001682:397113094; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 8s(total), 7s(copy); streamer: SVR14883DE630-bin.001682:397120198; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 9s(total), 8s(copy); streamer: SVR14883DE630-bin.001682:397127713; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 10s(total), 9s(copy); streamer: SVR14883DE630-bin.001682:397135191; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 11s(total), 10s(copy); streamer: SVR14883DE630-bin.001682:397142298; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 12s(total), 11s(copy); streamer: SVR14883DE630-bin.001682:397149408; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 13s(total), 12s(copy); streamer: SVR14883DE630-bin.001682:397156516; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 14s(total), 13s(copy); streamer: SVR14883DE630-bin.001682:397163609; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 15s(total), 14s(copy); streamer: SVR14883DE630-bin.001682:397170720; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 16s(total), 15s(copy); streamer: SVR14883DE630-bin.001682:397177828; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 17s(total), 16s(copy); streamer: SVR14883DE630-bin.001682:397184939; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 18s(total), 17s(copy); streamer: SVR14883DE630-bin.001682:397192050; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 19s(total), 18s(copy); streamer: SVR14883DE630-bin.001682:397198529; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 20s(total), 19s(copy); streamer: SVR14883DE630-bin.001682:397206260; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 21s(total), 20s(copy); streamer: SVR14883DE630-bin.001682:397213371; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 22s(total), 21s(copy); streamer: SVR14883DE630-bin.001682:397220479; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 23s(total), 22s(copy); streamer: SVR14883DE630-bin.001682:397227584; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 24s(total), 23s(copy); streamer: SVR14883DE630-bin.001682:397234695; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 25s(total), 24s(copy); streamer: SVR14883DE630-bin.001682:397241803; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 26s(total), 25s(copy); streamer: SVR14883DE630-bin.001682:397248911; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 27s(total), 26s(copy); streamer: SVR14883DE630-bin.001682:397256019; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 28s(total), 27s(copy); streamer: SVR14883DE630-bin.001682:397263127; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 29s(total), 28s(copy); streamer: SVR14883DE630-bin.001682:397270236; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 30s(total), 29s(copy); streamer: SVR14883DE630-bin.001682:397277343; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 31s(total), 30s(copy); streamer: SVR14883DE630-bin.001682:397284451; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 32s(total), 31s(copy); streamer: SVR14883DE630-bin.001682:397291562; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 33s(total), 32s(copy); streamer: SVR14883DE630-bin.001682:397298673; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 34s(total), 33s(copy); streamer: SVR14883DE630-bin.001682:397305781; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 35s(total), 34s(copy); streamer: SVR14883DE630-bin.001682:397312889; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 36s(total), 35s(copy); streamer: SVR14883DE630-bin.001682:397319997; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 37s(total), 36s(copy); streamer: SVR14883DE630-bin.001682:397327102; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 38s(total), 37s(copy); streamer: SVR14883DE630-bin.001682:397334213; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 39s(total), 38s(copy); streamer: SVR14883DE630-bin.001682:397341321; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 40s(total), 39s(copy); streamer: SVR14883DE630-bin.001682:397348432; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 41s(total), 40s(copy); streamer: SVR14883DE630-bin.001682:397355543; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 42s(total), 41s(copy); streamer: SVR14883DE630-bin.001682:397362648; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 43s(total), 42s(copy); streamer: SVR14883DE630-bin.001682:397369756; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 44s(total), 43s(copy); streamer: SVR14883DE630-bin.001682:397376855; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 45s(total), 44s(copy); streamer: SVR14883DE630-bin.001682:397383963; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 46s(total), 45s(copy); streamer: SVR14883DE630-bin.001682:397391065; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 47s(total), 46s(copy); streamer: SVR14883DE630-bin.001682:397398176; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 48s(total), 47s(copy); streamer: SVR14883DE630-bin.001682:397405282; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 49s(total), 48s(copy); streamer: SVR14883DE630-bin.001682:397412387; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 50s(total), 49s(copy); streamer: SVR14883DE630-bin.001682:397419497; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 51s(total), 50s(copy); streamer: SVR14883DE630-bin.001682:397426596; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 52s(total), 51s(copy); streamer: SVR14883DE630-bin.001682:397433707; State: migrating; ETA: N/A
Copy: 0/4330416 0.0%; Applied: 0; Backlog: 0/100; Time: 53s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397440803; State: migrating; ETA: N/A
2017-07-10 15:38:45 ERROR Error 1205: Lock wait timeout exceeded; try restarting transaction
2017-07-10 15:38:45 INFO Row copy complete
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 53s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397441644; State: migrating; ETA: due
2017-07-10 15:38:45 INFO Grabbing voluntary lock: gh-ost.3089140.lock
2017-07-10 15:38:45 INFO Setting LOCK timeout as 6 seconds
2017-07-10 15:38:45 INFO Looking for magic cut-over table
2017-07-10 15:38:45 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-10 15:38:45 INFO Magic cut-over table created
2017-07-10 15:38:45 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 54s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397449224; State: migrating; ETA: due
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 55s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397456318; State: migrating; ETA: due
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 56s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397463421; State: migrating; ETA: due
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 57s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397470524; State: migrating; ETA: due
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 58s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397477624; State: migrating; ETA: due
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 59s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397484724; State: migrating; ETA: due
2017-07-10 15:38:51 ERROR Error 1205: Lock wait timeout exceeded; try restarting transaction
2017-07-10 15:38:51 INFO Looking for magic cut-over table
2017-07-10 15:38:51 ERROR Error 1205: Lock wait timeout exceeded; try restarting transaction
2017-07-10 15:38:51 INFO Dropping magic cut-over table
2017-07-10 15:38:51 INFO Droppping table `ghostdb`.`_test1g_del`
2017-07-10 15:38:51 INFO Table dropped
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 1m0s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397491405; State: migrating; ETA: due
2017-07-10 15:38:52 INFO Grabbing voluntary lock: gh-ost.3089201.lock
2017-07-10 15:38:52 INFO Setting LOCK timeout as 6 seconds
2017-07-10 15:38:52 INFO Looking for magic cut-over table
2017-07-10 15:38:52 INFO Creating magic cut-over table `ghostdb`.`_test1g_del`
2017-07-10 15:38:52 INFO Magic cut-over table created
2017-07-10 15:38:52 INFO Locking `ghostdb`.`test1g`, `ghostdb`.`_test1g_del`
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/100; Time: 1m5s(total), 52s(copy); streamer: SVR14883DE630-bin.001682:397524485; State: migrating; ETA: due
2017-07-10 15:38:58 ERROR Error 1205: Lock wait timeout exceeded; try restarting transaction
2017-07-10 15:38:58 INFO Looking for magic cut-over table
2017-07-10 15:38:58 ERROR Error 1205: Lock wait timeout exceeded; try restarting transaction
2017-07-10 15:38:58 INFO Dropping magic cut-over table
2017-07-10 15:38:58 INFO Droppping table `ghostdb`.`_test1g_del`
2017-07-10 15:38:58 INFO Table dropped
^C
```
Thank you!

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.