Cómo rastrear interbloqueos en Firebird

Alexey Kovyazin, 08-May-2019, (c) IBSurgeon

Los conflictos de actualización (a menudo llamados «deadlocks») ocurren en aplicaciones Firebird que realizan actualizaciones concurrentes intensivas de datos.

Como puede ver en el artículo « Transacciones en Firebird», hay 3 tipos de errores que contienen la palabra clave «deadlock»:

Code

deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN

lock time-out on wait transaction
-deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN

lock conflict on no wait transaction
-deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN

Los 3 tipos de conflictos de actualización tienen en común el hecho de que el conflicto de actualización generalmente es el resultado de 2 operaciones de modificación que intentan modificar el mismo registro.

Las opciones posibles son las siguientes: UPDATE, DELETE SELECT WITH LOCK, MERGE, UPDATE OR INSERT.

Es relativamente fácil rastrear la operación «víctima», que recibe el mensaje de error - solo colóquela en try… catch y registre los parámetros utilizados en la consulta que falla con el error.

Sin embargo, con este enfoque, es difícil rastrear al «ganador» - es decir, la transacción concurrente donde la actualización se realizó con éxito, sin error.

Para ayudar a los desarrolladores a investigar los conflictos de actualización, Firebird coloca en los mensajes de error la referencia a la transacción concurrente - es decir, la transacción donde la actualización concurrente aún no está confirmada. Junto con Trace API, esto nos da la capacidad de rastrear ambas operaciones en conflicto.

Consideremos los pasos prácticos sobre cómo hacerlo.

Primero, necesitamos configurar el rastreo. Para esto, cree el archivo de texto (en nuestro caso es C:\Temp\mytrace.conf) con el siguiente contenido:

Code

database
{
	enabled = true
	include_filter="(UPDATE%)|(DELETE%)|(MERGE%)|(SELECT%FROM%WITH LOCK)|(UPDATE OR INSERT%)"
	log_statement_finish = true
	log_errors = true
	include_gds_codes="deadlock"
	log_initfini = false
	time_threshold = 0
	max_sql_length = 65000

}

El archivo de configuración anterior habilita el rastreo para todas las bases de datos, por lo que si tiene más de 1 base de datos activa, es mejor especificar el nombre de la base de datos en el archivo de configuración, es decir:

Code

Database=mydatabase.fdb
{
  enabled = true
…
}

Revisemos los parámetros más importantes en el archivo de configuración:

Parámetro include filter

Code

include_filter="(UPDATE%)|(DELETE%)|(MERGE%)|(SELECT%FROM%WITH LOCK)|(UPDATE OR INSERT%)"

Significa que queremos rastrear solo las sentencias UPDATE y DELETE e ignorar los selects. Es necesario filtrar tantas sentencias como sea posible, porque en el sistema de producción bajo alta carga, la cantidad de registros en el registro de texto puede ser demasiado alta para analizarla.

Generalmente, sabemos qué tabla participa en el conflicto de actualización; una buena idea será colocarla en el filtro para reducir el número de actualizaciones a analizar:

Code

include_filter="(UPDATE T1%)|(DELETE FROM T1%)|(MERGE INTO T1%)|(SELECT% FROM T1%WITH lock%)|(UPDATE OR INSERT INTO T1%)"

¿Qué pasa si las actualizaciones y eliminaciones se realizan mediante procedimientos almacenados? Bueno, esto hace que todo el proceso sea más difícil: agregue al filtro todos los procedimientos almacenados que pueden estar involucrados en actualizaciones concurrentes, y también habilite el registro de procedimientos:

Code

include_filter="(UPDATE T1%)|(DELETE FROM T1%)|(MERGE INTO T1%)|(SELECT% FROM T1%with lock%)|(UPDATE OR INSERT INTO T1%)|(%SP_UPDATE_T1%)|(%SP_DEL_T1%)"
log_procedures=true

Parámetros de registro de errores

Luego, necesitamos especificar el registro de errores y limitarlo a los deadlocks.

Code

log_errors = true
include_gds_codes="deadlock"

Tenga en cuenta: el parámetro include_gds_codes apareció solo en Firebird 3.0.2, por lo que si usa 2.5 o 3.0.0 o 3.0.1, no es posible filtrar solo errores de deadlock, por lo que todos los errores se imprimirán en el registro.

Demostración

Para demostrar el proceso general, preparemos la base de datos de prueba - por simplicidad, habrá 1 tabla con 1 columna de clave primaria.

Code

C:\HQbird\Firebird30>isql
Use CONNECT or CREATE DATABASE to specify a database
SQL> create database "c:\temp\testdeadlock.fdb" user "SYSDBA" password "masterkey";
SQL> create table t1(i1 integer not null primary key);
SQL> insert into t1(i1) values(1);
SQL> commit; exit;

Después de eso, necesitamos iniciar la sesión de rastreo:

Code

fbtracemgr.exe -se localhost:service_mgr -start -conf "C:\temp\mytrace.conf" -user SYSDBA -pass masterkey

En este caso, fbtracemgr imprime el registro en la pantalla, pero en producción, necesitamos redirigirlo a un archivo, por supuesto.

Después del inicio exitoso, fbtracemgr imprime algo como esto:

Code

Trace session ID 4 started

Luego, iniciemos 2 sesiones de isql e intentemos simular el conflicto de actualización. En la tabla a continuación tenemos 2 columnas para 2 sesiones de isql. Cada fila representa un momento en el tiempo en que se ejecutaron los comandos.


Tiempo	sesión isql 1	sesión isql 2
T1	`<br>isql -user SYSDBA -pass masterkey localhost:c:\temp\testdeadlock.fdb<br>Database: localhost:c:\temp\testdeadlock.fdb, User: SYSDBA<br>SQL> set transaction wait;<br>Commit current transaction (y/n)?y<br>Committing.<br>SQL> select current_transaction from rdb$database;<br> CURRENT_TRANSACTION<br>=====================<br> 15<br>SQL> select * from t1;<br> I1<br>============<br> 2<br>SQL><br>`
T2		`<br>isql -user SYSDBA -pass masterkey localhost:c:\temp\testdeadlock.fdb<br>Database: localhost:c:\temp\testdeadlock.fdb, User: SYSDBA<br>SQL> set transaction wait;<br>Commit current transaction (y/n)?y<br>Committing.<br>SQL> select current_transaction from rdb$database;<br> CURRENT_TRANSACTION<br>=====================<br> 20<br>SQL> select * from t1;<br> I1<br>============<br> 2<br>SQL><br>`
Entonces, en el punto de partida, podemos ver que se iniciaron 2 transacciones, #15 y #20. Luego, intentemos realizar la actualización concurrente del mismo registro:

T3	`<br>SQL> UPDATE T1 SET i1=5 where i1=2;<br>`
T4		`<br>SQL> UPDATE T1 SET i1=100 where i1=2;<br>`
T5	`<br>SQL> commit;<br>SQL><br>`	`<br>Statement failed, SQLSTATE = 40001<br>deadlock<br>-update conflicts with concurrent update<br>-concurrent transaction number is 15<br>SQL><br>`

Iniciamos UPDATE en la sesión 1 pero no lo confirmamos.

En la sesión 2, UPDATE «se colgó» - esperó el final de la transacción concurrente, y cuando confirmamos UPDATE en la sesión 1, la sesión 2 recibió el error:

Code

Statement failed, SQLSTATE = 40001
deadlock
-update conflicts with concurrent update
-concurrent transaction number is 15
SQL>

Entonces, tenemos una situación típica en caso de conflicto de actualización con transacción en espera.

Revisemos el registro de rastreo para encontrar la evidencia del conflicto de actualización.

En este caso, el registro de rastreo es muy corto, pero en el caso de un sistema de producción, puede ser mucho más largo, pero el enfoque para encontrar deadlocks es el mismo.

Code

fbtracemgr.exe -se localhost:service_mgr -start -conf "C:\temp\fbtrace.conf" -user SYSDBA -pass masterkey
Trace session ID 4 started

2019-05-07T11:28:43.9850 (2692:00000000018C1940) EXECUTE_STATEMENT_FINISH
        C:\TEMP\TESTDEADLOCK.FDB (ATT_12, SYSDBA:NONE, NONE, TCPv6:::1/52938)
        C:\HQbird\Firebird30\isql.exe:8828
                (TRA_15, CONCURRENCY | WAIT | READ_WRITE)

Statement 52:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=5 where i1=2
0 records fetched
      0 ms, 2 read(s), 21 fetch(es), 3 mark(s)

2019-05-07T11:29:45.0190 (2692:00000000018C0040) FAILED EXECUTE_STATEMENT_FINISH
        C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
        C:\HQbird\Firebird30\isql.exe:7032
                (TRA_20, CONCURRENCY | WAIT | READ_WRITE)

Statement 55:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=100 where i1=2
0 records fetched
  40242 ms, 19 fetch(es), 2 mark(s)

2019-05-07T11:29:45.0190 (2692:00000000018C0040) ERROR AT JStatement::execute
        C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
        C:\HQbird\Firebird30\isql.exe:7032
335544336 : deadlock
335544451 : update conflicts with concurrent update
335544878 : concurrent transaction number is 15

Como puede ver, tenemos registros en el registro sobre ambas actualizaciones - exitosa y fallida, y un mensaje de error sobre el deadlock.

Consideremos cómo analizar el registro:

En el mensaje de error, localicemos el identificador de la transacción:

Code

 2019-05-07T11:29:45.0190 (2692:00000000018C0040) ERROR AT JStatement::execute
        C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
        C:\HQbird\Firebird30\isql.exe:7032
335544336 : deadlock
335544451 : update conflicts with concurrent update
335544878 : concurrent transaction number is 15

Cerca del registro sobre el error (generalmente justo encima), verá la sentencia fallida:

Code

2019-05-07T11:29:45.0190 (2692:00000000018C0040) FAILED EXECUTE_STATEMENT_FINISH
        C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
        C:\HQbird\Firebird30\isql.exe:7032
                (TRA_20, CONCURRENCY | WAIT | READ_WRITE)

Statement 55:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=100 where i1=2
0 records fetched
  40242 ms, 19 fetch(es), 2 mark(s)

Observe que el tiempo de ejecución es enorme (~40 segundos) - indica el tiempo en que la operación esperó el resultado de la transacción concurrente.

Y, finalmente, busque el número de transacción con la operación UPDATE exitosa: para esto, localice TRA_NNN, donde NNN es el número de transacción. En nuestro caso, será TRA_15:

Code

2019-05-07T11:28:43.9850 (2692:00000000018C1940) EXECUTE_STATEMENT_FINISH
        C:\TEMP\TESTDEADLOCK.FDB (ATT_12, SYSDBA:NONE, NONE, TCPv6:::1/52938)
        C:\HQbird\Firebird30\isql.exe:8828
                (TRA_15, CONCURRENCY | WAIT | READ_WRITE)

Statement 52:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=5 where i1=2
0 records fetched
      0 ms, 2 read(s), 21 fetch(es), 3 mark(s)

Entonces, esto es todo - encontramos ambas partes del conflicto de actualización - la exitosa y la fallida.

Herramientas para identificar deadlocks

Como puede ver, puede ser bastante difícil identificar la fuente raíz del conflicto de bloqueo/deadlock: dado que el conflicto siempre tiene 2 lados, y un lado «gana» (se completa sin mensajes de error), puede ser complicado identificar al ganador. Por ejemplo, el conflicto puede ocurrir dentro de EXECUTE STATEMENT, o en un procedimiento almacenado anidado, o dentro de un trigger, o podría ser una combinación de todas estas cosas.

Para identificar deadlocks, IBSurgeon ha desarrollado la herramienta «Deadlock Analyzer», que analiza el registro de rastreo y crea diagramas fáciles de entender con detalles de las llamadas que han llevado a deadlocks. Esta herramienta está disponible como parte de Enterprise Subscription (tiene prueba) - regístrese en cc.ib-aid.com.

Además, HQbird introduce una versión extendida del plugin fbtrace, que se puede configurar para guardar solo cambios e intentos de cambios (es decir, operaciones fallidas y conflictos de bloqueo y deadlocks).

Contacte al soporte de IBSurgeon para obtener más información al respecto: [email protected].

¿Cómo evitar deadlocks?

Ahora necesita identificar la mejor solución para su aplicación para evitar deadlocks - puede ser un cambio en los parámetros de transacción, o es posible agregar procesamiento de errores adicional y repetir la operación o realizar verificaciones adicionales a nivel de negocio de la aplicación.