[MDEV-24185] Mariabackup is getting stuck when event_scheduler is running and acquired lock on mysql.event Created: 2020-11-10  Updated: 2021-04-19  Resolved: 2021-01-31

Status: Closed
Project: MariaDB Server
Component/s: mariabackup
Affects Version/s: 10.5.7
Fix Version/s: 10.5.9

Type: Bug Priority: Critical
Reporter: Nilnandan Joshi Assignee: Vladislav Lesin
Resolution: Duplicate Votes: 10
Labels: None

Issue Links:
Duplicate
duplicates MDEV-24452 ALTER TABLE event take infinite time ... Closed

 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)
 
 



 Comments   
Comment by Paul Fletcher [ 2020-11-24 ]

I have the same issue with Server version: 10.5.6-4-MariaDB-enterprise-log MariaDB Enterprise Server

If the scheduler is enabled and there are events scheduled, the mariadb-backup will hang on BACKUP STAGE BLOCK_COMMIT and never complete.

set global event_scheduler = OFF;
and the backup runs perfectly

Comment by Anton Petin [ 2021-01-24 ]

same thing when i try to
SET GLOBAL read_only = 1 and the scheduler is ON and active events.

I use MaxScale to change the master and in this situation I had to abandon the use of events for everything to work, which is not very good.

Perhaps this is still some kind of bug.

Since I do not see any connection with the mysql.event lock (the event is executed once an hour) and the server's transfer to read_only = 1

10.5.8-MariaDB

Comment by Elena Stepanova [ 2021-01-25 ]

Could be the same problem as MDEV-24452

Generated at Thu Feb 08 09:28:05 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.