SQL: ¿Qué está ralentizando INSERT si no es CPU o IO?

19

Tenemos una base de datos para un producto que es pesado para escribir. Acabamos de comprar una nueva máquina servidor con un SSD para ayudar. Para nuestra sorpresa, las inserciones no fueron más rápidas que en nuestra vieja máquina con un almacenamiento mucho más lento. Durante la evaluación comparativa, notamos que la tasa de E / S exhibida por el proceso de SQL Server era muy baja.

Por ejemplo, ejecuté el script que se encuentra en esta página , excepto que agregué un BEGIN TRAN y COMMIT alrededor del ciclo. En el mejor de los casos, pude ver que el uso del disco alcanza los 7Mb / s, mientras que la CPU apenas alcanzó el 5%. El servidor tiene 64 Gb instalados y está utilizando 10. El tiempo total de ejecución fue de 2 minutos y 15 segundos para la primera llamada, hasta alrededor de 1 minuto para las siguientes. La base de datos está en recuperación simple y estaba inactiva durante la prueba. Dejé caer la mesa entre cada llamada.

¿Por qué un script tan simple es tan lento? El hardware apenas se está utilizando en absoluto. Tanto las herramientas dedicadas de evaluación comparativa de disco como SQLIO indican que el SSD funciona correctamente con velocidades superiores a 500 Mb / s tanto para lectura como para escritura. Entiendo que las escrituras aleatorias son más lentas que las escrituras secuenciales, pero esperaría que una inserción simple como esta, en una tabla sin indexación agrupada, sea mucho más rápida.

En última instancia, nuestro escenario es mucho más complejo, pero siento que primero necesito entender un caso simple. En pocas palabras, nuestra aplicación elimina datos antiguos, luego usa SqlBulkCopy para copiar datos nuevos en tablas de preparación, realiza algunos filtros y finalmente usa MERGE y / o INSERT INTO dependiendo de los casos para copiar los datos en las tablas finales.

-> EDITAR 1: Seguí el procedimiento vinculado por Martin Smith, y obtuve el siguiente resultado:

[Wait Type]  [Wait Count] [Total Wait (ms)] [T. Resource Wait (ms)] [T. Signal Wait (ms)]
NETWORK_IO          5008              46735                 46587        148
LOGBUFFER           901               5994                  5977         17
PAGELATCH_UP        40                866                   865          1
SOS_SCHEDULER_YIELD 53279             219                   121          98
WRITELOG            5                 145                   145          0
PAGEIOLATCH_UP      4                 58                    58           0
LATCH_SH            5                 0                     0            0

Encuentro extraño que NETWORK_IO toma la mayor parte del tiempo, considerando que no hay resultados para mostrar y que no hay datos para transferir a ningún otro lugar que no sea a los archivos SQL. ¿El tipo NETWORK_IO incluye todas las IO?

-> EDIT 2: creé un disco RAM de 20 Gb y monté una base de datos desde allí. El mejor tiempo que tuve en el SSD fue de 48 segundos, con el disco RAM bajó a 37 segundos. NETWORK_IO sigue siendo la mayor espera. La velocidad máxima de escritura en el disco RAM era de aproximadamente 250 Mb / s, mientras que es capaz de hacer varios gigabytes por segundo. Todavía no estaba usando mucha CPU, entonces, ¿qué está retrasando SQL?

Djof
fuente
1
Puede usar el script aquí para capturar las estadísticas de espera de un spid específico . Yo también agregaría SET NOCOUNT ONa eso.
Martin Smith
3
el NETWORK_IOpodría ser del 3 millones "1 fila (s) afectadas" mensajes que están siendo enviados de vuelta. ¿Intentaste agregar SET NOCOUNT ONal script?
Martin Smith
Sí, agregué el NOCOUNT.
Djof
2
Extraño. No esperaría mucho de la actividad de la red en absoluto. ¿Eliminó los viejos archivos de eventos extendidos entre ejecuciones? El script que los lee utiliza un comodín para EE_WaitStats*.xelque los viejos contaminen sus resultados.
Martin Smith
Buena llamada, actualizaré los resultados mañana.
Djof

Respuestas:

9

Sé que es una vieja pregunta, pero esto podría ayudar a los buscadores y es un problema que aparece de vez en cuando.

La razón principal por la que está alcanzando un límite de rendimiento sin ver ningún cuello de botella de recursos es porque ha alcanzado el límite de lo que es posible procesar dentro de un solo hilo de sesión. El bucle no se procesa en paralelo, pero todas las inserciones se realizan en serie.

En mi caso, lleva 36 segundos insertar 3 millones de filas. Eso significa 36/30000000 = 0.000012 segundos por fila. Eso es bastante rápido En mi sistema, simplemente se necesita 0.000012 para seguir todos los pasos necesarios.

La única forma de hacerlo más rápido es iniciar una segunda sesión en paralelo.

Si comienzo 2 sesiones en paralelo, ambas hacen 15 millones de inserciones. Ambos terminan en 18 segundos. Podría escalar más, pero mi configuración de prueba actual está llegando al 95% de la CPU con dos sesiones paralelas, por lo que hacer 3 sesgaría los resultados ya que golpearía un cuello de botella de la CPU.

Si comienzo 2 sesiones paralelas, ambas insertando 3 millones de filas, ambas terminan en 39 segundos. así que ahora son 6 millones de filas en 39 segundos.

Bien, eso todavía nos deja con la espera de NETWORK_IO.

Las esperas NETWORK_IO se agregan por el hecho de que está utilizando eventos extendidos para rastrearlos. En mi caso, la inserción tarda 36 segundos (en promedio). Cuando se utiliza el modo de evento extendido (desde el enlace anterior en el primer comentario), esto es lo que se registra:

Wait Type             Wait Count  Total Wait Time (ms) Total Resource Wait Time (ms) Total Signal Wait Time (ms)
NETWORK_IO            3455        68808                68802                         6
PAGEIOLATCH_SH        3           64                   64                            0
PAGEIOLATCH_UP        12          58                   58                            0
WRITE_COMPLETION      8           15                   15                            0
WRITELOG              3           9                    9                             0
PAGELATCH_UP          2           4                    4                             0
SOS_SCHEDULER_YIELD   32277       1                    0                             1
IO_COMPLETION         8           0                    0                             0
LATCH_SH              3           0                    0                             0
LOGBUFFER             1           0                    0                             0

Puede ver que 68 segundos de NETWORK_IO están registrados. Pero como el bucle de inserción es una acción de subproceso único que tardó 36 segundos, esto no puede ser. (Sí, se utilizan varios subprocesos, pero las operaciones son seriales, nunca en paralelo, por lo que no puede acumular más tiempo de espera que la duración total de la consulta)

Si no uso eventos extendidos, sino solo los DMV de estadísticas de espera en una instancia silenciosa (solo yo ejecutando el inserto) obtengo esto:

Wait Type                   Wait Count  Total Wait Time (ms)  Total Resource Wait Time (ms) Signal Resource Wait Time (ms)
SOS_SCHEDULER_YIELD             8873                 0.21                                    0.01                                    0.20
PAGEIOLATCH_UP                  3                    0.02                                    0.02                                    0.00
PREEMPTIVE_OS_AUTHENTICATIONOPS 17                   0.02                                    0.02                                    0.00
PAGEIOLATCH_SH                  1                    0.00                                    0.00                                    0.00

Por lo tanto, el NETWORK_IO que estaba viendo en el registro extendido de eventos no estaba relacionado con su ciclo de inserción. (Si no activara el conteo, tendría una red asíncrona masiva IO espera, +1 Martin)

Sin embargo, no sé por qué NETWORK_IO aparece en el seguimiento de eventos extendido. Seguro que la escritura en un destino de archivo asíncrono de los eventos acumula ASYNC_NETWORK_IO, pero seguramente todo esto se hace en un SPID diferente al que estamos filtrando. Podría hacer esto como una nueva pregunta yo mismo)

Edward Dortland
fuente
1
"está alcanzando un límite de rendimiento sin ver ningún cuello de botella de recursos porque ha alcanzado el límite de lo que es posible procesar dentro de un solo hilo de sesión": está describiendo un cuello de botella del 100% de la CPU (en un núcleo). Si no hay un cuello de botella, entonces el sistema se vaya más rápido, así que algo más debe estar en juego.
Remus Rusanu
Tu respuesta es muy informativa, Edward. Parece que el paralelismo es la solución a nuestro problema en el que ya estamos trabajando, aunque requiere cambios en el diseño de nuestra base de datos. Sin embargo, al igual que Remus, todavía tengo curiosidad por saber por qué la máquina no parece usar todos (de uno) recursos de CPU o disco.
Djof
9

Por lo general, comienza mirando sys.dm_exec_requests, específicamente en wait_time, wait_typey wait_resourcepara su (s) solicitud (es) INSERT. Esto le dará una indicación clara de lo que está bloqueando su INSERT. Los resultados indicarán si es contención de bloqueo, eventos de crecimiento de archivos, esperas de descarga de registros, contención de asignación (se manifiesta como contención de bloqueo de página PFS), etc., etc. Una vez que realice la medición, actualice su pregunta en consecuencia. Le recomiendo encarecidamente que se detenga ahora y lea la metodología de solución de problemas de colas y esperas antes de continuar.

Remus Rusanu
fuente
3

Ejecuté el script de prueba en la página vinculada en el OP con BEGIN TRAN / COMMIT alrededor del ciclo. En mi máquina, tardé 1:28 en completarse la primera vez.

Luego moví estos dos comandos fuera del bucle:

SELECT @Random = ROUND(((@Upper - @Lower -1) * RAND() + @Lower), 0)
SET @InsertDate = DATEADD(dd, @Random, GETDATE())

Se completó en 28 segundos después de eso.

No estoy seguro de lo que está sucediendo, pero supongo que podría haber un sueño de algún tipo en el RAND() código, tal vez como parte del algoritmo que están utilizando para generar entropía (mejores números aleatorios).

FWIW, los SSD no siempre son la mejor tecnología para aplicaciones con gran capacidad de escritura. Para obtener el mejor rendimiento, asegúrese de que el registro de la base de datos esté en una letra de unidad diferente de los datos de la base de datos, el archivo de registro se haya desarrollado previamente hasta su tamaño máximo y nunca trunque el registro.

RickNZ
fuente
Gracias por tu aporte RickNZ. No obtuve resultados más rápidos al mover el código fuera del bucle. Espere que haya observado es que si lo ejecuta varias veces se vuelve más rápido, eso podría ser lo que experimentó. Sé que los SSD no son balas de plata, pero todavía siento que el rendimiento no es lo que podría ser.
Djof
1

Otro DMV que utilizo para identificar la lentitud es sys.dm_os_waiting_tasks . Si su consulta no requiere mucha CPU, puede encontrar más información sobre las esperas de este DMV.

StanleyJohns
fuente
0

Estoy revisando la lista de eventos de espera para sql 2008 y no veo NETWORK_IO en la lista: http://technet.microsoft.com/en-us/library/ms179984(v=sql.100).aspx

Pensé que NETWORK_IO ahora solo figuraba como ASYNC_NETWORK_IO, por lo que quería preguntarle si podía verificar su versión de SQL nuevamente, porque simplemente tengo curiosidad sobre cómo / por qué aparece ese evento de espera para esa versión.

En cuanto a la espera de la red, sí, eso puede suceder incluso si está trabajando en un servidor independiente. ¿Ha verificado la configuración de sus tarjetas de red? Me pregunto si son un problema.

Al final del día, solo hay algunos cuellos de botella de recursos posibles: memoria, CPU, E / S de disco, red y bloqueo. Ha indicado que la CPU y la E / S no son el problema, y ​​tiene un evento de espera de NETWORK_IO, por lo que le sugiero que primero mire esas tarjetas NIC.

SQLRockstar
fuente
1
El NETWORK_IOse muestra porque el OP está utilizando eventos extendidos. Nunca se actualizó ensys.dm_xe_map_values
Martin Smith
Estoy pensando en el mismo SQLRockstar, justo lo que podría estar pasando. Intenté deshabilitar las tarjetas de red por completo. Martin señaló que algunos archivos antiguos aún podrían estar allí. Actualizaré los resultados mañana para ver si cambia algo.
Djof
Además, podría ayudar si pudiéramos ver los planes de ejecución de las declaraciones.
SQLRockstar