wp_commentmeta seleccionada documentación dicho datos already mysql debugging transactions innodb acid

mysql - seleccionada - #1050 table wp_commentmeta already exists



¿Cómo depurar el tiempo de espera de espera de bloqueo excedido en MySQL? (11)

En mis registros de errores de producción ocasionalmente veo:

SQLSTATE [HY000]: Error general: 1205 Se excedió el tiempo de espera de bloqueo; intente reiniciar la transacción

Sé qué consulta está intentando acceder a la base de datos en ese momento, pero ¿hay alguna forma de averiguar qué consulta tuvo el bloqueo en ese momento preciso?

Active MySQL general.log (uso intensivo del disco) y use mysql_analyse_general_log.pl para extraer transacciones de larga ejecución, por ejemplo con:

--min-duration = su valor innodb_lock_wait_timeout

Desactivar general.log después de eso.

Como mencionó alguien en uno de los muchos subprocesos SO relacionados con este problema: ¡A veces el proceso que ha bloqueado la tabla aparece como inactivo en la lista de procesos! Me estaba arrancando el pelo hasta que maté todos los hilos para dormir que estaban abiertos en la base de datos en cuestión (ninguno estaba activo en ese momento). Eso finalmente desbloqueó la tabla y dejó que se ejecutara la consulta de actualización.

El comentarista dijo algo parecido a "A veces, un hilo de MySQL bloquea una tabla y luego se duerme mientras espera que suceda algo que no esté relacionado con MySQL".

Después de volver a revisar el registro de show engine innodb status del show engine innodb status (una vez que localicé al cliente responsable del bloqueo), noté que el hilo atascado en cuestión estaba en la parte inferior de la lista de transacciones, debajo de las consultas activas que estaban a punto de error debido a la cerradura congelada:

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

(No estoy seguro si el mensaje "Vista de lectura de Trx" está relacionado con el bloqueo congelado, pero a diferencia de las otras transacciones activas, este no aparece con la consulta que se emitió y en su lugar afirma que la transacción está "limpiando", pero tiene varios cerraduras de fila)

La moraleja de la historia es que una transacción puede estar activa aunque el hilo esté inactivo.

Debido a la popularidad de MySQL, no es de extrañar que se haya excedido el tiempo de espera de bloqueo; intente reiniciar la excepción de transacción recibe tanta atención en SO.

Cuanta más contención tenga, mayor será la posibilidad de interbloqueos, que un motor de base de datos resolverá al descartar una de las transacciones bloqueadas. Además, las transacciones de larga duración que han modificado (p. Ej., UPDATE o DELETE ) una gran cantidad de entradas (que toman bloqueos para evitar anomalías de escritura sucia, como se explica en el libro Persistencia de Java de alto rendimiento ) tienen más probabilidades de generar conflictos con otras transacciones .

Aunque InnoDB MVCC, todavía puede solicitar bloqueos explícitos utilizando la cláusula FOR UPDATE . Sin embargo, a diferencia de otros DB populares (Oracle, MSSQL, PostgreSQL, DB2), MySQL usa REPEATABLE_READ como el nivel de aislamiento predeterminado .

Ahora, los bloqueos que adquirió (ya sea modificando filas o utilizando el bloqueo explícito), se mantienen durante la duración de la transacción actualmente en ejecución. Si desea una buena explicación de la diferencia entre REPEATABLE_READ y READ COMMITTED con respecto al bloqueo, lea este artículo de Percona .

En REPEATABLE READ, todos los bloqueos adquiridos durante una transacción se mantienen durante la duración de la transacción.

En LEER COMPROMETIDOS, los bloqueos que no coincidieron con la exploración se liberan una vez finalizada la DECLARACIÓN.

...

Esto significa que en READ COMMITTED, otras transacciones son libres de actualizar filas que no habrían podido actualizar (en REPEATABLE READ) una vez que se complete la instrucción UPDATE.

REPEATABLE_READ más restrictivo sea el nivel de aislamiento ( REPEATABLE_READ , SERIALIZABLE ), mayor será la posibilidad de interbloqueo. Esto no es un problema "per se", es una compensación.

Puede obtener muy buenos resultados con READ_COMMITED , ya que necesita prevención de actualización perdida a nivel de la aplicación cuando utiliza transacciones lógicas que abarcan varias solicitudes HTTP. El enfoque de bloqueo optimista apunta a las actualizaciones perdidas que pueden suceder incluso si usa el nivel de aislamiento SERIALIZABLE tiempo que reduce la contención del bloqueo permitiéndole usar READ_COMMITED .

Eche un vistazo a la página man de la utilidad pt-deadlock-logger :

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

Extrae información del engine innodb status del engine innodb status mencionado anteriormente y también se puede utilizar para crear un daemon que se ejecuta cada 30 segundos.

El gran problema con esta excepción es que, por lo general, no se puede reproducir en un entorno de prueba y no estamos disponibles para ejecutar el estado del motor innodb cuando se produce en el producto. Entonces, en uno de los proyectos, coloco el siguiente código en un bloque catch para esta excepción. Eso me ayudó a captar el estado del motor cuando ocurrió la excepción. Eso ayudó mucho.

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

Esto es lo que finalmente tuve que hacer para averiguar qué "otra consulta" causó el problema del tiempo de espera de bloqueo. En el código de la aplicación, rastreamos todas las llamadas de base de datos pendientes en un subproceso separado dedicado a esta tarea. Si cualquier llamada a la base de datos demora más de N segundos (para nosotros es de 30 segundos) registramos:

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

Con lo anterior, pudimos identificar consultas concurrentes que bloquearon las filas que causaron el interbloqueo. En mi caso, eran declaraciones como INSERT ... SELECT que, a diferencia de los SELECTs sin formato, bloquean las filas subyacentes. Luego, puede reorganizar el código o usar un aislamiento de transacción diferente, como la lectura no confirmada.

¡Buena suerte!

Extrapolando de la respuesta anterior de Rolando, son estos los que están bloqueando su consulta:

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

Si necesita ejecutar su consulta y no puede esperar a que se ejecuten los demás, elimínelos utilizando el ID de hilo de MySQL:

kill 5341773

(desde dentro de mysql, no el shell, obviamente)

Tienes que encontrar los ID de hilo de la:

show engine innodb status/G

comando, y averiguar cuál es el que está bloqueando la base de datos.

Lo que da esto es la palabra transacción . Es evidente por la declaración que la consulta estaba intentando cambiar al menos una fila en una o más tablas InnoDB.

Como ya conoce la consulta, todas las tablas a las que se accede son candidatas para ser el culpable.

Desde allí, debería poder ejecutar SHOW ENGINE INNODB STATUS/G

Debes poder ver la (s) mesa (s) afectada (s)

Usted obtiene todo tipo de información adicional de bloqueo y mutex.

Aquí hay una muestra de uno de mis clientes:

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)

Debería considerar aumentar el valor de tiempo de espera de bloqueo para InnoDB configurando innodb_lock_wait_timeout , el valor predeterminado es 50 segundos

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

Puede establecerlo en un valor más alto en /etc/my.cnf permanente con esta línea

[mysqld] innodb_lock_wait_timeout=120

y reiniciar mysql. Si no puede reiniciar mysql en este momento, ejecute esto:

SET GLOBAL innodb_lock_wait_timeout = 120;

También puedes configurarlo para la duración de tu sesión.

SET innodb_lock_wait_timeout = 120;

seguido de su consulta

Para el registro, la excepción del tiempo de espera de espera de bloqueo también ocurre cuando hay un interbloqueo y MySQL no puede detectarlo, por lo que solo se agota el tiempo de espera. Otra razón podría ser una consulta de ejecución extremadamente larga, que es más fácil de resolver / reparar, sin embargo, no describiré este caso aquí.

MySQL generalmente puede lidiar con puntos muertos si se construyen "adecuadamente" dentro de dos transacciones. MySQL simplemente elimina / deshace la transacción que posee menos bloqueos (es menos importante, ya que afectará a menos filas) y permite que la otra finalice.

Ahora, supongamos que hay dos procesos A y B y 3 transacciones:

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

Esta es una configuración muy desafortunada porque MySQL no puede ver que hay un interbloqueo (abarcado en 3 transacciones). Entonces, lo que MySQL hace es ... ¡nada! Solo espera, ya que no sabe qué hacer. Espera hasta que el primer bloqueo adquirido exceda el tiempo de espera (Proceso A Transacción 1: Bloqueos X), entonces esto desbloqueará el Bloqueo X, que desbloquea la Transacción 2, etc.

El arte es averiguar qué (qué consulta) causa el primer bloqueo (Bloquear X). Podrá ver fácilmente ( show engine innodb status ) que la transacción 3 espera la transacción 2, pero no verá qué transacción está esperando la transacción 2 (transacción 1). MySQL no imprimirá ningún bloqueo o consulta asociada con la Transacción 1. La única pista será que en la parte inferior de la lista de transacciones (de la impresión del show engine innodb status ), verá que la Transacción 1 aparentemente no hace nada (pero en realidad está esperando) para la transacción 3 para terminar).

La técnica de cómo encontrar qué consulta SQL causa que se otorgue el bloqueo (Bloqueo X) para una transacción dada que está en espera se describe aquí Tracking MySQL query history in long running transactions

Si se está preguntando qué es exactamente el proceso y la transacción en el ejemplo. El proceso es un proceso de PHP. Transacción es una transacción definida por innodb-trx-table . En mi caso, tuve dos procesos PHP, en cada uno comencé una transacción manualmente. Lo interesante fue que, aunque inicié una transacción en un proceso, MySQL usó internamente, de hecho, dos transacciones separadas (no tengo idea de por qué, tal vez algunos desarrolladores de MySQL puedan explicarlo).

MySQL está administrando sus propias transacciones internamente y decidió (en mi caso) usar dos transacciones para manejar todas las solicitudes SQL provenientes del proceso PHP (Proceso A). La afirmación de que la transacción 1 está esperando que la transacción 3 termine es una cuestión interna de MySQL. MySQL "sabía" que la Transacción 1 y la Transacción 3 se crearon en realidad como parte de una solicitud de "transacción" (del Proceso A). Ahora toda la "transacción" fue bloqueada porque la transacción 3 (una subparte de "transacción") fue bloqueada. Debido a que "transacción" no pudo finalizar la Transacción 1 (también una subparte de la "transacción") se marcó como no finalizada también. Esto es lo que quise decir con "La transacción 1 espera que la transacción 3 termine".

Puedes usar:

show full processlist

que mostrará una lista de todas las conexiones en MySQL y el estado actual de la conexión, así como la consulta que se está ejecutando. También hay una variante más corta show processlist; que muestra la consulta truncada, así como las estadísticas de conexión.