WRITELOG

---

Ya ha pasado mucho tiempo desde la última entrada que escribí en este blog, lamentablemente hasta me había olvidado de él y lo había dejado de lado para atender otros temas.

He querido retomarlo con un tema que me resultó muy interesante y que significó en una que otra discusión álgida con otro proveedor de un cliente.

Sucede que el cliente estaba experimentando una lentitud muy importante en las transacciones de índole de escritura, es decir los queries del tipo INSERT, DELETE, UPDATE, MERGE, etc.

¿Qué es lo primero que hay que hacer?, darle una revisada a lo que se está ejecutando en este momento, analizar lo que lleva más tiempo ejecutándose y el tipo de bloqueo que está reportando.    Esta información la podríamos obtener con el siguiente query:

SELECT ER.session_id, DB_NAME(ES.database_id) AS database_name, DATEDIFF(SECOND, ER.start_time, GETDATE()) AS seconds_elapsed, ER.command, ES.host_name, ES.program_name, ES.host_process_id, ER.blocking_session_id, ER.wait_type
FROM sys.dm_exec_requests ER
INNER JOIN sys.dm_exec_sessions ES
ON ER.session_id = ES.session_id
WHERE ES.is_user_process = 1
AND ER.last_wait_type NOT IN ('BROKER_RECEIVE_WAITFOR', 'XE_TIMER_EVENT', 'XE_DISPATCHER_WAIT', 'XE_LIVE_TARGET_TVF', 'FT_IFTS_SCHEDULER_IDLE_WAIT')

Me encontré con que había una lista importante de queries en ejecución y cuya cantidad de segundos transcurridos ya estaba por encima de los 10 segundos.    Noté que el valor de la columna wait_type en casi todos los casos era "WRITELOG".

Si verificamos la documentación de este tipo de wait, encontraremos que está relacionado con el tiempo que le está llevando el escribir en el archivo de transacciones de las bases de datos, es decir que se está tardando en escribir en el sistema de almacenamiento.

Para confirmar la sospecha generé un medidor de rendimiento en el PerfMon y agregué el contador Physical Disk - Avg. Disk sec/Write seleccionando la unidad de almacenamiento donde se encontraban los archivos de registro de transacciones de las bases de datos.

¿Qué fue lo que encontré?, que la escritura le estaba tomando, en promedio, 170 milisegundos en ejecutarse.   ¡Sí!, 170 milisegundos; no perdamos de vista que el tiempo máximo de escritura y de lectura es de 15 milisegundos, es decir que estaban muy por encima del tiempo máximo aceptable.

Después de correos, revisiones, discusiones, reuniones y llamadas; el proveedor del sistema de almacenamiento encontró (y aceptó) que el sistema de almacenamiento estaba teniendo problemas y que solamente tenía que cambiar las unidades problemáticas.

Hay veces que le echarán la culpa a SQL porque es lo que ven y lo que percibe tanto el usuario final como el departamento de TI de nuestro cliente, pero es importante tener información sólida a la mano para determinar que el problema no es el motor sino algún recurso que necesita el motor para ejecutarse correctamente.

¡Saludos y que este 2024 esté lleno de salud y de trabajo!

---

CONVERT vs FORMAT

Hace poco estaba revisando el código T-SQL de un cliente y le comentaba que resulta un poco complicado el deducir qué formato de fecha se estará devolviendo al usuario cuando utiliza la función CONVERT, por ejemplo:

CONVERT(VARCHAR(10), GETDATE(), 23)

De forma inmediata recordé que existe la función FORMAT que hace mucho más legible el código. Si tomamos como base la expresión que anteriormente mencioné, su versión en FORMAT sería:

FORMAT(GETDATE(), 'yyyy-MM-dd')

Es evidente que es muchísimo más legible, y de manera inevitable me brincó la pregunta, ¿cuál de las dos opciones es mejor? Para responder a esta pregunta he preparado un ejercicio bastante sencillo, pero que nos ayudará a comprender la enorme diferencia.

Comencemos por crear nuestra tabla y llenarla con 500 mil registros:

CREATE TABLE TestFormat(
    Fecha DATETIME2(0)
)
GO
SET NOCOUNT ON
INSERT INTO TestFormat (Fecha)
VALUES (DATEADD(MINUTE, ABS(CHECKSUM(NEWID())) % 15768000, '1992-01-01 00:00:00'))
GO 500000


Vamos a comenzar por obtener las fechas en el formato yyyy-MM-dd con CONVERT y tomaremos los tiempos de ejecución.   Para tener una mejor perspectiva, ejecutaremos el ejercicio tres veces.

SET STATISTICS TIME ON
SELECT CONVERT(VARCHAR(10), Fecha, 23)
FROM TestFormat


Y después vamos a obtener el mismo formato pero utilizando la función FORMAT.   Al igual que en el ejercicio anterior, vamos a ejecutarlo unas tres veces para tener más datos de comparación.

SET STATISTICS TIME ON
SELECT FORMAT(Fecha, 'yyyy-MM-dd')
FROM TestFormat


La diferencia en las métricas es muy importante:

Ahora vamos a hacer el mismo ejercicio pero obteniendo la fecha y hora en formato yyyy-MM-dd HH:mm:ss.    Con CONVERT quedaría de la siguiente manera:

SET STATISTICS TIME ON
SELECT CONCAT(CONVERT(VARCHAR(10), Fecha, 23), ' ', CONVERT(VARCHAR(10), Fecha, 24))
FROM TestFormat


Y con FORMAT quedaría de la siguiente manera:

SET STATISTICS TIME ON
SELECT FORMAT(Fecha, 'yyyy-MM-dd HH:mm:ss')
FROM TestFormat


En la imagen siguiente podremos notar que el tiempo de CPU de CONVERT se incrementa y que el tiempo de CPU de FORMAT se mantiene muy parecido:

Pero ni con el incremento de tiempo de CPU en el formato yyyy-MM-dd HH:mm:ss nos acercamos al tiempo de CPU de FORMAT, porque FORMAT se ejecuta casi 10 veces más lento cuando incluimos la hora y casi 20 veces más lento cuando únicamente tenemos la fecha.

¿Qué factores debemos tomar en cuenta para entender estos datos?

1. FORMAT está implementada a través de un ensamblado de .NET, es decir que se está ejecutando de forma externa.
2. CONVERT se va al doble cuando hay que incluir la hora porque podemos ver que hay dos ejecuciones de la función, una para obtener la fecha y otra para obtener la hora.

La recomendación que te puedo hacer, es que en el código incluyan un comentario donde se indique el formato de fecha que se estará obteniendo, por ejemplo:

--yyyy-MM-dd HH:mm:ss
SELECT CONCAT(CONVERT(VARCHAR(10), Fecha, 23), ' ', CONVERT(VARCHAR(10), Fecha, 24))
FROM TestFormat


De esta forma será mucho más sencillo el darle mantenimiento al código porque podremos ver de forma inmediata lo que se está obteniendo.   La programación considerada no es una buena práctica, es una obligación.

Espero te haya resultado útil esta entrada.

PAGEIOLATCH_EX

---

He querido hacer esta entrada porque este tipo de wait es muy buscado, poco entendido y puede significar un dolor de cabeza.

El día de hoy recibimos el reporte de un cliente de que su sistema estaba sumamente lento, que la cantidad de timeouts estaba siendo insoportable y que estaba afectando seriamente la operación.

Al ingresar y visualizar la lista de sentencias que estaban en ejecución, notamos que la mayoría de ellas estaban con un wait del tipo PAGEIOLATCH_EX o del tipo PAGEIOLATCH_SH.

Primero, ¿qué diferencia existe entre un PAGEIOLATCH_XX y un PAGELATCH_XX?, es simple, el primer grupo se refiere a eventos de lectura y escritura desde el sistema de almacenamiento y el segundo se refiere a eventos de lectura y escritura sobre el buffer de datos de SQL Server.    En nuestro caso notamos que todas las esperas eran del tipo PAGEIOLATCH_XX.

Utilizando la función sys.dm_io_virtual_file_stats obtuvimos información acerca de los tiempos de espera para actividades de IO desde y hacia el sistema de almacenamiento por cada uno de los archivos de la base de datos del ERP.    El query utilizado fue el siguiente:

SELECT F.name, F.filename, FS.io_stall_read_ms / FS.num_of_reads END AS avg_read_wait_ms, FS.io_stall_write_ms / FS.num_of_writes AS avg_write_wait_ms
FROM sys.sysfiles F
CROSS APPLY sys.dm_io_virtual_file_stats(DB_ID(), F.fileid) FS

Los resultados que obtuvimos nos indicaron problemas catastróficos sobre la unidad de almacenamiento donde están ubicados los archivos de datos de la base de datos del ERP. Recordemos que el tiempo de espera ideal no debe de pasar de los 15 milisegundos.

El personal de infraestructura nos ayudó a verificar la situación actual del arreglo de discos y fue posible determinar que uno de los tres discos que formaban el RAID estaba dando muchos problemas, y es por ello que los tiempos de espera de lectura y escritura estaban por los cielos.

Se quitó el disco del arreglo y después de que pasó algún tiempo en lo que SQL terminaba de "calentar" la memoria, el rendimiento volvió a su estado óptimo.

Espero te resulte de utilidad esta información, nos vemos la siguiente.

---