[MDEV-24185] Mariabackup is getting stuck when event_scheduler is running and acquired lock on mysql.event - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Duplicate
Affects Version/s: 10.5.7
Fix Version/s: 10.5.9
Component/s: mariabackup
Labels:
None

Description

Hi Team,

With MariaDB 10.5.7, when event_scheduler is ON and events are running on server, it will acquiring lock MDL_SHARED_WRITE on mysql.event table and due to that when we run mariabackup on that server, it's getting stuck after below line.

[00] 2020-11-10 10:34:46 Acquiring BACKUP LOCKS...

How to reproduce:

Step:1 Enable event_scheduler

MariaDB [test]> SET GLOBAL event_scheduler=ON;

Query OK, 0 rows affected (0.000 sec)

Step:2 create event

MariaDB [test]> CREATE EVENT test_event

    ->   ON SCHEDULE EVERY 1 MINUTE DO show databases;

Query OK, 0 rows affected (0.003 sec)

Step:3 After 2 minutes, run backup

[root@localhost backup]# mariabackup --user=root --backup --target-dir=/root/backup/

[00] 2020-11-10 10:33:31 Connecting to MySQL server host: localhost, user: root, password: not set, port: not set, socket: not set

[00] 2020-11-10 10:33:31 Using server version 10.5.7-MariaDB

mariabackup based on MariaDB server 10.5.7-MariaDB Linux (x86_64)

[00] 2020-11-10 10:33:31 uses posix_fadvise().

[00] 2020-11-10 10:33:31 cd to /var/lib/mysql/

[00] 2020-11-10 10:33:31 open files limit requested 0, set to 1024

[00] 2020-11-10 10:33:31 mariabackup: using the following InnoDB configuration:

[00] 2020-11-10 10:33:31 innodb_data_home_dir =

[00] 2020-11-10 10:33:31 innodb_data_file_path = ibdata1:12M:autoextend

[00] 2020-11-10 10:33:31 innodb_log_group_home_dir = ./

[00] 2020-11-10 10:33:31 InnoDB: Using Linux native AIO

2020-11-10 10:33:31 0 [Note] InnoDB: Number of pools: 1

[00] 2020-11-10 10:33:31 mariabackup: Generating a list of tablespaces

[00] 2020-11-10 10:33:31 >> log scanned up to (45142)

[01] 2020-11-10 10:33:31 Copying ibdata1 to /root/backup/ibdata1

[01] 2020-11-10 10:33:31         ...done

[01] 2020-11-10 10:33:31 Copying ./mysql/innodb_table_stats.ibd to /root/backup/mysql/innodb_table_stats.ibd

[01] 2020-11-10 10:33:31         ...done

[01] 2020-11-10 10:33:31 Copying ./mysql/innodb_index_stats.ibd to /root/backup/mysql/innodb_index_stats.ibd

[01] 2020-11-10 10:33:31         ...done

[01] 2020-11-10 10:33:31 Copying ./mysql/transaction_registry.ibd to /root/backup/mysql/transaction_registry.ibd

[01] 2020-11-10 10:33:31         ...done

[01] 2020-11-10 10:33:31 Copying ./mysql/gtid_slave_pos.ibd to /root/backup/mysql/gtid_slave_pos.ibd

[01] 2020-11-10 10:33:31         ...done

[00] 2020-11-10 10:33:32 Acquiring BACKUP LOCKS...

[00] 2020-11-10 10:33:32 >> log scanned up to (45142)

[00] 2020-11-10 10:33:33 >> log scanned up to (45142)

[00] 2020-11-10 10:33:34 >> log scanned up to (45142)

[00] 2020-11-10 10:33:35 >> log scanned up to (45142)

[00] 2020-11-10 10:33:36 >> log scanned up to (45142)

[00] 2020-11-10 10:33:37 >> log scanned up to (45142)

[00] 2020-11-10 10:33:38 >> log scanned up to (45142)

[00] 2020-11-10 10:33:39 >> log scanned up to (45142)

[00] 2020-11-10 10:33:40 >> log scanned up to (45142)

[00] 2020-11-10 10:33:41 >> log scanned up to (45142)

[00] 2020-11-10 10:33:42 >> log scanned up to (45142)

[00] 2020-11-10 10:33:43 >> log scanned up to (45142)

[00] 2020-11-10 10:33:44 >> log scanned up to (45142)

[00] 2020-11-10 10:33:45 >> log scanned up to (45142)

2020-11-10 10:33:46 0 [Note] InnoDB: Read redo log up to LSN=45568

[00] 2020-11-10 10:33:46 >> log scanned up to (45142)

[00] 2020-11-10 10:33:47 >> log scanned up to (45142)

[00] 2020-11-10 10:33:48 >> log scanned up to (45142)

[00] 2020-11-10 10:33:49 >> log scanned up to (45142)

[00] 2020-11-10 10:33:50 >> log scanned up to (45142)

[00] 2020-11-10 10:33:51 >> log scanned up to (45142)

[00] 2020-11-10 10:33:52 >> log scanned up to (45142)

[00] 2020-11-10 10:33:53 >> log scanned up to (45142)

[00] 2020-11-10 10:33:54 >> log scanned up to (45142)

[00] 2020-11-10 10:33:55 >> log scanned up to (45142)

[00] 2020-11-10 10:33:56 >> log scanned up to (45142)

[00] 2020-11-10 10:33:57 >> log scanned up to (45142)

[00] 2020-11-10 10:33:58 >> log scanned up to (45142)

[00] 2020-11-10 10:33:59 >> log scanned up to (45142)

[00] 2020-11-10 10:34:00 >> log scanned up to (45142)

2020-11-10 10:34:01 0 [Note] InnoDB: Read redo log up to LSN=45568

[00] 2020-11-10 10:34:01 >> log scanned up to (45142)

[00] 2020-11-10 10:34:02 >> log scanned up to (45142)

[00] 2020-11-10 10:34:03 >> log scanned up to (45142)

[00] 2020-11-10 10:34:04 >> log scanned up to (45142)

c[00] 2020-11-10 10:34:05 >> log scanned up to (45142)

[00] 2020-11-10 10:34:06 >> log scanned up to (45142)

[00] 2020-11-10 10:34:07 >> log scanned up to (45142)

^C

[root@localhost backup]#

Step: 4 on another session

MariaDB [(none)]> SELECT * FROM information_schema.metadata_lock_info;

+-----------+---------------------+---------------+---------------------+--------------+------------+

| THREAD_ID | LOCK_MODE           | LOCK_DURATION | LOCK_TYPE           | TABLE_SCHEMA | TABLE_NAME |

+-----------+---------------------+---------------+---------------------+--------------+------------+

|         4 | MDL_BACKUP_SYS_DML  | NULL          | Backup lock         |              |            |

|        16 | MDL_BACKUP_WAIT_DDL | NULL          | Backup lock         |              |            |

|         4 | MDL_SHARED_WRITE    | NULL          | Table metadata lock | mysql        | event      |

+-----------+---------------------+---------------+---------------------+--------------+------------+

3 rows in set (0.000 sec)

MariaDB [(none)]> show processlist;

+----+-----------------+-----------+------+---------+------+-----------------------------+---------------------------+----------+

| Id | User            | Host      | db   | Command | Time | State                       | Info                      | Progress |

+----+-----------------+-----------+------+---------+------+-----------------------------+---------------------------+----------+

|  4 | event_scheduler | localhost | NULL | Daemon  | 1295 | Waiting for next activation | NULL                      |    0.000 |

| 14 | root            | localhost | NULL | Query   |    0 | starting                    | show processlist          |    0.000 |

| 28 | root            | localhost | NULL | Query   |    2 | Waiting for backup lock     | BACKUP STAGE BLOCK_COMMIT |    0.000 |

+----+-----------------+-----------+------+---------+------+-----------------------------+---------------------------+----------+

3 rows in set (0.000 sec)

MariaDB [(none)]> SELECT

    -> CONCAT('Thread ',P.ID,' executing "',P.INFO,'" IS LOCKED BY Thread ',

    -> M.THREAD_ID) WhoLocksWho

    -> FROM INFORMATION_SCHEMA.PROCESSLIST P,

    -> INFORMATION_SCHEMA.METADATA_LOCK_INFO M

    -> WHERE LOCATE(lcase(LOCK_TYPE), lcase(STATE))>0;

+------------------------------------------------------------------------+

| WhoLocksWho                                                            |

+------------------------------------------------------------------------+

| Thread 28 executing "BACKUP STAGE BLOCK_COMMIT" IS LOCKED BY Thread 4  |

| Thread 28 executing "BACKUP STAGE BLOCK_COMMIT" IS LOCKED BY Thread 28 |

+------------------------------------------------------------------------+

2 rows in set (0.001 sec)

Attachments

Issue Links

duplicates

MDEV-24452 ALTER TABLE event take infinite time which for example breaks mysql_upgrade

Closed

Mariabackup is getting stuck when event_scheduler is running and acquired lock on mysql.event

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration