Es bastante habitual encontrarnos con el siguiente diálogo al aterrizar en un cliente:
- SolidQ: ¿Me puedes comentar o mostrar los gráficos del consumo de CPU del servidor X?
- Cliente: De CPU vamos bien, no es problema.
- SolidQ: Si no te importa, ¿puedes mostrarme los datos que tienes al respecto?
- Cliente: Claro. Mira, aquí puedes ver que tenemos medias (en periodos de 5 minutos) del 60% de CPU y en los momentos de más carga no pasamos del 85% de media. Está correcto, ¿verdad?
El problema de esta aproximación a la hora de interpretar a la utilización de recursos es que, intuitivamente, no solemos ser conscientes de qué implicaciones tienen estos grados de utilización tan altos. No debemos confundir la interpretación respecto a la que tendríamos del % de uso de memoria o del % de uso de disco, que únicamente indican cuanta cantidad de memoria/espacio estamos utilizando, pero no el grado de utilización de dicho recurso.
Para entender mejor la problemática debemos saber que en SQL Server el acceso a la CPU se gestiona mediante schedulers (1 por core) que dan paso a los distintos workers (threads de trabajo) los cuales ejecutan las tareas. Por tanto tenemos un modelo de colas, donde los procesos, threads, etc. que necesitan CPU se encolan esperando a que el recurso esté disponible lo cual hace que el grado de utilización afecte de forma importante a la latencia que sufriremos a la hora de acceder a la CPU. Esta latencia no es lineal respecto a la utilización como intuitivamente podríamos pensar, sino que tiene una componente exponencial por lo que cuando el porcentaje de utilización es elevado pequeños aumentos implican grandes aumentos de latencia:
En general en base a pruebas de estrés, donde se empieza a disparar la latencia cuando el cuello de botella principal es la CPU suele ser a partir del 80% de la utilización. Sin embargo, la medición real del uso de CPU es “traicionera” debido a la muy habitual presencia de HyperThreading (2 cores lógicos por core físico) o del uso de virtualización. En ambos casos es probable que los cores que se presentan para su utilización a SQL Server tengan alguna limitación adicional oculta y no tengan un rendimiento lineal cuando aumenta la carga.
En el caso de HyperThreading la presencia de dos cores lógicos por core físico real causa que cuando las operaciones a realizar no requieren de muchas esperas externas a la CPU (accesos a memoria, por ejemplo) podamos encontrarnos incluso que la capacidad real de proceso sea la mitad de la que el número de cores lógicos indicaría. La propia Intel explica esto en su documentación técnica y explica cómo podemos medir mejor la utilización de sus CPUs (https://software.intel.com/en-us/articles/intel-performance-counter-monitor y https://github.com/opcm/pcm) También tenemos que tener en cuenta otro factor propio de los controles de temperatura y de disipación de los procesadores que entran en juego cuando la carga es elevada. Con porcentajes de uso pequeños, podemos tener frecuencias de trabajo superiores (TurboBoost en nomenclatura de Intel) y trabajar dentro de los límites térmicos del encapsulado mientras que esas frecuencias de trabajo se van modulando a la baja a medida que la utilización va subiendo y con ella la temperatura.
En el caso de la virtualización en muchas ocasiones tenemos que compartir nuestras vCPU con otras máquinas virtuales. Además, tenemos que compartir y potencialmente esperar más de lo deseable en el acceso a otros recursos críticos para la base de datos como es la memoria, el disco, el acceso a la red. etc. Por tanto, en estos casos necesitaremos contextualizar el uso también en base al grado de utilización del host, ya que, si el host está el 85% de uso por ejemplo y nuestra virtual aparentemente solo al 10% “virtual”, estaremos probablemente pagando ya un alto precio en forma de esperas y latencias en el acceso a la CPU física real que tenemos por debajo de la vCPU virtual.
Sin poder realizar pruebas de carga es realmente complicado medir en qué punto puede estar el “codo” real para una carga dada a partir del cual se disparen las latencias y el throughput aumente de forma más lenta. En casos críticos este punto puede estar tan bajo como el 40% y en otras ocasiones puede estar tan alto como el 90%. Lo que queremos dejar claro es que el % de utilización de la CPU es un indicador muy pobre respecto a cómo nos está impactando en nuestra carga las esperas de acceso a la CPU. En el caso de SQL Server debemos contextualizar esta medida de “uso de cpu” a nivel de host con las esperas a nivel de CPU que se registren en los waitstats de la instancia.
Una vez tenemos claro este comportamiento en lo que respecta al acceso a la CPU podemos continuar y exponer una problemática curiosa que nos encontramos en un cliente. En el cliente teníamos un escenario de alto consumo de CPU y nos encontramos una consulta bastante frecuente cuyo tiempo de respuesta pretendíamos mejorar. Para simular el escenario vamos a crear una base de datos de ejemplo donde crearemos una tabla sin índice cluster (un heap) y la rellenaremos con 10 millones de registros:
CREATE DATABASE heaps_Test
GO
USE heaps_Test
GO
CREATE TABLE heap (id INT, d1 DATETIME, c1 VARCHAR(10), c2 VARCHAR(100))
GO
CREATE INDEX ix_id ON heap (id)
GO
CREATE INDEX ix_d1 ON heap (d1)
GO
CREATE INDEX ix_c1 ON heap (c1)
GO
CREATE INDEX ix_c2 ON heap (c2)
GO
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE FUNCTION [dbo].[GetNums](@n AS BIGINT) RETURNS TABLE
AS
RETURN
WITH
L0 AS(SELECT 1 AS c UNION ALL SELECT 1),
L1 AS(SELECT 1 AS c FROM L0 AS A CROSS JOIN L0 AS B),
L2 AS(SELECT 1 AS c FROM L1 AS A CROSS JOIN L1 AS B),
L3 AS(SELECT 1 AS c FROM L2 AS A CROSS JOIN L2 AS B),
L4 AS(SELECT 1 AS c FROM L3 AS A CROSS JOIN L3 AS B),
L5 AS(SELECT 1 AS c FROM L4 AS A CROSS JOIN L4 AS B),
Nums AS(SELECT ROW_NUMBER() OVER(ORDER BY (SELECT NULL)) AS n FROM L5)
SELECT n FROM Nums WHERE n <= @n;
GO
INSERT INTO dbo.heap ( id,
d1 ,
c1 ,
c2
)
SELECT n, CONVERT(DATE,GETDATE()+n/100), REPLICATE(CHAR(n%10+65),n%10), REPLICATE(CHAR(n%60+65),n%100) FROM dbo.[GetNums] (10000000)
Las consultas que queremos analizar su rendimiento son estas dos:
SELECT * FROM heap WHERE id BETWEEN 1 AND 20250 SELECT * FROM heap WHERE d1 BETWEEN GETDATE() AND getdate()+240
En el cliente la tabla en cuestión no disponía de ningún índice, era un heap sin ninguna indexación adicional. Para mejorar el rendimiento de las consultas nos planteamos el uso de índices apropiados lo cual suele otorgar un beneficio de rendimiento importante tanto a nivel de CPU como de tiempo. En este ejemplo para simular el comportamiento “sin índices” forzaremos con index=0 las consultas que queremos que utilicen exclusivamente el heap. Lanzaremos una tanda sin carga en el equipo y otra con carga elevada (>80%). También testearamos el comportamiento de las consultas con caché de datos fría y caché de datos caliente.
-- Cold cache and no CPU load SET STATISTICS TIME ON -- Using indexes DBCC DROPCLEANBUFFERS SELECT * FROM heap WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 94 ms, elapsed time = 888 ms. DBCC DROPCLEANBUFFERS SELECT * FROM heap WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 140 ms, elapsed time = 754 ms. -- Using heap DBCC DROPCLEANBUFFERS SELECT * FROM heap WITH (INDEX=0) WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 1609 ms, elapsed time = 25228 ms. DBCC DROPCLEANBUFFERS SELECT * FROM heap WITH (INDEX=0) WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 1360 ms, elapsed time = 25385 ms.
-- Cold cache and high CPU load -- Using indexes DBCC DROPCLEANBUFFERS SELECT * FROM heap WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 109 ms, elapsed time = 1349 ms. DBCC DROPCLEANBUFFERS SELECT * FROM heap WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 171 ms, elapsed time = 1698 ms. -- Using heap DBCC DROPCLEANBUFFERS SELECT * FROM heap WITH (INDEX=0) WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 1467 ms, elapsed time = 27055 ms. DBCC DROPCLEANBUFFERS SELECT * FROM heap WITH (INDEX=0) WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 1532 ms, elapsed time = 27690 ms.
-- Hot cache and no CPU load SET STATISTICS TIME ON -- Using indexes SELECT * FROM heap WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 47 ms, elapsed time = 400 ms. SELECT * FROM heap WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 94 ms, elapsed time = 517 ms. -- Using heap SELECT * FROM heap WITH (INDEX=0) WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 1061 ms, elapsed time = 526 ms. SELECT * FROM heap WITH (INDEX=0) WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 1264 ms, elapsed time = 685 ms.
-- Hot cache and high CPU load SELECT * FROM heap WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 109 ms, elapsed time = 1349 ms. -- Using indexes SELECT * FROM heap WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 171 ms, elapsed time = 1698 ms. -- Using heap SELECT * FROM heap WITH (INDEX=0) WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 1343 ms, elapsed time = 755 ms. SELECT * FROM heap WITH (INDEX=0) WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 1173 ms, elapsed time = 736 ms.
Viendo los resultados en formato de texto se nos puede escapar algo curioso. Veámoslos con unos gráficos, primero el gráfico del consumo de CPU:
Podemos ver que el consumo de CPU es más o menos similar en todos los casos, siendo menor en el caso de caché caliente y baja carga de CPU. Las diferencias más sustanciales ocurren en el caso de los scans que con caché caliente consumen menos CPU al no tener que perder tanto tiempo manejando entrada/salida. Lo curioso aparece cuando observamos los tiempos de ejecución:
Podemos ver que, en el escenario particular de alto uso de CPU con caché caliente, realizar la búsqueda en el índice está siendo bastante perjudicada en lo que a duración se refiere respecto a hacer un scan. Esta penalización es la que nos encontramos en el caso que estamos tratando y nos sorprendió a priori bastante que empeorara tanto el tiempo (el doble más o menos) solo por el hecho de haber añadido un índice.
El siguiente paso es analizar los planes de ejecución para ver con más detalle qué está ocurriendo exactamente. Nos centraremos únicamente en el escenario que nos genera el problema al compararlo con el scan, es decir el escenario, con caché caliente y alta carga de CPU. Debemos tener en cuenta que, probablemente, este escenario sea el que más se aleje del entorno “ideal” en base al cual se generan los planes de ejecución. Al generar el plan de ejecución SQL Server presupone que no va a tener limitaciones de CPU importantes por concurrencia (otra cosa distinta es que en tiempo de ejecución puede hacer algunos ajustes, como el grado de paralelismo efectivo a utilizar) y también que el plan de ejecución debe ser bueno en el caso de dato frío. Es decir que se intenta generar un plan de ejecución que en caso de caché fría no sea muy ineficiente, presuponiendo que si el dato está caliente el rendimiento será igual o mejor.
El plan de ejecución que obtenemos es el siguiente:
Si observamos un poco más las propiedades de los operadores vemos que, aunque no estamos solicitando el resultado ordenado, se está solicitando devolver el dato ordenado al índice:
Si nos fijamos en el operador nested loop vemos que tenemos un flag de “optimized” y que además, más allá del Bmk1000 (es el bookmark, el identificador físico de donde está ubicada la fila), se añade una expresión extra en la outer reference:
Por tanto, lo que estamos viendo es que fruto de una optimización del nested loop se están solicitando los datos ordenados y además se está añadiendo una expresión extra, un “filtro extra” en el cruce entre el resultado de la búsqueda. También vemos que en el operador se está utilizando un prefetch de datos a la hora de leer los datos del heap. Pensemos que en la parte outer del loop join normalmente el read-ahead es suficiente para tener en memoria las páginas necesarias incluso en caso de caché fría. Sin embargo, en el caso de la parte inner join, la cosa se complica y lo que busca este prefetching es, de forma asíncrona, intentar traer páginas que pueden llegar a ser necesarias posteriormente en la ejecución pero no lo sabemos con certeza en ese momento. Es en este punto donde entra en juego el filtro de la expr1007 que nos asegurará que, aunque hagamos prefetch y traigamos algun dato extra, este nunca terminará devolviéndose en la query final.
En definitiva, tenemos dos mecanismos de optimización funcionando de forma simultánea para intentar que la ejecución sea lo más rápida posible pero que, en este escenario particular de caché caliente y CPU elevada, tiene el efecto contrario. Si lo pensamos bien, el prefetching (Nested Loops Prefetching) en caché caliente no tiene sentido alguno y la preordenación (Nested Loops Implicit Batch Sort) tampoco. Como en muchas otras ocasiones, existen trace flags que nos permiten habilitar o deshabilitar algunas optimizaciones de forma que podamos comprobar si en nuestro escenario concreto son beneficiosas o no. Concretamente el trace flag 2340 deshabilitará la optimización Nested Loops Implicit Batch Sort y el trace flag 8744 deshabilita el Nested Loops Prefetching.
Vamos a comprobar cómo se comporta esta consulta cuando deshabilitamos alguna de estas optimizaciones en este escenario particular. Comenzamos deshabilitando el prefetching:
-- Disable prefetch DBCC TRACEON(8744,-1) DBCC FREEPROCCACHE -- Hot cache and high CPU load SELECT * FROM heap WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 93 ms, elapsed time = 424 ms. SELECT * FROM heap WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 125 ms, elapsed time = 473 ms.
Podemos ver cómo al deshabilitar el prefetching las duraciones bajan a valores similares a los que teníamos cuando la carga de CPU no era elevada. A nivel del plan de ejecución el único cambio visible que tenemos es en las propiedades donde vemos que desaparece la expresión Expr1007 y la propiedad “WithUnorderedPrefech” desaparece:
Si adicionalmente habilitamos el trace flag 2340 veremos cómo desaparece la optimización Implicit Batch Sort y por tanto ya nos aparecerá “Optimized=false” en el operador:
-- Disable prefetch & implicit batch sort DBCC TRACEON(8744,-1) DBCC TRACEON(2340,-1) DBCC FREEPROCCACHE -- Hot cache and high CPU load SELECT * FROM heap WHERE id BETWEEN 1 AND 20250 --SQL Server Execution Times: -- CPU time = 47 ms, elapsed time = 423 ms. SELECT * FROM heap WHERE d1 BETWEEN GETDATE() AND getdate()+240 --SQL Server Execution Times: -- CPU time = 78 ms, elapsed time = 466 ms.
Aunque las duraciones tras deshabilitar esta optimización no varían prácticamente sí apreciamos que el consumo de CPU baja a 47ms y 78ms respecto a los 93ms y 125ms que teníamos por lo que el plan es más eficiente a nivel de CPU. Esto es algo que normalmente es bastante insignificante, pero si pensamos en pruebas de rendimiento o stress como TPC-E, puede ser la diferencia entre un buen resultado y uno excelente. Por poner un ejemplo podemos ver como concretamente el trace flag 8744 se ha utilizado en alguno de los resultados TPC-E recientes basados en SQL Server 2017:
También vemos que para este TPC-E en particular se está utilizando el trace flag 652 que desactiva el prefetching:
Trace flag 652: Disable page pre-fetching scans
Trace flag 652 disables page pre-fetching during scans. You can turn on trace flag 652 at startup or in a user session. When you turn on trace flag 652 at startup, the trace flag has global scope. When you turn on trace flag 652 in a user session, the trace flag has session scope. If you turn on trace flag 652, SQL Server no longer brings database pages into the buffer pool before these database pages are consumed by the scans. If you turn on trace flag 652, queries that benefit from the page pre-fetching feature exhibit low performance.
La conclusión de este post es que, aunque un comportamiento en un principio puede no tener explicación o no tener sentido al final si seguimos tirando del hilo y bajando a bajo nivel es posible encontrar “el culpable”. Desgraciadamente no siempre tenemos tiempo de poder realizar este tipo de pruebas y análisis “insitu” y es por ello que aprovechamos este blog para poder exponerlas con más detalle. No olvidemos que el uso de este tipo de trace flags de forma indiscriminada no está recomendado, ya que sin prefetching algunas consultas con caché fría y nested loop podrían eternizarse. Por suerte cada vez SQL Server permite aplicar más trace flags a nivel de consulta con la opción QUERYTRACEON lo cual nos permite poder ser muy granulares cuando necesitamos que un trace flag afecte únicamente a una consulta.
