MariaDB blocking & locked query 찾는 방법

얼마전 고객에게서 lock 발생했을 때 lock을 유발한 query와 이 query에 의해 block된 query를 어떻게 하는 지 문의가 있었습니다.

예를 들면 아래의 각 세션의 목적과 테이블 생성문은 아래와 같습니다.

SESSION #15 : Monitoring Session
SESSION #16 : Blocking Query
SESSION #17 : Locked Query

t1 테이블 생성문

create table t1 (
c1 int primary key,
c2 varchar(20)
);

세션 #16은 t1 테이블에 INSERT를 수행한 후, (3,'C')인 레코드를 (2,'B')로 UPDATE를 하고 COMMIMT을 하지 않고 대기 하고 있습니다.

세션 #17에서는 t1 테이블에 INSERT를 수행하지만 세션 #16의 UPDATE에 의해 record lock이 발생합니다.

SESSION #16

MariaDB [insertDB]> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
|              16 |
+-----------------+
1 row in set (0.000 sec)
 
MariaDB [insertDB]> truncate table t1;
Query OK, 0 rows affected (0.025 sec)
 
MariaDB [insertDB]> insert into t1 values (1,'A'),(3,'C');
Query OK, 2 rows affected (0.005 sec)
Records: 2  Duplicates: 0  Warnings: 0
 
MariaDB [insertDB]> set autocommit=OFF;
Query OK, 0 rows affected (0.000 sec)
 
MariaDB [insertDB]> update t1 set c1=2,c2='B' where c1=3;
Query OK, 1 row affected (0.001 sec)
Rows matched: 1  Changed: 1  Warnings: 0

SESSION #17

MariaDB [insertDB]> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
|              17 |
+-----------------+
1 row in set (0.000 sec)
 
MariaDB [insertDB]> set autocommit=OFF;
Query OK, 0 rows affected (0.000 sec)
 
MariaDB [insertDB]> insert into t1 values (2,'B');

모니터링 세션 #15에서 Lock 상황을 Monitoring 하면 아래와 같습니다

현재 세션 #16의 trx_id는 4872이고 trx_state는 RUNNING 이며, 세션 #17의 trx_id는 4873이고 trx_state는 LOCK WAIT 입니다

또한 세션 #17의 insert문은 lock wait 상태이므로 trx_query는 세션 #16의 4873 트랜잭션의 쿼리인 "update t1 set c1=2,c2='B' where c1=3" 가 보입니다.

SESSION #15 - INNODB_TRX

MariaDB [insertDB]> MariaDB [information_schema]> select * from INNODB_TRX \G;
*************************** 1. row ***************************
                    trx_id: 4873
                 trx_state: LOCK WAIT
               trx_started: 2021-03-03 02:20:38
     trx_requested_lock_id: 4873:133:3:3
          trx_wait_started: 2021-03-03 02:20:38
                trx_weight: 2
       trx_mysql_thread_id: 17
                 trx_query: update t1 set c1=2,c2='B' where c1=3
       trx_operation_state: starting index read
         trx_tables_in_use: 1
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 1
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
 
 
*************************** 2. row ***************************
                    trx_id: 4872
                 trx_state: RUNNING
               trx_started: 2021-03-03 02:20:30
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 4
       trx_mysql_thread_id: 16
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 1
         trx_rows_modified: 2
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
          trx_is_read_only: 0
trx_autocommit_non_locking: 0

INNODB_LOCK_WAITS 시스템 테이블을 살펴보면 아래와 같이 트랜잭션 별 requesting/blocking ID를 확인할 수 있습니다.
SESSION #15 - INNODB_LOCK_WAITS

MariaDB [information_schema]> select * from INNODB_LOCK_WAITS ;
+-------------------+-------------------+-----------------+------------------+
| requesting_trx_id | requested_lock_id | blocking_trx_id | blocking_lock_id |
+-------------------+-------------------+-----------------+------------------+
| 4873              | 4873:133:3:3      | 4872            | 4872:133:3:3     |
+-------------------+-------------------+-----------------+------------------+
1 row in set (0.000 sec)

INNODB_LOCKS 시스템 테이블을 살펴보면 LOCK에 대한 더 자세한 정보를 볼수 있습니다
SESSION #15 - INNODB_LOCKS

MariaDB [information_schema]> select * from INNODB_LOCKS;
+--------------+-------------+-----------+-----------+-----------------+------------+------------+-----------+----------+-----------+
| lock_id      | lock_trx_id | lock_mode | lock_type | lock_table      | lock_index | lock_space | lock_page | lock_rec | lock_data |
+--------------+-------------+-----------+-----------+-----------------+------------+------------+-----------+----------+-----------+
| 4873:133:3:3 | 4873        | X         | RECORD    | `insertDB`.`t1` | PRIMARY    | 133        | 3         | 3        | 3         |
| 4872:133:3:3 | 4872        | X         | RECORD    | `insertDB`.`t1` | PRIMARY    | 133        | 3         | 3        | 3         |
+--------------+-------------+-----------+-----------+-----------------+------------+------------+-----------+----------+-----------+
2 rows in set (0.001 sec)

SHOW ENGINE INNODB STATUS의 상태를 보면 먼저 수행된 세션 #16의 트랜잭션(trx_id=4872)을 살펴보면 2개의 lock struct(s)를 갖고 있고 2개의 undo log entries, MySQL thread_id(connection_id) 16인 것이 확인됩니다.

하지만 해당 세션(트랜잭션)에서 수행했던 쿼리는 확인되지 않습니다. 오히려 4873 트랜잭션을 살펴보면 현재 blocking 쿼리(update t1 set c1=2,c2='B' where c1=3)를 확인 할 수 있습니다.

하지만 locked 쿼리(insert into t1 values (2,'B');)는 확인되지 않습니다.

SESSION #15 - show engine innodb status

MariaDB [information_schema]> show engine innodb status \G;

............................................ 생략 ............................................
------------
TRANSACTIONS
------------
Trx id counter 4874
Purge done for trx's n:o < 4872 undo n:o < 0 state: running but idle
History list length 99
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 4873, ACTIVE 11 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
MySQL thread id 17, OS thread handle 139731333658368, query id 228 localhost root Updating
update t1 set c1=2,c2='B' where c1=3
------- TRX HAS BEEN WAITING 11 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 133 page no 3 n bits 72 index PRIMARY of table `insertDB`.`t1` trx id 4873 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 80000003; asc     ;;
 1: len 6; hex 000000001308; asc       ;;
 2: len 7; hex 35000001d129a0; asc 5    ) ;;
 3: len 1; hex 43; asc C;;
 
---------------------TRANSACTION 4872, ACTIVE 19 sec
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2
MySQL thread id 16, OS thread handle 139731333965568, query id 226 localhost root
---TRANSACTION 421206311948792, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421206311936144, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
 
............................................ 생략 ............................................

locked 쿼리를 확인하기 위해서는 processlist에서 확인 가능합니다.

locked 쿼리의 trx_id=4873, conneciton_id=17인데 connection_id를 활용하면 아래와 같이 조회 가능합니다.

SESSION #15 - Thread ID 확인

root@localhost:(none) 10:18:37>select id,info from information_schema.processlist where id=17;
+----+-------------------------------+
| id | info                          |
+----+-------------------------------+
| 17 | insert into t1 values (2,'B') |
+----+-------------------------------+
1 row in set (0.00 sec)