Tell Me Where To Go: Estudio de Consultas AdHoc en SQL Server

Uno de mis temas favoritos a la hora de dar charlas de rendimiento de SQL Server es el estudio de la cache de planes de ejecución y la presencia de consultas AdHoc. Puedo pasarme horas hablando sobre ello, y contando batallitas… muy a pesar de los pobres asistentes que deben acabar hasta las narices de las consultas AdHoc, de mí, y de mi santa madre 🙂

Pero no nos engañemos, si me apasiona tanto este tema es porque se trata de un aspecto muy importante de la salud del servidor y de las aplicaciones que le atacan. Y, además, resulta muy fácil comprobar si estamos sufriendo algún problema relacionado con la presencia masiva de consultas AdHoc en el sistema.

Lo curioso es que, a pesar de lo mucho que me gusta y lo importante que es el tema, no le he hecho justicia con artículos en este blog. Y con esto no quiero decir que no haya escrito acerca de ello; aquí podéis encontrar una breve descripción del ciclo de vida de las consultas en SQL Server, y aquí podéis leer sobre la opción de optimización para cargas de trabajo AdHoc en SQL Server 2008.

Sin embargo, creo que nunca he explicado como procedo a estudiar el estado de salud de la cache de planes de ejecución y procedimientos almacenados, así que espero redimirme un poquito con esta entrada.

NOTA: En esta entrada no voy a explicar el qué son las consultas AdHoc, ni el por qué pueden resultar perniciosas desde el punto de vista del rendimiento. Para esta explicación os recomiendo revisar los dos enlaces que os he puesto un poco más arriba. En esta ocasión solo me centraré en el proceso de estudio de estas consultas.

Vistazo General

Una de las maneras más rápidas y cómodas de comprobar si tenemos una elevada presencia de consultas AdHoc en el sistema es mediante los informes del SQL Server Management Studio (SSMS).

Aunque parezca mentira, voy a dedicar un par de párrafos y capturas de pantalla a detallar como localizar estos informes. Con el paso de los años y las charlas es ido aprendiendo que, curiosamente, estos informes son tan potentes como desconocidos. Lo más habitual es que más de la mitad de los asistentes a mis sesiones desconozcan la existencia de los mismos, por lo que aprovecho para presentarlos a quienes aún no los conozcáis.

Dentro de la interfaz del SSMS, y más concretamente, en el menú pop-up (el del botón derecho del ratón) de todos los nodos del Object Explorer, tenemos una opción llamada Reports.

image

Esta opción es contextual: vamos a tener informes a nivel de instancia, a nivel de base de datos, de usuarios, etc. Evidentemente, hay ciertos tipos de nodos que no tienen ningún informe predefinido, pero siempre podríamos crearnos informes personalizados incluso para los nodos vacíos; son simples ficheros RDLC.

Si bien en esta caso solo vamos a trabajar con un informe concreto, os recomiendo encarecidamente que os deis una vuelta por los informes que vienen predefinidos (Standard Reports), y especialmente por los definidos sobre el nodo de instancia y los definidos sobre los nodos de bases de datos específicas.

En esta caso concreto, nos interesa un informe llamado Server Dashboard, que se encuentra a nivel de instancia. Por tanto, para llegar a él, pinchamos con el botón derecho sobre el nodo de la instancia. Ahí vámos a Reports –> Standard Reports –> Server Dashboard.

NOTA: Esto habituado a trabajar con la versión del producto en inglés, por lo que me vais a perdonar que los pantallazos estén en este idioma, y que no realice las traducciones pertinentes.

image

Como su propio nombre indica, este informe nos muestra un vistazo general del servidor, con la configuración del mismo, versiones del producto, detalles de actividad, etc. Y, cómo no, también nos deja ver un par de gráficas de tarta que alegran el informe con su vivos colores 😛

Estas gráficas muestran el porcentaje de utilización de CPU y de E/S por parte de cada una de las bases de datos del sistema, algo bastante útil para detectar si alguna de las bases de datos está monopolizando los recursos del sistema.

A continuación os muestro, a modo de ejemplo, un pantallazo del informe en mi máquina local:

image

Si os fijáis, las tareas que más CPU están empleando en mi entorno no son relacionadas con ninguna de las bases de datos presentes (msdb, PerfDW, ReportServer y db_ProcedimientosAdministrativos), sino con tareas AdHoc.

Como podéis ver, un rápido vistazo a este informe nos muestra que podríamos estar experimentando un problema de consultas AdHoc en el sistema, ya que el consumo de CPU de las consultas AdHoc muy es elevado. ¿Quiere esto decir que si en la gráfica no aparece un gran consumo de CPU o E/S por consultas AdHoc, estamos libres del problema?

… pues va a ser que no 🙂

Cierto es… aunque tengamos muy poca presencia de consultas AdHoc en el diagrama, es posible que las consultas de este tipo sean un problema en nuestro sistema. Desde aquí, haciendo un pequeño esfuerzo, puedo escuchar vuestras voces de incredulidad en la distancia:

– ¡¿Cómo es posible?! (…se oyen las voces desde más alla del Manzanares…)
– Das ist Unglaublich!! (…algun avezado lector desde la puerta de Brandemburgo…)
– Cómo ye, ¡ho! (…estremecedores palabras que oigo entre Mieres y La Moreda…)

¡Muy fácil! Puede ser que el sistema tenga miles de consultas AdHoc, muy livianas, cuya ejecución no es costosa ni en CPU ni en E/S, pero sin embargo genera presión por recompilación, etc.

Entrando en Detalle

Vale, ya sabemos que puede ser necesario investigar un poco más ¿Cómo podemos hacerlo? Yo recomiendo empezar por comparar el ratio entre consultas AdHoc y consultas No AdHoc. A continuación os pongo un ejemplo capturado de un cliente en el que he estado recientemente:

SELECT
   COUNT(*)
FROM sys.dm_exec_cached_plans
WHERE objtype LIKE ‘Adhoc’

En el caso concreto de este servidor, esta consulta ha devuelto 15636 planes adhoc. ¡No es precisamente un número pequeño de planes de ejecución en la cache! Vamos a ver ahora cuantos planes de ejecución no adhoc hay en la cache:

SELECT
   COUNT(*)
FROM sys.dm_exec_cached_plans
WHERE objtype NOT LIKE ‘Adhoc’

La consulta anterior nos indica que hay 706 planes de ejecución de consultas no AdHoc. Evidentemente, el ratio entre unas y otras es extremadamente preocupante, y signo evidente de que el sistema está generando constantemente consultas AdHoc.

NOTA: Es difícil dar reglas a seguir en estos casos, pero generalmente puedo decir que si detecto que más del 30% de las consultas de la cache son de tipo AdHoc, considero que hay un problema que investigar respecto a la generación y parametrización de las consultas.

El siguiente paso sería detectar la memoria empleada en planes reutilizados, y en planes no reutilizados, y catalogarlos apropiadamente. En este caso yo utilizo un script, basado en el excelente trabajo de Davide Mauri, que me viene de perlas en estos casos:

WITH Planes AS
(
    SELECT
        Reutilizado = CASE
                        WHEN usecounts > 1 THEN ‘Plan Reutilizado (Mb)’
                        ELSE ‘Plan No Reutilizado (Mb)’
                      END,
        size_in_bytes AS [Tamaño (Mb)],
        cacheobjtype AS TipoObjetoCache,
        objtype AS Tipo
    FROM
        sys.dm_exec_cached_plans
),
Agregado AS
(
    SELECT
        Reutilizado,
        Tipo,
        TipoObjetoCache,
        [Tamaño (Mb)] = SUM([Tamaño (Mb)] / 1024. / 1024.)
    FROM
        Planes
    GROUP BY
        Reutilizado,
        TipoObjetoCache,
        Tipo
),
Pivote AS
(
    SELECT *
    FROM
        Agregado a
        PIVOT
        ( SUM([Tamaño (Mb)]) FOR Reutilizado IN ([Plan Reutilizado (Mb)], [Plan No Reutilizado (Mb)]) ) p
)
SELECT
    Tipo,
    TipoObjetoCache,
    [Tamaño Reutilizado (Mb)] = SUM([Plan Reutilizado (Mb)]),
    [Tamaño No Reutilizado (Mb)] = SUM([Plan No Reutilizado (Mb)])
FROM
    Pivote
GROUP BY
    Tipo,
    TipoObjetoCache
    WITH ROLLUP
HAVING
    (Tipo IS NULL AND TipoObjetoCache IS NULL ) OR
    (Tipo IS NOT NULL AND TipoObjetoCache IS NOT NULL )

Volviendo al caso de mi cliente, la ejecución de esta consulta devolvió los siguientes resultados:

image

Como podéis comprobar, en este caso el tamaño no reutilizado es casi similar al listado para los planes reutilizados, lo cual es otro indicativo claro de que hay un gran problema de no reutilización de planes de ejecución debido a consultas AdHoc mal parametrizadas.

Después de comprobar que realmente estamos sufriendo el problema ¿cual sería mi siguiente paso? Pues el más divertido de todos… ¡buscar al culpable! 😉

Para ello, buscaría las consultas que aparecen en la cache, de tipo AdHoc, y cruzaría la vista con la funcion sys.dm_exec_sql_text para poder sacar el texto de la SQL a partir del handle:

SELECT
   refcounts,
   size_in_bytes,
   cacheobjtype,
   text
FROM
   sys.dm_exec_cached_plans
   CROSS APPLY sys.dm_exec_sql_text(plan_handle)
WHERE objtype LIKE ‘Adhoc’

Os muestro una salida parcial para que veais el problema (sin mostrar toda la consulta y revelar parte del modelo de datos de mi cliente, evidentmente):

image

Como se puede ver, las consultas son iguales, variando exclusivamente en los parámetros; el hecho de que sigan recompilandose y no se reutilicen es significativo, y un potencial problema de rendimiento (como ya se comentó en los otros posts).

¡Ya tenemos nuestros culpables! ¡¡Yeah!!

Resumiendo

A modo de resumen, yo abordaría el estudio del siguiente modo:

  1. Revisión del informe Server Dashboard para buscar presencia de consultas AdHoc
  2. Consulta sobre sys.dm_exec_cached_plans para ver el ratio AdHoc/No AdHoc
  3. Consulta para ver la memoria fugada en planes no reutilizados
  4. Si procede, revisar las consultas problematicas.

Fácil, sencillo y para toda la familia 🙂

Después de ver esta información, tendremos una buena idea de si estamos siendo víctimas de algún tipo de problema derivado de la presencia masiva de consultas AdHoc en nuestro sistema. Si fuera así, habrá que comprobar la presencia de consultas dinámicas sin preparar, consultas sin parametrizar desde el cliente, etc.

Espero que os haya resultado interesante la entrada, y os animo a que probéis en vuestros servidores SQL Server: ¡seguro que más de uno de vosotros se lleva una sorpresa!

Rock Tip:

Los últimos rock tips, si bien han sido temazos, se han alejado un poco de mi corazoncito hardrockero ochentero, así que es buen momento de retomarlo. Y para ocasiones especiales, nada mejor que los grandísimos glam-metaleros noruegos Wig Wam.

Representantes de su país en el festival de Eurovisión de 2005, con el temazo ‘In My Dreams’, en esta ocasión nos quedamos con su balada ‘Tell Me Where To Go’ para acompañar este post.

A todo esto, apuntaros esta fecha en vuestros calendarios: 18 de Septiembre de 2010. Ese será el día que los chicos de WigWam nos visitarán en Madrid por primera vez, en la sala Ritmo y Compás ¡No creí que mis ojos fueran a ver esto! Ya solo queda ver por estas tierras a Steel Panther y seré un hombre plenamente feliz 🙂

I Know You’re Here: Materiales de Optimizacion de SQL Server en el CIIN

Aquí os dejo los materiales de la sesión de optimización de SQL Server que tuve la suerte de dar el pasado viernes en tierras cántabras, gracias a la invitación de los chicos del CIIN.

Quiero aprovechar para dar las gracias también a todos los asistentes por las interesantes preguntas y la atención a lo largo de una sesión de más de 5 horas… sé que es duro, y más aún en viernes y, sobre todo, siendo el primer día de las fiestas de Santander! 🙂

Para los que no hayáis podido ver la sesión el viernes ni presencialmente ni a través de LiveMeeting, pero tengáis interés en la optimización de SQL Server, os dejo aquí el enlace al evento grabado para que lo podáis descargar y ver tranquilamente a vuestro ritmo.

Si se me quedó alguna pregunta por responder, o tenéis más dudas, no dejéis de consultármelas a través del blog o de mi dirección de email!

Rock Tip:

I Know You’re Here”, del grandísimo Steve Vai, es el tema que he escogido en esta ocasión como Rock Tip. Más que nada porque siempre es un placer ver que la gente sacrifica su tiempo personal por acudir a los eventos de la comunidad, por intentar aprender y compartir. Porque sé que siempre estáis ahi, por eso me pareción un Rock Tip apropiado 😉

¡¿Que decir de Steve Vai?! Creo que a todos los que nos gusta la música y nos apasiona la guitarra nos proporciona el mismo feeling: envidia cochina! XD Sus creaciones te pueden gustar más o menos, pero su estilo, su técnica y su virtuosísmo no te van a dejar indiferente. Como lo describiera Brian May en el concierto de leyendas de la guitarra, en Sevilla en 1991: “.. el genio, el maestro de la guitarra de la era espacial.. mr. Steve Vai”. Ahí es nada.

Pinball Map: Cuidado con los Mapeos en NHibernate

Ermm… si, chicos y chicas, sonará raro, pero hoy voy a hablar de NHibernate. Sé que me arriesgo a la condenación eterna en las llamas del infierno, pero yo soy así de altruista y me la juego por vosotros! 😉

Uno de los clientes con los que he estado esta semana(*) estaba experimentando problemas de rendimiento en el acceso a datos en su aplicación, sospechando que el causante pudiera ser una vista poco optimizada. Afortunadamente, el cliente tenía muy bien localizada la operativa más costosa, hasta el punto que podíamos llegar con gran facilidad a la consulta problemática, que era la siguiente:

EXEC sp_executesql N’
SELECT
   this_.ID as ID90_0_,
   this_.BorradoLogico as BorradoL2_90_0_,
   this_.Descripcion as Descripc3_90_0_,
   this_.Estado as Estado90_0_,
   this_.VisibleWeb as VisibleWeb90_0_,
   this_.CodigoDB2 as CodigoDB6_90_0_,
   this_.FechaPrevistaInicioComercializacion as FechaPre7_90_0_,
   this_.FechaFinComercializacion as FechaFin8_90_0_, 
   this_.Comentarios as Comentar9_90_0_,
   this_.URLFoto as URLFoto90_0_,
   this_.Orden as Orden90_0_,
   this_.URLFotoMiniatura as URLFoto12_90_0_,
   this_.SufijoID as SufijoID90_0_,
   this_.MarcaID as MarcaID90_0_,
   this_.VersionId as VersionId90_0_
FROM 
   VistaProblematica this_
WHERE
   this_.CodigoDB2 in (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9) and
   this_.SufijoID in (@p10, @p11, @p12, @p13, @p14) and this_.BorradoLogico = @p15′,
N’@p0 nvarchar(5),@p1 nvarchar(5),@p2 nvarchar(5),@p3 nvarchar(5),@p4 nvarchar(5),@p5 nvarchar(5),@p6 nvarchar(5),@p7 nvarchar(5),@p8 nvarchar(5),@p9 nvarchar(5),@p10 bigint,@p11 bigint,@p12 bigint,@p13 bigint,@p14 bigint,@p15 bit’,
    @p0 = N’040  ‘, @p1 = N’1F7  ‘, @p2 = N’1G3  ‘, @p3 = N’209  ‘,
    @p4 = N’3R3  ‘, @p5 = N’8S1  ‘, @p6 = N’8S6  ‘, @p7 = N’8T4  ‘,
    @p8 = N’8T8  ‘, @p9 = N’9AK  ‘, @p10 = 1819, @p11 = 1820, @p12 = 1821,
    @p13 = 1822, @p14 = 3614, @p15 = 0

De un primer vistazo, podemos ver que la consulta esta generada automáticamente por NHibernate. No es que sea inherentemente malo, solo lo digo a título informativo 🙂

Procedimos a comprobar los tiempos de esta consulta con SET STATISTICS TIME ON:

SQL Server Execution Times:
   CPU time = 703 ms,  elapsed time = 796 ms
.

A la vista del tamaño de filas y la vista, sí que es cierto que el tiempo de ejecución de casi un segundo parece ser demasiado elevado. Por ello, procedimos a analizar el número de operaciones de E/S de cada elemento involucrado en la consulta, mediante SET STATISTICS IO ON:

(50 row(s) affected)
Table ‘Worktable’. Scan count 51, logical reads 92037, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Versiones’. Scan count 53, logical reads 316, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Modelos’. Scan count 106, logical reads 424, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Sufijos’. Scan count 9852, logical reads 20996, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Colores’. Scan count 10, logical reads 292, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

Como se puede ver, hay bastante actividad de E/S en casi todas las tablas, pero lo que me llamó la atención por encima de todo fue la elevada actividad en las worktables

¿¡Worktables?! ¡¿Que mi madre es eso?!

Pues las worktables son un concepto muy importante en SQL Server, y a la vez, muy poco conocido. En muchas ocasiones son la causa de la degradación de rendimiento de un procedimiento almacenado al suministrarle diferentes parámetros, el origen de los temidos Sort Warning y Hash Warning, y la raíz de todos los males de la huma… perdón, que me dejé llevar 🙂

Las worktables en realidad son un mal necesario; no son más que unas tablas temporales que se crean en tempDb para las operaciones de Sort y Hash que no han conseguido suficiente memoria como para hacerlas sobre el Buffer Pool, u operaciones grandes de cursores o tipos de datos LOB… en definitiva, son una solución de emergencia para cuando deseamos realizar una operación que va a requerir gran cantidad de memoria.

Habría muchos ejemplos de su utilización, pero os voy a poner uno muy sencillo: Imaginad que tenemos un procedimiento almacenado para realizar un proceso que hace una JOIN de las filas de dos tablas en un periodo de tiempo determinado. Este procedimiento recibe dos parámetros: fecha de inicio y fecha de fin.

Ahora imaginad que la primera vez que se despliega ese procedimiento, se ejecuta para un rango de un solo día. Ese procedimiento va a compilarse tratando de optimizar la ejecución para ese rango de fechas: SQL Server podría decidir realizar la JOIN mediante un operador HASH JOIN debido a que el número de filas no es demasiado elevado, y reservará la cantidad de memoria justa para realizar la operacion de HASH para esas filas.

Supongamos que al día siguiente, esta consulta se realiza para un rango temporal de un mes entero; SQL Server ya tiene el plan cacheado, por lo que va a tratar de reutilizarlo, pero la asignación de memoria para la operación de HASH era la justa para las filas de un día. Al comenzar a ejecutar la consulta, el procesador de consultas detectará que no tiene memoria suficiente y decidirá terminar la operación sobre una Worktable en TempDb. Esto es mucho más lento, pero al menos garantiza que la operación pueda finalizar.

Volviendo al Turrón:

A la vista de la actividad de E/S en Worktables, decidí confirmar mis sospechas, por lo que adjunté una traza de profiler:

profiler

¡Bingo! Podemos comprobar que aparece un evento de Hash Warning al ejecutar la consulta.

Bien, ya sabemos la razón de nuestro problema de rendimiento: el uso de tempDb. Ahora solo nos queda saber por qué esta consulta esta ejecutándose en TempDb.

Después de un par de ideas no muy afortunadas basadas en la recompilación de esa consulta, decidí estudiar los tipos de datos de la definición de esa tabla, para ver si coincidían con los que se pasaban como parámetros en el sp_executesql.

A continuación os muestro las columnas de la vista en cuestion. Permitidme que antes os avise de que lo que vais a ver a continuación puede herir la sensibilidad de más de un desarrollador o arquitecto de datos(**) 🙂

Definicion

Como podéis ver, la columna CodigoDB2 está definida como char(5), pero en el código de la consulta que genera NHibernate nos pasa el parámetro como nvarchar(5), lo cual aumenta el peso de la consulta considerablemente, y puede estar provocando que la memoria reservada para la consulta no sea suficiente y tenga que volcar la operación sobre worktables en tempDb.

Hicimos la prueba, cambiando los tipos de datos sobre la consulta generada por NHibernate en el sp_executesql, quedando la misma así:

EXEC sp_executesql N’
SELECT
   this_.ID as ID90_0_,
   this_.BorradoLogico as BorradoL2_90_0_,
   this_.Descripcion as Descripc3_90_0_,
   this_.Estado as Estado90_0_,
   this_.VisibleWeb as VisibleWeb90_0_,
   this_.CodigoDB2 as CodigoDB6_90_0_,
   this_.FechaPrevistaInicioComercializacion as FechaPre7_90_0_,
   this_.FechaFinComercializacion as FechaFin8_90_0_, 
   this_.Comentarios as Comentar9_90_0_,
   this_.URLFoto as URLFoto90_0_,
   this_.Orden as Orden90_0_,
   this_.URLFotoMiniatura as URLFoto12_90_0_,
   this_.SufijoID as SufijoID90_0_,
   this_.MarcaID as MarcaID90_0_,
   this_.VersionId as VersionId90_0_
FROM
   VistaProblematica this_
WHERE
   this_.CodigoDB2 in (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9) and
   this_.SufijoID in (@p10, @p11, @p12, @p13, @p14) and this_.BorradoLogico = @p15′,
N’@p0 char(5),@p1 char(5),@p2 char(5),@p3 char(5),@p4 char(5),@p5 char(5),@p6 char(5),@p7 char(5),@p8 char(5),@p9 char(5),@p10 bigint,@p11 bigint,@p12 bigint,@p13 bigint,@p14 bigint,@p15 bit’,
    @p0 = N’040  ‘, @p1 = N’1F7  ‘, @p2 = N’1G3  ‘, @p3 = N’209  ‘,
    @p4 = N’3R3  ‘, @p5 = N’8S1  ‘, @p6 = N’8S6  ‘, @p7 = N’8T4  ‘,
    @p8 = N’8T8  ‘, @p9 = N’9AK  ‘, @p10 = 1819, @p11 = 1820, @p12 = 1821,
    @p13 = 1822, @p14 = 3614, @p15 = 0

Tras realizar los cambios, volví a ejecutar la consulta con la información de tiempos y actividad de E/S, y obtuve los siguientes resultados:

SQL Server Execution Times:
   CPU time = 78 ms,  elapsed time = 78 ms.

(50 row(s) affected)
Table ‘Worktable’. 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 ‘Colores’. Scan count 10, logical reads 292, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Sufijos’. Scan count 2, logical reads 27, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Versiones’. Scan count 4, logical reads 22, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table ‘Modelos’. Scan count 8, logical reads 32, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

¡No está nada mal! Hemos conseguido que la consulta se ejecute diez veces más rápido, sin hacer ninguna modificación real sobre la misma. Toda esa pérdida de tiempo se estaba produciendo por el uso de tempdb como consecuencia de la diferencia entre la memoria estimada y la necesaria.

Al final, el cliente arregló el mapeo del tipo de datos, estableciendo el sql-type de modo explícito, lo que eliminó este problema puntual. La gran noticia es que, con toda seguridad, este cambio en el mapeo afectará a muchas otras consultas, por lo que se espera un incremento generalizado del rendimiento en todas las consultas.

Conclusiones:
  • Es muy importante garantizar la corrección de los tipos de datos en los mapeos de cualquier solución de persistencia.
  • Revisad el uso de vuestras tempdb, la creación de worktables y la presencia de eventos de tipo Hash Warning o Sort Warning en vuestros sistemas; es muy posible que os llevéis alguna sorpresa!
  • Estaba claro que si yo iba a hablar acerca de NHibernate, no iba a ser enteramente para bien… 😉

Keep Rockin’!

(*): Soy perfectamente consciente de lo mal que puede llegar a sonar esa frase!
(**): Tengo que dejarlo claro: el modelo de datos NO es mío!!! 🙂

Rock Tip:

En esta ocasión, voy a dar un poquito más de caña de lo habitual. Los que seguís este blog y sus Rock Tips(tm) sabéis que casi siempre me decanto por un puntito hardrockero melódico, que es lo que suelo escuchar gran parte del tiempo. Sin embargo, en esta ocasión creo que os voy a sorprender con uno de mis grupos favoritos, aunque son de un palo bastante mas heavy: se trata de los suecos ‘In Flames’, grupo fundado y liderado hasta hace poco por ese genio que es Jesper Strömblad.

Cuando estaba escribiendo este post sobre el mapeo en Hibernate, no pude evitar que se me viniera a la cabeza su tema ‘Pinball Map’; quizá fue simplemente por la palabra map, o quizá porque necesitaba un poco de buen death metal melódico sueco para desintoxicarme de NHibernate xD Sea como sea, me apetece compartirlo con vosotros, así que.. enjoy! 😉

Rainbow In The Dark: Materiales de la sesión de Optimización de SQL Server

El pasado Jueves 27 tuve la oportunidad de pasar un par de horas muy agradables en compañía de la gente de MAD.NUG, hablando de optimización de SQL Server. En resumen, vine a explicar un poco el proceso que yo sigo a la hora de enfrentarme a un problema de rendimiento en un entorno SQL Server que, en la práctica totalidad de los casos, me resulta desconocido.

Empezamos repasando algunos de los informes básicos que el producto pone a nuestra disposición, para hacernos una idea de la salud general del servidor, y fuimos bajando de nivel y obteniendo más detalle gracias a la utilización de alguna de las muchas DMVs del sistema. Repasamos y explicamos las esperas del servidor (sys.dm_os_wait_stats) y aproveché para contar un par de batallitas sobre optimizaciones extremas mediante la eliminación de CPUs 🙂

Por último, dedicamos la última parte de la sesión a estudiar algunos escenarios curiosos de rendimiento, como el uso inapropiado de UDFs en los predicados de las consultas, el tan conocido empleo de cursores, los peligros de las consultas Ad Hoc y por último, un escenario muy interesante de ordenación en tempDb por problemas de estimación de memoria y parameter sniffing.

He de admitir que, para ser una sesión de SQL Server, me lo pasé bien! y es que no solo de WinDbg vive el hombre 😉

Aprovecho para dejaros aquí los materiales de la sesión, tanto las PPTs como los scripts que utilicé durante la misma.

Gracias a todos los asistentes (muy buenas preguntas!) y por supuesto, a la organización de Mad.Nug 🙂

Keep Rockin’!

Rock Tip:

Podría tratar de encontrar algún rebuscado nexo entre el Rock Tip de hoy y el texto del post; como que espero que los consejos que compartí con vosotros os sirvan en alguna ocasión como ese ‘arcoíris en la oscuridad’ para resolver algún problema en vuestros entornos SQL Server, o que algunos de esos scripts valen más que el oro al otro lado del arcoíris…

Pero esta vez no. Esta vez no necesito justificación para mi Rock Tip. Hoy se trata de un homenaje, y para eso no son necesarias excusas. Ronnie James Dio, la voz del heavy metal, el padre de la mano cornuta (los cuernos heavies de toda la vida!) nos abandonó el día 16 del pasado mes. Un hombre que, pese a sus 67 años, seguía subiéndose a al escenario con una tremenda energía, con una voz asombrosa y sobre todo, con unas ganas de entretener y de ganarse el cariño de sus fans noche tras noche.

Se nos ha ido un grande, pero está claro que será recordado siempre por su legión de seguidores desde los años 70, los chavales de hoy y, sin duda, los que vendrán.

Aquí os dejo una versión del “Rainbow In The Dark” en directo en el Wacken de 2004, donde podemos ver que el gran Ronnie James Dio seguía estando como un chaval y disfrutando como si aún estuviera en Black Sabbath allá por 1979!

Looks that Kill: Componentes de DevExpress y ThreadAbortException

Aviso a Navegantes: El siguiente post no va a ser políticamente correcto. Es más, creo que este año los chicos de Developer Express Inc. no me van a enviar un jamoncito ni una botella de vino por Navidad, precisamente. Y sin embargo, me siento en la obligación de compartir esto con vosotros… así que ¡allá vamos!

Últimamente he pasado bastante tiempo en tierras Navarras: alegrándome la vista con el verdecito que ya voy echando tanto de menos, disfrutando como un enano de los increibles pintxos de Pamplona y, de cuando en cuando, tirando de WinDbg para resolver algunos problemas de rendimiento que tiene uno de nuestros clientes aquí 🙂

Y es que en estas semanas he visto muchos escenarios interesantes: las tradicionales fugas de memoria por manejadores de eventos en páginas ASP.NET, problemas con el tamaño de sesión y el histórico de ViewStates, un curioso caso de excepciones indeseadas en cada invocación a un Servicio Web con transacciones que espero poder postear en breve… vamos, ¡que no me he aburrido!

Uno de estos problemas, y uno de los más llamativos, tenía que ver con la increible cantidad de excepciones lanzadas en el frontal web de la aplicación; estamos hablando de varias decenas de miles a la hora! A estas alturas no hace falta que os diga que el mero hecho de lanzar una excepción (aunque esta sea capturada por nuestro código) supone un impacto negativo en el rendimiento, y debemos tratar de evitar estas situaciones.

Si bien el contador de rendimiento # of Excepts Thrown en .NET CLR Exceptions era suficiente para detectar el problema, necesitabamos algo más para averiguar el tipo de excepiones lanzadas y poder investigar mejor el problema real. Como no podía ser de otra manera, ese algo más fue WinDbg 🙂

Después de adjuntarme al proceso, le pedí a WinDbg que se detuviera cada vez que saltara una excepcion .NET (sxe clr) y que en cada una de ellas, me mostrara la información de la excepción (!pe), la pila de llamadas administrada (!clrstack) y que prosiguiera la ejecución sin manejar la excepción (gn):

sxe –c “!pe; !clrstack; gn” clr

La salida demostró que había dos tipos que conformaban la práctica totalidad de las excepciones:

  • MissingManifestResourceException:

Esta excepción no me preocupaba demasiado, porque en número era muy inferior a la que veremos a continuación. Sin embargo, es curioso el hecho de que siempre sucedía en unas DLLs de DevExpress.

A continuación os pongo una ocurrencia del problema (omitiendo la pila de llamadas, que en este caso no es relevante):

(d18.11b4): CLR exception – code e0434f4d (first chance)
Missing image name, possible paged-out or corrupt data.
Exception object: 0000000240991ed8
Exception type: System.Resources.MissingManifestResourceException
Message: Could not find any resources appropriate for the specified culture or the neutral culture.  Make sure "Resources.DevExpress_XtraScheduler_v9_3_Core.resources" was correctly embedded or linked into assembly "App_GlobalResources.2gule58b" at compile time, or that all the satellite assemblies required are loadable and fully signed.
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80131532

Después de revisar la solución, comprobamos que todas las referencias a todas las DLLs de DevExpress estaban aparentemente bien, por lo que decidimos involucrar al soporte de Developer Express en este caso.

  • ThreadAbortException:

Esta excepción ya suena peor ¿verdad? Hacía no mucho, en este mismo cliente, nos habíamos encontrado con el conocido bug de la plataforma en el método Response.End(), pero…. ¡no adelantemos acontecimientos!

Primero veamos un ejemplo de una de las excepciones que capturamos y su volcado de pila:

(d18.11b4): CLR exception – code e0434f4d (first chance)
Exception object: 0000000200f83940
Exception type: System.Threading.ThreadAbortException
Message: Thread was being aborted.
InnerException: <none>
StackTrace (generated):
SP               IP               Function
000000000911E8E0 0000000000000001 System.Threading.Thread.AbortInternal()
000000000911E8E0 000006427834300A System.Threading.Thread.Abort(System.Object)
000000000911E930 00000642BC9131D6 System.Web.HttpResponse.End()
000000000911E980 0000064281AC2EA6 DevExpress.Web.ASPxClasses.Internal.HttpUtils.EndRespons

StackTraceString: <none>
HResult: 80131530
OS Thread Id: 0x11b4 (23)
Child-SP         RetAddr          Call Site
000000000911e980 00000642803d1965 DevExpress.Web.ASPxClasses.Internal.HttpUtils.EndResponse()
000000000911e9c0 00000642803d049d DevExpress.Web.ASPxClasses.Internal.ResourceManager.ProcessRequest()
000000000911ea80 00000642bc8f2eb0 DevExpress.Web.ASPxClasses.ASPxHttpHandlerModule.BeginRequestHandler(System.Object, System.EventArgs)
000000000911eab0 00000642bc8e449b System.Web.HttpApplication+SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
000000000911eb10 00000642bc8f2215 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
000000000911ebb0 00000642bc8e3553 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
000000000911ec60 00000642bc8e7874 System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
000000000911ecc0 00000642bc8e745c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
000000000911ed50 00000642bc8e608c System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
000000000911ed90 000006427f602012 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)

Como se puede ver, uno de los métodos de las librerias de DevExpress, DevExpress.Web.ASPxClasses.Internal.HttpUtils.EndResponse está invocando a System.Web.HttpResponse.End(), el cual a su vez lanza una excepción de tipo ThreadAbortException.

Mmm… antes hablabamos de un caso conocido de excepción ThreadAbortException en las llamadas a HttpResponse.End(), así que una rápida busqueda nos lleva al KB312629, que si no conoceis os recomiendo que leais y comprobéis si vuestras aplicaciones se ven afectadas por él.

Una comprobación del código fuente del método de DevExpress (con la siempre inestimable ayuda de .NET Reflector), nos revela que los desarrolladores del producto son conscientes del problema, implementando un catch para el ThreadAbortException:

public static void EndResponse()
{
    HttpContext.Current.ApplicationInstance.CompleteRequest();
    try
    {
        GetResponse().End();
    }
    catch (ThreadAbortException)
    {
    }
}

Sin embargo, esta solución no evita el lanzamiento descontrolado de las excepciones que, como ya se ha comentado, a pesar de ser controladas, siguen teniendo un impacto sobre el rendimiento de la aplicación, ¡por no hablar del ruido que meten a la hora del monitorizar el sistema!

Con esta información en la mano, elaboré un documento detallado (mucho más que este post) para que mi cliente pudiera abrir un caso de soporte con la gente de DevExpress, esperando que resolvieran el problema que nos estaba impactando severamente en producción, mediante la implementación condicional de una llamada a HttpContext.Current.ApplicationInstance.CompleteRequest() en lugar de invocar al método HttpResponse.End().

La respuesta de la gente de DevExpress no se hizo esperar mucho (punto para ellos!), y se resume en lo siguiente:

  1. No van a cambiar el código, ni a dejar la opcion al desarrollador de asumir el cambio con el CompleteRequest.
  2. Del problema de las MissingManifestResourceException simplemente nos comentaron que esas excepciones son esperadas y que no nos preocupemos.
  3. Con las dos respuestas (a todas luces insuficientes y debatibles) llegó la notificación del cierre del caso. Sin derecho a réplica.

En esta ocasion, lo que más rabia me da no es la parte técnica; puedo entender los problemas que tengan para realizar el cambio (aunque no es de recibo que su código levante tantas excepciones), hasta casi puedo entender que su código levanta excepciones buscando recursos localizados inexistentes… pero por lo que no paso es por la dejadez y el mal trato al usuario en el soporte técnico.

Asi que… ¡Avisados estais! 🙂 Vamos a por el mini-resumen del día…

Resumiendo:

  1. ¿Habéis monitorizado su vuestra aplicacion tira excepciones? Si no es así, revisad los contadores de rendimiento y tirad de WinDbg… ¡a lo mejor os llevais una sorpresa!
  2. Comprobad si teneis ThreadAbortException, y si es así, evaluad el workaround descrito en el KB.
  3. ¿Estais planteandoos adquirir una licencia para controles de usuario para un nuevo proyecto? ¡Aseguraos de tener un buen soporte, no sabeis lo útil que puede llegar a ser!

Keep Rockin’!

Rock Tip:

No podía ser de otra manera, este post solo lo podían presentar los chicos de Mötley Crüe con su “Looks that Kill”. Apropiado, porque en este caso la vistosa interfaz de usuario de la aplicación es la que contiene un pequeño veneno, como hemos visto 😉

Bang Bang!: Optimización Económica en SQL Server

Soy un impresentable. No hay manera de que actualice el blog, y cuando lo hago, es para promocionarme de mala manera. Y, como no podía ser de otra manera, esta es una de esas ocasiones 🙂

Esta vez tengo que agradecer a Gisela, Luis y el resto de chicos de Madrid.NET la oportunidad de pasar un ratito friki serio, formal y productivo hablando de optimización económica de SQL Server. La idea será aprender a localizar de dónde vienen los problemas, en lugar de tratar de optimizar las consultas en base a su duration elevado de modo sistemático… vamos, la venerable metodología ASM (A Salto deMata(tm)).

La primera parte del evento abordará las técnicas de revision que yo suelo emplear en mi trabajo en el equipo DOT de Plain Concepts, mientras que la segunda parte se centrará en una serie de casos particulares de optimización que me encuentro en algunos clientes y que, a pesar de que alguno de ellos es muy frecuente, siguen siendo problemas bastante desconocidos para los que no nos pasamos delante de un SQL Server todo el dia 🙂

Si el plan os resulta interesante o apetecible, ya sabeis.. ¡nos vemos el jueves! El evento será en las oficinas de Microsoft en La Finca, y los datos del registro los teneis en el siguiente enlace:

https://msevents.microsoft.com/CUI/EventDetail.aspx?EventID=1032451680&Culture=es-ES

Keep rockin’!

Rock Tip:

Hoy me toca hacer algo que no me gusta, y que creo que solo hice en otra ocasión en este blog: voy a repetir un Rock Tip. Y voy a hacer esto por tres razones totalmente justificadas:

  1. El nombre es apropiado… vamos a hacer nuestro el lema de ’Biggest Bang for the Buck’, así que el Bang Bang! nos viene que ni pintado…
  2. Estamos hablando de la que posiblemente sea la mejor canción del mejor grupo de la historia. Punto pelota. xD
  3. El blog es mio y…. mmmm, creo que recurro con demasiada frecuencia a este punto 🙂

Por todo esto, hoy le ha tocado el turno a Bang Bang, un tema del primer disco de Danger Danger. Si os apetece oir una cancion happy, que anima al instante, probadla. Como la gente que me conoce sabe de sobra, esta banda neoyorkina es mi grupo favorito, así que no me extenderé en detalles porque podría llegar a aburriros 🙂

Si os interesa la musica de guitarristas para guitarristas, principalmente instrumental, no os perdais los trabajos en solitario de su guitarrista, Andy Timmons, que para mi es el guitar hero con mas estilo que ha parido madre 🙂 Por cierto, el señor Timmons ha estado esta pasada semana en Madrid… así que también lo celebraremos con un temazo suyo: Cry for You.

Photograph: SQL Server Crash Dump Analysis

Just a small post to remind that this week I’ll be presenting at SQLBits VI, in UK! I’m going to talk about SQL Server crash dump analysis – some post-mortem debugging techniques that help us to discover what went wrong and why our SQL Server crashed, using mostly WinDbg. We will also do a little tour on managed debugging, showing how these techniques and tools can be useful when trying to detect anomalous behaviors on our .NET Applications accessing the database.

 SQLBitsLogo

 

It goes without saying that I’m really excited to be able to share event with such an incredible list of speakers! There are other incredible tracks at the same time: Conor Cunningham will come all the way from Redmond to London to share with us some of the internals and secrets the Query Optimizer, James will deliver a very interesting session on sequential I/Os (I wish I could invite some of my customers to that session!) and Satya will share his huge experience with us in a best practices session. With this great sessions at the same time, I understand many of you that could be interested in attending my session won’t be able to! So if you cannot attend my session, just catch me anytime on the venue and I will be more than happy to have a nice chat about post-mortem debugging, WinDbg or whatever… by the way, I’m the one with the cowboy boots and long hair! 🙂

See you at SQL Bits on Thursday!

Rock Tip:

Each time that I write a new entry on this blog I use to spend a ridiculous amount of time looking for a song that fits the post; you know I don’t want my Rock Tips to be just a bunch of songs that I like without a reason. Well, this time the job was really easy! Think about it: the session is going to be in the UK… so a band from the country is definitely a must. And I’m going to be talking about memory snapshot analysis… about ‘photographs’ of the process memory… so, without further ado, let me introduce you the Rock Tip of the day: Photograph, by Def Leppard.

One of that classic 80’s tunes that I love so much, and definitely one of my fave from this always impressive bands. This time I’ve chosen to link the song to a live performance of the band, and not to the promotional video of the single, so you can enjoy the impressive work on the backing vocals, the acting and the always missed guitar playing of the late Steve Clark.

Just Push Play: Depuración Avanzada (2ª Parte) en Second Nug

Lo se, lo se… ¡os tengo muy abandonados! y de hecho, la entrada de hoy no va a cambiar mucho la situación, ya que será muy breve; un simple ejercicio de autopromoción 🙂

Solo quería recordaros que mañana, Martes 15 de Diciembre, tengo el placer de poder dar la continuación del evento de Depuración Avanzada que dí en colaboración con los chicos y chicas de Second Nug.

A continuación teneis los detalles de registro para el evento de mañana:

Debugging

PISTA: Pinchad en la imagen 🙂

En el abordaremos alguna demo de depuración con WinDbg que nos quedó pendiente en la primera sesión, así como depuracion con CLR 4.0. Por ultimo, terminaremos echando un vistazo a las neuvas características de depuración de Visual Studio 2010, que son sencillamente espectaculares. De echo, para una vez que escribo, voy a tirar la casa por la vetnana y también os recuerdo el link a la descarga de Visual Studio 2010 Beta 2, para que podais jugar con él 🙂

Keep Rockin’!!!

Rock Tip:

Ya sabéis, los chicos de Aerosmith están de actualidad por el espectáculo de prensa rosa que están protagonizando últimamente; la útlima barbaridad que yo he escuchado es que Lenny Kravitz quiere sustituir a Steven Tyler a la voz!! Yo me quedo con la idea de que es todo un truco publicitario, la necesidad de hacer un poco de ruido. Y si es así, les ha funcionado porque aqui estoy yo para recordaros a todos lo grande que es esta banda!

En este caso, hemos querido dedicarle el tema Just Push Play… un tema que nos va a venir al pelo al analizar los volcados de memoria desde el Visual Studio 2010, ¡ya veréis! 🙂

Beat The Bullet: Aplazado el Evento de SQL Server en Coruña

No os podéis imaginar lo que me fastidia tener que daros esta noticia, pero me he visto obligado a tener que posponer mi sesión de Optimización de SQL Server que los chicos de .NUGG habían organizado en Coruña.

Estamos intentando moverla al Viernes de la semana que viene; se que es precipitado, pero si esperamos más, nos metemos en periodo de vacaciones. Espero editar este post a lo largo de la tarde y daros la confirmación definitiva.

A todos los que estabais apuntados para el evento, por favor, aceptad mis disculpas. A veces estas cosas pasan.

Parece que esa Estrella Galicia va a tener que esperar un poquito 🙂 Keep Rockin’!

Rock Tip:

Como ya sabréis, Beat The Bullet es una expresión que viene a querer decir algo así como ‘aguantar estoicamente cuando algo va mal’, una expresión que ya emplee en otra entrada de este blog, curiosamente para hacer referencia a otra sesión en Coruña. En aquella ocasión, el Beat the Bullet hacia mención al mejor tema del mejor grupo de la historia, el Beat the Bullet de los Danger Danger.

Como no me gusta repetir temas en los Rock Tips, en esta ocasión haré mención a otro temazo con el mismo nombre, el Beat the Bullet de Vain.

Speed of Light: Evento sobre Optimización de SQL Server en Coruña

Este Viernes 17 voy a tener la oportunidad de volver a pasarme por tierras gallegas. En esta ocasión, los chicos de .NUGG han tenido a bien invitarme a presentar una sesión sobre Optimización de SQL Server, así que antes de nada, permitidme que agradezca a Edu y a Euge su invitación y la organización del evento! Gracias chicos!

Para ser sinceros, esta sesión no deja de ser una deuda contraída con los asistentes a mi última sesión en Coruña sobre Depuración y Optimización con WinDbg. En ella se demostró un claro interés por la optimización de SQL Server, y prometí volver con un temario centrado en exclusiva en este tema. Como lo prometido es deuda, y como necesitaba alguna excusa para tomarme una Estrella Galicia en buena compañía, este viernes nos veremos en Coruña!

Aquí os dejo los detalles de la sesión, a la que os podéis registrar pulsando aquí. ¡¡Nos vemos en Coruña!!

Speed of Light: Optimización de SQL Server

Fecha: viernes, 17 de julio de 2009
Horario: 17:00 – 19:00
Lugar:
– UNIVERSIDADE DA CORUÑA
– Aula 1, Edificio Xoana Capdevielle
– Campus de Elviña s/n A Coruña 15071

Descripción:

Esta sesión está dedicada a detallar las técnicas y herramientas que nos permitirán exprimir el rendimiento de nuestro SQL Server al máximo, haciendo un repaso por la teoría implicada, y pasando directamente a ejemplos del Mundo Real™. Se abordarán buenas prácticas de indizado, las consideraciones de almacenamiento más relevantes, el análisis de planes de ejecución, así como la utilización de nuevas características de SQL Server 2008 para optimizar cargas de trabajo.

1.- Arquitectura general de SQL Server
2.- Metodología Waits & Queues: Monitorización de Esperas en SQL Server
3.- Optimización de Almacenamiento
4.- Optimización del Uso de Memoria
5.- Aislamiento Transaccional
6.- Optimización de Consultas

Rock Tip:

Esta vez, tanto la sesión como el post comparten rock tip, que no podía ser otro que el ‘Speed of Light’ de los speed-metaleros fineses Statovarius. Un tema clásico, con una formación clásica en la banda, antes de que al señor Timo Tolkki le diera por seguir las instrucciones que le dictaba una patata en llamas, a fingir un asalto y acuchillamiento en plena gira, o a hacer cambios ridículos en la formación de la banda con fines promocionales.

¡Vamos a poner nuestros servidores SQL Server a la velocidad de la luz! Keep Rockin’!