Diagnostico de problemas de IO en SQL Server

Este es un tema que no tiene realmente mucho que ver con SQL Server, pero que siento que es necesario que los DBA sean consientes de las implicaciones en el desempeño de sus servidores tiene el subsistema de IO.

En mi experiencia e visto que en ocasiones muchos DBA buscan un problema pero no dan con el resultado en ocasiones to es bastante obvio (y en otras aun no tan obvio) como cuando vemos estos errores en el log de errores.

SQL Server has encountered x occurrence(s) of I/O requests taking longer than 15 seconds to complete on file.

Para esto podemos seguir este documento que tiene excelentes recomendaciones, como lo son:

Revisar los wait stats y el mensaje de error puesto en la parte de arriba, pero como ver los wait stats, podemos seguir su recomendación de la DMV sys.sysprocesses y sys.dm_os_wait_stats pero los valores que veamos tal vez no nos sean representativos en primera instancia.

Podemos usar este query que encontraremos en un post muy educativo de Paul Randal

WITH [Waits] AS
    (SELECT
        [wait_type],
        [wait_time_ms] / 1000.0 AS [WaitS],
        ([wait_time_ms] - [signal_wait_time_ms]) / 1000.0 AS [ResourceS],
        [signal_wait_time_ms] / 1000.0 AS [SignalS],
        [waiting_tasks_count] AS [WaitCount],
        100.0 * [wait_time_ms] / SUM ([wait_time_ms]) OVER() AS [Percentage],
        ROW_NUMBER() OVER(ORDER BY [wait_time_ms] DESC) AS [RowNum]
    FROM sys.dm_os_wait_stats
    WHERE [wait_type] NOT IN (
        N'BROKER_EVENTHANDLER',             N'BROKER_RECEIVE_WAITFOR',
        N'BROKER_TASK_STOP',                N'BROKER_TO_FLUSH',
        N'BROKER_TRANSMITTER',              N'CHECKPOINT_QUEUE',
        N'CHKPT',                           N'CLR_AUTO_EVENT',
        N'CLR_MANUAL_EVENT',                N'CLR_SEMAPHORE',
        N'DBMIRROR_DBM_EVENT',              N'DBMIRROR_EVENTS_QUEUE',
        N'DBMIRROR_WORKER_QUEUE',           N'DBMIRRORING_CMD',
        N'DIRTY_PAGE_POLL',                 N'DISPATCHER_QUEUE_SEMAPHORE',
        N'EXECSYNC',                        N'FSAGENT',
        N'FT_IFTS_SCHEDULER_IDLE_WAIT',     N'FT_IFTSHC_MUTEX',
        N'HADR_CLUSAPI_CALL',               N'HADR_FILESTREAM_IOMGR_IOCOMPLETION',
        N'HADR_LOGCAPTURE_WAIT',            N'HADR_NOTIFICATION_DEQUEUE',
        N'HADR_TIMER_TASK',                 N'HADR_WORK_QUEUE',
        N'KSOURCE_WAKEUP',                  N'LAZYWRITER_SLEEP',
        N'LOGMGR_QUEUE',                    N'ONDEMAND_TASK_QUEUE',
        N'PWAIT_ALL_COMPONENTS_INITIALIZED',
        N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP',
        N'QDS_SHUTDOWN_QUEUE',
        N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP',
        N'REQUEST_FOR_DEADLOCK_SEARCH',     N'RESOURCE_QUEUE',
        N'SERVER_IDLE_CHECK',               N'SLEEP_BPOOL_FLUSH',
        N'SLEEP_DBSTARTUP',                 N'SLEEP_DCOMSTARTUP',
        N'SLEEP_MASTERDBREADY',             N'SLEEP_MASTERMDREADY',
        N'SLEEP_MASTERUPGRADED',            N'SLEEP_MSDBSTARTUP',
        N'SLEEP_SYSTEMTASK',                N'SLEEP_TASK',
        N'SLEEP_TEMPDBSTARTUP',             N'SNI_HTTP_ACCEPT',
        N'SP_SERVER_DIAGNOSTICS_SLEEP',     N'SQLTRACE_BUFFER_FLUSH',
        N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP',
        N'SQLTRACE_WAIT_ENTRIES',           N'WAIT_FOR_RESULTS',
        N'WAITFOR',                         N'WAITFOR_TASKSHUTDOWN',
        N'WAIT_XTP_HOST_WAIT',              N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG',
        N'WAIT_XTP_CKPT_CLOSE',             N'XE_DISPATCHER_JOIN',
        N'XE_DISPATCHER_WAIT',              N'XE_TIMER_EVENT')
    AND [waiting_tasks_count] > 0
 )
SELECT
    MAX ([W1].[wait_type]) AS [WaitType],
    CAST (MAX ([W1].[WaitS]) AS DECIMAL (16,2)) AS [Wait_S],
    CAST (MAX ([W1].[ResourceS]) AS DECIMAL (16,2)) AS [Resource_S],
    CAST (MAX ([W1].[SignalS]) AS DECIMAL (16,2)) AS [Signal_S],
    MAX ([W1].[WaitCount]) AS [WaitCount],
    CAST (MAX ([W1].[Percentage]) AS DECIMAL (5,2)) AS [Percentage],
    CAST ((MAX ([W1].[WaitS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgWait_S],
    CAST ((MAX ([W1].[ResourceS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgRes_S],
    CAST ((MAX ([W1].[SignalS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgSig_S]
FROM [Waits] AS [W1]
INNER JOIN [Waits] AS [W2]
    ON [W2].[RowNum] <= [W1].[RowNum]
GROUP BY [W1].[RowNum]
HAVING SUM ([W2].[Percentage]) - MAX ([W1].[Percentage]) < 95; -- percentage threshold
GO

Lo que nos interesa principalmente seria cuestiones como PAGEIOLATCH_XX, WRITELOG, IO_COMPLETITION, si la suma de estos supera el 40% conjunto del tiempo agregado de los waits es muy posible que estemos teniendo problemas de IO.

También dejo este video que esta publicado tanto en youtube como en channel 9 donde explico como detectarlo y sacar una linea base con las siguientes herramientas

• CPU Z
• IO Meter
• Crystal Disk Mark
• Performance Monitor
• Performance Analysis of Logs

Para poder realizar la captura de Performance Monitor en la linea de comando podemos usar:

logman.exe create counter %computername% -cnf 00:00:00 -f bin -v mmddhhmm -max 600 -o "c:\perflogs\%computername%.blg" -c "\LogicalDisk(*)\*" "\Memory\*" "\Network Interface(*)\*" "\Paging File(*)\*" "\PhysicalDisk(*)\*" "\Processor(*)\*" "\Process(*)\*" "\Redirector\*" "\Server\*" "\System\*" -si 00:00:30"

Normalmente si ven en PAL o en IO Meter tiempos de respuesta mas altos de 100ms de manera constante es posible que tengamos un problema en el subsistema de IO o estemos sobre la capacidad del mismo (en PAL podrán ver la cantidad de datos que están enviando), si por el contrario tiene algo arriba de 1 segundo vayan con su administrador de storage y busquen trabajar en encontrar que esta pasando.

Notas: 

Impacto negativo al no usar planes de energía en alto rendimiento

Impacto en el IO

https://support.microsoft.com/en-us/kb/2254067
https://support.microsoft.com/en-us/kb/2207548

Impacto en SQL Server

http://www.brentozar.com/archive/2010/10/sql-server-on-powersaving-cpus-not-so-fast/