간단하게 InnoDB가 실행하고 있는 트랜잭션들의 정보들을 이해하는 방법을 살펴보자.
InnoDB Plug-in 버전에서는 트랜잭션에 대한 정보와 Lock 그리고 Lock 대기에 관련된 정보들을 INFORMATION_SCHEMA에 정의된 테이블들(INNODB_TRX, INNODB_LOCKS, INNODB_LOCK_WAITS)을 조회함으로써 쉽게 파악할 수 있다. (이 부분은 InnoDB Plug-in의 엄청난 발전으로 느껴진다)
하지만, Built-in 버전의 InnoDB에서는 이러한 딕셔너리를 제공하지 않는다. 유일한 방법은 “SHOW ENGINE INNODB STATUS” 명령문밖에 해결책이 없다.
간단히 아래와 같은 테이블을 만들고, 두 개의 세션에서 동일 UPDATE 쿼리 문장을 실행한 상태에서 트랜잭션과 Lock의 상태를 SHOW ENGINE INNODB STATUS로 확인해 보도록 하겠다.
-- //-----------------------------------------------------------------------------------------
-- // Table specification
-- //-----------------------------------------------------------------------------------------
CREATE TABLE article (
article_id int(10) unsigned NOT NULL AUTO_INCREMENT,
article_category tinyint(3) unsigned NOT NULL DEFAULT '0',
article_title varchar(200) NOT NULL DEFAULT '',
article_type enum('sticky','general') NOT NULL DEFAULT 'general',
PRIMARY KEY (article_id),
KEY ix_category_type_id_user (article_category,article_type)
) ENGINE=InnoDB;
-- //-----------------------------------------------------------------------------------------
-- // Session1
-- //-----------------------------------------------------------------------------------------
begin;
update article set article_title='xx' where article_category=112 and article_type='general';
-- //-----------------------------------------------------------------------------------------
-- // Session2
-- //-----------------------------------------------------------------------------------------
begin;
update article set article_title='xx' where article_category=112 and article_type='general';
-- //-----------------------------------------------------------------------------------------
-- // SHOW ENGINE INNODB STATUS 명령의 결과
-- //-----------------------------------------------------------------------------------------
mysql> show engine innodb status;
........
........
01 ------------
02 TRANSACTIONS
03 ------------
04 Trx id counter 0 1809461
05 Purge done for trx's n:o < 0 1809457 undo n:o < 0 0
06 History list length 21
07 LIST OF TRANSACTIONS FOR EACH SESSION:
08
09 ---TRANSACTION 0 0, not started, process no 5975, OS thread id 1099274560
10 MySQL thread id 6, query id 309 localhost root
11 show engine innodb status
12
13 ---TRANSACTION 0 1809460, ACTIVE 4 sec, process no 5975, OS thread id 1281038656 starting index read
14 mysql tables in use 1, locked 1
15 LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
16 MySQL thread id 7, query id 308 localhost root Updating
17 update article set article_title='xx' where article_category=112 and article_type='general'
18 ------- TRX HAS BEEN WAITING 4 SEC FOR THIS LOCK TO BE GRANTED:
19 RECORD LOCKS space id 88 page no 4 n bits 88 index ix_category_type_id_user of table test.article trx id 0 1809460 lock_mode X locks rec but not gap waiting
20 Record lock, heap no 10 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
21 0: len 1; hex 70; asc p;; 1: len 1; hex 02; asc ;; 2: len 4; hex 00000009; asc ;; 3: len 4; hex 00000000; asc ;;
22
23 ---TRANSACTION 0 1809458, ACTIVE 17251 sec, process no 5975, OS thread id 1099008320
24 3 lock struct(s), heap size 368, 2 row lock(s), undo log entries 1
25 MySQL thread id 4, query id 301 localhost root
........
........
- 우선 각 트랜잭션은 “TRANSACTION 999999 999999”으로 시작된다. (TRANSACTION ID는 8바이트 숫자 값인데, 이러한 형태의 8바이트 숫자 값은 모두 상위 4바이트와 하위 4바이트 두 영역으로 나뉘어서 출력된다.)
- 그러므로, 여기 예제에서는 현재 3개의 트랜잭션 (09번 라인, 13번 라인, 23번 라인)이 존재한다는 것을 확인할 수 있다.
- 각 TRANSACTION 라인에는 현재 해당 트랜잭션이 어떤 작업을 하고 있는지 어떤 상태인지를 알려 주는 키워드가 표시되며, 해당 트랜잭션이 몇 초 동안 진행 중인지도 보여 준다.- 09번 라인 : not started è 현재 트랜잭션이 진행 중이지 않음을 의미- 13번 라인 : ACTIVE è 현재 트랜잭션이 4초 동안 활성화된 상태임 (경우에 따라 문장 끝에 어떤 작업 중인지를 표시해 줌 : starting index read)- 23번 라인 : ACTIVE è 현재 트랜잭션이 17251초 동안 활성화된 상태임
- 각각의 트랜잭션들은 “MySQL thread id”라는 항목(10, 16, 24번 라인)을 가지는데, 이 thread id값은 MySQL에서 “SHOW PROCESSLIST” 명령의 결과에 보여지는 “id”와 동일한 값을 가지게 된다. 즉, 현재 트랜잭션 목록에서 제일 밑 트랜잭션 (TRANSACTION 0 1809458)을 종료하고자 하면, “kill 4”명령으로 트랜잭션을 종료시킬 수 있다.
- 13번 라인의 트랜잭션은 “TRX HAS BEEN WAITING 4 SEC FOR THIS LOCK TO BE GRANTED:”이라는 항목을 가지고 있는데, 이는 현재 트랜잭션 (TRANSACTION 0 1809460)이 다른 트랜잭션이 이미 점유한 Lock 때문에 Blocking(대기) 상태임을 표시하며, 어떤 Lock을 기다리고 있는지 상세히 보여 준다. 하지만, 안타깝게도 이 결과로는 어떤 트랜잭션이 그 Lock을 가지고 있는지는 알아낼 수 없다. 대략 짐작해 보건데 그 밑에 있는 트랜잭션이 지금 17251초 동안 트랜잭션이 ACTIVE 상태인 것으로 보아서 문제를 유발하고 있을 것이라는 것 정도는 짐작해 볼 수 있게 된다. 조금 더 자세히 확인하기 위해서는 “innodb_lock_monitor” 가 필요한데, 이 내용은 하단의 “InnoDB Lock monitoring” 을 참조 바란다.
- 19번 라인을 보면, 레코드 Lock에 관련된 정보가 나오는데, 이것은 현재 트랜잭션이 대기 중인 레코드(인덱스)를 의미하며, 그 인덱스의 정보를 20, 21번 라인에 걸쳐서 보여 주고 있다. 19번 라인에는 지금 대기하고 있는 Lock이 Shared-lock인지 Exclusive-lock인지를 그리고 Gap까지 잠그고 있는지 아닌지를 보여 준다. 일반적으로 Gap lock이 아니라고 표현되는 경우를 제외하고는 거의 모두 Gap까지 잠그고 있다고 생각하면 될 듯 하다. (Gap을 잠그고 있는지 아닌지 판단하는 또 다른 방법은 “undo entries” 항목의 수가 “row lock(s)”의 수보다 작으면 대부분 Gap lock 으로 판단할 수 있다. 하지만 이 방법도 정확한 것은 아니다. 예를 들어서 한 트랜잭션에서 하나의 레코드만 계속 업데이트하게 되면 undo entries가 row locks보다 커질 수 있기 때문이다.)
- 21번 라인을 보면, 드디어 이해 불가능의 단어들이 출력되는데, 사실 이 부분이 의외로 문제 해결에 도움이 될 수 있다. 우선 이 라인에 표시되는 내용은 인덱스 레코드의 필드 값들을 출력해서 보여 주는데, HEX값과 ASCII값을 동시에 보여 준다. 21번 라인의 내용을 정리해 보면 아래와 같이 잘라서 생각해 볼 수 있다. (구분자는 ;; 임)- 0: len 1; hex 70; asc p;;- 1: len 1; hex 02; asc ;;- 2: len 4; hex 00000009; asc ;;- 3: len 4; hex 00000000; asc ;;각 라인은 [인덱스상에서의 번호 : 필드 길이 : 16진수 필드 값(HEX) : ASCII 필드 값(ASC) ] 포맷으로 구성되어 있다. 그리고 이 필드들의 개수는 20번 라인의 n_fields와 동일한 값을 가지게 된다.이 값들과 19번 라인의 테이블 및 인덱스 명을 이용하면 어느 테이블의 어떤 레코드를 지금 기다리고 있는지를 알아낼 수 있다.
- "SHOW ENGINE INNODB STATUS"의 "DEADLOCK" 섹션에 출력되는 내용도 지금까지의 설명한 내용과 동일한 패턴으로 출력되므로, DEADLOCK 정보를 확인할 때에도 이와 같은 방식으로 해석할 수 있다.
지금까지 간단히 트랜잭션의 내용을 읽는 방법을 확인해 보았다.
InnoDB Lock monitoring
우선 InnoDB의 Lock을 모니터링 하기 위해서는 아래와 같은 테이블을 생성해야 한다.
Create table innodb_lock_monitor (fd1 int) engine=innodb;
- 이 테이블을 생성하면, 매 몇 초 단위로 SHOW ENGINE INNODB STATUS 결과를 MySQL 에러 로그 파일에 기록하므로 모니터링이완료되면 테이블을 삭제 해주는 것이 좋다.
- 위의 테이블을 생성 후, “SHOW ENGINE INNODB STATUS” 명령을 실행하면 아래와 같은 좀 더 상세한 트랜잭션 정보를 확인할 수 있다.
- 어떤 트랜잭션이 다른 트랜잭션의 처리를 Blocking(막고) 하고 있는지를 판단하기 위해서는, 각 트랜잭션에서 가지고 있거나 또는 기다리고 있는 테이블 및 인덱스 그리고 그 인덱스 페이지 번호로 추적해 볼 수 있다. (물론 이 방법도 정확하게 찾을 수 있는 방법은 아니다. 하지만 더 자세히는 지금의 InnoDB 에서는 무리일지도 모른다)
- 아래 빨간색으로 표기된 부분을 비교해 봄으로써 두 개의 트랜잭션이 서로 Racing 상태임을 확인할 수 있다. (동일 테이블의 동일 인덱스에서 같은 인덱스 페이지 번호 4를 참조하고 있음)
------------
TRANSACTIONS
------------
01 Trx id counter 0 1809465
02 Purge done for trx's n:o < 0 1809462 undo n:o < 0 0
03 History list length 22
04 LIST OF TRANSACTIONS FOR EACH SESSION:
05 ---TRANSACTION 0 0, not started, process no 5975, OS thread id 1099274560
06 MySQL thread id 10, query id 442 localhost root
07 show engine innodb status
08
09
10 ---TRANSACTION 0 1809464, ACTIVE 12 sec, process no 5975, OS thread id 1281038656 starting index read
11 mysql tables in use 1, locked 1
12 LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
13 MySQL thread id 9, query id 400 localhost root Updating
14 update article set article_title='xx' where article_category=112 and article_type='general'
15 ------- TRX HAS BEEN WAITING 12 SEC FOR THIS LOCK TO BE GRANTED:
16 RECORD LOCKS space id 88 page no 4 n bits 88 index ix_category_type_id_user of table test.article trx id 0 1809464 lock_mode X locks rec but not gap waiting
17 Record lock, heap no 10 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
18 0: len 1; hex 70; asc p;; 1: len 1; hex 02; asc ;; 2: len 4; hex 00000009; asc ;; 3: len 4; hex 00000000; asc ;;
19
20 TABLE LOCK table test.article trx id 0 1809464 lock mode IX
21 RECORD LOCKS space id 88 page no 4 n bits 88 index ix_category_type_id_user of table test.article trx id 0 1809464 lock_mode X locks rec but not gap waiting
22 Record lock, heap no 10 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
23 0: len 1; hex 70; asc p;; 1: len 1; hex 02; asc ;; 2: len 4; hex 00000009; asc ;; 3: len 4; hex 00000000; asc ;;
24
25
26 ---TRANSACTION 0 1809463, ACTIVE 21 sec, process no 5975, OS thread id 1099008320
27 3 lock struct(s), heap size 368, 2 row lock(s), undo log entries 1
28 MySQL thread id 8, query id 355 localhost root
29 TABLE LOCK table test.article trx id 0 1809463 lock mode IX
20 RECORD LOCKS space id 88 page no 4 n bits 88 index ix_category_type_id_user of table test.article trx id 0 1809463 lock_mode X locks rec but not gap
21 Record lock, heap no 10 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
22 0: len 1; hex 70; asc p;; 1: len 1; hex 02; asc ;; 2: len 4; hex 00000009; asc ;; 3: len 4; hex 00000000; asc ;;
23
24 RECORD LOCKS space id 88 page no 6 n bits 80 index PRIMARY of table test.article trx id 0 1809463 lock_mode X locks rec but not gap
25 Record lock, heap no 11 PHYSICAL RECORD: n_fields 10; compact format; info bits 0
26 0: len 4; hex 00000009; asc ;; 1: len 6; hex 0000001b9c37; asc 7;; 2: len 7; hex 000000002d1f51; asc - Q;; 3: len 1; hex 70; asc p;; 4: len 2; hex 7878; asc xx;; 5: len 30; hex 3c703e3c7370616e207374796c653d22666f6e742d73697a653a20313470; asc
