[BUG] issue restoring [...] Deadlock found when trying to get lock; try restarting transaction

[str]

Trying to restorere a dump, I get the following error message:

** (myloader:136776): CRITICAL **: 15:03:22.290: Thread 3 issue restoring [...]-schema.sql: Deadlock found when trying to get lock; try restarting transaction

** (myloader:136776): CRITICAL **: 15:04:05.698: Thread 3 issue restoring [..].00000.sql: 

How can we try to load a dump without any locks?

[stardatasrl]

we've the same problem here:

2021-12-16 16:49:46 [ERROR] - Thread 7 issue restoring export-20211216-060252/mydb.DimEmail-schema.sql.gz: Deadlock found when trying to get lock; try restarting transaction
2021-12-16 16:49:49 [ERROR] - Thread 6 issue restoring export-20211216-060252/mydb.AppointmentType-schema.sql.gz: Deadlock found when trying to get lock; try restarting transaction
2021-12-16 16:50:07 [ERROR] - Thread 4 issue restoring export-20211216-060252/mydb.DimLocation-schema.sql.gz: Deadlock found when trying to get lock; try restarting transaction

there's no other connections except mydumper connections.

if we use just one thread no deadlock found, but in this way is useless.

deadlocks are not shown in innodb status, they're not deadlock.

[davidducos]

Hi @stardatasrl / @str , did you tried with --innodb-optimize-keys ? do you have foreign keys on that tables? what database version? might be related to #469.

[stardatasrl]

hi,

we executed this:

myloader -d export-20211216-060252/ -o -t 8 --innodb-optimize-keys -q 20 -L error.log

package: mydumper-0.11.3-5.x86_64
mysql 8.0.26 on centos 7.

no FK.
no existing tables (we tried both with -o and without it, dropping all the tables, we've the same).

there's some internal locking, because we found a metadata lock on mysql where no other connections were active, and the only myloader one was in metadata lock.

MYSQL 8 test > {H:localhost} [U:root] (DB:(none)) >>> show processlist;
+----+------+-----------+-------------+---------+------+---------------------------------+--------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------+-------------+---------+------+---------------------------------+--------------------------+

| 61 | root | localhost | mydb | Query | 39 | Waiting for table metadata lock | drop table FactContent |
| 62 | root | localhost | NULL | Query | 0 | init | show processlist |
+----+------+-----------+-------------+---------+------+---------------------------------+--------------------------+
`

BR.

[davidducos]

Hi @stardatasrl , that metadata lock looks like a mysql bug. I saw similar issue on mydumper that were already fixed for your version. Can you check bugs on mysql side?

[davidducos]

Ah, btw can you share a test case? We might need it to create a bug on mysql.

[davidducos]

@stardatasrl your drop table statement doesn't look like a statement created by myloader.

[hubiongithub]

Hello
I hit the same problem, for the testcase I used

percona server 8.0.26-16 on Ubuntu 20.04 
myloader 0.11.5, built against MySQL 5.7.33-36 (from mydumper_0.11.5-1.focal_amd64.deb)
database "sakila" https://dev.mysql.com/doc/sakila/en/

mydumper 0.11.5 created the backup with no errors and multiple threads used

2021-12-28 08:55:41 [INFO] - MyDumper backup version: 0.11.5
2021-12-28 08:55:41 [INFO] - Server version reported as: 8.0.26-16
2021-12-28 08:55:41 [INFO] - Connected to a MySQL server
2021-12-28 08:55:41 [INFO] - Disabling Percona Backup Locks for Percona Server 8
2021-12-28 08:55:41 [INFO] - Started dump at: 2021-12-28 08:55:41
2021-12-28 08:55:41 [INFO] - Written master status
2021-12-28 08:55:41 [INFO] - Thread 1 connected using MySQL connection ID 104
2021-12-28 08:55:41 [INFO] - Thread 2 connected using MySQL connection ID 105
2021-12-28 08:55:41 [INFO] - Thread 3 connected using MySQL connection ID 106
2021-12-28 08:55:41 [INFO] - Thread 4 connected using MySQL connection ID 107

myloader -d 2021-12-28_0855/ -s sakila -B sakila3 -o -e -v 3 -L log.txt
shows several like:
2021-12-28 09:12:29 [ERROR] - Thread 1 issue restoring 2021-12-28_0855/sakila.actor-schema.sql.gz: Deadlock found when trying to get lock; try restarting transaction and depending on wether I dropped the database before or not there are other errors (Table does not exist ...).

If I use myloader with -t 1 it does not have errors.

I compiled 0.11.5 myself against the PS8 libs:
myloader 0.11.5, built against MySQL 8.0.26-16
I run
myloader -d 2021-12-28_0939/ -s sakila -B sakila4 -o -e -v 3 -L log.txt
several times and got same errors, (some runs without errors but using -t with different values brought back the errors)
-t 1 shows no errors

[stardatasrl]

@stardatasrl your drop table statement doesn't look like a statement created by myloader.

hi @davidducos ,

maybe it's a mysql bug (i've to test it, but i think you're right), but i cannot upgrade all the mysql i have to dump. i think the easyest way to fix it is to add an option to serialize the drop/create table: I have to use the new mydumper version for the innodb-optimize-keys feature, but if i do this, it does not work because the deadlock errors (and it seems mydumper does not catch the error and retry, just skip the table after the deadlock).

BR

patrizio

[peng19832]

Hello
I hit the same problem.
When I restore data in a new mysql instance, especially when restoring mysql system tables, it will trigger a deadlock.
When the number of -t used is less, the probability of occurrence is less.
mysql version:

2022-01-21 17:15:36 [ERROR] - Thread 1 issue restoring /data/mysqldata/scripts/../mysql80/10.100.10.157_3000/logical/20220120/20220120020002/mysql.columns_priv-schema.sql.gz: Deadlock found when trying to get lock; try restarting transaction 2022-01-21 17:15:36 [ERROR] - Thread 7 issue restoring /data/mysqldata/scripts/../mysql80/10.100.10.157_3000/logical/20220120/20220120020002/mysql.default_roles-schema.sql.gz: Deadlock found when trying to get lock; try restarting transaction 2022-01-21 17:15:36 [ERROR] - Thread 4 issue restoring /data/mysqldata/scripts/../mysql80/10.100.10.157_3000/logical/20220120/20220120020002/mysql.procs_priv-schema.sql.gz: Deadlock found when trying to get lock; try restarting transaction 2022-01-21 17:15:36 [ERROR] - Thread 5 issue restoring /data/mysqldata/scripts/../mysql80/10.100.10.157_3000/logical/20220120/20220120020002/mysql.role_edges-schema.sql.gz: Deadlock found when trying to get lock; try restarting transaction

I use the following parameters：
-o --purge-mode=DROP --disable-redo-log --innodb-optimize-keys -v 3 -t 8 --max-threads-per-table 8 -r 100000

[davidducos]

#469

[davidducos]

@peng19832 , why don't you use --purge-mode=TRUNCATE ?

[peng19832]

@peng19832 , why don't you use --purge-mode=TRUNCATE ?

THANKS
This is a test instance, do some test work