Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-24185

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

    XMLWordPrintable

    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

            Activity

              People

              Assignee:
              vlad.lesin Vladislav Lesin
              Reporter:
              niljoshi Nilnandan Joshi
              Votes:
              10 Vote for this issue
              Watchers:
              16 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: