Búsqueda interminable en la tienda de consultas

10

Voy a decir desde el principio que mi pregunta / problema es similar a esta anterior, pero ya no estoy seguro de si la causa o la información de partida es el mismo, decidí publicar mi pregunta con algunos detalles más.

Tema en cuestión:

  • a una hora extraña (cerca del final del día laboral) una instancia de producción comienza a comportarse de manera errática:
    • CPU alta para la instancia (desde una línea base de ~ 30% fue casi el doble y todavía estaba creciendo)
    • mayor número de transacciones / segundo (aunque la carga de la aplicación no ha visto ningún cambio)
    • mayor número de sesiones inactivas
    • eventos de bloqueo extraños entre sesiones que nunca mostraron este comportamiento (incluso leer sesiones no confirmadas causaban bloqueo)
    • las esperas superiores para el intervalo no fueron el cierre de la página en el primer lugar, con los bloqueos en el segundo lugar

Investigación inicial:

  • usando sp_whoIsActive vimos que una consulta ejecutada por nuestra herramienta de monitoreo decide ejecutarse extremadamente lento y tomar mucha CPU, algo que no sucedió antes;
  • su nivel de aislamiento fue leído no comprometido;
  • miramos el plan, vimos números extravagantes: StatementEstRows = "3.86846e + 010" con unos 150 TB de datos estimados que se devolverán
  • sospechamos que la función de monitoreo de consultas de la herramienta de monitoreo era la causa, por lo que deshabilitamos la función (también abrimos un ticket con nuestro proveedor para verificar si están al tanto de algún problema)
  • desde ese primer evento, sucedió unas cuantas veces más, con cada vez que cerramos la sesión, todo vuelve a la normalidad;
  • nos damos cuenta de que la consulta es extremadamente similar a una de las consultas utilizadas por MS en BOL para el monitoreo del Almacén de consultas: consultas que recientemente regresaron en rendimiento (comparando diferentes puntos en el tiempo)
  • ejecutamos la misma consulta manualmente y vemos el mismo comportamiento (la CPU se usa cada vez más, aumentando las esperas de bloqueo, bloqueos inesperados, etc.)

Consulta culpable:

Select qt.query_sql_text, 
    q.query_id, 
    qt.query_text_id, 
    rs1.runtime_stats_id AS runtime_stats_id_1,
    interval_1 = DateAdd(minute, -(DateDiff(minute, getdate(), getutcdate())), rsi1.start_time), 
    p1.plan_id AS plan_1, 
    rs1.avg_duration AS avg_duration_1, 
    rs2.avg_duration AS avg_duration_2,
    p2.plan_id AS plan_2, 
    interval_2 = DateAdd(minute, -(DateDiff(minute, getdate(), getutcdate())), rsi2.start_time), 
    rs2.runtime_stats_id AS runtime_stats_id_2
From sys.query_store_query_text AS qt 
Inner Join sys.query_store_query AS q 
    ON qt.query_text_id = q.query_text_id 
Inner Join sys.query_store_plan AS p1 
    ON q.query_id = p1.query_id 
Inner Join sys.query_store_runtime_stats AS rs1 
    ON p1.plan_id = rs1.plan_id 
Inner Join sys.query_store_runtime_stats_interval AS rsi1 
    ON rsi1.runtime_stats_interval_id = rs1.runtime_stats_interval_id 
 Inner Join sys.query_store_plan AS p2 
    ON q.query_id = p2.query_id 
Inner Join sys.query_store_runtime_stats AS rs2 
    ON p2.plan_id = rs2.plan_id 
Inner Join sys.query_store_runtime_stats_interval AS rsi2 
    ON rsi2.runtime_stats_interval_id = rs2.runtime_stats_interval_id
Where rsi1.start_time > DATEADD(hour, -48, GETUTCDATE()) 
    AND rsi2.start_time > rsi1.start_time 
    AND p1.plan_id <> p2.plan_id
    AND rs2.avg_duration > rs1.avg_duration * 2
Order By q.query_id, rsi1.start_time, rsi2.start_time

Configuraciones e información:

  • SQL Server 2016 SP1 CU4 Enterprise en un clúster de Windows Server 2012R2
  • Query Store habilitado y configurado como predeterminado (no se modificó la configuración)
  • base de datos importada de una instancia de SQL 2005 (y aún en el nivel de compatibilidad 100)

Observación empírica:

  • Debido a las estadísticas extremadamente extravagantes, tomamos todos los objetos * plan_persist ** utilizados en el plan estimado incorrecto (todavía no hay un plan real, porque la consulta nunca terminó) y verificamos estadísticas, algunos de los índices utilizados en el plan no tenían ninguna estadística (DBCC SHOWSTATISTICS no devolvió nada, seleccione de sys.stats mostró la función NULL stats_date () para algunos índices

Solución rápida y sucia:

  • crear manualmente estadísticas faltantes en objetos del sistema relacionados con el Almacén de consultas o
  • forzar la ejecución de la consulta utilizando el nuevo CE (traceflag), que también creará / actualizará las estadísticas necesarias o
  • cambie el nivel de compatibilidad de la base de datos a 130 (por lo que, de manera predeterminada, usará el nuevo CE)

Entonces, mi verdadera pregunta sería:

¿Por qué una consulta en Query Store causa problemas de rendimiento en toda la instancia? ¿Estamos en un territorio de errores con Query Store?

PD: Subiré algunos archivos (pantallas de impresión, estadísticas de IO y planes) en breve.

Archivos agregados en Dropbox .

Plan 1 - plan estimado inicial loco en producción

Plan 2 : plan real, CE anterior, en un entorno de prueba (mismo comportamiento, mismas estadísticas extravagantes)

Plan 3 - plan real, nueva CE, en un entorno de prueba

Mariana
fuente
1
Terminamos deshabilitando el almacén de consultas, no estábamos seguros de cuál era la causa raíz (teníamos más de 1 problema seguro). Por mi parte, la CPU aumentaría todo lo que hicimos clic para mostrar estadísticas del almacén de consultas.
A_V

Respuestas:

6

Como dije en la respuesta, la prueba empírica mostró que había índices en los objetos del sistema sys.plan_persisted * sin ninguna estadística (ninguna) creada sobre ellos. Sospecho que se debe a que la base de datos se migra desde una instancia de SQL 2005 y se mantiene durante un tiempo en el nivel de compatibilidad 100, por lo que no se pudo usar el nuevo CE.

Comprobación de recuento de filas:

Select count(1) from NoNameDB.sys.plan_persist_runtime_stats with (nolock) --60362   
Select count(1) from NoNameDB.sys.plan_persist_plan with (nolock) --1853    
Select count(1) from NoNameDB.sys.plan_persist_runtime_stats_interval with (nolock) --671    
Select count(1) from NoNameDB.sys.plan_persist_query with (nolock) --1091    
Select count(1) from NoNameDB.sys.plan_persist_query_text with (nolock) --911

Esto mostró que las estimaciones iniciales estaban equivocadas. Hecho con una conexión DAC, de lo contrario las tablas no están disponibles para consultar.

Verificación de estadísticas:

DBCC SHOW_STATISTICS ('sys.plan_persist_runtime_stats_interval', plan_persist_runtime_stats_interval_cidx);    
DBCC SHOW_STATISTICS ('sys.plan_persist_runtime_stats', plan_persist_runtime_stats_idx1);    
DBCC SHOW_STATISTICS ('sys.plan_persist_runtime_stats', plan_persist_runtime_stats_cidx);    
DBCC SHOW_STATISTICS ('sys.plan_persist_plan', plan_persist_plan_cidx);    
DBCC SHOW_STATISTICS ('sys.plan_persist_plan', plan_persist_plan_idx1);    
DBCC SHOW_STATISTICS ('sys.plan_persist_query', plan_persist_query_cidx)    
DBCC SHOW_STATISTICS ('sys.plan_persist_query_text', plan_persist_query_text_cidx);

Esto mostró que algunos índices tenían estadísticas vacías (faltantes, ninguna, cero).

Arreglo inicial:

UPDATE STATISTICS sys.plan_persist_runtime_stats WITH fullscan;
UPDATE STATISTICS sys.plan_persist_plan WITH fullscan;
UPDATE STATISTICS sys.plan_persist_runtime_stats_interval WITH fullscan;
UPDATE STATISTICS sys.plan_persist_query WITH fullscan;
UPDATE STATISTICS sys.plan_persist_query_text WITH fullscan;

Esto fijó las estadísticas e hizo que la consulta finalizara en 10-12 segundos.

Segunda solución :

(verificado solo en un entorno de prueba) y muy probablemente el adecuado, ya que mostró las mejores estadísticas para la consulta, fue cambiar el nivel de compatibilidad de la base de datos a 130. El resultado final fue que la consulta terminó en aproximadamente 10-12 segundos con Estadísticas de números normales (10k filas).

Corrección intermedia :

DBCC TRACEON (2312) -- new CE

Alguna ayuda relacionada sobre estadísticas en tablas ocultas del sistema.

Mariana
fuente
3

El problema subyacente, que es visible si abre el plan real en SSMS y observa el uso de la CPU (o examina XML), es el nodo 32, un TVF. El culpable de las consultas lentas en el almacén de consultas es el acceso repetido a los TVF en memoria .

Costo de TVF

No importa cuántas filas devuelvan estos TVF, solo la cantidad de veces que se accede a ellas. La solución será lo que puedas hacer para alejar tus planes de leerlos varias veces.

Basado en mi depuración limitada (tanto en habilidades como en tiempo dedicado), mi hipótesis es que la totalidad de la memoria asignada para el componente particular en memoria de los datos del Almacén de consultas se escanea con cada ejecución de TVF. No he podido afectar esta asignación de memoria con sp_query_store_flush_dbo DBCC FREESYSTEMCACHE.

Las soluciones alternativas exitosas hasta ahora incluyen guías de plan, sugerencias ( OPTION(HASH JOIN, LOOP JOIN)ha funcionado lo suficientemente bien para mí hasta ahora) y ejecutar las consultas del Almacén de consultas en un nodo de solo lectura de un AG.

Para descanso
fuente