Come eseguire il debug Lock timeout di attesa superato su MySQL?

Nei miei log degli errori di produzione occasionalmente vedo:

SQLSTATE [HY000]: errore generale: 1205 Lock timeout di attesa superato; prova a riavviare la transazione

So quale query sta cercando di accedere al database in quel momento, ma c’è un modo per scoprire quale query ha avuto il blocco in quel preciso momento?

Ciò che dà questo è la parola transazione . È evidente dall’affermazione che la query stava tentando di modificare almeno una riga in una o più tabelle InnoDB.

Dal momento che conosci la query, tutte le tabelle a cui si accede sono candidate per essere colpevoli.

Da lì, dovresti essere in grado di eseguire SHOW ENGINE INNODB STATUS\G

Dovresti essere in grado di vedere le tabelle interessate

Ottieni tutti i tipi di informazioni aggiuntive di blocco e mutex.

Ecco un esempio da uno dei miei clienti:

 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) 

Dovresti considerare di aumentare il valore di timeout di attesa del blocco per InnoDB impostando il parametro innodb_lock_wait_timeout , il valore predefinito è 50 secondi

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

Puoi impostarlo su un valore più alto in /etc/my.cnf in /etc/my.cnf permanente con questa linea

 [mysqld] innodb_lock_wait_timeout=120 

e riavvia mysql. Se al momento non è ansible riavviare mysql, eseguire questo:

 SET GLOBAL innodb_lock_wait_timeout = 120; 

Potresti anche impostarlo per la durata della sessione

 SET innodb_lock_wait_timeout = 120; 

seguito dalla tua domanda

Come qualcuno ha menzionato in uno dei tanti thread SO relativi a questo problema: A volte il processo che ha bloccato la tabella viene visualizzato come inattivo nella lista di processi! Mi stavo strappando i capelli finché non ho ucciso tutti i fili del sonno che erano aperti nel database in questione (nessuno era attivo all’epoca). Questo finalmente sbloccò la tabella e permise l’esecuzione della query di aggiornamento.

Il commentatore ha detto qualcosa di simile a “A volte un thread MySQL blocca un tavolo, quindi dorme mentre attende che qualcosa di non correlato a MySQL si verifichi”.

Dopo aver riesaminato il log di show engine innodb status (una volta rintracciato il responsabile del blocco), ho notato che il thread bloccato in questione era elencato nella parte inferiore dell’elenco delle transazioni, al di sotto delle query attive che stavano per errore fuori causa del blocco congelato:

 ------------------ ---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 

(non è sicuro se il messaggio "Visualizzazione lettura Trx" sia correlato al blocco congelato, ma a differenza delle altre transazioni attive, questo non viene visualizzato con la query emessa e invece afferma che la transazione sta "ripulendo", ma ha più serrature a fila)

La morale della storia è che una transazione può essere triggers anche se il thread sta dormendo.

A causa della popolarità di MySQL, non c’è da meravigliarsi che Lock timeout di attesa sia stato superato; provare a riavviare l’ eccezione di transazione riceve così tanta attenzione su SO.

Maggiore è il conflitto, maggiore è la possibilità di deadlock, che un motore DB risolverà scadendo una delle transazioni bloccate. Inoltre, le transazioni di lunga durata che hanno modificato (ad esempio UPDATE o DELETE ) un gran numero di voci (che prendono blocchi per evitare anomalie di scrittura sporca come spiegato nel libro di Persistenza di prestazioni elevate di Java ) hanno maggiori probabilità di generare conflitti con altre transazioni .

Sebbene InnoDB MVCC, è ancora ansible richiedere blocchi espliciti utilizzando la clausola FOR UPDATE . Tuttavia, a differenza di altri DB diffusi (Oracle, MSSQL, PostgreSQL, DB2), MySQL utilizza REPEATABLE_READ come livello di isolamento predefinito .

Ora i blocchi acquisiti (modificando le righe o utilizzando il blocco esplicito) vengono conservati per la durata della transazione attualmente in esecuzione. Se si desidera una buona spiegazione della differenza tra REPEATABLE_READ e READ COMMITTED in merito al blocco, leggere questo articolo di Percona .

In REPEATABLE READ ogni blocco acquisito durante una transazione viene mantenuto per la durata della transazione.

In READ COMMITTED i lock che non corrispondono alla scansione vengono rilasciati dopo il completamento dello STATEMENT.

Ciò significa che in READ COMMITTED altre transazioni sono libere di aggiornare le righe che non sarebbero state in grado di aggiornare (in REPEATABLE READ) una volta completata l’istruzione UPDATE.

Questo più restrittivo livello di isolamento ( REPEATABLE_READ , SERIALIZABLE ) maggiore è la possibilità di deadlock. Questo non è un problema “di per sé”, è un compromesso.

È ansible ottenere risultati READ_COMMITED con READ_COMMITED , poiché è necessaria la prevenzione degli aggiornamenti persi a livello di applicazione quando si utilizzano transazioni logiche che si estendono su più richieste HTTP. L’approccio di blocco ottimistico si rivolge agli aggiornamenti persi che potrebbero verificarsi anche se si utilizza il livello di isolamento SERIALIZABLE riducendo al contempo il conflitto di blocco consentendo l’utilizzo di READ_COMMITED .

Per la cronaca, l’eccezione di timeout di attesa del lock si verifica anche quando c’è un deadlock e MySQL non è in grado di rilevarlo, quindi va in timeout. Un altro motivo potrebbe essere una query estremamente lunga, che è più facile da risolvere / riparare, tuttavia, e non descriverò questo caso qui.

MySQL è solitamente in grado di gestire deadlock se sono costruiti “correttamente” all’interno di due transazioni. MySQL uccide / rollback appena una transazione che possiede meno lock (è meno importante in quanto avrà un impatto su meno righe) e lascia che l’altro finisca.

Ora, supponiamo che ci siano due processi A e B e 3 transazioni:

 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 

Questa è una configurazione molto sfortunata perché MySQL non riesce a vedere che c’è un deadlock (con spanning in 3 transazioni). Quindi ciò che fa MySQL è … niente! Aspetta, dato che non sa cosa fare. Aspetta fino a quando il primo blocco acquisito supera il timeout (Processo A Transazione 1: Blocca X), quindi sbloccherà il Blocco X, che sblocca la Transazione 2, ecc.

L’arte è scoprire cosa (quale query) provoca il primo blocco (Lock X). Sarai in grado di vedere facilmente ( show engine innodb status ) che Transaction 3 attende Transaction 2, ma non vedrai quale transazione Transaction 2 è in attesa (Transaction 1). MySQL non stamperà alcun blocco o query associata alla Transazione 1. L’unico suggerimento sarà che nella parte inferiore dell’elenco delle transazioni (della stampa dello show engine innodb status dello show engine innodb status ), apparirà Transaction 1 che apparentemente non fa nulla (ma in realtà sta aspettando per Transazione 3 alla fine).

La tecnica su come trovare quale query SQL causa il blocco (Lock X) da concedere per una determinata transazione che è in attesa è descritta qui Tracking MySQL query history in long running transactions

Se ti stai chiedendo quale sia il processo e la transazione esattamente nell’esempio. Il processo è un processo PHP. La transazione è una transazione definita da innodb-trx-table . Nel mio caso, ho avuto due processi PHP, in ciascuno ho avviato una transazione manualmente. La parte interessante è che, anche se ho iniziato una transazione in un processo, MySQL utilizzava internamente in realtà due transazioni separate (non ho idea del perchè, forse qualche sviluppatore MySQL può spiegare).

MySQL gestisce le proprie transazioni internamente e decide (nel mio caso) di utilizzare due transazioni per gestire tutte le richieste SQL provenienti dal processo PHP (Processo A). L’affermazione che Transaction 1 è in attesa del completamento di Transaction 3 è una cosa interna a MySQL. MySQL “sapeva” che Transaction 1 e Transaction 3 erano in realtà istanziati come parte di una richiesta di “transazione” (dal Processo A). Ora l’intera “transazione” è stata bloccata perché la Transazione 3 (una sottoparte di “transazione”) è stata bloccata. Poiché “transazione” non è stata in grado di completare la Transazione 1 (anche una sottoparte della “transazione”) è stata contrassegnata come non completata. Questo è ciò che intendevo per “La Transazione 1 attende che la Transazione 3 termini”.

Il grosso problema con questa eccezione è che di solito non è riproducibile in un ambiente di test e non siamo in giro per eseguire lo stato del motore innodb quando succede su prod. Quindi in uno dei progetti ho inserito il codice seguente in un blocco catch per questa eccezione. Questo mi ha aiutato a prendere lo stato del motore quando si è verificata l’eccezione. Questo ha aiutato molto.

 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)); } 

Dai un’occhiata alla pagina man dell’utilità pt-deadlock-logger :

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

Estrae informazioni dallo engine innodb status del engine innodb status menzionato sopra e può anche essere usato per creare un daemon che viene eseguito ogni 30 secondi.

Estrapolando dalla risposta di Rolando sopra, sono questi che stanno bloccando la tua query:

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

Se devi eseguire la tua query e non puoi aspettare che gli altri vengano eseguiti, eliminali usando l’id del thread MySQL:

 kill 5341773 

(da dentro mysql, non dalla shell, ovviamente)

Devi trovare gli ID dei thread da:

 show engine innodb status\G 

comando, e capire quale è quello che sta bloccando il database.

Puoi usare:

 show full processlist 

che elenca tutte le connessioni in MySQL e lo stato corrente della connessione, nonché la query in esecuzione. C’è anche una breve show processlist; varianti di show processlist; che visualizza la query troncata e le statistiche di connessione.

Se stai usando JDBC, allora hai l’opzione
includeInnodbStatusInDeadlockExceptions = true

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

Attiva MySQL general.log (disco intensivo) e usa mysql_analyse_general_log.pl per estrarre transazioni lunghe e lunghe, ad esempio con:

–min-duration = il tuo valore innodb_lock_wait_timeout

Disabilitare general.log dopo.