Consulta de larga duración en la réplica de solo lectura que toma momentos en el primario

Tengo una configuración AG de 4 nodos de la siguiente manera:

Configuración de hardware de VM de todos los nodos:

• Microsoft SQL Server 2017 Enterprise Edition (RTM-CU14) (KB4484710)
• 16 vCPU
• 356 GB de RAM (larga historia para este ...)
• grado máximo de paralelismo: 1 (según lo requiera el proveedor de la aplicación)
• umbral de costo para paralelismo: 50
• memoria máxima del servidor (MB): 338944 (331 GB)

Configuración AG:

• Nodo 1: Compromiso primario o sincrónico Secundario no legible, configurado para conmutación por error automática
• Nodo 2: Compromiso primario o sincrónico Secundario no legible, configurado para conmutación por error automática
• Nodo 3: conjunto secundario legible con confirmación asincrónica, configurado para conmutación por error manual
• Nodo 4: conjunto secundario legible con confirmación asincrónica, configurado para conmutación por error manual

La consulta en cuestión:

No hay nada terriblemente loco en esta consulta, proporciona un resumen de elementos de trabajo pendientes en varias colas dentro de la aplicación. Puede ver el código de uno de los enlaces del plan de ejecución a continuación.

Comportamiento de ejecución en el nodo primario:

Cuando se ejecuta en el nodo primario, el tiempo de ejecución es generalmente alrededor de la marca de 1 segundo. Aquí está el plan de ejecución , y a continuación se muestran las estadísticas capturadas de STATISTICS IO y STATISTICS TIME del nodo primario:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 500 ms,  elapsed time = 656 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Comportamiento de ejecución en el nodo secundario de solo lectura:

Cuando se ejecuta en Nodo secundario de solo lectura (es decir, Nodo 3 o Nodo 4), esta consulta usa el mismo plan de ejecución (este es un enlace de plan diferente) y se muestran aproximadamente las mismas estadísticas de ejecución (por ejemplo, puede haber algunas páginas más escaneos ya que estos resultados siempre están cambiando), pero con la excepción del tiempo de CPU, se ven muy similares. Aquí están las estadísticas capturadas de STATISTICS IO y STATISTICS TIME del nodo secundario de solo lectura:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 55719 ms,  elapsed time = 56335 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Otros detalles:

También ejecuté el script de Paul Randalsp_WhoIsActive y ambos en el secundario mientras se ejecuta esta consulta, pero no veo que ocurra ninguna espera, lo que es francamente frustrante:WaitingTasks.sql

Esto tampoco parece ser un caso de latencia AG ya que el estado de sincronización es bastante bueno:

--https://sqlperformance.com/2015/08/monitoring/availability-group-replica-sync

SELECT 
       ar.replica_server_name, 
       adc.database_name, 
       ag.name AS ag_name, 
       drs.is_local, 
       drs.synchronization_state_desc, 
       drs.synchronization_health_desc, 
       --drs.last_hardened_lsn, 
       --drs.last_hardened_time, 
       drs.last_redone_time, 
       drs.redo_queue_size, 
       drs.redo_rate, 
       (drs.redo_queue_size / drs.redo_rate) / 60.0 AS est_redo_completion_time_min,
       drs.last_commit_lsn, 
       drs.last_commit_time
FROM sys.dm_hadr_database_replica_states AS drs
INNER JOIN sys.availability_databases_cluster AS adc 
       ON drs.group_id = adc.group_id AND 
       drs.group_database_id = adc.group_database_id
INNER JOIN sys.availability_groups AS ag
       ON ag.group_id = drs.group_id
INNER JOIN sys.availability_replicas AS ar 
       ON drs.group_id = ar.group_id AND 
       drs.replica_id = ar.replica_id
ORDER BY 
       ag.name, 
       ar.replica_server_name, 
       adc.database_name;

Esta consulta parece ser el peor delincuente. Otras consultas que también tardan menos de un segundo en el nodo primario pueden tardar de 1 a 5 segundos en el nodo secundario, y aunque el comportamiento no es tan grave, parece estar causando problemas.

Finalmente, también examiné los servidores y verifiqué los procesos externos, tales como escaneos de A / V, trabajos externos que generan E / S inesperadas, etc. y he llegado con las manos vacías. No creo que esto sea causado por algo fuera del proceso de SQL Server.

La pregunta:

Es solo mediodía donde estoy y ya ha sido un día largo, así que sospecho que me estoy perdiendo algo obvio aquí. O eso, o tenemos algo mal configurado, lo cual es posible ya que hemos recibido varias llamadas al Proveedor y MS relacionadas con este entorno.

Para toda mi investigación, parece que no puedo encontrar lo que está causando esta diferencia en el rendimiento. Esperaría ver algún tipo de espera en los nodos secundarios, pero nada. ¿Cómo puedo solucionar esto para identificar la causa raíz? ¿Alguien ha visto este comportamiento antes y ha encontrado una manera de resolverlo?

ACTUALIZACIÓN # 1 Después de cambiar los estados del tercer nodo (una de las réplicas de solo lectura) a no legible y luego de nuevo a legible como prueba, esa réplica todavía está retenida por una transacción abierta, y cualquier consulta del cliente muestra el HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGEspere.

Ejecutar un DBCC OPENTRANcomando produce los siguientes resultados:

Oldest active transaction:
    SPID (server process ID): 420s
    UID (user ID) : -1
    Name          : QDS nested transaction
    LSN           : (941189:33148:8)
    Start time    : May  7 2019 12:54:06:753PM
    SID           : 0x0
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Al buscar este SPID sp_who2, lo muestra como un BACKGROUNDproceso con el QUERY STORE BACKlistado.

A pesar de que somos capaces de realizar copias de seguridad tlog, sospecho que se están ejecutando en funcionalidad similar de este error corregido , por lo que tengo la intención de abrir un ticket con EM sobre este tema en particular hoy en día.

Dependiendo del resultado de ese ticket, intentaré capturar un seguimiento de la pila de llamadas según la sugerencia de Joe y ver a dónde vamos.

Actualización final (problema con resolución propia)

Después de eclipsar la marca de 52 horas de la transacción de Query Store abierta (como se identificó anteriormente), el AG decidió realizar una conmutación por error automática. Antes de que esto sucediera, extraje algunas métricas adicionales. Según este enlace , proporcionado por Sean, la base de datos en cuestión tenía una tienda de versiones muy grande dedicada a esta base de datos, específicamente en un momento había registrado 1651360 páginas en el reserved_page_countcampo y 13210880 por el reserved_space_kbvalor.

Según los ERRORLOG, la conmutación por error se produjo después de un diluvio de 5 minutos de fallas de endurecimiento de transacciones relacionadas QDS base transactiony QDS nested transactiontransacciones.

La conmutación por error causó una interrupción de aproximadamente 10 minutos en mi caso. La base de datos tiene un tamaño de ~ 6 TB y es muy activa, por lo que en mi opinión eso fue bastante bueno. Mientras el nuevo nodo primario estuvo en línea durante este tiempo, no se pudieron completar consultas de clientes ya que todos estaban esperando el QDS_LOADDBtipo de espera.

Después de la conmutación por error, los números de la tienda de versiones se redujeron a 176 para reserved_page_county 1408 para reserved_space_kb. Las consultas contra las réplicas secundarias de solo lectura también comenzaron a ejecutarse tan rápido como si se ejecutaran desde la primaria, por lo que parece que el comportamiento desapareció por completo, como resultado de la conmutación por error.

Esta respuesta es adicional a la respuesta de Joe, ya que no puedo estar 100% seguro de que sea la tienda de versiones, sin embargo, hasta ahora hay suficiente evidencia para implicar que es parte del problema.

Cuando una réplica secundaria se marca como legible, primero se debe alcanzar un buen estado estable para la información de versiones, de modo que haya un punto de partida conocido y bueno para todas las operaciones de lectura en la secundaria. Cuando esto está esperando para la transición y todavía hay transacciones abiertas en el primario, esto se manifestará como HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGy también es un buen indicador de que el primario atraviesa bastante cambio de datos (o al menos alguien tiene una transacción abierta muy larga que tampoco es bueno). Cuanto más tiempo estén abiertas las transacciones y más cambios de datos haya, más versiones se producirán.

Las réplicas secundarias alcanzan un estado legible mediante el uso de aislamiento de instantáneas debajo de las cubiertas de la sesión, aunque si verifica la información de su sesión, verá que se muestra en la lectura predeterminada confirmada. Dado que el aislamiento de instantáneas es optimista y usa el almacén de versiones, todos los cambios deberán ser versionados. Esto se exacerba cuando hay muchas consultas en ejecución (y potencialmente de larga ejecución) en el secundario mientras la rotación de datos es alta en el primario. En general, esto se manifiesta solo en unas pocas tablas para un sistema OLTP, pero depende completamente de la aplicación y la carga de trabajo.

El almacén de versiones en sí se mide en generaciones y cuando se ejecuta una consulta que requiere el uso del almacén de versiones, el puntero del registro de versiones se usa para apuntar a la cadena TempDB de esa fila. Digo cadena, porque es una lista de versiones para esa fila y se debe recorrer la cadena completa secuencialmente para encontrar la versión adecuada en función de la marca de tiempo de inicio de la transacción para que los resultados estén en línea con los datos en ese momento dado.

Si el almacén de versiones tiene muchas generaciones para estas filas debido a transacciones de ejecución prolongada en las réplicas primaria y secundaria, esto provocará tiempos más largos que el promedio para que se ejecuten las consultas y, en general, en forma de CPU más alta, mientras que todos los demás elementos aparentemente permanecen exactamente iguales - como el plan de ejecución, estadísticas, filas devueltas, etc. El recorrido de la cadena es casi una operación puramente de CPU, por lo que cuando las cadenas se vuelven muy largas y la cantidad de filas devueltas es muy alta, obtienes un (no lineal, pero puede estar cerca) aumento en el tiempo para la consulta.

Lo único que se puede hacer es limitar la duración de las transacciones tanto en el primario como en el secundario para asegurarse de que la tienda de versiones no se esté volviendo demasiado grande en TempDB mientras que tenga muchas generaciones. Los intentos de limpiar el almacén de versiones ocurren aproximadamente una vez por minuto, sin embargo, la limpieza requiere que ya no se necesiten todas las versiones de la misma generación antes de que se pueda eliminar y que todas las versiones futuras no se puedan limpiar hasta que la versión más antigua ya no sea necesaria. Por lo tanto, una consulta de larga duración puede causar la incapacidad de limpiar eficazmente muchas generaciones no utilizadas.

Cambiar la réplica dentro y fuera del modo legible también borrará el almacén de versiones, ya que ya no es legible.

Hay otros elementos que también podrían estar en juego, pero este parece ser el más plausible dados los datos actuales y la forma en que reaccionaba la réplica.

DMV de versiones de TempDB (no debe confundirse con las versiones de ADR).

Descargo de responsabilidad: no sé nada acerca de los grupos de disponibilidad, pero sí sé un poco sobre las consultas de resolución de problemas que parecen usar más CPU de lo que deberían.

Tienes un problema de CPU porque estás usando demasiado. Una cosa importante que decir sobre las esperas es que casi todas ellas no están ocupadas por la CPU. Cuando un trabajador entra en un estado de espera, ha cedido y ya no se ejecuta en el planificador en SQLOS. Entonces, si tiene una consulta MAXDOP 1 con las siguientes estadísticas de ejecución:

Tiempo de CPU = 55719 ms, tiempo transcurrido = 56335 ms.

Llegaste a casi el 99% de utilización de la CPU para la consulta. ¿Por qué debería haber estadísticas de espera significativas para esa consulta? Es posible que vea algunos si tiene algunas de las esperas ocupadas de la CPU, como esperas externas o preventivas, pero eso tampoco está garantizado. La conclusión es que las estadísticas de espera pueden no ser tan útiles aquí.

Hay algunas cosas que debe verificar en orden aproximado (el orden depende de lo que sepa sobre el medio ambiente):

• ¿El servidor secundario tiene alguna supervisión costosa en curso, como eventos extendidos, rastreos o perfiles?
• ¿El hardware del servidor secundario coincide aproximadamente con el primario?
• ¿Hay algún problema de configuración o software con el servidor secundario?
• ¿Alguna espera o pestillo significativo? Puede no ser aplicable a su consulta, pero aún puede proporcionar pistas.
• ¿Algún spinlocks significativo?
• ¿Hay otros DMV o cosas que puede verificar en SQL Server que puedan dar pistas? Usted mencionó que los grupos de disponibilidad son probablemente una parte clave del problema.
• ¿Qué te dice el rastreo de ETW?
• ¿Qué tipo de acuerdos de soporte tiene?

La mayor parte de lo anterior está bien cubierto en varias publicaciones de blog y documentación, pero ampliaré el seguimiento de ETW. Si desea saber por qué SQL Server está usando tanta CPU para una consulta en particular y tiene acceso al host, siempre puede hacer un seguimiento de ETW para ver las pilas de llamadas y ver la cantidad de CPU que hacen varias pilas de llamadas. En otras palabras, el sistema operativo host se complace en decirle para qué CPU se está utilizando si sabe cómo preguntar. Los métodos comunes de seguimiento de ETW incluyen Windows Performance Recorder y PerfView .

Darle sentido a esos resultados requiere un profundo conocimiento interno y es fácil llegar a una conclusión incorrecta. En muchos casos, es mejor recopilar los datos sin procesar y pedirles a los expertos que los examinen. Al realizar un seguimiento, desea que se realice la menor actividad posible en SQL Server. A continuación se presentan algunas respuestas publicadas aquí que utilizan el seguimiento de ETW para sacar conclusiones sobre SQL Server:

• ¿Cómo diagnosticar try_parse es muy lento?
• ¿Por qué puede tomar hasta 30 segundos crear un simple grupo de filas CCI?
• ¿Las lecturas lógicas en RAM aparecen en las estadísticas de espera o dónde?
• ¿Por qué NOLOCK hace un escaneo con una asignación de variables más lenta?
• ¿Cuál es el algoritmo detrás del operador EXCEPTO?
• ¿El comando ALTER TABLE sin valor predeterminado tarda una eternidad?
• Datos ordenados implícitamente como si fuera un índice agrupado; ¿Puedo aprovechar eso?

Sospecho que en su caso, si puede recopilar pilas de llamadas mientras se ejecuta la consulta de 45 segundos, obtendrá algunas pistas muy útiles sobre la naturaleza del problema.

Como el problema se resolvió por sí solo, me queda especular sobre su causa (la rima no es intencional). Según la publicación de Sean y el hecho de que una transacción abierta del Almacén de consultas parece haber sido la causa principal de mi mayor tamaño del almacén de versiones (por ejemplo, la causa de las HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGesperas), solo puedo suponer que el Almacén de consultas tuvo una parte en el comportamiento que fue presentado. Esta base de datos es más grande (~ 6TB), bastante activa, y una gran mayoría de las consultas que la alcanzan se generan en el cliente y no se parametrizan (es decir, consultas ad-hoc), por lo que no creo que Query Store se preste a proporcionar mucho uso en este escenario. Debido a eso, deshabilitaremos el Almacén de consultas en este entorno durante una ventana de mantenimiento futuro, después de lo cual sospecho que no volveremos a ver este comportamiento.

Abrimos un ticket con Microsoft, pero el tiempo no estaba a nuestro favor ya que el problema se resolvió antes de que pudiéramos hacer un análisis detallado a través de un seguimiento de PSSDIAG o similar. Espero que puedan hacer algunas pruebas localizadas y replicar este problema en caso de que se trate de un error con el que nos encontramos. Si se identifican más actualizaciones sobre una resolución más permanente, también me aseguraré de actualizar esta respuesta.