Overview

최근 xtrabackup을 이용해서 백업을 하는 장비에서 오랜 시간 실행된 쿼리와 xtrabackup의 'flush tables with read lock' 쿼리가 맞물려 해당 장비가 특정 테이블에 대해서 약 1시간 동안 DML 처리를 전혀하지 못했던 상황이 있었습니다.

이러한 상황은 'lock_wait_timeout' 시스템 변수 값과 관련된 것으로 보이며, 일단 문제가 발생한 전반적인 상황과 함께 테스트 했던 내용을 설명하도록 하겠습니다.

Description

xtrabackup은 InnoDB 스토리지 엔진을 사용하는 MySQL을 위한 백업 툴입니다.

xtrabackup에서는 백업이 거의 완료될 시점에 현재 데이터베이스의 스냅샷을 얻고자 'flush tables with read lock'을 실행합니다.

이 때, 만약 'flush tables with read lock' 쿼리가 실행되기 이전에 이미 실행되고 있는 DML문들이 있다면 DML 쿼리들의 처리 대상이 되는 테이블들은 이미 metadata lock이 점유된 상태이기 때문에,

'flush tables with read lock'은 해당 테이블에 대한 쿼리가 끝날 때 까지 기다리게 됩니다. (table을 flush하기 위해 metadata lock을 획득해야 되기 때문)

최근 문제됐던 상황이 바로 이 경우입니다.

A라는 테이블이 있고, 이 A 테이블에 장시간 실행중인 쿼리가 있었습니다. 이 때 xtrabackup에서는 백업이 거의 완료되어 'flush tables with read lock'을 실행하였습니다.

하지만 이미 A 테이블에 대하여 처리중인 쿼리가 있어서 해당 테이블에 대해서 flush table을 하지 못하고 대기하는 상황이 발생했고,

'flush tables with read lock' 쿼리 이후에 들어온 A 테이블 관련 DML 쿼리들도 먼저 대기하고 있는 'flush tables with read lock' 쿼리로 인해 DB에서 전혀 처리되지 못해서 1시간 가량 어플리케이션 서버가 처리결과를 받지 못했었습니다.

위의 내용들을 바탕으로 장시간 실행중인 쿼리가 있는 상태에서 'flush tables with read lock'을 수행했을 때, flush table 단계와 read lock을 거는 단계 이 두 단계에서 전체 테이블들의 대한 DML 쿼리 처리 여부와 이 상황에서 'lock_wait_timeout' 값이 미치는 영향을 테스트해보았습니다.

TEST 1. 아래 그림과 같이 테스트를 진행합니다.

이 테스트에서는 'flush tables with read lock'가 실행되기 전에 오로지 t1 테이블에 대한 쿼리만 수행되고 있도록 하였습니다.

총 테이블은 t1, t2, t3 3개 입니다.

1) t1 테이블에 대한 select쿼리를 실행합니다. 6분동안 실행되도록 sleep을 넣어주었습니다.

root@test001:test 16:05:07>select count(*), sleep(360) from t1;

2) 1번에서 실행한 쿼리가 3분쯤 실행되었을 때, 다른 세션에서 'flush tables with read lock'을 실행합니다.

root@test001:test 16:08:18>flush tables with read lock;

3) 그럼 아래와 같이 'flush tables with read lock'가 table을 flush하기 위해 대기하고 있는 것을 볼 수 있습니다.

root@test001:test 16:08:20>show processlist;

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

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

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

| 50759 | kadba | localhost | test | Query   |   35 | User sleep              | select count(*), sleep(360) from t1 |    0.000 |

| 50760 | kadba | localhost | test | Query   |    3 | Waiting for table flush | flush tables with read lock         |    0.000 | <========

| 50761 | kadba | localhost | test | Query   |    0 | NULL                    | show processlist                    |    0.000 |

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

4) 이 때 또 다른 세션에서 t1,t2,t3 테이블들에 대하여 DML을 수행합니다. 아래는 일부 테이블의 DML에 대한 'show processlist' 결과이며, 전체 테이블에 대한 select/insert/update/delete 처리여부는 표로 정리하였습니다.

root@test001:test 16:08:30>show processlist;

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

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

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

| 50759 | kadba | localhost | test | Query   |   84 | User sleep              | select count(*), sleep(360) from t1 |    0.000 |

| 50760 | kadba | localhost | test | Query   |   52 | Waiting for table flush | flush tables with read lock         |    0.000 |

| 50761 | kadba | localhost | test | Query   |    0 | NULL                    | show processlist                    |    0.000 |

| 50762 | kadba | localhost | test | Query   |    4 | Waiting for table flush | select count(*) from t1             |    0.000 | <========

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

root@test001:test 16:08:33>show processlist;

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

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

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

| 50759 | kadba | localhost | test | Query   |  117 | User sleep                   | select count(*), sleep(360) from t1 |    0.000 |

| 50760 | kadba | localhost | test | Query   |   85 | Waiting for table flush      | flush tables with read lock         |    0.000 |

| 50761 | kadba | localhost | test | Query   |    0 | NULL                         | show processlist                    |    0.000 |

| 50762 | kadba | localhost | test | Query   |    3 | Waiting for global read lock | insert into t1 values (20,20)       |    0.000 | <========

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

root@test001:test 16:08:35>show processlist;

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

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

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

| 50759 | kadba | localhost | test | Query   |  130 | User sleep                   | select count(*), sleep(360) from t1                         |    0.000 |

| 50760 | kadba | localhost | test | Query   |   98 | Waiting for table flush      | flush tables with read lock                                 |    0.000 |

| 50761 | kadba | localhost | test | Query   |    0 | NULL                         | show processlist                                            |    0.000 |

| 50762 | kadba | localhost | test | Query   |    4 | Waiting for global read lock | update t2 set value = 100 where id = 1 values (20,20)       |    0.000 | <========

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

** 테이블 별 select/insert/update/delete 처리 여부

	select	insert	update	delete
t1	X	X	X	X
t2	O	X	X	X
t3	O	X	X	X

이미 쿼리가 실행중인 테이블(t1)은 이미 metadata lock을 점유하고 있는 쿼리로 인해 테이블을 flushing하는 단계에서 대기하게 되어 아예 다른 세션에서 select 조차 되지 않았으며,

쿼리가 없었던 t2,t3 테이블은 'flush tables with read lock'이 수행된 시점에 바로 테이블이 flush되고 read lock까지 걸려있음을 알 수 있습니다.

5) 6분이 지나 1번에서 실행한 쿼리가 끝나고, 'flush tables with read lock' 쿼리가 모든 테이블들을 flush하고 글로벌 리드락을 걸은 상황에서 t1, t2, t3 테이블들에 대하여 DML을 수행해봅니다.

root@test001:test 16:12:26>select count(*) from t1;

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

| count(*) |

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

|       10 |

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

root@test001:test 16:12:46>show processlist;

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

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

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

| 50759 | kadba | localhost | test | Sleep   |  402 |                              | NULL                          |    0.000 |

| 50760 | kadba | localhost | test | Sleep   |  370 |                              | NULL                          |    0.000 |

| 50761 | kadba | localhost | test | Query   |    0 | NULL                         | show processlist              |    0.000 |

| 50762 | kadba | localhost | test | Query   |    4 | Waiting for global read lock | insert into t2 values (20,20) |    0.000 | <========

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

root@test001:test 16:12:50>show processlist;

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

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

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

| 50759 | kadba | localhost | test | Sleep   | 1354 |                              | NULL                                   |    0.000 |

| 50760 | kadba | localhost | test | Sleep   | 1322 |                              | NULL                                   |    0.000 |

| 50761 | kadba | localhost | test | Query   |    0 | NULL                         | show processlist                       |    0.000 |

| 50762 | kadba | localhost | test | Query   |    3 | Waiting for global read lock | update t2 set value = 200 where id = 3 |    0.000 | <========

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

root@test001:test 16:12:53>show processlist;

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

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

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

| 50759 | kadba | localhost | test | Sleep   | 1388 |                              | NULL                         |    0.000 |

| 50760 | kadba | localhost | test | Sleep   | 1356 |                              | NULL                         |    0.000 |

| 50761 | kadba | localhost | test | Query   |    0 | NULL                         | show processlist             |    0.000 |

| 50762 | kadba | localhost | test | Query   |    2 | Waiting for global read lock | delete from t3 where id = 10 |    0.000 | <========

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

** 테이블 별 select/insert/update/delete 처리 여부

	select	insert	update	delete
t1	O	X	X	X
t2	O	X	X	X
t3	O	X	X	X

글로벌 리드락이 걸린 상태이기 때문에 select는 정상적으로 수행되지만, 데이터 변경이 있는 insert/update/delete문은 실행되지 않습니다.

6) 테스트를 종료합니다.

root@test001:test 16:13:20>unlock tables;

위 테스트 결과로 보았을 때,

가장 큰 문제점은 'flush tables with read lock' 이후에 들어온 select 쿼리가 이미 장시간 동안 실행되고 있는 테이블에 대한 쿼리라면, 처리 되지 않고 계속 대기하게 된다는 것입니다.

만약 장시간 실행되는 쿼리가 9시간 동안 실행되었다면 'flush tables with read lock'도 9시간을 대기하였을 것이고, 그렇게 되면 해당 테이블을 9시간 동안 select하지 못하게 되는 것입니다.

이는 단순히 이런 상황을 조심해야될 것이 아니라, 'flush tables with read lock'이 왜 굳이 장시간 실행 중인 쿼리가 끝날 때 까지 대기하고 있어야 되는 지를 먼저 살펴볼 필요가 있습니다.

MySQL 5.5.3 버전부터 도입된 'lock_wait_timeout' 이라는 System variable이 있습니다.

이 변수는 metadata lock을 획득하려고 대기하고 있는 시간에 대한 제한을 나타내며(단위는 seconds) Default 값은 '31536000'초, 즉 1년입니다.

'flush tables with read lock' 케이스 처럼, 어떤 테이블의 metadata lock 획득에 대한 경합이 발생했을 때 이미 점유한 쿼리가 끝나지 않는 이상 계속 기다릴 수 밖에 없는 이유는 바로 metadata lock 타임아웃시간이 무려 '1년'이기 때문입니다.

실제로 이 값을 작게 변경해주었을 때 'flush tables with read lock'이 제대로 타임아웃이 되는지 확인해보았습니다.

TEST 2. lock_wait_timeout 값을 3분으로 변경한 뒤 'flush tables with read lock' 대기 상황 재연

1) lock_wait_timeout의 global값을 3분(180초)으로 변경합니다.

root@test001:(none) 20:35:25>set global variable lock_wait_timeout = 180;

root@test001:(none) 20:35:27>show global variables like 'lock_wait_timeout';

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

| Variable_name     | Value |

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

| lock_wait_timeout | 180   |

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

2) t1 테이블에 대해서 6분 동안 쿼리가 실행되도록 합니다.

root@test001:test 20:38:08>select count(*), sleep(360) from t1;

3) 1분 뒤, 다른 세션에서 'flush tables with read lock'을 실행합니다.

root@test001:test 20:39:09>flush tables with read lock;

root@test001:(none) 20:39:51>show processlist;

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

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

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

| 50776 | kadba | localhost | test | Query   |   12 | Waiting for table flush | flush tables with read lock         |    0.000 |

| 50777 | kadba | localhost | test | Query   |   77 | User sleep              | select count(*), sleep(360) from t1 |    0.000 |

| 50778 | kadba | localhost | NULL | Query   |    0 | NULL                    | show processlist                    |    0.000 |

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

4) 3분 뒤 timeout이 발생한 것을 알 수 있습니다.

root@test001:test 20:39:09>flush tables with read lock;

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

Conclusion

이렇게 metadata lock 획득을 위해 대기하는 경우는 본문에서 테스트했던 xtrabackup 관련 'flush tables with read lock' 케이스 외에도 다양하게, 또 흔히 발생할 수 있다고 생각이 됩니다.

MySQL 5.6 버전에서 Online DDL을 수행할 때에도 metadata lock 획득이 필요하며(자세한 내용은 Real MariaDB 99쪽 참고)

테이블 스키마 변경작업은 마스터 DB에서 실행하게 되므로, 만약 이러한 상황으로 인해 서비스 테이블의 select 쿼리가 오랜시간 처리되지 않는 상태에 놓이게 된다면 이는 당연히 서비스에 큰 악영향을 줄 수 밖에 없습니다.

따라서 'lock_wait_timeout'을 적절한 시간으로 조정하여 일정 시간 이상 대기하지 않도록 해줘야 합니다.

추가로,

Xtrabackup의 경우 버전업이 되면서 기능 추가 및 버그 개선이 이루어지고 있으며, Xtrabackup 2.1.4에서는 'FLUSH TABLE WITH READ LOCK'을 핸들링할 수 있는 옵션( --lock-wait-timeout)이 추가되었습니다.

이에 대해서는 아래 url을 참고해주시기 바랍니다.

(http://www.percona.com/doc/percona-xtrabackup/2.2/innobackupex/improved_ftwrl.html)

또한 pt-online-schema-change tool을 사용하다가도 metadata lock waiting 현상이 발생할 수 있는데, (트리거 생성 및 rename으로 인하여)

pt-online-schema-change tool도 lock_wait_timeout값을 조정할 수 있는 옵션이 있어서 사용자가 툴 실행시에 값을 변경할 수 있습니다.

사용자가 옵션을 주지않더라도 툴 자체에서 실행 시 디폴트 설정값인 60초로 lock_wait_timeout을 설정하여 작업을 진행합니다.

만약 디폴트값을 변경시키려면 사용자는 '--set-vars' 옵션을 사용해서 원하는 값을 넣어줄 수 있습니다.

(참고 : http://www.percona.com/doc/percona-toolkit/2.2/pt-online-schema-change.html)

Kakao DB Team

2015년 1월 9일 금요일

lock_wait_timeout 의 Default 값이 불러일으키는 문제점