공부하다가 오라클의 Trace 의 개념으로 예상되는 부분을 찾았다.
show engine innodb status
-> InnoDB 에 대한 현재 상태를 확인할 수 있는 명령어
- Semaphores
- Transactions
- File I/O
- Insert Buffer and Adaptive Hash Index
- Buffer pool and memory
- Row operations
- Lastest Detected deadlock
- Deadlock 발생 시 해당 항목 확인
- Transaction 정보를 표시
- Waiting for this lock to be Granted (트랜잭션이 실행하기 위해 lock 을 걸어야 하는 데이터에 대한 정보, row에 대한 정보를 표시
- Holds the lock(s) (현재 잡고있는 lock 의 정보)
- Lastest Foreign key error
이론도 중요하지만 당장 테스트 해 보았다.
2개의 Session 에 대해서 lock 을 걸어 보았다.
※ MySQL 5.7 InnoDB on Windows 이며, 전부 Default 로 설정 하였다.
Lock 을 발생하기 위해서는 autocommit 을 반드시 off 인지 확인해 보자
mysql> show variables like '%commit%';
+-----------------------------------------+-------+
| Variable_name | Value |
+-----------------------------------------+-------+
| autocommit | OFF |
| binlog_group_commit_sync_delay | 0 |
| binlog_group_commit_sync_no_delay_count | 0 |
| binlog_order_commits | ON |
| innodb_api_bk_commit_interval | 5 |
| innodb_commit_concurrency | 0 |
| innodb_flush_log_at_trx_commit | 1 |
| slave_preserve_commit_order | OFF |
+-----------------------------------------+-------+
8 rows in set, 1 warning (0.00 sec)
양쪽 session 에서 동일한 데이터에 update 를 하여 Lock 을 발생 후 확인해 보자
1번 session
mysql> update test1 set txt='4' where id =1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
mysql> select * from employees.test1;
+----+-----+
| id | txt |
+----+-----+
| 1 | 4 |
| 2 | 2 |
| 3 | 3 |
| 5 | 5 |
| 6 | 7 |
+----+-----+
5 rows in set (0.00 sec)
2번 session
mysql> select * from test1;
+----+-----+
| id | txt |
+----+-----+
| 1 | 1 |
| 2 | 2 |
| 3 | 3 |
| 5 | 5 |
| 6 | 7 |
+----+-----+
5 rows in set (0.00 sec)
mysql> update test1 set txt='3' where id=1;
mysql> show engine innodb status \G;
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2016-06-02 15:41:56 0x2b84 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 24 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 421 srv_idle
srv_master_thread log flush and writes: 423
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 15
OS WAIT ARRAY INFO: signal count 14
RW-shared spins 0, rounds 54, OS waits 5
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 54.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 17161
Purge done for trx's n:o < 16713 undo n:o < 0 state: running but idle
History list length 60
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 17160, ACTIVE 32 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 2, OS thread handle 11152, query id 23 localhost ::1 root updating
update test1 set txt='3' where id=1
------- TRX HAS BEEN WAITING 32 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 80 page no 3 n bits 72 index PRIMARY of table `employees`.`test1` trx id 17160 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000001; asc ;;
1: len 6; hex 000000004307; asc C ;;
2: len 7; hex 270000022302e9; asc ' # ;;
3: len 1; hex 34; asc 4;;
------------------
---TRANSACTION 17159, ACTIVE 94 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 3, OS thread handle 11140, query id 24 localhost ::1 root starting
show engine innodb status
Trx read view will not see trx with id >= 17159, sees < 17159
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (read thread)
I/O thread 4 state: wait Windows aio (read thread)
I/O thread 5 state: wait Windows aio (read thread)
I/O thread 6 state: wait Windows aio (write thread)
I/O thread 7 state: wait Windows aio (write thread)
I/O thread 8 state: wait Windows aio (write thread)
I/O thread 9 state: wait Windows aio (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
507 OS file reads, 64 OS file writes, 15 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 345901173
Log flushed up to 345901173
Pages flushed up to 345901173
Last checkpoint at 345901164
0 pending log flushes, 0 pending chkp writes
15 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137297920
Dictionary memory allocated 673260
Buffer pool size 8192
Free buffers 7678
Database pages 514
Old database pages 209
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 479, created 35, written 41
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 514, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=4620, Main thread ID=10324, state: sleeping
Number of rows inserted 2, updated 1, deleted 0, read 26
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 row in set (0.00 sec)
ERROR:
No query specified
이렇게 Lock 이 발생한 것을 확인 할 수 있고, 어떤 쿼리가 Lock 이 걸려 있는지 확인이 가능하다.
해당 쿼리에 대한 해석은 제대로 해야 될 듯 싶다.
그러면 튜닝 또는 장애 발생 시 정확한 원일을 알 수 있는 척도가 될 듯 싶다.
mysql> show engine innodb status \G;
[출처] http://dba-jadelee.blogspot.kr/2014/10/mysql-innodb-status-monitoring.html
MySQL INNODB Status Monitoring
InnoDB 메인 백그라운드 스레드의 작업실행 통계 : 각 숫자는 Innodb Engine이 시작된 이후부터의 카운트 값
InnoDB 내부 세마포어(뮤텍스나 리드/라이트 락 세마포어를 기다리는 스레드에 대한 정보)의 통계 : 각 숫자는 Innodb Engine이 시작된 이후부터의 카운트 값이며 각 카운트 값이 갑자기 높은 시간대에 대해서는 DISK I/O 성능 및 InnoDB 엔진경합을 의심
최근 발생한 트랜잭션별 참조키 에러내역 히스토리 : 제약조건에 위배되는 내역에 대한 트랜잭션 및 쿼리 정보 확인
세부 에러 내역은 생략
------------------------------------
최근 발생한 트랜잭션별 데드락내역 히스토리 : 가장 최근 발생한 트랜잭션간 데드락 이슈에 대한 처리내역 확인 (경합된 트랜잭션간의 내역 및 데드락 해결을 위한 트랜잭션 처리내역)
-------------------
현재 트랜잭션별 락모니터링 정보 : 실제 수행되고 있는 트랜잭션별 작업내역에 대한 락 핸들링 정보 및 락 사용 세부쿼리 내역을 확인
----------
다양한 I/O 연산에 대한 Innodb 스레드 실행내역 및 통계 : 내부적인 I/O 스레드의 현재 상태 및 전체 통계값 제공하며 만약 I/O상의 부하나 상태이상이 의심될 때 참조될 수 있음.
인서트 버퍼와 적응형 해시에 대한 정보 : 버퍼와 해시의 효율에 대한 통계정보 확인
Innodb Log 활동에 대한 통계
Innodb 버퍼풀과 메모리 사용량에 대한 통계정보 : Innodb 버퍼에 대한 LRU 관리방법에 의한 할당내역 및 사용내역(byte단위)과 버퍼사용율에 대한 세부통계수치 확인
메인 스레드의 행 연산에 대한 통계 정보
========================================================
[출처] http://intomysql.blogspot.kr/2010/12/innodb-lock.html
- 우선 각 트랜잭션은 “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 정보를 확인할 때에도 이와 같은 방식으로 해석할 수 있다.
- 이 테이블을 생성하면, 매 몇 초 단위로 SHOW ENGINE INNODB STATUS 결과를 MySQL 에러 로그 파일에 기록하므로 모니터링이완료되면 테이블을 삭제 해주는 것이 좋다.
- 위의 테이블을 생성 후, “SHOW ENGINE INNODB STATUS” 명령을 실행하면 아래와 같은 좀 더 상세한 트랜잭션 정보를 확인할 수 있다.
- 어떤 트랜잭션이 다른 트랜잭션의 처리를 Blocking(막고) 하고 있는지를 판단하기 위해서는, 각 트랜잭션에서 가지고 있거나 또는 기다리고 있는 테이블 및 인덱스 그리고 그 인덱스 페이지 번호로 추적해 볼 수 있다. (물론 이 방법도 정확하게 찾을 수 있는 방법은 아니다. 하지만 더 자세히는 지금의 InnoDB 에서는 무리일지도 모른다)
- 아래 빨간색으로 표기된 부분을 비교해 봄으로써 두 개의 트랜잭션이 서로 Racing 상태임을 확인할 수 있다. (동일 테이블의 동일 인덱스에서 같은 인덱스 페이지 번호 4를 참조하고 있음)
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
'MySQL' 카테고리의 다른 글
| [MySQL] Federated Engine (Table) (1) | 2016.06.09 |
|---|---|
| [펌] [MySQL] Oracle의 그룹별 번호 매기기와 같은 기능 구현하기 (0) | 2016.06.07 |
| [펌][Mysql] *MySQL 쓰면서 하지 말아야 할 것 17가지* (0) | 2016.06.02 |
| [펌]MariaDB와 MySQL의 호환성 (0) | 2016.06.02 |
| [MySQL] 버전별 기능(Features) 변경 이력 (0) | 2016.06.01 |