MySQL에서 Lock wait timeout exceededed를 디버깅하는 방법

MySQL에서 Lock wait timeout exceededed를 디버깅하는 방법

실가동 에러 로그에 다음과 같이 표시되는 일이 있습니다.

SQLSTATE[HY000]: 일반 오류: 1205 잠금 대기 시간 초과. 트랜잭션 재시작을 시도하십시오.

어떤 쿼리가 그 시점에 데이터베이스에 접속하려고 하는지 알고 있습니다만, 어떤 쿼리가 그 시점에 잠겼는지 알 수 있는 방법이 있습니까?

이것을 드러내는 것은 단어 거래이다.쿼리가 하나 이상의 InnoDB 테이블에서 적어도1개의 행을 변경하려고 시도하고 있는 것을 알 수 있습니다.

쿼리를 알고 있기 때문에 액세스하는 모든 테이블이 범인으로 간주됩니다.

「」를 실행할 수 됩니다.SHOW ENGINE INNODB STATUS\G

해당 테이블을 볼 수 있어야 합니다.

모든 종류의 추가 잠금 및 뮤텍스 정보를 얻을 수 있습니다.

다음은 제 고객 중 한 명으로부터 받은 샘플입니다.

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
110514 19:44:14 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 9014315, signal count 7805377
Mutex spin waits 0, rounds 11487096053, OS waits 7756855
RW-shared spins 722142, OS waits 211221; RW-excl spins 787046, OS waits 39353
------------------------
LATEST FOREIGN KEY ERROR
------------------------
110507 21:41:35 Transaction:
TRANSACTION 0 606162814, ACTIVE 0 sec, process no 29956, OS thread id 1223895360 updating or deleting, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
14 lock struct(s), heap size 3024, 8 row lock(s), undo log entries 1
MySQL thread id 3686635, query id 124164167 10.64.89.145 viget updating
DELETE FROM file WHERE file_id in ('6dbafa39-7f00-0001-51f2-412a450be5cc' )
Foreign key constraint fails for table `backoffice`.`attachment`:
,
  CONSTRAINT `attachment_ibfk_2` FOREIGN KEY (`file_id`) REFERENCES `file` (`file_id`)
Trying to delete or update in parent table, in index `PRIMARY` tuple:
DATA TUPLE: 17 fields;
 0: len 36; hex 36646261666133392d376630302d303030312d353166322d343132613435306265356363; asc 6dbafa39-7f00-0001-51f2-412a450be5cc;; 1: len 6; hex 000024214f7e; asc   $!O~;; 2: len 7; hex 000000400217bc; asc    @   ;; 3: len 2; hex 03e9; asc   ;; 4: len 2; hex 03e8; asc   ;; 5: len 36; hex 65666635323863622d376630302d303030312d336632662d353239626433653361333032; asc eff528cb-7f00-0001-3f2f-529bd3e3a302;; 6: len 40; hex 36646234376337652d376630302d303030312d353166322d3431326132346664656366352e6d7033; asc 6db47c7e-7f00-0001-51f2-412a24fdecf5.mp3;; 7: len 21; hex 416e67656c73204e6f7720436f6e666572656e6365; asc Angels Now Conference;; 8: len 34; hex 416e67656c73204e6f7720436f6e666572656e6365204a756c7920392c2032303131; asc Angels Now Conference July 9, 2011;; 9: len 1; hex 80; asc  ;; 10: len 8; hex 8000124a5262bdf4; asc    JRb  ;; 11: len 8; hex 8000124a57669dc3; asc    JWf  ;; 12: SQL NULL; 13: len 5; hex 8000012200; asc    " ;; 14: len 1; hex 80; asc  ;; 15: len 2; hex 83e8; asc   ;; 16: len 4; hex 8000000a; asc     ;;

But in child table `backoffice`.`attachment`, in index `PRIMARY`, there is a record:
PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 30; hex 36646261666133392d376630302d303030312d353166322d343132613435; asc 6dbafa39-7f00-0001-51f2-412a45;...(truncated); 1: len 30; hex 38666164663561652d376630302d303030312d326436612d636164326361; asc 8fadf5ae-7f00-0001-2d6a-cad2ca;...(truncated); 2: len 6; hex 00002297b3ff; asc   "   ;; 3: len 7; hex 80000040070110; asc    @   ;; 4: len 2; hex 0000; asc   ;; 5: len 30; hex 416e67656c73204e6f7720436f6e666572656e636520446f63756d656e74; asc Angels Now Conference Document;;

------------
TRANSACTIONS
------------
Trx id counter 0 620783814
Purge done for trx's n:o < 0 620783800 undo n:o < 0 0
History list length 35
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1192212800
MySQL thread id 5341758, query id 189708501 127.0.0.1 lwdba
show innodb status
---TRANSACTION 0 620783788, not started, process no 29956, OS thread id 1196472640
MySQL thread id 5341773, query id 189708353 10.64.89.143 viget
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1223895360
MySQL thread id 5341667, query id 189706152 10.64.89.145 viget
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1227888960
MySQL thread id 5341556, query id 189699857 172.16.135.63 lwdba
---TRANSACTION 0 620781112, not started, process no 29956, OS thread id 1222297920
MySQL thread id 5341511, query id 189696265 10.64.89.143 viget
---TRANSACTION 0 620783736, not started, process no 29956, OS thread id 1229752640
MySQL thread id 5339005, query id 189707998 10.64.89.144 viget
---TRANSACTION 0 620783785, not started, process no 29956, OS thread id 1198602560
MySQL thread id 5337583, query id 189708349 10.64.89.145 viget
---TRANSACTION 0 620783469, not started, process no 29956, OS thread id 1224161600
MySQL thread id 5333500, query id 189708478 10.64.89.144 viget
---TRANSACTION 0 620781240, not started, process no 29956, OS thread id 1198336320
MySQL thread id 5324256, query id 189708493 10.64.89.145 viget
---TRANSACTION 0 617458223, not started, process no 29956, OS thread id 1195141440
MySQL thread id 736, query id 175038790 Has read all relay log; waiting for the slave I/O thread to update it
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
519878 OS file reads, 18962880 OS file writes, 13349046 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 6.25 writes/s, 4.50 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 1190, seg size 1192,
174800 inserts, 174800 merged recs, 54439 merges
Hash table size 35401603, node heap has 35160 buffer(s)
0.50 hash searches/s, 11.75 non-hash searches/s
---
LOG
---
Log sequence number 28 1235093534
Log flushed up to   28 1235093534
Last checkpoint at  28 1235091275
0 pending log writes, 0 pending chkp writes
12262564 log i/o's done, 3.25 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 18909316674; in additional pool allocated 1048576
Dictionary memory allocated 2019632
Buffer pool size   1048576
Free buffers       175763
Database pages     837653
Modified db pages  6
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 770138, created 108485, written 7795318
0.00 reads/s, 0.00 creates/s, 4.25 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 29956, id 1185823040, state: sleeping
Number of rows inserted 6453767, updated 4602534, deleted 3638793, read 388349505551
0.25 inserts/s, 1.25 updates/s, 0.00 deletes/s, 2.75 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set, 1 warning (0.00 sec)

innodb_lock_wait_innodb을 설정하여 InnoDB의 잠금 대기 타임아웃 값을 늘리는 것을 고려해야 합니다.기본값은 50초입니다.

mysql> show variables like 'innodb_lock_wait_timeout';
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_lock_wait_timeout | 50    |
+--------------------------+-------+
1 row in set (0.01 sec)

을 더 할 수 있습니다./etc/my.cnf 회선으로

[mysqld]
innodb_lock_wait_timeout=120

mysql을 재시작합니다.지금 mysql을 재시작할 수 없는 경우 다음을 수행합니다.

SET GLOBAL innodb_lock_wait_timeout = 120; 

세션 기간 동안 설정할 수도 있습니다.

SET innodb_lock_wait_timeout = 120; 

그 후 당신의 질문

이 문제에 관한 많은 SO 스레드 중 하나에서 언급한 바와 같이:테이블을 잠근 프로세스가 프로세스 목록에 sleeve로 표시될 수 있습니다.문제의 데이터베이스에 열려 있는 모든 sleep threads를 없앨 때까지 머리를 쥐어뜯고 있었습니다(당시 액티브한 것은 없었습니다).이것으로 마침내 테이블이 잠금 해제되고 업데이트 쿼리가 실행됩니다.

해설자는 "가끔 MySQL 스레드는 테이블을 잠그고 MySQL과 관련이 없는 일이 일어나기를 기다리는 동안 잠을 잔다"고 말했다.

「 」를 한 후show engine innodb status후 되어 있는 알 수 있었습니다. locklog(잠금로 인해 아래에 .

------------------
---TRANSACTION 2744943820, ACTIVE 1154 sec(!!)
2 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 276558, OS thread handle 0x7f93762e7710, query id 59264109 [ip] [database] cleaning up
Trx read view will not see trx with id >= 2744943821, sees < 2744943821

("Trx read view" 메시지가 동결된 잠금과 관련이 있는지 확실하지 않지만 다른 활성 트랜잭션과 달리 이 메시지는 실행된 쿼리와 함께 표시되지 않고 대신 트랜잭션이 "cleaning" 중이지만 여러 행 잠금이 있다고 주장합니다.)

그 이야기의 교훈은 실타래가 잠자고 있어도 거래가 활발할 수 있다는 것이다.

경합이 많을수록 교착 상태가 발생할 가능성이 높아지며, DB 엔진은 교착 상태의 트랜잭션 중 하나를 타임아웃하여 이를 해결합니다.

변경 변경)된.UPDATE ★★★★★★★★★★★★★★★★★」DELETE엔트리가 많으면 다른 트랜잭션과의 경합이 발생할 가능성이 높아집니다.

에서도 InnoDB MVCC를 할 수 .FOR UPDATE절을 클릭합니다. 일반적인 , , "Data" DB(Oracle, MSSQL, Postgre)와는 () MySQL은 SQL, DB2) MySQL을 사용합니다.REPEATABLE_READ이치노

이제 행을 수정하거나 명시적 잠금을 사용하여 획득한 잠금이 현재 실행 중인 트랜잭션 기간 동안 유지됩니다.의 REPEATABLE_READ ★★★★★★★★★★★★★★★★★」READ COMMITTED잠금에 대해서는 이 Percona 기사를 읽어주세요.

반복 가능 읽기에서는 트랜잭션 중에 획득한 모든 잠금이 트랜잭션 기간 동안 유지됩니다.

READ COMMITED에서 스캔과 일치하지 않는 잠금은 문이 완료된 후 해제됩니다.

...

즉, READ COMMITED에서는 UPDATE 스테이트먼트가 완료되면 갱신할 수 없었던 행을 다른 트랜잭션에서 갱신할 수 있습니다(반복 가능 읽기에서는).

: 분리 레벨분리 레벨)이될수록( 「격리모션레벨이 한정됩니다.REPEATABLE_READ,SERIALIZABLE는 교착 상태가 될 가 교착 상태가 될 가능성이 높아집니다.이것은 "그 자체"가 아니라 트레이드오프입니다.

좋은 수 있어요.READ_COMMITTED여러 HTTP 요구에 걸친 논리 트랜잭션을 사용할 경우 응용 프로그램 수준의 업데이트 손실 방지 기능이 필요하기 때문입니다.은 " " " " " 를 할 수 .SERIALIZABLE을 줄일 수 .READ_COMMITTED.

레코드의 경우 잠금 대기 시간 초과 예외는 교착 상태가 있고 MySQL이 이를 감지할 수 없으므로 시간 초과만 발생합니다.다른 이유로는 매우 오랜 시간 실행되는 쿼리를 생각할 수 있습니다.이것은 해결/복구하기 쉬운 것입니다.여기에서는 이 케이스에 대해 설명하지 않습니다.

MySQL은 일반적으로 교착 상태가 두 트랜잭션 내에서 "적절하게" 구성되면 이러한 교착 상태를 처리할 수 있습니다.그런 다음 MySQL은 잠금 수가 적은 트랜잭션 하나를 삭제/롤백하고(줄에 미치는 영향이 적기 때문에 중요도가 낮습니다) 다른 트랜잭션을 완료합니다.

다음으로 A와 B의 2개의 프로세스와 3개의 트랜잭션이 있다고 가정합니다.

Process A Transaction 1: Locks X
Process B Transaction 2: Locks Y
Process A Transaction 3: Needs Y => Waits for Y
Process B Transaction 2: Needs X => Waits for X
Process A Transaction 1: Waits for Transaction 3 to finish

(see the last two paragraph below to specify the terms in more detail)

=> deadlock 

MySQL은 교착 상태(트랜잭션 수 3개 이내)를 인식하지 못하기 때문에 매우 불행한 설정입니다.MySQL의 역할은 다음과 같습니다.아무것도 아니예요!어떻게 해야 할지 모르기 때문에 그냥 기다린다.첫 번째 취득한 잠금이 타임아웃을 초과할 때까지 기다립니다(프로세스 A 트랜잭션 1: 잠금 X). 그러면 잠금 X가 해제되고 트랜잭션 2 등이 잠금 해제됩니다.

이 기술은 첫 번째 잠금(잠금 X)의 원인이 무엇인지를 알아내는 것입니다.볼 수 예요.show engine innodb status트랜잭션 3이 트랜잭션2를 대기하지만 트랜잭션2가 대기하고 있는 트랜잭션(트랜잭션1)은 표시되지 않습니다.MySQL은 트랜잭션 1과 관련된 잠금 또는 쿼리를 인쇄하지 않습니다.는 트랜잭션목록의입니다(「 」 「 」 「 」 「 」 「 」 「 」 「 」 。show engine innodb status출력물)이 표시됩니다(트랜잭션1은 아무것도 하지 않습니다(그러나 실제로는 트랜잭션3이 완료될 때까지 대기하고 있습니다).

여기에서는 대기 중인 특정 트랜잭션에 대해 잠금(Lock X)을 부여하는 SQL 쿼리를 찾는 방법에 대해 설명합니다.

이 예에서 정확히 어떤 프로세스와 트랜잭션이 있는지 궁금할 경우.프로세스는 PHP 프로세스입니다.트랜잭션은 innodb-trx-table로 정의된 트랜잭션입니다.제 경우, 두 개의 PHP 프로세스가 있었고, 각각의 프로세스에서 수동으로 트랜잭션을 시작했습니다.흥미로운 점은 한 프로세스에서 하나의 트랜잭션을 시작했는데도 MySQL은 사실상 두 개의 개별 트랜잭션을 내부적으로 사용했다는 것입니다(왜 그랬는지는 모르겠지만, 일부 MySQL dev는 설명할 수 있을 것입니다).

MySQL은 자체 트랜잭션을 내부적으로 관리하고 있으며 PHP 프로세스(프로세스 A)에서 발생하는 모든 SQL 요청을 처리하기 위해 두 개의 트랜잭션을 사용하기로 결정했습니다.Transaction 1이 Transaction 3이 완료되기를 기다리고 있다는 문장은 내부 MySQL입니다.MySQL "knew" 트랜잭션 1과 트랜잭션 3은 (프로세스 A에서) 하나의 "트랜잭션" 요청의 일부로 실제로 인스턴스화되었습니다.트랜잭션 3(트랜잭션의 하위 부분)이 차단되었기 때문에 전체 "트랜잭션"이 차단되었습니다."트랜잭션"이 트랜잭션 1(트랜잭션의 하위 부분)을 완료할 수 없었기 때문에 "트랜잭션"도 마찬가지입니다.이것이 바로 "트랜잭션 1이 트랜잭션 3이 완료될 때까지 기다립니다"라는 의미입니다.

이 예외의 큰 문제는 보통 테스트 환경에서는 재현할 수 없고 innodb 엔진 상태를 실행할 수 없다는 것입니다.그래서 프로젝트 중 하나에서 이 예외를 위해 아래 코드를 캐치 블록에 넣었습니다.예외 발생 시 엔진 상태를 파악하는 데 도움이 되었습니다.도움이 많이 됐어요.

Statement st = con.createStatement();
ResultSet rs =  st.executeQuery("SHOW ENGINE INNODB STATUS");
while(rs.next()){
    log.info(rs.getString(1));
    log.info(rs.getString(2));
    log.info(rs.getString(3));
}

다음은 잠금 타임아웃 문제의 원인이 되는 "기타 쿼리"를 찾기 위해 최종적으로 수행해야 했던 작업입니다.응용 프로그램코드에서는 이 태스크 전용의 개별 스레드 상의 보류 중인 모든 데이터베이스 콜을 추적합니다.DB 호출이 N초보다 오래 걸리는 경우(당사의 경우 30초) 다음과 같이 기록합니다.

-- Pending InnoDB transactions
SELECT * FROM information_schema.innodb_trx ORDER BY trx_started; 

-- Optionally, log what transaction holds what locks
SELECT * FROM information_schema.innodb_locks;

위에서 교착상태의 원인이 되는 행을 잠그는 동시 쿼리를 특정할 수 있었습니다.'아까', '아까', '아까', '아까', '아까', '아까', '아까', '아까', '아까' 거였어요.INSERT ... SELECT셀렉트하다그런 다음 코드를 재구성하거나 커밋되지 않은 읽기처럼 다른 트랜잭션 격리를 사용할 수 있습니다.

행운을 빕니다.

유틸리티의 man 페이지를 확인합니다.

brew install percona-toolkit
pt-deadlock-logger --ask-pass server_name

명령어는 에서 정보를 합니다.engine innodb status한 바와 같이, 또한 하여 '아주 좋다'를 수 .또한 이 기능을 사용하여daemon30분

위의 Rolando의 답변에서 추정할 수 있는 것은 다음과 같습니다.

---TRANSACTION 0 620783788, not started, process no 29956, OS thread id 1196472640
MySQL thread id 5341773, query id 189708353 10.64.89.143 viget

쿼리를 실행해야 하고 다른 쿼리가 실행될 때까지 기다릴 수 없는 경우 MySQL 스레드 ID를 사용하여 쿼리를 삭제합니다.

kill 5341773 <replace with your thread id>

^{(shell이 아닌 mysql 내에서)}

다음에서 스레드 ID를 찾아야 합니다.

show engine innodb status\G

어떤 명령어가 데이터베이스를 차단하고 있는지 알아냅니다.

다음을 사용할 수 있습니다.

show full processlist

MySQL의 모든 연결과 현재 연결 상태 및 실행 중인 쿼리를 나열합니다. 변종도 show processlist;그러면 잘린 쿼리와 연결 통계 정보가 표시됩니다.

JDBC 를 사용하고 있는 경우는, 다음의 옵션을 사용할 수 있습니다.
= Innodb Status In Deadlock 예외 = true Innodb Status In Deadlock = true

https://dev.mysql.com/doc/connector-j/8.0/en/connector-j-reference-configuration-properties.html

MySQL general.log(디스크 집약)를 활성화하고 mysql_analyse_general_log.pl을 사용하여 장기간 실행 중인 트랜잭션을 추출합니다.예를 들어 다음과 같습니다.

--min-syslog=innodb_lock_wait_syslog 값

그 후 general.log를 비활성화합니다.

언급URL : https://stackoverflow.com/questions/6000336/how-to-debug-lock-wait-timeout-exceeded-on-mysql