Surviving the Night : Rendimiento

Why Do I?: Memoria para los Workspaces en SQL Server (I)

Pablo Alvarez — Sun, 30 Dec 2012 02:51:35 GMT

Os voy a confesar un oscuro secreto: tengo un plan. Y no solo eso, sino que es un plan de los buenos. De los de Dominación Mundial™. Curiosamente, y como no podía se de otro modo, ese plan pasa por hacerme bueno, muy bueno en SQL Server¹, así que últimamente estoy aprovechando este descanso navideño para estudiar en profundidad algunos temas en los que nunca entre en suficiente detalle, o que tengo olvidados.

Durante las sesiones de estudio me gusta tomar notas de lo que voy repasando, así como preparar unas slides personales sobre el tema, que voy almacenando para futuras referencias y para dar charlas de esas que me gusta hacer de vez en cuando para satisfacer mi lado mas nerd. En esta ocasión, sin embargo, he pensado utilizar parte de esas notas para darle un poco mas de vidilla al blog y aprovechar para escribir de algunas partes de SQL Server de las que no hay demasiada literatura en nuestro idioma.

En esta ocasión, voy a hablaros de una zona de memoria especial de SQL Server, llamada Workspace y que me niego a traducir al castellano :) Mi objetivo para esta mini serie será explicaros algunos fenómenos perniciosos desde el punto de vista del rendimiento en SQL Server (como son Hash Warnings, Sort Warnings, etc…) y su relación con esta misteriosa y desconocida área.

NOTA: Tras muchos intentos en el pasado, soy plenamente consciente de que esta pequeña reactivación de mi blog va a tener un carácter muy temporal; después vendrá el día a día y se llevará todas mis buenas intenciones. Así que, tomaros esto como una pequeña aportación navideña, un regalo de reyes anticipado :P

La Memoria en SQL Server

Esta claro que antes de zambullirnos en la manera en la que SQL Server gestiona la memoria workspace, es importante conocer el funcionamiento básico de la memoria en el producto. Para esta entrada tengo que hacer la suposición de que ya estáis familiarizados con la gestión de memoria básica de SQL Server. Algunas de las cosas básicas que debes de saber antes de continuar leyendo es que…

La memoria de SQL Server se divide en dos zonas principalmente:

Buffer Pool: Es la caché principal de datos de SQL Server. Aquí se cachean, en páginas de 8Kb, datos, índices, planes de ejecución… Todas las reservas de 8Kb van aquí, y es sin duda la zona mas importante de memoria del producto.
Non-Buffer Pool: También llamada mem-to-leave, es la zona de memoria en al que se realizan las reservas superiores a 8Kb.

El parámetro de configuración max server memory (MB) limita sólo Buffer Pool
El tamaño de la región Non-Buffer Pool viene determinado por la siguiente formula: Memoria Física Total – (Max Server Memory + Memoria Física usada por el OS y otras aplicaciones)

Si no es así, os recomiendo que busquéis alguna introducción básica al tema y luego continuéis leyendo por aquí :)

NOTA: Aunque estas cosas son bastante genéricas, en realidad solo son correctas para un SQL Server 2008 R2 con arquitectura x64.

Este maravilloso diagrama “Windows 8 Modern UI” que os he preparado, sin bordes, ni colorido, ni ná de ná, muestra la relación entre los componentes de asignación de memoria en SQL Server 2008 R2:

Un rápido resumen podría ser el siguiente:

Las reservas de memoria de 8Kb o menores se almacenan en el Buffer Pool (mediante en single-page allocator)
Las reservas de memoria mayores de 8Kb se dirigen al área mal llamada Mem-to-leave a través del multi-page allocator.
Las reservas de memoria del código de CLR que se ejecuta dentro del proceso de SQL Server se dirigen también al mem-to-leave mediante el VAS allocator.

En SQL Server 2012 se han producido bastantes cambios a la gestión de memoria: sin duda, el más importante es que ya no se realiza una diferencia entre el single-page allocator y el multi-page allocator, habiendo sido sustituidos ambos por un único y genérico gestor de reservas de memoria, como se puede ver en el siguiente diagrama:

A partir de ahora, tanto las reservas tradicionales menores de 8Kb, como las reservas superiores a 8Kb y las reservas del CLR pasan a estar en los limites de memoria definidos entre el max server memory (MB) y el min server memory (MB).

NOTA: Si habéis hecho una actualización a SQL Server 2012 sin tener en cuenta este cambio, es probable que queráis repasar vuestra configuración de memoria después de leer esto. Tened en cuenta también que que muchas DMVs han cambiado, por lo que scripts de captura y monitorización pueden estar devolviéndoos resultados no fiables.

Una vez descritas las dos grandes zonas de memoria de SQL Server, estoy seguro de que muchos de vosotros ya estáis poniendo en su lugar, dentro de la zona controlada por el Memory Manager (la zona verde), las varias caches de datos que conocéis en SQL Server: para los datos recientemente usados, para los planes de ejecución, etc. Sin embargo, SQL Server tiene mas usos para la memoria principal, y uno de ellos es para la…. ¡¡Ejecución de Consultas!!

<sonido de truenos y lluvia distante, por favor….. …… ¡gracias!>

Ok… ok… se que era predecible :) Pero es un paso importante para llegar a donde os quiero llevar. Vamos a hablar de unas pequeñas estructuras muy amigables que viven de de nuestros planes de ejecución.

Los Iteradores

En realidad, los iteradores (u operadores, pero como en realidad todos son iteradores, prefiero llamarlos asi) son las piezas de lego con las que se construyen nuestros planes de ejecución. Hay aproximadamente un centenar de ellos en SQL Server 2012, y nos sirven para realizar acciones tan variadas como leer registros, realizar filtrados y agregados, actualizar datos, etc… Estos se combinan y son los que finalmente dan lugar a nuestros planes de ejecución.

A nivel interno, todos exponen los mismos tres métodos:

Init(): Instancia el operador físico e inicializa todos los recursos que pueda necesitar. Idealmente solo se ejecutará una vez, pero puede ser necesario llamarle múltiples veces: esto suele indicar algún problema y se materializa con un número alto de binds/rebinds en el plan de ejecución.
GetNext(): La llamada a este método devuelve la primera fila, o la fila siguiente a la actual. El operador puede recibir cualquier número de llamadas a este método. ¿Entendéis ahora porque llamamos iteradores a todos los operadores? ;)
Close(): Este método provoca la ejecución de las tareas de limpieza y eliminación de recursos del operador. Solo puede ser invocado una vez.

Aunque a primera vista parece extraño que *todos* los operadores se implementen básicamente con un GetNext(), esta aproximación hace que sea relativamente fácil implementar nuevos operadores para el Query Optimizer/Query Processor.

NOTA: Aquí tenéis la referencia de los disponibles en SQL Server 2012: http://msdn.microsoft.com/es-es/library/ms191158.aspx

Sigamos: todos los iteradores (Table Scan, index Scan, Compute Scalar, etc…) en un plan de ejecución necesitan algo de memoria para levantar su infraestructura básica, para mantener el estado del iterador y para almacenar las filas que están siendo procesadas. Este último punto es el más interesante, veamos por qué.

Los iteradores pueden ser de dos tipos:

La mayoría de los iteradores que nos vamos a encontrar en un plan de ejecución son de tipo streaming; esto es, pedirán una fila, la procesarán y pedirán la siguiente. Evidentemente, en estos escenarios el consumo de memoria del iterador para almacenar las filas que están siendo procesadas será escaso y predecible: siempre se almacena una única fila.
Hay unos pocos operadores que son de tipo parcialmente o completamente bloqueantes (blocking). Estos deben de mantener un subconjunto (o la totalidad) de las filas en memoria hasta que finaliza su proceso, en cuyo momento el GetNext() devuelve un bloque de n filas, en lugar de una única filas.

Evidentemente los iteradores parcialmente o completamente bloqueantes consumen mucha más memoria. Un ejemplo básico es el operador sort, que es complentamente bloqueante ya que requiere que todas las filas se almacenen hasta la llegada de la última fila de su operador de entrada, antes de empezar a producir resultados por su salida. Esto es así, porque la última fila en entrar podría ordenarse la primera; es un ejemplo muy claro.

La buena noticia es que son muy pocos los operadores bloqueantes, y se pueden categorizar en estos tres tipos:

Hash Match:

Hash Match
Hash Match (Aggregate)

Sort:

Sort
Sort (Top N Sort)

Exchange:

Distribute Streams
Gather Streams
Repartition Streams

Cuando una consulta utiliza este tipo de operadores, tiene que realizar peticiones de memoria especiales a SQL Server para poder realizar las tareas que estos iteradores requieren: estas peticiones de memoria son las que definen el workspace de la consulta (workspace memory grants).

Algunas Preguntas

Lo primero que nos podemos preguntar es, ¿de dónde sacamos esa memoria? Esta pregunta es la fácil; estoy convencido de que todos ya sabéis que viene del Buffer Pool… entre otras cosas porque ya lo hemos comentado antes ;)

La siguiente pregunta es: ¿cuanta memoria se va a reservar de nuestro Buffer Pool para la ejecución de la consulta? De esto se encargará nuestro amigo, el Query Optimizer, que tratará de averiguar el Ideal Grant, es decir, la reserva de memoria total para el plan de ejecución que permitirá que todos los operadores puedan ejecutarse completamente en memoria. Para realizar este calculo del Ideal Grant se utilizarán las estadísticas (histograma de distribución de los valores de cada columna), en concreto el número de filas, y el tamaño por cada fila.

Es interesante aquí darse cuenta de que estamos trabajando con estimaciones. A modo de ejemplo, supongamos un escenario de una consulta simple con un ORDER BY: el Query Optimizer sabe que ese operador necesitara “estimated rows * estimated row size” bytes. ¿porque decimos que son estimados? Bien, imaginaros que el tipo de datos es NVARCHAR(100)… realmente no sabemos lo que ocupa esa columna en cada fila, solo tenemos una estimación.

Para ver la información de la memoria asignada al workspace de una consulta desde el SSMS (y sin tener que recurrir a leer el XML a mano), podemos simplemente mirar las propiedades del operador principal (el SELECT en el ejemplo), y veremos un nodo llamada MemoryGrantInfo:

SQL Server impone un limite máximo a la memoria destinada a los workspaces (sobre el 75% del Buffer Pool), para evitar que una consulta extremadamente pesada impida la correcta ejecución de consultas mucho mas livianas y rápidas en el servidor.

Esto puede parecer mucha memoria, pero imaginaros que tenéis un Data Warehouse con una tabla de hechos que os pesa 500 Gb, y queréis realizar algo ‘tan simple’ como un ‘SELECT * FROM FactTable ORDER BY Date’, ¿Podría vuestro servidor mantener todo el operador en memoria? ¿que sucedería?

Las respuestas, ¡en la próxima entrada! ;)

Resumiendo

Buff.. ¡no ha estado nada mal! En una única entrada hemos hablado de la gestión de memoria en SQL Server, de qué son y como funcionan los iteradores y hemos introducido el concepto de iteradores bloqueantes y sus workspaces asociados. Nos queda mucho por ver aún; de hecho, aún no os he presentado ni siquiera los problemas que queremos resolver, pero no he podido evitar la tentación de aprovechar esta mini serie para ir introduciendo algunos elementos de SQL Server de los que no solemos hablar.

Por cierto, si has llegado hasta aquí, ¡enhorabuena! Definitivamente debes de tener interés en SQL Server o mucho tiempo libre, ya que admito que no es el tema más ameno y ligero para una lectura en temporada navideña.

¹: Lo siento, pero no puedo explicaros la razón por la que un plan de Dominación Mundial™ requiere un conocimiento extremo las tripas de SQL Server. Bueno… en realidad si que podría explicarlo, pero tendría que mataros después. Y la verdad es que ya os he cogido cariño y esas cosas, así qué mejor no preguntéis :)

Rock Tip:

Si en la última entrada os ponía un temazo de W.E.T., en esta ocasión no me voy a ir muy lejos: ‘Why do I?’ es el tema que abre Artwork, el disco de debut de los suecos Work of Art. I digo que no me voy muy lejos, ya que el guitarrista, principal compositor y lider de esta banda no es otro que Robert Säll, uno de los lideres de W.E.T. de quien ya os hablaba anteriormente.

¿Que deciros de esta banda? Una de las mayores y más agradables sorpresas de mi vida musical: hablamos de un hard rock melódico de mucha, mucha clase, estilo y elegancia. Si duda una de mis bandas favoritas del momento, aunque he de reconocer que les tengo un cariño especial y poco objetivo. Decidieron hacer el primer concierto de su historia en Madrid, en la venerable sala Ritmo & Compás, y os puedo decir que todos los que tuvimos la suerte de vivir ese momento lo vamos a guardar como uno de los conciertos de nuestras vidas.

Keep Rockin’!

Hot: Inserciones Masivas en MongoDB vs SQL Server

Pablo Alvarez — Thu, 17 Nov 2011 02:09:00 GMT

Esta semana estoy en San Sebastián, impartiendo una pequeña formación sobre optimización de SQL Server. A priori, la semana se presentaba tranquila y con gran carga turística al tratarse de la primera ocasión que visito esta ciudad, y mi predilección general por estas tierras del norte.

Lamentablemente, todos mis planes se torcieron tan pronto como descubrí que Unai estaba en la misma ciudad que yo. Como no podía ser de otro modo, ente pintxo y pintxo nuestros temas técnicos favoritos empezaron a surgir en nuestras conversaciones. Y, como cualquiera que conozca a nuestro Unai podrá intuir, no pasó demasiado tiempo antes de que MongoDB secuestrara todos nuestros hilos conversacionales y se convirtiera en nuestro particular trending topic, por delante de otras apasionantes cuestiones como la entropía de la demografía en el postmoderno barroco, o el peculiar criterio que tengo a la hora de escoger mis guitarras.

He de confesar que no recuerdo muy bien la cadena de acontecimientos que nos condujo a la historia que os voy a contar; quizá fuera mi falta de conocimiento respecto a este producto tan de moda (MongoDB), o el número de zuritos que nos habíamos tomado… No lo acabo de tener muy claro, pero el hecho es que, de algún modo, me metí de lleno en un juego/apuesta que acabaría con el escaso tiempo libre que me quedaba a lo largo de la semana.

La Apuesta

Las reglas eran muy sencillas: el ganador sería aquel de nosotros dos que fuera capaz de insertar una carga de trabajo acordada previamente en menos tiempo. Él con su MongoDB de marras, y yo con mi viejo, fiable, pero no siempre bien ponderado SQL Server 2008 R2, ¡como no!

Tras duras negociaciones de paz, Unai y yo llegamos a un acuerdo para evitar emplear armas de destrucción masiva; por este motivo finalmente decidimos no evaluar la que es, de lejos, la manera más rápida de insertar datos en SQL Server: las Bulk Inserts.

La carga de trabajo que nos pusimos de objetivo fue 500.000 registros, cada uno conteniendo un GUID y 20 caracteres textuales (no unicode).

Descargo de Responsabilidad: Siempre que escribo acerca de una tecnología ajena al ecosistema de Microsoft acabo con problemas de fanatismos y guerras de religión. Por ello, dejadme que deje muy claro que este post solo pretende contar la historia de un pique interesante con un compañero, así como tratar de aprovechar la ocasión para comentaros un par de técnicas no triviales para realizar cargas rápidas de datos en SQL Server. Vaya por delante que MongoDB me resulta un producto más que interesante y con escenarios para los que es más idóneo que una base de datos relacional.

Construcción del Entorno de Prueba

En entorno de prueba inicial consistió simplemente en una base de datos que contiene la tabla sobre la que vamos a insertar nuestros 500.000 registros. La única preparación inicial que he realizado de cara a mejorar un poco el rendimiento ha sido dimensionar de modo apropiado los ficheros (para evitar autocrecimientos por uso del log de transacciones en las inserciones) y establecer el modelo de recuperación a SIMPLE.

A continuación os dejo el script inicial, aunque como veréis más adelante hemos realizado algún que otro cambio:

CREATE DATABASE DemoInserts ON PRIMARY 
( 
    NAME = 'DemoInserts', 
    FILENAME = 'c:\Databases\DemoInserts.MDF', 
    SIZE = 200, 
    FILEGROWTH = 10% 
) 
LOG ON 
( 
    NAME = N'DemoInserts_Log', 
    FILENAME = N'c:\Databases\DemoInserts_Log.LDF', 
    SIZE = 200, 
    FILEGROWTH = 10% 
) 
GO 
ALTER DATABASE DemoInserts SET RECOVERY SIMPLE 
GO 
USE DemoInserts 
GO 
CREATE TABLE [Test] 
( 
    ID UNIQUEIDENTIFIER NOT NULL DEFAULT NEWID(), 
    Payload VARCHAR(20) NULL, 
)

¡Vamos a Insertar Filas!

La primera solución consistirá en un simple bucle de 500.000 ejecuciones, en el que para cada iteración insertamos una fila. Su única ‘optimización’ fue el empleo de la opción NCOUNT ON para evitar saturar el output buffer con los típicos mensajes de (1 row affected), tal como se puede ver en el siguiente fragmento de código:

SET NOCOUNT ON

DECLARE @cont INT 
SET @cont = 0

WHILE (@cont < 500000) 
BEGIN 
   INSERT INTO Test(ID, Payload) VALUES (DEFAULT, REPLICATE('X', 20)) 
   SET @cont = @cont + 1 
END

El tiempo de ejecución de la inserción en mi equipo fue de 3 minutos y 8 segundos.

NOTA: Todos los tiempos tomados en este artículo se han calculado realizando el promedio de tres ejecuciones sucesivas.

Evidentemente, desde antes de realizar esta prueba yo era consciente de que este mecanismo no iba a arrojar buenos resultados, pero me serviría para tener una línea base respecto a la que poder evaluar las mejoras posteriores y para hacerme una idea respecto a lo que podría esperar de SQL Server.

Llegados a este punto le comenté a Unai que me daría con un canto en los dientes si era capaz de bajar mi tiempo de inserción por debajo de los 20 segundos. Mi amigo y competidor me corrigió, asegurándome que sería él mismo quien se encargaría de darme con el susodicho canto en toda mi dentadura si conseguía tal hazaña. Creo que en ese momento empecé a tomarme nuestra pequeña competición en serio ;)

Manos a la Obra… ¿Dónde esta mi cuello de botella?

Siempre hay un cuello de botella; ¡siempre! Aunque el rendimiento sea excelente, siempre hay un factor limitante, y solo uno. En este caso, un vistazo rápido al Task Manager me permitió ver que la CPU no eran en este caso el problema:

Esto me dio una buena idea para el siguiente intento: realizar una pequeña aplicación en C# que se encargara de lanzar INSERTS modo masivo en paralelo, usando múltiples hilos, para tratar de aprovechar al máximo las cuatro CPUs de las que dispone mi equipo de pruebas.

A continuación os pongo el código exacto que he empleado para esta prueba, aunque casi me da vergüenza ;) No me juzguéis por él, es solo un ejemplo ‘quick and dirty’!:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using System.Data.SqlClient;
using System.Diagnostics;

namespace ConsoleApplication5
{
    class Program
    {

        static void Main(string[] args)
        {
            Stopwatch watch = Stopwatch.StartNew();

            var mainTask = new TaskFactory().StartNew(() =>
            {
                new Task(() => DoWork(125000), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(125000), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(125000), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(125000), TaskCreationOptions.AttachedToParent).Start();
            });

            mainTask.ContinueWith((t) =>
            {
                watch.Stop();
                Console.WriteLine(watch.Elapsed);
            }, TaskContinuationOptions.OnlyOnRanToCompletion);

            Console.ReadLine();
        }

        private static void DoWork(int rows)
        {
            string connStr = "Data Source=.;Initial Catalog=DemoInserts
;Integrated Security=true;Application Name=TestInserts";

            int countIterations = 0;
            while (countIterations < rows)
            {
                using (SqlConnection conn = new SqlConnection(connStr))
                {
                    conn.Open();

                    using (SqlCommand cmd = new SqlCommand())
                    {
                        cmd.Connection = conn;
                        cmd.CommandText = "INSERT INTO Test(Id,Payload) VALUES (NEWID(), REPLICATE('X',20))";
                        cmd.ExecuteNonQuery();
                        countIterations++;
                    }
                }
            }
        }
    }
}

Como podéis ver, el código simplemente instancia 4 tareas (una por cara núcleo disponible en mi máquina). Estas tareas reciben el número de filas a insertar, y proceden a realizar estas inserciones como comandos SQL dentro de un bucle.

La inserción de las dichosas 500.000 filas por este mecanismo se produjo en 1 minuto y 7 segundos; si bien el valor no está nada mal en términos de mejora, sabía que aún me quedaba mucho para tener un tiempo competitivo. Una nueva visita al Task Manager me hizo darme cuenta rápidamente de que, si bien había aumentado mucho mi consumo de CPU, aparentemente aún disponía de mucho margen adicional:

A la vista de esto, decidí probar a aumentar el número de hilos empleados para lanzar las sentencias INSERT, y monitorizar tras cada prueba tanto la duración de la misma como la utilización de los procesadores durante el transcurso de las inserciones. De este modo pude lograr grandes usos del procesador, pero es importante tener presente una cuestión: el incremento de la actividad de CPU no implica necesariamente un mejor rendimiento en las inserciones.

Para demostrar este punto, os adjunto una pequeña gráfica que muestra los tiempos obtenidos en función del número de hilos empleados:

(Atiende que graficazaaa… ¿verdad que una de estas ayuda a darle un look más profesional a cualquier artículo? ;))

Como se puede apreciar, el sweet spot de este proceso de inserción en mi equipo se encuentra en los 8 hilos, con un tiempo de ejecución de 43 segundos. A continuación os muestro la gráfica de uso de CPU de esta ejecución, para que podáis contrastarla con la primera de todas y apreciéis el notable incremento en la utilización que hemos logrado:

¿Por donde seguimos ahora?

Bien, llegados a este punto ya tenía mas o menos claro el punto más idóneo de paralelismo desde el lado de la aplicación C# de inserciones, pero no conocía lo que estaba sucediendo por parte de SQL Server. Por esto, decidí estudiar las esperas del servidor; borre las estadísticas de esperas, lancé el proceso y a su finalización, use el celebérrimo script de Glenn Berry, personalizado por Paul Randal para la agregación de información de esperas por recursos en SQL Server.

El resultado de la prueba, si bien era de esperar, resulta revelador:

Como se puede ver, un 99.22% del tiempo total de la prueba se destino a realizar entradas en el log de transacciones; esto se debe al hecho de que las inserciones, salvo casos muy puntuales en escenarios de BULK INSERT, son operaciones completamente logeadas. Dicho a lo bestia: por cada inserción, a parte del dato en si, hay que escribir la intención de realizar la inserción previamente en el log de transacciones. Esta operación es síncrona, y es la que esta provocando una gran cantidad de esperas.

Para tratar de remediarlo, se me ocurrió tratar de reducir el número de cláusulas INSERT que enviamos al servidor mediante las sentencias de inserción múltiples de SQL Server 2008, que nos permiten insertar en el mismo statement hasta mil filas(*). Ya sabéis, algo así:

INSERT INTO Test(ID, Payload) VALUES
(NEWID(), 'AAA'),
(NEWID(), 'BBB'),
...
(NEWID(), 'XXX')

Modifique un poco la aplicación para realizar estas sentencias, quedando el código del siguiente modo:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using System.Data.SqlClient;
using System.Diagnostics;

namespace ConsoleApplication5
{
    class Program
    {

        static void Main(string[] args)
        {
            Stopwatch watch = Stopwatch.StartNew();

            var mainTask = new TaskFactory().StartNew(() =>
            {
                new Task(() => DoWork(), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(), TaskCreationOptions.AttachedToParent).Start();
                new Task(() => DoWork(), TaskCreationOptions.AttachedToParent).Start();
            });

            mainTask.ContinueWith((t) =>
            {
                watch.Stop();
                Console.WriteLine(watch.Elapsed);
            }, TaskContinuationOptions.OnlyOnRanToCompletion);

            Console.ReadLine();
        }

        private static void DoWork()
        {
            string connStr = "Data Source=.;Initial Catalog=DemoInserts;Integrated Security=true;
Application Name=DemoInserts";

            int countIterations = 0;
            while (countIterations < 63) // 63
            {
                using (SqlConnection conn = new SqlConnection(connStr))
                {
                    conn.Open();

                    using (SqlCommand cmd = new SqlCommand())
                    {
                        cmd.Connection = conn;

                        int countValues = 0;
                        var builder = new StringBuilder();

                        builder.Append("INSERT INTO Test(Id,Payload) VALUES ");

                        while (countValues < 1000)
                        {
                            builder.Append("(NEWID(), REPLICATE('X',20)) ");

                            if (countValues != 999)
                                builder.Append(",");

                            countValues++;
                        }

                        cmd.CommandText = builder.ToString();
                        cmd.ExecuteNonQuery();
                        countIterations++;
                    }
                }
            }
        }
    }
}

Con esta nueva versión, usando ocho hilos, baje el tiempo a… (redoble de tambor, por favor) 4 segundos escasos!!!!

Llegados a este punto me sorprendí yo mismo; no creí que pudiera bajar tanto el tiempo de estas inserciones, y por primera vez vi peligrar mi dentadura ;) Como me encanta tener datos y números de cada mejora que voy logrando, volví a lanzar la prueba y consulté las estadísticas de esperas del servidor durante el tiempo de ejecución de la misma:

Como podéis ver, el hecho de agrupar las inserciones en batches ha hecho milagros! ahora mismo el servidor esta dedicando aproximadamente el mismo tiempo a escribir en el log de transacciones que en en resolver bloqueos de latches, una situación más normal, y que ha repercutido de manera espectacular en el rendimiento de estas inserciones.

(*): Por si alguien se lo pregunta, yo tampoco tengo ni puñetera idea de por qué el hard-limit de mil filas.

Y por hoy ha estado bien, ¿no? ;)

Con esta entrada he buscado abriros un poco el apetito y, con un poco de suerte, picar a alguien más para que entre al pequeño juego que tenemos Unai y yo. He explicado mis aproximaciones iniciales, pero me reservo para la siguiente entrada la solución ‘buena, buena’ desde el lado del SQL Server.

Para los mas ansiosos os iré adelantando que se basa en particionar la tabla para evitar contención sobre la misma; los detalles de implementación los pondré en mi siguiente post, pero como mis actualizaciones son como los despertares del lazy_writer (ya sabéis, puede ser dentro de 3 milisegundos, o dentro de 3 años!), os he querido adelantar la técnica por si queréis investigarla por vosotros mismos.

A modo de resumen, voy a finalizar con otra gráfica de estas elegantes y vistosas, que hoy tengo el día ejecutivo ;)

Por cierto, si os preguntáis que tal lo hizo MongoDb… vais a tener que esperar a que Unai lo publique en su blog. No obstante, os puedo adelantar que fue capaz de bajar de estos 4 segundos….

...

¡¡¡¡Pero yo también!!!! Muahahahaha!!! ;)

Keep Rockin’!

Rock Tip:

Hacía mucho tiempo que no compartía con vosotros uno de mis rock tips… o mejor dicho, hacía mucho que no compartía nada con vosotros! Tengo el blog muy dejado, pero un servidor no da para más :(

En esta ocasión me traigo a uno de mis descubrimientos del año, los geniales Reckless Love. Banda finlandesa liderada por el increíble Olly Herman, quien fuera vocalista de Crashdiet por una breve temporada y una de las personas con mas carisma y buen rollo que he visto nunca sobre un escenario. Herederos de las mejores raíces del hard rock melódico ochentero, pero con un increíble toque dance y discotequero, puedo afirmar que verles en directo es la experiencia mas cercana a ver al David Lee Roth sin recurrir a un De Lorean con condensador de fluzo.

El tema que he escogido es el single de su segundo (y último hasta la fecha) disco: Hot. No tiene gran relación con la temática de la entrada, pero realmente me apetece compartir este tema con el mundo: si a uno solo de vosotros le hace sentir tan solo una decima parte de lo bien que me sienta a mi escuchar este temazo, ya habrá justificado saltarme mi costumbre de poner temas relacionados.

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

Pablo Alvarez — Tue, 27 Jul 2010 15:39:00 GMT

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.

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.

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 :P

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:

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:

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):

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:

Revisión del informe Server Dashboard para buscar presencia de consultas AdHoc
Consulta sobre sys.dm_exec_cached_plans para ver el ratio AdHoc/No AdHoc
Consulta para ver la memoria fugada en planes no reutilizados
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 :)

Pinball Map: Cuidado con los Mapeos en NHibernate

Pablo Alvarez — Tue, 08 Jun 2010 11:25:00 GMT

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! ;)

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

Pablo Alvarez — Tue, 01 Jun 2010 18:13:00 GMT

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!

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

Pablo Alvarez — Tue, 25 May 2010 20:41:00 GMT

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:

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…
Estamos hablando de la que posiblemente sea la mejor canción del mejor grupo de la historia. Punto pelota. xD
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.

The Hunter: Cazando bloqueos e interbloqueos

Pablo Alvarez — Sat, 07 Feb 2009 16:53:00 GMT

Después de una semana bastante dura, he podido sacar un rato para escribiros sobre un tema realmente interesante y con mucha relevancia desde el punto de vista del rendimiento y estabilidad de nuestras aplicaciones: la correcta utilización de las diversas primitivas de sincronización en nuestro código.

Bueno… en realidad os estoy engañando un poco ;) Hoy me voy a centrar en el viejo y venerable lock, y en algunas peculiaridades suyas. Quizá algún día escriba mas entradas sobre otras primitivas de sincronización, o quizá no… por ello, y si os interesan estos aspectos de la programación concurrente, permitidme que os recomiende el excelente libro de Joe Duffy.

Me vais a permitir que emplee como excusa para introducir el tema un escenario que me encontré esta semana en un cliente nuestro….

El Problema

Este cliente solicito nuestros servicios por problemas masivos de estabilidad en sus aplicación, concretamente en los servicios WCF que atacan los clientes. Durante la investigación comprobamos que teníamos muchos frentes abiertos: pérdidas de memoria, problemas con el ODP de Oracle, etc. Pero uno de los principales problemas se manifestaban a través de bloqueos masivos, que provocaban que la aplicación dejara de dar servicio durante unos minutos, a pesar de hallarse en una situación de bajo uso de CPU.

Procedimos a capturar un volcado de memoria del proceso w3wp asociado al servicio que mostraba el problema de rendimiento, a través de adplus.vbs, y se pudo comprobar rápidamente que había hilos bloqueados.

Empecé pidiéndole a tándem WinDbg + SOS.dll que me mostraran un volcado de todos los hilos administrados (.NET) de la aplicación en el momento de la captura del volcado, con el comando ~*e !ClrStack, y pude comprobar que había múltiples hilos con el mismo call stack:

OS Thread Id: 0x82c (81)
Child-SP RetAddr Call Site
0000000005a0edf0 00000642801b10c3 X.Sesion.SesionServidor.setValorConexion(System.String) 0000000005a0ee40 00000642801b0fcd X.CredencialServidor.asignarIdSesion(System.String)
0000000005a0ee70 00000642801b0de1 X.SessionInfoInterceptor.OnReceive(System.ServiceModel.Channels.Message ByRef)
0000000005a0eeb0 00000642801b0d03 X.InspectingChannelBase`1[[System.__Canon, mscorlib]].OnReceive(System.ServiceModel.Channels.Message ByRef)
[ – Corto aqui para ahorrar espacio -- ]
0000000005a0f480 000006427f67d4a2 System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)

Mucha casualidad sería que en el momento de capturar el volcado de memoria realmente 11 hilos estuvieran ejecutando el mismo método - setValorConexion - por lo que la intuición que teníamos acerca de un problema de bloqueos iba materializándose.

Hicimos una rápida comprobación mediante el comando !syncblk de las sos.dll, que nos revelo la presencia de un bloqueo:

0:000> !syncblk
Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner
   40 00000000001a3a60           13         1 000000000d99a370   748 65   0000000160058648 System.RuntimeType
-----------------------------
Total           901
CCW             2
RCW             54
ComClassFactory 0
Free            787

La línea marcada en rojo nos indica que tenemos un bloqueo sobre un objeto de tipo System.RuntimeType y que el padre del bloqueo es el hilo 65. Comprobamos a continuación los detalles del objeto de sincronización del bloqueo:

0:000> !do 0000000160058648
Name: System.RuntimeType
MethodTable: 00000642788c5790
EEClass: 00000642788c56d0
Size: 40(0x28) bytes
Type MethodTable: 000006428023ef40
Type Name: X.Comun.Seguridad.Sesion.SesionServidor

Vemos que, aparentemente, la intención del desarrollador de la aplicación era escribir un bloqueo sobre una parte del código que afectara solo a la sesión actual, pero ¿no os llama algo la atención?

Fijaros en que el bloqueo no se obtuvo sobre un objeto de tipo X.Comun.Seguridad.Sesion.SesionServidor, sino sobre un System.RuntimeType. Si pensamos a nivel de código C#, lo más posible es que le usuario haya introducido el siguiente código para obtener el bloqueo:

lock (typeof(SesionServidor))
{
// Hacer algo...
}

O bien algo como lo siguiente:

lock (this.GetType())
{
// Hacer algo...
}

Esto explica el porque vemos un bloque sobre un System.RuntimeType, y más importante aún… explica la razón de los bloqueos. Pero antes de desvelar el misterio, es hora de….

Un poquito de teoría

DISCLAIMER: No puedo evitarlo, me gustan los internals y el saber el porque de las cosas ;) Aun así, entiendo que no todo el mundo es igual, por lo que si quieres saltarte esta parte lo entenderé perfectamente. Lo que si te recomendaría es que te leyeras las conclusiones, ya que ahí resumo las recomendaciones mas importantes que se derivan de lo que voy a explicar aquí.

El establecer estos bloqueos sobre un objeto de tipo System.RuntimeType o System.Type debe ser considerado, no solo como una mala practica, sino directamente como un bug. Hay dos motivos principales por los que esto se puede considerar un bug de consideración:

Al emplear un objeto publico como objeto de sincronización, la aplicación se está exponiendo a que cualquier usuario o desarrollador emplee ese mismo tipo para adquirir un bloqueo, provocando en ese momento el interbloqueo.
Los tipos System.RuntimeType y System.Type son tipos Marshall-By-Bleed, lo que quiere decir que se comparten incluso a través de la frontera de los AppDomains. Si cualquier otro hilo, en cualquier otro proceso del sistema (ya sea desarrollado por nosotros o por terceros) adquiere un bloqueo sobre cualquier tipo a través de un typeof() o de un GetType(), se podrá producir esta situación de interbloqueo.

El segundo punto es particularmente importante, ya que implica que las posibilidades de que ocurra un interbloqueo son mucho más elevadas, al tener que tomar en consideración los bloqueos que todas las aplicaciones administradas que se estén ejecutando en la máquina vayan a tomar, hayan sido desarrolladas por nosotros o no. Además, su localización y depuración va a resultar extremadamente costosa, debido a que algunos participantes del bloqueo podrían no aparecer en los volcados de memoria, al estar en otro proceso diferente.

Volviendo a nuestra Historia

Cuando comprobamos que había un bloqueo sobre un System.RuntimeType, decidimos hacer una revisión sobre el código de nuestro cliente, y pudimos comprobar como había cientos de ocurrencias, literalmente, de bloqueos sobre typeof() y GetType().

Evidentemente esto incrementa las posibilidades de interbloqueo de una manera salvaje, y sobre todo, no controlada, ya que nos pone a merced de otros desarrollos que se ejecuten en el mismo servidor.

¿Cual es la solución? Pues generalmente es revertir al viejo y clásico mecanismo de bloquear sobre un object, que sea un atributo de clase privado y estático para hacerlo robusto a hilos. Es el viejo sistema, si… y el que deberemos emplear en el 99,9% de los casos. :)

Conclusiones

Me gustaría terminar con una serie de recomendaciones:

Nunca bloquees por un objeto que no sea estático:

Eso solo serviría para proteger los miembros de esa instancia concreta, y rara vez es esto lo que deseamos con un lock.

Nunca hagas un lock sobre un objeto publico:

Como se explico previamente, el lock sobre el objeto publico significa que otra parte de la aplicación puede hacer un lock sobre el mismo objeto y ocasionar un interbloqueo.

Sobre todo, la mas importante de todas… Nunca hagas un lock sobre un System.RuntimeType o System.Type:

Ya sabéis, si leísteis la parte teórica, que estos tipos son Marshal-by-bleed, lo que significa que se comparten entre dominios de aplicación diferentes. El riesgo de interbloqueo es enorme, y no puedo pensar en un solo escenario en que tenga sentido hacer ese bloqueo.

NOTA: Evidentemente, todos mis nunca son matizables xDD

NOTA 2: Os dejo, que me voy a ver a Medina Azahara :P

Rock Tip:

El Rock Tip de esta entrada le corresponde a The Hunter, un grandísimo tema de Dokken, grupo que, si la memoria no me traiciona, ¡nunca había aparecido en mi blog! Para intentar resarcirme de esta afrenta a los dioses del metal he decidido incluirlos en esta entrada por los siguientes motivos:

The Hunter me pareció una metáfora bastante acertada al trabajo realizado para localizar los problemas de interbloqueos, y para el trabajo del DOT en general :)
El disco (perdón, ¡discazo!) en el que este tema vio la luz se llama Under Lock and Key…. under lock…. ehh.. bueno, dejadlo, me hizo gracia en su momento xD

Lo dicho, grupo muy recomendable; tremenda pareja hacían el vocalista Don Dokken y el guitarrista George Lynch. No os perdáis temas como ‘In my dreams’, ‘Alone Again’ o ‘Dream Warriors’, que sin duda están entre lo mejorcito que nos trajo el hard rock/AOR ochentero americano.

Children of the Damned: Cuidado con vuestras aplicaciones MDI

Pablo Alvarez — Mon, 02 Feb 2009 17:25:00 GMT

A pesar del titulo de esta entrada, no voy a entrar a discutir si las aplicaciones con interfaz MDI son usables o no, si son feas como el demonio o si le dan un bonito toque retro a nuestras aplicaciones. No, eso se lo dejo a nuestros chicos de UX.

Yo me pondré el uniforme del DOT, ya que os voy a hablar de un escenario que nos encontramos recientemente en un cliente nuestro y que reunió, en único caso, los tres ingredientes que toda buena sesión de depuración y optimización deben de tener: problemas de gestión de memoria, un bug escandaloso y grandes dosis de cafeína :)

Al turrón…

El Problema

Nuestro cliente requirió nuestros servicios de optimización para optimizar una aplicación que iba a pasar a producción en menos de un mes. Como os podéis imaginar éste requisito supone todo un reto, ya que nos podemos ir olvidando de las mejores recomendaciones a nivel de rendimiento – las que implican cambios de arquitectura – y nos obliga a centrarnos en la búsqueda de rendimiento línea a línea, byte a byte. Divertidísimo, seguro, pero no tanto cuando solo tienes una semana, ¡y las máquinas cliente que van a ejecutar la aplicación cuentan con 512Mb en el mejor de los casos!

Bien, con estas premisas os podéis imaginar que uno de nuestros objetivos principales fue estudiar el consumo de memoria de la aplicación, monitorizando los aspectos básicos como el número de recolecciones de basura en cada generación, la memoria total en el Managed Heap, y la valiosísima información mostrada por el comando !DumpHeap –stat de las SOS.dll para comprobar el histograma de distribución de Tipos en el Managed Heap. También agregamos a nuestro arsenal el .NET Memory Profiler, un producto que, a pesar de ser poco más que un maquillaje sobre el venerable CLR Profiler en muchos aspectos, me ha sorprendido muy gratamente por algunas de sus funcionalidades, su facilidad de uso y de lectura de datos. En breves espero hacer una pequeña reseña del mismo, pero os invito a que os descarguéis la versión de evaluación y empecéis a jugar con ella.

Nuestras primeras investigaciones arrojaron unos números elevadísimos de recolecciones de basura, mucha fragmentación de memoria y, en definitiva, una gran cantidad de indicaciones de que la aplicación estaba sufriendo una gran presión de memoria. Modificamos la aplicación levemente para agregarle un botón que invocaba a GC.Collect() y GC.WaitForPendingFinalizers(), y lanzamos una serie de pruebas monitorizando como se comportaba la memoria y si estábamos fugando en algún sitio.

… y descubrimos algo interesante ;) La interfaz de la aplicación consistía en una ventana MDI padre, que instanciaba una ventana MDI hija para cada tipo de operativa de la aplicación. Estas ventanas tenían un coste masivo en memoria, pues contenían gran cantidad de DataSets, DataTables, etc. pudiendo alcanzar los 60Mb en memoria, pero el cliente confiaba en que al cerrar la ventana esta memoria se eliminara. Hicimos una prueba muy sencilla, por el método clásico ;)

Abrimos la aplicación y comprobamos el estado de la memoria en vacio.
Abrimos un formulario, trabajamos un poquito con el.
Cerramos el formulario.
Pulsamos el botón mágico que invoca al GC y monitorizamos el estado de la memoria.

Al fin de la prueba pudimos comprobar como la memoria consumida por el formulario no se liberaba nunca, a pesar de las invocaciones explicitas al GC.Collect(). Estaba claro que había alguna referencia al formulario hijo que no se liberaba, y eso impedía la recolección del mismo, con todos sus instancias internas de DataTables, etc. Como ya hemos visto en otros casos en este blog, tiramos de !DumpHeap para encontrar la dirección del formulario en cuestión (MDIPropuesta) y, a partir de su dirección, miramos las roots con !GCRoot:

0:011> !DumpHeap -stat
total 59745 objects
Statistics:
      MT    Count    TotalSize Class Name
[…]
03c94a3c        1          496 XXX.Dominio.Activo.Propuestas.IU.Formularios.MDIPropuesta
[…]

0:011> !DumpHeap -mt 03c94a3c
Address       MT     Size
01b23528 03c94a3c      496
total 1 objects
Statistics:
      MT    Count    TotalSize Class Name
03c94a3c        1          496 XXX.Dominio.Activo.Propuestas.IU.Formularios.MDIPropuesta
Total 1 objects

0:011> !GCRoot 01b23528
eax:Root:01555428(System.Windows.Forms.Application+ComponentManager+ComponentHashtableEntry)->
015247f8(System.Windows.Forms.Application+ThreadContext)->
015d3910(XXX.Dominio.Activo.Propuestas.IU.Formularios.ShellMDI)->
015d3b08(System.Windows.Forms.PropertyStore)->
01632b94(System.Windows.Forms.PropertyStore+ObjectEntry[])

Como podemos ver, tenemos una referencia en el PropertyStore de la clase ShellMDI, la ventana MDI principal. Por alguna razón, no esta soltando su referencia a la ventana hija al salir esta de contexto, y en esta aplicación esta provocando que entre 40 y 60 preciados Mb no se liberen, provocando gran cantidad de GCs efímeras y la promoción de objetos de corta vida a generación 2 en muchos escenarios.

La Solución

Buscando un poco por la red pudimos comprobar que se trata de un problema conocido y reportado en https://connect.microsoft.com/VisualStudio/feedback/ViewFeedback.aspx?FeedbackID=357705&wa=wsignin1.0. Actualmente no hay parche oficial de Microsoft que conozcamos, pero aprovechándome de la información recogida en otros foros y documentos, os resumo el problema y la solución.

Hasta la versión 2.0 RTM del framework .NET, aparecía el siguiente fragmento de código para actualizar el icono cuando una ventana hija MDI es desactivada:

if( this.FormerlyActiveMdiChild != null ) { this.FormerlyActiveMdiChild.UpdateWindowIcon(true); this.FormerlyActiveMdiChild = null; }

En la versión 2.0 SP1 y siguientes, Microsoft modifico el código para resolver un problema en el caso de que la ventana se estuviera cerrando en ese momento:

if( this.FormerlyActiveMdiChild != null && !this.FormerlyActiveMdiChild.IsClosing ) {this.FormerlyActiveMdiChild.UpdateWindowIcon(true); this.FormerlyActiveMdiChild = null; }

Este cambio en el código provoca que, en ese escenario, no se ponga a NULL la propiedad FormerlyActiveMDIChild, manteniendo el padre siempre una referencia a su ultima ventana hija activa, provocando la fuga de memoria comentada.

Como solución, adoptamos una publicada orginalmente en el blog .NET and Memory, que consiste en poner la propiedad FormerlyActiveMdiChild a NULL a manopla mediante reflexión en el evento OnMdiChildActivate:

protected override void OnMdiChildActivate( EventArgs e ) { base.OnMdiChildActivate( e ); try { typeof( Form ).InvokeMember( "FormerlyActiveMdiChild", BindingFlags.Instance | BindingFlags.SetProperty | BindingFlags.NonPublic, null, this, new object[] { null } ); } catch( Exception ) { } }

Una vez implementado este cambio, comprobamos como la aplicación comenzó a comportarse como se esperaba, liberando la memoria en las siguientes invocaciones al GC.Collect() posteriores al cierre del formulario.

En nuestro caso particular, persistieron otros problemas de presión de memoria… pero como ya decía el cronista de Conan, eso, amigos… eso es otra historia ;)

Conclusión

Seré breve: Si vuestras aplicaciones emplean el framework .NET 2.0 SP1 o superior y estáis empleando una interfaz MDI, con toda probabilidad seréis victimas de este problema. No hay fix oficial de Microsoft, así que os recomiendo el workaround sugerido.

No es una perdida de memoria acumulativa, solo perderéis la memoria del ultimo formulario abierto, pero aún así puede ser determinante como en el caso que os he expuesto aquí.

Notas Finales

Supongo que a estas alturas no es necesario recordarlo, pero nunca esta de más: las continuas referencias en este articulo a GC.Collect() se han empleado solo con fines de depuración y análisis. Nunca debéis invocar explícitamente al GC a no ser que Jeffrey Richter, Maoni o Luis Guerrero os lo pidan en persona :)
Cada vez que invocáis a GC.Collect(), Dios mata a un gatito.
De verdad, no lo hagáis.

Rock Tip:

Children of the Daaaaaaaaamneed!!! Chiiiiildren of the Damneeeeeeed!! (entónese con estilo Bruce Dickinson o estilo alcade Adam West, es indiferente).

La aventurilla de los formularios ‘hijos’ de ese ‘maldito’ MDIParent me sirven como excusa perfecta para recomendaros ese ‘Children of the Damned’, temazo aparecido en el The Number of the Beast de los Iron Maiden alla por el año 1982.

Por cierto, esta canción la empleaba Sebastian Bach en sus tiempos de Skid Row para calentar y para las pruebas de sonido; ¡no os perdáis sus excelentes versiónes!.

Für Immer: The Return of the WeakReference

Pablo Alvarez — Fri, 07 Nov 2008 22:55:00 GMT

¿A que el titulo del post parece de una película de Hollywood? Bueno, pues por ahí van los tiros, y es que recientemente he tenido la oportunidad de tirar bastante de WinDbg para resolver problemas de rendimiento o estabilidad en algunos de nuestros clientes, y uno de estos escenarios ha sido particularmente interesante y lo he vivido casi como un episodio de CSI. ¡Y luego me preguntan por qué me gusta mi trabajo! :)

Si me gustaría dejar claro que este post no forma parte del tutorial de WinDbg que tenía empezado; voy a suponer ciertos conocimientos de la herramienta y de .NET ya que mi objetivo es compartir esta sesión de depuración con vosotros, y no utilizarlo como ejemplo de formación.

Ah... y al más puro estilo de las películas y series americanas, os diré que todos nombres han sido cambiados para preservar la identidad de los implicados. En este caso, si veis nombres de métodos o clases ridículas, simplemente achacadlo a mi falta de imaginación o creatividad.

Al turrón...

El problema

El cliente nos comenta que sus servicios presentan graves problemas de estabilidad, provocando que con cierta frecuencia (últimamente esta frecuencia era diaria) estos servicios dejaran de responder y tuvieran que reciclarse.

Evidentemente, lo que el cliente deseaba en este caso era localizar la raíz del problema y descubrir alguna solución o workaround para mejorar la disponibilidad de sus servicios.

El Análisis

Lo primero que hice fue capturar un volcado de memoria del proceso una vez que éste se encontraba detenido, mediante el script adplus.vbs en modo hang. Una vez con el volcado en mi poder, me senté a analizarlo con calma con el WinDbg.

Lo primero que hice fue examinar el estado de los hilos, y pude comprobar que multitud de ellos estaban detenidos en espera por otros recursos, como reflejaban las cimas de sus pilas con WaitForMultipleObjects y WaitForSingleObject. Me llamo especial atención este calll stack:

26 Id: fec.c20 Suspend: 1 Teb: 000007ff`fff7c000 Unfrozen

Child-SP RetAddr Call Site
00000000`0588fad8 00000000`77d6cffb ntdll!ZwWaitForMultipleObjects+0xa
00000000`0588fae0 00000000`77d6bb01 kernel32!WaitForMultipleObjectsEx+0x1cf
00000000`0588fc00 00000642`7f48455e kernel32!WaitForMultipleObjects+0x11
00000000`0588fc40 00000642`7f5e5fab mscorwks!SVR::WaitForFinalizerEvent+0x7e
00000000`0588fc70 00000642`7f498474 mscorwks
SVR::GCHeap::FinalizerThreadWorker+0x6b
00000000`0588fcb0 00000642`7f5ca069 mscorwks!FusionBind::VerifyBindingStringW+0x78
00000000`0588fd00 00000642`7f47297d mscorwks!EEClass::FindPropertyMethod+0x175
00000000`0588fdd0 00000642`7f45cc3a mscorwks
MDInternalRW::GetMethodSpecProps+0xc9
00000000`0588fe10 00000642`7f5eb824 mscorwks!ManagedThreadBase_NoADTransition+0x42
00000000`0588fe70 00000642`7f4545bc mscorwks!SVR::GCHeap::FinalizerThreadStart+0x74
00000000`0588feb0 00000000`77d6b6da mscorwks!Thread::intermediateThreadProc+0x78
00000000`0588ff80 00000000`00000000 kernel32!BaseThreadStart+0x3a

Se trata de un hilo especial, pues éste hilo se corresponde al finalizador, responsable de finalizar los objetos en las recolecciones de basura. ¿Como sabemos que es el finalizador? Es fácil, por el call stack... ¡métodos como el GCHeap::FinalizerThreadStart nos dan una buena pista! Aún así, si queremos asegurarnos podemos lanzar un !Threads, que en este caso devolvió la siguiente salida:

0:000> !threads
ThreadCount: 24
UnstartedThread: 0
BackgroundThread: 19
PendingThread: 0
DeadThread: 5
Hosted Runtime: yes
                                              PreEmptive
       ID OSID        ThreadOBJ     State   GC    ... APT Exception
16    1 12b8 00000000001563a0   1808220 Enabled ... MTA (Threadpool Worker)
26    2 c20 0000000000171c10      b220 Enabled ... MTA (Finalizer)
27    3 1244 00000000001799c0      1220 Enabled ... Ukn
28    4 efc 000000000019b010    80a220 Enabled ... MTA (Threadpool Completion Port)
14    7 13e8 000000000659c480   880a220 Enabled ... MTA (Threadpool Completion Port)
30    9 1248 00000000065bd650   200b220 Enabled ... MTA
31    b 7bc 00000000065897d0   200b220 Enabled ... MTA
32    d 9dc 0000000006618760    80a220 Enabled ... MTA (Threadpool Completion Port)
37    e c60 00000000065d83e0   180b220 Enabled ... MTA (Threadpool Worker)
40   11 2b4 00000000066718b0   180b220 Enabled ... MTA (Threadpool Worker)
41   12 162c 00000000065f7990   180b220 Enabled ... MTA (Threadpool Worker)
42   13 149c 00000000067692f0   180b220 Enabled ... MTA (Threadpool Worker)
43   14 1280 0000000009261760   180b220 Enabled ... MTA (Threadpool Worker)
44   15 a84 0000000006686060   180b220 Enabled ... MTA (Threadpool Worker)
45   19 14fc 00000000095e7880   200b220 Enabled ... MTA
46    5 e50 00000000092c2a40   200b220 Enabled ... MTA
47   1a a04 00000000066a4c60   200b220 Enabled ... MTA
48   16 11ec 0000000033046980   880b220 Enabled ... MTA (Threadpool Completion Port)
50   25 d64 000000002f4ca930   180b220 Enabled ... MTA (Threadpool Worker)
XXXX   18    0 000000002cb93a40   8801820 Enabled ... Ukn (Threadpool Completion Port)
XXXX   1d    0 0000000016b345f0   8801820 Enabled ... Ukn (Threadpool Completion Port)
XXXX   1b    0 00000000154fa520   8801820 Enabled ... Ukn (Threadpool Completion Port)
XXXX   20    0 00000001c0750a10   8801820 Enabled ... Ukn (Threadpool Completion Port)
XXXX   1e    0 00000001c0bc0010   8801820 Enabled ... Ukn (Threadpool Completion Port)

Como vemos, la salida nos muestra claramente que el hilo 26 es el finalizador, lo que confirma nuestra sospecha de antes.

Sabiendo que el finalizador está bloqueado no nos es difícil llegar a la conclusión de que la memoria no debe andar muy fina. Para ver su estado general, lanzamos un !dumpheap -stat, que nos devuelve la siguiente información:

0:031> !dumpheap -stat
------------------------------
Heap 0
total 1222297 objects
------------------------------
Heap 1
total 1273253 objects
------------------------------
Heap 2
total 1126040 objects
------------------------------
Heap 3
total 1243940 objects
------------------------------
Heap 4
total 1344846 objects
------------------------------
Heap 5
total 1194789 objects
------------------------------
Heap 6
total 1279943 objects
------------------------------
Heap 7
total 1137244 objects
------------------------------
total 9822352 objects

Statistics:

MT Count TotalSize Class Name
00000642bcf6ddd8 1 24 System.Web.Configuration.FormsProtectionEnum
(..)
000006428044b780 286785 36708480 XX.Contratos.Entidad.Maestros.CompaniaEntidad
0000064280564b40 389036 37347456 XX.Contratos.Entidad.Maestros.TipoBasicoEntidad
0000064278909f18 9736 37949592 System.Int32[]
(..)
000006427890a150 330357 117567984 System.Object[]
0000064280588ec0 235248 120446976 XX.Contratos.Entidad.Proveedores.FacturaProveedorEntidad
000000000015c1a0 368 182038624 Free
00000642788c1ad0 4208597 243318792 System.String
Total 9822352 objects
Fragmented blocks larger than 0.5 MB:
Addr Size Followed by
00000000a6d9fb88 67.6MB 00000000ab140920 System.Collections.ArrayList
00000000c63b7740 66.5MB 00000000ca63b0d0 System.ServiceModel.Activation.HostedHttpContext

He recortado mucho la salida del !dumpheap para que coja correctamente en el blog, y os he marcado los detalles mas relevantes. Por una parte, la gran cantidad de objetos que tenemos en todos los heaps, así como esos dos objetos enormes que tenemos en los Large Object Heaps (LOH). Y por último, y más significativo, es la gran cantidad de memoria que aparece como Free, que se corresponde con memoria que ha sido marcada para limpieza, pero que aun no ha sido recogida por el GC. Generalmente, un alto porcentaje (a partir de un 30%) de memoria Free vs. la memoria total de todos los heaps suele ser indicativo de problemas de fragmentación de memoria, a menudo producida por objetos pinned (objetos estáticos, que van a permanecer siempre en la misma posición en el managed heap).

Vamos a concretar un poco más mirando nuestra cola de finalización, con !FinalizeQueue:

0:031> !FinalizeQueue
SyncBlocks to be cleaned up: 0
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
------------------------------
Heap 0
generation 0 has 6 finalizable objects (000000002ff5c8c8->000000002ff5c8f8)
generation 1 has 15 finalizable objects (000000002ff5c850->000000002ff5c8c8)
generation 2 has 9480 finalizable objects (000000002ff4a010->000000002ff5c850)
Ready for finalization 0 objects (000000002ff5c8f8->000000002ff5c8f8)
------------------------------
Heap 1
generation 0 has 36 finalizable objects (00000000392f56d8->00000000392f57f8)
generation 1 has 13 finalizable objects (00000000392f5670->00000000392f56d8)
generation 2 has 10956 finalizable objects (00000000392e0010->00000000392f5670)
Ready for finalization 0 objects (00000000392f57f8->00000000392f57f8)
------------------------------
Heap 2
generation 0 has 42 finalizable objects (00000001c3cf9ee8->00000001c3cfa038)
generation 1 has 91 finalizable objects (00000001c3cf9c10->00000001c3cf9ee8)
generation 2 has 11334 finalizable objects (00000001c3ce39e0->00000001c3cf9c10)
Ready for finalization 0 objects (00000001c3cfa038->00000001c3cfa038)
------------------------------
Heap 3
generation 0 has 109 finalizable objects (00000001c3d23208->00000001c3d23570)
generation 1 has 15 finalizable objects (00000001c3d23190->00000001c3d23208)
generation 2 has 12986 finalizable objects (00000001c3d09bc0->00000001c3d23190)
Ready for finalization 0 objects (00000001c3d23570->00000001c3d23570)
------------------------------
Heap 4
generation 0 has 8 finalizable objects (00000001c3af48b8->00000001c3af48f8)
generation 1 has 64 finalizable objects (00000001c3af46b8->00000001c3af48b8)
generation 2 has 12035 finalizable objects (00000001c3adcea0->00000001c3af46b8)
Ready for finalization 0 objects (00000001c3af48f8->00000001c3af48f8)
------------------------------
Heap 5
generation 0 has 71 finalizable objects (000000001f6c9070->000000001f6c92a8)
generation 1 has 87 finalizable objects (000000001f6c8db8->000000001f6c9070)
generation 2 has 11207 finalizable objects (000000001f6b2f80->000000001f6c8db8)
Ready for finalization 0 objects (000000001f6c92a8->000000001f6c92a8)
------------------------------
Heap 6
generation 0 has 146 finalizable objects (00000001c3c3a1c0->00000001c3c3a650)
generation 1 has 25 finalizable objects (00000001c3c3a0f8->00000001c3c3a1c0)
generation 2 has 12829 finalizable objects (00000001c3c21010->00000001c3c3a0f8)
Ready for finalization 0 objects (00000001c3c3a650->00000001c3c3a650)
------------------------------
Heap 7
generation 0 has 9 finalizable objects (00000001c3d4bd48->00000001c3d4bd90)
generation 1 has 26 finalizable objects (00000001c3d4bc78->00000001c3d4bd48)
generation 2 has 14299 finalizable objects (00000001c3d2fda0->00000001c3d4bc78)
Ready for finalization 0 objects (00000001c3d4bd90->00000001c3d4bd90)
Statistics:
              MT    Count    TotalSize Class Name
00000642bcf589f8        1           24 System.Web.Configuration.ImpersonateTokenRef
0000064278963e28        1           24 System.Threading.OverlappedDataCache
00000642bcf4d948        1           32 System.Web.PerfInstanceDataHandle
00000642b78f1b28        1           32 Bid+AutoInit
00000642789b0608        1           32 System.Security.Cryptography.SafeHashHandle
00000642788cd1b8        1           32 Microsoft.Win32.SafeHandles.SafeFileMappingHandle
00000642788cd110        1           32 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle
0000064274f044d8        1           32 System.Net.SafeLocalFree
0000064274ee4c20        1           32 Microsoft.Win32.SafeHandles.SafeFileMapViewHandle
0000064274ee4ad0        1           32 Microsoft.Win32.SafeHandles.SafeFileMappingHandle
0000064274ee0598        1           32 Microsoft.Win32.SafeHandles.SafeProcessHandle
0000064278964118        1           40 System.Threading.RegisteredWaitHandleSafe
0000064278963da8        1           40 System.Threading.OverlappedDataCacheLine
0000064274ed8928        1           48 Microsoft.CSharp.CSharpCodeProvider
00000642bcf56b88        1           56 System.Web.Compilation.CompilationMutex
00000642802cd880        1           56 Microsoft.Practices.EnterpriseLibrary.Caching.Cache
00000642788ffea8        2           64 Microsoft.Win32.SafeHandles.SafePEFileHandle
00000642788e3160        2           64 System.Security.Cryptography.SafeProvHandle
0000064274ef89b0        2           64 System.Net.SafeCloseSocket+InnerSafeCloseSocket
0000064274f05b90        2           80 System.Net.SafeRegistryHandle
00000642788f9c68        3           96 Microsoft.Win32.SafeHandles.SafeTokenHandle
0000064274f05798        2           96 System.Net.SafeCloseSocketAndEvent
00000642bc59aea0        4          128 System.Transactions.SafeIUnknown
00000642802b2380        2          176 Oracle.DataAccess.Client.ConnectionPool
00000642788e1428        2          208 System.Runtime.Remoting.Contexts.Context
00000642802b9b00        8          256 Oracle.DataAccess.Types.OpoDecCtx
00000642802374c0        4          320 Microsoft.Practices.EnterpriseLibrary.Common.Configuration.Storage.ConfigurationChangeFileWatcher
00000642bcf4f7a0        7          392 System.Web.DirMonCompletion
00000642bc593f80       11          440 System.Transactions.FinalizedObject
00000642788d2110       14          448 Microsoft.Win32.SafeHandles.SafeRegistryHandle
0000064274eda4c0       10          480 System.CodeDom.Compiler.TempFileCollection
00000642bcf53138       14          560 System.Web.ProcessImpersonationContext
00000642788d5b40       10          640 System.Threading.ReaderWriterLock
00000642bcf4eb78       20          800 System.Web.ApplicationImpersonationContext
00000642788ec748       28          896 Microsoft.Win32.SafeHandles.SafeWaitHandle
00000642788c9250       28          896 Microsoft.Win32.SafeHandles.SafeFileHandle
00000642788ec928       28         1120 System.Threading.TimerBase
00000642bcf6f9f0       32         1280 System.Web.ClientImpersonationContext
0000064274ee3290       10         1680 System.Diagnostics.PerformanceCounter
00000642bc59af50       60         1920 System.Transactions.Oletx.CoTaskMemHandle
0000064278963bb8       16         1920 System.Threading.OverlappedData
00000642788c2360       21         2184 System.Threading.Thread
00000642802b6180       12         2496 Oracle.DataAccess.Client.OracleDataReader
00000642788df980       27         3240 System.IO.FileStream
00000642800c9200      190         6080 Oracle.DataAccess.Client.UTF8CommandText
00000642800c8a40       46         9936 Oracle.DataAccess.Client.OracleConnection
00000642800c6f00       55        14960 Oracle.DataAccess.Client.OracleCommand
00000642789a9290     1062        76464 System.Reflection.Emit.DynamicResolver
00000642bcf89bd0     7542       301680 System.Web.HttpResponseUnmanagedBufferElement
00000642800c90c0     8992       503552 Oracle.DataAccess.Client.MetaData
00000642788cf7d0    77605      2483360 System.WeakReference
Total 95889 objects

Wow!! A parte de la enorme cantidad de objetos en Generación 2 en todos los heaps, algo bastante alarmante de por si... ¡fijaros en esas 77605 instancias de System.WeakReferences pendientes de finalización!

Er... WeakReferences... mm... ¿de que no suenan? Bueno, a los geekeros de pro, seguro que nos trae a la mente estos dos geniales posts: Fugando Memoria con .NET y Un poco de WinDbg aplicado, de los grandes Rodrigo Corral y David Salgado :)

Mi primera pregunta fue ¿de dónde demonios salen todas esas WeakReferences? Tras tirar un poco del hilo con !GCRoot no encontré claramente su origen, por lo que saque la artillería pesada: La funcionalidad de 'buscar en toda la solución' de Visual Studio :D Pues bien... ninguna coincidencia con WeakReference. Fue entonces cuando se me encendió la bombillita y recordé que nuestro cliente empleaba Enterprise Library 3.0, así que fui raudo y veloz como una exhalación a buscar mi WeakReference perdida en la EntLib... y nada :(

Finalmente decidí dejarme de artillería pesada, y hacer las cosas bien nuevamente :_) Así que recurrí al comando !TraverseHeap, con el cual genere un fichero de salida con el cual alimenté al CLR Profiler. Gracias a esta jugada pude ver que las WeakReferences estaban siendo creadas en un módulo antiguo del cliente, reutilizado de una versión anterior de su producto. ¡Genial! Busco en el código de esa versión y... ¡ni rastro de la WeakReference!

Llegados a este punto la sesión de depuración ya se había convertido en algo personal; ahi estaba el volcado. Yo, cerca de él. Y entre nosotros dos, un viejo camino polvoriento, y una planta rodadora solitaria... (¡Hey... ya os dije que esto era una pelicula de Hollywood!). Decidí volver al dump y volcarme la .dll del cliente que contenía las WeakReferences a disco, gracias al comando .writemem, para así poder estudiarla con Reflector.

Una vez abierto el código con Reflector, pude comprobar como el constructor del objeto en cuestión contenía este código:

public Presupuesto(int CodigoCompañia)
{
     ArrayList list = __ENCList;
     lock (list)
     {
        __ENCList.Add(new WeakReference(this));
     }
     this.mCodigoPais = Program.PaisActual;
     this.mCodigoCompañia = CodigoCompañia;
}

Er... ¿WTF? XD ¿Qué demonios es esa colección llamanda __ENCList y que está haciendo en nuestro modulo? ¡¡Pero si esa colección no esta en el código fuente del cliente!!

[Saco mi guía del autoestopista galáctico, leo el 'Don't Panic' e inmediatamente me siento reconfortado... procedamos...]

Una búsqueda por internet me hizo descubrir que esa colección __ENCList la crea automágicamente Visual Studio para Vb.NET en modo DEBUG, y en C# activando una opción llamada Edit And Continue. Si, señores y señoras, al parecer el Edit And Continue instrumenta el código. ¡En nuestro caso esta instrumentación acabó en producción ya que se desplegó la .DLL en modo DEBUG!

Conclusiones

La primera conclusión es clara y concisa... ¡repetid conmigo!

"No voy a poner en producción código compilado en modo DEBUG."

Bien, después de interiorizar esta frase y adquirir el firme propósito de repetirla 5 veces cada mañana al despertarnos durante un mes, podemos extraer otras conclusiones:

WinDbg mola:

Si no fuera gracias a la captura del volcado de memoria, hubiera sido muy, pero que muy difícil dar con este problema. ¡Recordad que el código 'ofensor' no se encontraba ni siquiera en los fuentes del cliente! Solo pudimos 'cazarlo' porque recurrimos a la imagen en memoria del módulo, que no se correspondía con el código fuente.

Invertir un tiempo en formar a nuestros desarrolladores en herramientas de depuración siempre compensa:

Si vais a acudir al Tech-Ed de Barcelona, me gustaría recordaros que Tess Ferrandez va a andar por ahí y va a dar un par de sesiones; podría ser un buen punto de partida para este tipo de formación en depuración avanzada. No hace falta que os la presente, a estas alturas todo el mundo conoce ya a la diosa del WinDbg!

Si no podéis acudir al Tech-Ed, no os preocupéis... siempre os quedará el DOT ;)

No poner en producción código compilado en modo DEBUG.

¿Que la he dicho ya? Nunca está de más repetirlo.

Rock Tip:

En alemán Für Immer significa para siempre. Für Immer estaría nuestro finalizador esperando, bloqueado, y haciendo que la memoria reservada por nuestra aplicación creciera y creciera, Für Immer estaría nuestro cliente experimentando las continuas caídas del servicio, y 'Für Immer'... es también uno de los temas más conocidos de la magnísima señora Doro Pesch.

Nuestra amiga Dorotea es una de las más grandes féminas que pululan por el panorama del hard rock y heavy internacional. Su estilo es inconfundible; si bien hace poco os hablaba de Sandi Saraya y de su dulce voz, con Doro nos encontramos con un enfoque totalmente diferente, caracterizado por autentica actitud heavy y una voz con más fuerza y garra que muchisimos vocalistas masculinos. Desde sus tiempos en Warlock hasta sus últimos trabajos en solitario, nunca ha perdido un ápice de su estilo.. nunca se ha vendido. ¡Tan solo eso me hace quitarme mi sombrero de cowboy ante esta señora!

En serio, si os va el heavy o el hard rock y nunca habéis escuchado nada de Doro, Tio Doval os recomienda muy encarecidamente que no os perdáis su discografía. Os sugiero empezar con esto: 'All we Are'.

Keep Rockin'!

Back to the Bullet: Sesión de Depuración y Optimización

Pablo Alvarez — Fri, 03 Oct 2008 23:55:12 GMT

El jueves pasado tuve la oportunidad de pasar unas horas hablando sobre depuración avanzada y optimización de aplicaciones junto a mi compañero y amigo Luis Guerrero, del DOT Team de Plain Concepts. La respuesta ha sido muy buena, tanto en correos de agradecimiento, así como comentarios y preguntas (que espero responder a lo largo de este fin de semana! ;-) ), así que lo suyo es que, a pesar de lo abandonadito que tengo el blog, al menos dedique una pequeña entrada para colgar los materiales y agradeceros la presencia en esta sesión tan especial :)

Aquí tenéis la presentación de Introducción a la Depuración Avanzada, y aquí la de optimización de SQL Server, aunque esta ultima no la llegamos a ver por falta de tiempo.

Os dejo aquí los enlaces a las sesiones grabadas:

Por último dar las gracias a todos los que nos acompañasteis durante la sesión, ya fuera presencialmente o a través de la sesión de Live Meeting, así como a los chicos del CIIN, que nos permitieron 'hostear nuestro proceso en su AppDomain' :) .

Rock Tip:

El rock tip de hoy no tiene mucha relación con el tema, simplemente me apeteció titular al post con 'Back to the Bullet' porque hacía mucho que no sacaba un ratín para escribir en geeks.ms, y esta es mi vuelta, mi regreso al redil ;) La expresión me vino a la cabeza gracias al gran tema de Saraya del mismo nombre, que a pesar de estar en el lado mas blando y ñoño de la música que yo pueda escuchar, no deja de ser un tema excelente.

Aunque el grupo tuvo éxito en su época, se separaron poco después de sacar el segundo disco; de la guapisima Sandi Saraya no os puedo contar mucho, ya que parece haberse escondido en las mismas montañas de Tora Bora, porque no ha vuelto a saberse nada de ella. El teclista de la formación, Gegg Munier, falleció hará un par de años y el guitarrista, Tony "Bruno" Rey, curiosamente fue el primer guitarrista de otro grupo que ya apareció en mas de un post mío, los inigualables Danger Danger, donde con el tiempo sería sustituido por Andy Timmons.

Patience: Ejecución de Tareas en SQL Server

Pablo Alvarez — Sun, 10 Aug 2008 13:23:00 GMT

En esta entrada estrenábamos una sección dedicada a la resolución de problemas de rendimiento en SQL Server, y os comentaba que tenía pensado dedicar éstas primeras entregas principalmente a la arquitectura del producto; mi idea es dedicar cada entrada a describir algunos de los conceptos determinantes para el rendimiento en la ejecución de nuestras consultas y acompañarlo de ejemplos prácticos.

Pues bien, en esta ocasión me gustaría hablaros de las esperas en SQL Server; un concepto fundamental de cara a la identificación de potenciales problemas de rendimiento. Y digo que me gustaría hablaros de las esperas, porque no voy a poder hacerlo :) Antes de ello, deberemos ver una introducción básica a la ejecución de tareas en SQL Server para posteriormente, en una entrada futura, introduciros a las esperas y a mi metodología de resolución de problemas de rendimiento favorita en SQL Server... (pero que bueno soy creando tensión y expectación, ¿eh? :) )

Al turrón...

Ejecución de Tareas en SQL Server

El objetivo último de SQL Server es procesar tareas, y para ello necesita una serie de recursos (disco, memoria, red...), así como, al menos, un procesador. Hasta ahí nada nuevo. Lo que quizá no se conoce tanto es que SQL Server dispone internamente de unos procesadores lógicos llamados schedulers, que van a ser clave a la hora de entender como se procesan las tareas, como interpretar las esperas y un sin fin de detalles relevantes para el rendimiento de nuestros servidores.

Cuando SQL Server arranca, una de las primeras cosas que hace es consultar al sistema operativo, mediante WMI, cuantos procesadores tiene la máquina, para posteriormente crear tantos schedulers como procesadores se hayan detectado. El objetivo de éstos será el de ejecutar las tareas del servidor (nuestras consultas, procesos internos de SQL Server como el lazy writer, etc.), de un modo coordinado con el UMS/SQLOS del que hablaremos en otra entrada.

Cada uno de esos procesadores lógicos tendrá asignada una lista de tareas, implementadas mediante worker threads, que se ejecutarán a medida que el scheduler vaya quedando libre. Estos worker threads se implementan, por defecto, como hilos del sistema operativo (se puede cambiar este comportamiento para que funcionen como fibras, en caso de tener el servidor funcionando en fiber mode), con su consiguiente consumo de memoria y recursos por cada uno de los hilos. Por esta razón, y para evitar un crecimiento masivo de hilos en el sistema, hay un parámetro de configuración del servidor llamado max_worker_threads, que permite limitar el número máximo de hilos que SQL Server va a pedir al sistema operativo para ejecutar tareas en ellos. Éste será también el número máximo de tareas que va a tener el sistema, distribuido entre todos sus schedulers.

Un par de ejemplos

El escenario más básico sería el que representamos en el diagrama de la derecha. En éste caso, disponemos de una máquina tradicional con una única CPU de un núcleo.

El proveedor WMI devolverá que hay una CPU, y SQL Server creará un único scheduler que gestionará la ejecución de todas las tareas del servidor. Habrá, por tanto, una única lista de tareas, con n worker threads, donde n es el número establecido en la variable de configuración max_worker_threads.

El siguiente escenario (en el diagrama de abajo) representa un entorno con dos CPUs de doble núcleo. Como podemos ver, cada uno de las CPUs se enumera como dos CPUs diferentes por WMI (hay dos núcleos por cada CPU), por lo que tendremos un total de cuatro schedulers. Por otra parte, vemos que habrá cuatro listas de ejecución de tareas, cada una de ellas con un limite máximo de una cuarta parte de las tareas máximas definidas por el max_worker_threads. Esto es así porqué SQL Server trata de equilibrar la carga equitativamente entre todos sus procesadores.

Hay un tercer escenario interesante, pero me lo reservo para un poquito más adelante en este mismo post :) Eso si, no me gustaría acabar esta sección sin comentar un par de detalles:

Una tarea no puede abandonar un scheduler y moverse a otro a mitad de su ejecución. Esto es, una tarea esta atada a un scheduler desde su creación hasta su finalización.
Se puede establecer una Mascara de Afinidad para determinar que CPUs vamos a usar en SQL Server, que schedulers vamos a crear, etc. pero esta fuera del ámbito de esta entrada por lo que no lo comentaremos de momento.

Consultando los Schedulers

Bien, ya hemos visto que, en teoría, existe por ahí algo que se llaman schedulers, que son CPUs lógicas que sirven para controlar la ejecución de tareas en SQL Server, y que además tienen forma de cajas de color verde con un suave y artístico degradado. Pero, sin duda alguna, en este instante os estáis preguntando si hay alguna manera de ver éstas estructuras en el servidor. Y también sé que, hasta que no descubráis como, no vas a poder conciliar el sueño. Por eso mismo, y porque no puedo tolerar el sufrimiento humano, pasamos sin más preámbulos a echar un vistazo a los metadatos que SQL Server expone para que veamos la información de los schedulers.

La siguiente query consulta sys.dm_os_schedulers, la DMV principal para obtener información acerca de los mismos:

SELECT
   scheduler_id,
   cpu_id,
   status
FROM sys.dm_os_schedulers

Mi máquina de pruebas tiene una única CPU dual core. En ella, la ejecución de la consulta muestra el siguiente resultado:

¿Y esto? ¿No deberían aparecer solo dos schedulers según lo que hemos visto arriba? Bien, lo cierto es que solo los dos que aparecen marcados en naranja son normales. Los dos que aparecen con estado HIDDEN ONLINE se emplean para procesar las tareas del sistema, mientras que los VISIBLE ONLINE se dedican al proceso de tareas de usuario, y son en las que nos fijaremos normalmente de cara a identificar potenciales problemas de rendimiento.

El último scheduler, categorizado como VISIBLE ONLINE (DAC), esta reservado exclusivamente para la Dedicated Administrator Connection (Conexión Dedicada de Administrador). Simplificando mucho, SQL Server 2005 incorpora, por defecto, un nodo NUMA oculto, compuesto por una pequeña cantidad de memoria y un scheduler, que nos permiten retomar el control del servidor para hacer troubleshooting básico del sistema en caso de que los schedulers 'normales' no estén disponibles o se encuentren monopolizados.

El la práctica, lo habitual es filtrar la búsqueda para que no nos muestre ningún scheduler cuyo ID sea menor a 255, con lo que nos quedamos solo con los schedulers de usuario.

Complicando un poco más el asunto...

En realidad el modelo no es tan sencillo como una lista de tareas por scheduler. En SQL Server la planificación de tareas es bastante mas compleja, con una serie de listas adicionales. Nosotros vamos a ver a continuación un modelo un poco más real, introduciendo la lista de esperas por recursos (resource waits).

Si os fijáis en el diagrama que tenemos a continuación, vemos como el Scheduler contiene una tarea que se haya en estado Running (en ejecución). También vemos una lista de tareas listas para ejecución (Runnable Queue), que contiene las tareas que el Scheduler podría ejecutar en cualquier momento, ya que no dependen de recursos externos (disco, otras transacciones, etc.). Por último, tenemos la lista de esperas por recursos (resource waits list) que contiene todas las tareas que aun no se han completado pero que no pueden pasar a la CPU porque dependen de una espera por un recurso externo, como pueda ser un bloqueo, operaciones de sincronización de paralelismo, una operación de disco o de red, etc.

En la siguiente entrada hablaremos de las esperas, y profundizaremos en este diagrama con ejemplos prácticos. Por ahora me conformo con haber introducido los conceptos que darán pie a hablar de las esperas en SQL Server.

Canzando Mitos: Hyperthreading vs. SQL Server

No se si os acordáis, pero en un post reciente (el término reciente en mi vida 'bloggeril' es, como podréis apreciar, bastante relativo) hice un ejercicio descarado de plagio y posiblemente violé tres o cuatrocientas leyes al adoptar el tema de los 'cazadores de mitos' para buscar un escenario práctico real en el que se aplicara la teoría vista en la entrada. Pues bien, vamos a seguir cazando mitos... en esta ocasión será el siguiente: ¿Realmente tiene sentido deshabilitar Hyperthreading(*) en nuestros servidores SQL Server?

Vamos a ver lo que sucede en una máquina con una CPU con Hyperthreading habilitado. Vemos como tenemos una única CPU, con un único núcleo, y a pesar de todo, SQL Server crea dos schedulers. ¿Por que hace esto SQL Server? Pues sencillamente porque, como os comenté, SQL Server le pregunta a Windows, a través de WMI, cuantos procesadores tiene la máquina... y no sé quien tomo la decisión de diseño (o quién pagó a quien, ni cuanto...) pero el caso es que para Windows, una máquina con Hyperthreading habilitado cuenta como si tuviera dos CPUs.

Nosotros, que somos chicos y chicas listos, sabemos que no es cierto; sabemos que el Hyperthreading es, simplificando mucho, una mejora en en las Execution Units(EU) del procesador que permiten que, en ciertas circunstancias, se ejecute trabajo en estas EU que en otros casos estarían ociosas. Pero (y éste es un gran pero...) realmente solo hay una CPU: las diferentes EUs comparten, entre otras cosas, las cachés de procesador L1 y L2. Y hete aquí que tales cachés son importantes en SQL Server, hasta el punto de que si se comparten puede haber serios problemas en dos partes fundamentales del servidor: el mecanismo de agujas del reloj del lazy writer (que sirve para sacar del Buffer Pool las páginas menos utilizadas), y el mecanismo para adquirir spinlocks (bloqueos livianos que se solicitan mediante polling constante). Al compartir las caches, es muy posible que en operaciones paralelizadas las cachés no tengan la información que deben de tener, lo que puede provocar que se saquen del Buffer Pool páginas que no deberían irse fuera (con su consiguiente pérdida de rendimiento), o peor aún, que no se pueda adquirir un spinlock.

Sin entrar en demasiado detalle, quedémonos con la idea de que SQL Server ve dos procesadores, y crea dos schedulers, pero en realidad solo es un 'truco', interesante en otro tipo de aplicaciones pero muy dañino para SQL Server. ¿Conclusión? Al menos en SQL Server 2000 y 2005 os recomiendo encarecidamente deshabilitar Hyperthreading desde la BIOS si vuestros servidores lo soportan. No se aún si SQL Server 2008 implementa algún cambio que afecte a servidores Hyperthreaded, pero en cuanto consiga hacerme con una máquina con un procesador apropiado haré la prueba.

(*): Ahhh... hyperthreading, aquella tecnología que amenaza con volver a nuestros procesadores :_) ¡que malo soy a veces con los chicos de Intel.

Conclusiones

Bueno, nos ha salido otro post un poco 'ladrillo', pero hemos sentado una buena base a la que nos referiremos en posteriores entradas. Lo más importante aquí es comprender lo que son los schedulers, tener una aproximación a las diferentes listas de tareas y ver como podemos estudiar los metadatos para hacernos una idea de si el sistema esta sufriendo de contención de CPU o no.

Evidentemente en este artículo hemos realizado algunas simplificaciones (sobre todo en el ámbito de las diferentes listas de tareas), pero en siguientes entradas entraremos en más detalle, y si no me equivoco empezaremos precisamente con las esperas de las diferentes tareas, los estados que pueden tener y como pasan de uno a otro y, sobre todo, cómo podemos utilizar esa información para comprender por donde se nos escapa el rendimiento.

Espero que os resulte interesante :)

Rock Tip:

Ya os dije en la presentación de esta entrada que vamos a tener que tener un poco de paciencia antes de poder saltar a las esperas de SQL Server, por lo que me ha parecido apropiado preceder el titulo de este post con el temazo 'Patience' de los Guns n' Roses.

Hablando de los Guns N' Roses (que, por cierto, son/fueron uno de mis grupos favoritos), ahí va mi órdago: sí el señor William 'Axl' Rose Jr. y sus secuaces (sean quienes sean) sacan el 'Chinese Democracy' durante éste año del señor de 2008, un servidor se corta el pelo. ¿Mi predicción? El disco será la banda sonora del Duke Nukem Forever xD