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:
¡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(**) :)
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! ;)