Surviving the Night

El blog de Pablo Doval sobre .NET, SQL, WinDbg...
Just Push Play: Depuración Avanzada (2ª Parte) en Second Nug

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

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

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

Debugging

PISTA: Pinchad en la imagen :)

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

Keep Rockin’!!!

Rock Tip:

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

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

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

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

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

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

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

Rock Tip:

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

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

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

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

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

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

Speed of Light: Optimización de SQL Server

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

Descripción:

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

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

Rock Tip:

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

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

Modern Day Cowboy: SOSEX para WinDbg

Quiero pediros un favor. Quiero que digáis todos en alto "Gracias, Steve! Tu molas!”. Y quiero que lo digáis mirando hacia el oeste. Y quiero que lo digáis alto. Y quiero que lo digáis en inglés (dejo la traducción como ejercicio al lector XD).

No se si Steve Johnson podrá oírnos, pero desde luego se merece nuestro reconocimiento y agradecimiento, pues es el autor de una de las extensiones de WinDbg más espectaculares que he probado nunca, y de la que hoy os quiero hablar: las SOSEX 2.0

Pero antes, vamos a hablar un poquito de las extensiones en WinDbg…

El Depurador Extensible

Las extensiones de WinDbg son una de sus características estrella, y lo que le convierten en un depurador tan especial. Estas extensiones son DLLs que exportan funciones que agregan ciertas capacidades al depurador a través de los comandos de extensión.

Si habéis seguido alguna de mis entradas anteriores sobre depuración de código administrado con WinDbg, ya habréis empleado comandos de extensión, ya que la archiconocida SOS.dll es una extensión de WinDbg, y comandos como !dumpheap, !printexception o !eeheap son comandos de extensión exportados por la SOS.dll. Todos los comandos que empiezan con el carácter ! (bang, en inglés), son comandos de extensión.

Podemos consultar todas las extensiones cargadas en WinDbg, y su orden, a través del comando .chain. Un ejemplo de salida de .chain en mi WinDbg:

0:001> .chain
Extension DLL search Path:

Extension DLL chain:
    dbghelp: image 6.11.0001.404, API 6.1.6, built Thu Feb 26 03:10:27 2009
        [path: C:\Program Files\Debugging Tools for Windows (x64)\dbghelp.dll]
    ext: image 6.11.0001.404, API 1.0.0, built Thu Feb 26 03:10:26 2009
        [path: C:\Program Files\Debugging Tools for Windows (x64)\winext\ext.dll]
    exts: image 6.11.0001.404, API 1.0.0, built Thu Feb 26 03:10:17 2009
        [path: C:\Program Files\Debugging Tools for Windows (x64)\WINXP\exts.dll]
    uext: image 6.11.0001.404, API 1.0.0, built Thu Feb 26 03:10:20 2009
        [path: C:\Program Files\Debugging Tools for Windows (x64)\winext\uext.dll]
    ntsdexts: image 6.1.7015.0, API 1.0.0, built Thu Feb 26 03:09:22 2009
        [path: C:\Program Files\Debugging Tools for Windows (x64)\WINXP\ntsdexts.dll]

Como se puede ver, tengo cargadas las extensiones dgbhelp, ext, exts, uext y ntsdexts, que son las extensiones que WinDBG carga por defecto, y gracias a las cuales tenemos comandos de extensión como !analyze y !locks en cualquier despliegue por defecto de WinDbg.

Ahora que hemos hecho un pequeño repaso a las extensiones y los comandos de extensión, os podéis descargar las SOSEX v2.0 desde esta entrada en el blog de Steve, y copiar la DLL en vuestro directorio winext dentro de las Debugging Tools for Windows. A partir de ese momento, mediante el comando .load sosex podréis cargar las extensiones y empezar a jugar.

SOSEX 2.0

NOTA: Una vez cargadas las SOSEX, estas pasan a la primera posición del chain de extensiones, con lo que si invocamos al comando !help, estaremos llamando realmente a !SOSEX.help. A lo largo de toda la entrada me ahorrare el prefijar las llamadas a los comandos de extensión.

Mediante !help vamos a obtener la lista de los comando expuestos por SOSEX. A continuación os detallo los que me resultan más interesantes:

  • !dlk:

Este comando nos muestra los interbloqueos producidos entre dos o más sync blocks, lo que en la practica supone mostrarnos los interbloqueos producidos en código administrado.

Las viejas SOS nos permitían ver todos los objetos de sincronización a través de la extensión !syncblk, pero la búsqueda de interbloqueos no era trivial, ya que nos obligaba a ver todos los call stacks de los hilos involucrados.

La salida de !dlk nos muestra información mucho más directa y concisa:

0:016> !dlk
Deadlock detected:
CLR thread 3 holds sync block 00000000024af3b8 OBJ:00000000105cfcb8[System.Object]
waits sync block 00000000024af1c0 OBJ:00000000105cfde8[System.Byte[]]
CLR thread 5 holds sync block 00000000024af1c0 OBJ:00000000105cfde8[System.Byte[]]
waits sync block 00000000024af3b8 OBJ:00000000105cfcb8[System.Object]
CLR Thread 3 is waiting at DemoThreading.Monitor.WriterFunc()+0x37(IL)
[c:\demosDOT\DemoThreads\Monitor.cs, line 63]
CLR Thread 5 is waiting at DemoThreading.Monitor.ReaderFunc()+0x15(IL)
[c:\demosDOT\DemoThreads\Monitor.cs, line 42]
1 deadlock detected.

Si os fijáis, no solo nos detecta la situación de interbloqueos, sino que es capaz de decirnos el fichero y la línea de código que se estaba ejecutando en cada uno de los hilos involucrados. Esto es impagable.

  • !dumpgen:

En mi día a día como especialista en depuración, una de las tareas a las que más tiempo dedico es a detectar fugas de memoria. No vamos a tratar en este artículo sobre las fugas de memoria administradas, pero me basta que sepáis con que es muy útil detectar los objetos que viven en una generación de memoria determinada. Mediante el comando !dumpgen, SOSEX nos ayuda a estudiar los objetos almacenados en generación concreta.

A modo de ejemplo, si quisiéramos monitorizar los objetos que viven en generación 2 podríamos ejecutar !dumpgen 2 –stat. Podéis pensar en el como un !dumpheap que, en lugar de inspeccionar todo el managed heap, inspecciona solo un heap particular.

  • !gcgen:

Siguiendo en la línea del !dumpgen, el !gcgen de las SOSEX nos permite averiguar en que generación reside un objeto concreto. Por ejemplo:

0:000> !gcgen 00000422714a7dd1
Gen 1

Esto es muy interesante en multitud de escenarios del Mundo Real(tm). Recientemente he estado empleando muy frecuentemente el comando !gcgen en un .foreach de un !dumpheap –mt para que me vuelque la generación en la que viven todos los objetos de un determinado tipo, con el fin de poder evaluar que porcentaje de ellos viven en generación 2. Generalmente busco por conexiones a la base de datos, y si el valor es muy elevado, en gran parte de los escenarios se deberá a que se mantienen referencias a esos objetos que impiden su recolección a tiempo. Un ejemplo de este uso sería el siguiente:

.foreach (obj {!dumpheap –mt <MT del Objeto> -short}) {!gcgen ${obj}}

  • !refs:

El comando de extensión !refs nos muestra una lista con todos los objetos que están referenciando a un objeto determinado, así como otra lista con todos los objetos que son referenciados por este.

Pensad un poco en ello… es un comando salvaje para averiguar porque un objeto determinado no se va de memoria, quien mantiene referencias sobre el. Es una autentica joya a la hora de buscar fugas de memoria administrada.

A continuación os pongo un ejemplo que he sacado del blog de John Robbins:

0:004> !refs 0000000002696918
Objects referenced by 0000000002696918 (System.Diagnostics.DefaultTraceListener):
00000000026941c0     40    System.String    STRVAL=Default
0000000002696b78     24    System.Collections.Specialized.StringDictionary
00000642787c78c8     26    System.String
Objects referencing 0000000002696918 (System.Diagnostics.DefaultTraceListener):
00000000026941e8     160    System.Diagnostics.ListenerElement
0000000002695468     24    System.Object
0000000002697150     48    System.Collections.ArrayList+ArrayListEnumeratorSimple
Thread 4
stack:000000001c1be7c8
stack:000000001c1be880
stack:000000001c1be8b0
stack:000000001c1be8e0
stack:000000001c1be8f0
stack:000000001c1be920
stack:000000001c1be930

¡Espectacular!

  • !mdt:

Dejo para el final el que seguramente sea mi comando favorito de las SOSEX. !mdt es la versión administrada del mítico comando dt de los escenarios de depuración nativa de WinDbg. Sirve para inspeccionar cómodamente un objeto, de modo que podríamos verlo como un sustituto para el venerable !dumpobject de las SOS.dll. Una de mis características favoritas es su parámetro –r, que permite explorar los objetos que componen el objeto de estudio de modo recursivo.

A continuación os pongo un ejemplo de !mdt sobre un objeto de tipo Oracle.DataAccess.Client.ConnectionPool:

0:044> !mdt 000000007fffe9d8 -r
000000007fffe9d8 (Oracle.DataAccess.Client.ConnectionPool)
   m_connections:000000007fffeae0 (System.Collections.Stack+SyncStack)
      _array:000000007fffeb18 (System.Object[], Elements: 10)
      _size:0x0 (System.Int32)
      _version:0x0 (System.Int32)
      _syncRoot:NULL (System.Object)
      _s:000000007fffea48 (System.Collections.Stack)
         _array:000000007fffea70 (System.Object[], Elements: 10)
         _size:0x0 (System.Int32)
         _version:0x8 (System.Int32)
         _syncRoot:000000007fffeb88 (System.Object)
            <NO FIELDS>
      _root:000000007fffeb88 (System.Object)
         <NO FIELDS>
   m_mtsConnections:000000007fffebe0 (System.EnterpriseServices.ResourcePool)
      _cb:000000007fffeba0 (System.EnterpriseServices.ResourcePool+TransactionEndDelegate)
         _target:000000007fffe9d8 (Oracle.DataAccess.Client.ConnectionPool)
            <RECURSIVE>
         _methodBase:NULL (System.Reflection.MethodBase)
         _methodPtr:00000642800fda60 (System.IntPtr)
         _methodPtrAux:0000000000000000 (System.IntPtr)
         _invocationList:NULL (System.Object)
         _invocationCount:0000000000000000 (System.IntPtr)
         <NO FIELDS>
   m_semAvaNumOfCons:0000000000000000 (System.IntPtr)
   m_timer:000000007ffff008 (System.Threading.Timer)
      __identity:NULL (System.Object)
      timerBase:000000007ffff028 (System.Threading.TimerBase)
         timerHandle:0000000005d40e10 (System.IntPtr)
         delegateInfo:0000000006bc0b90 (System.IntPtr)
         timerDeleted:0x1 (System.Int32)
         m_lock:0x0 (System.Int32)
   m_clonedCtx:000000007fffee98 (Oracle.DataAccess.Client.OpoConCtx)
      opsConCtx:0000000000000000 (System.IntPtr)
      opsErrCtx:0000000000000000 (System.IntPtr)
      pOpoConValCtx:0000000000000000 (System.UIntPtr)
      opoConRefCtx:000000007fffef50 (Oracle.DataAccess.Client.OpoConRefCtx)
         serverVersion:000000007fffe880 (System.String: "<censurado ;)>")
         userID:000000007fffe8b0 (System.String: "<censurado ;)>")
         password:000000007fffe8e0 (System.String: "<censurado ;)>")
         dataSource:000000007fffe910 (System.String: "<censurado ;)>")
         newPassword:00000000dfff0370 (System.String: "")
         proxyUserId:00000000dfff0370 (System.String: "")
         proxyPassword:00000000dfff0370 (System.String: "")
         dbName:000000007fffe938 (System.String: "<censurado ;)>")
         hostName:000000007fffe960 (System.String: "<censurado ;)>")
         instanceName:000000007fffe988 (System.String: "<censurado ;)>")
         serviceName:000000007fffe9b0 (System.String: "<censurado ;)>")
         clientID:NULL (System.String)
         pITransaction:NULL (System.EnterpriseServices.ITransaction)
      conString:000000007fffd350 (System.String: "<censurado ;)>")
      pool:NULL (Oracle.DataAccess.Client.ConnectionPool)
      maxPoolSize:0x64 (System.Int32)
      minPoolSize:0x0 (System.Int32)
      poolIncSize:0x5 (System.Int32)
      poolDecSize:0x1 (System.Int32)
      poolRegulator:0xB4 (System.Int32)
      creationTime:000000007fffef28 (System.DateTime) 2009/06/23 18:53:51.511 VALTYPE (MT=0000064278476ad8, ADDR=000000007fffef28)
      lifeTime:000000007fffef30 (System.TimeSpan) VALTYPE (MT=00000642784769d8, ADDR=000000007fffef30)
         _ticks:0x0 (System.Int64)
      timeOut:000000007fffef38 (System.TimeSpan) VALTYPE (MT=00000642784769d8, ADDR=000000007fffef38)
         _ticks:0x0 (System.Int64)
      pooledConCtx:NULL (Oracle.DataAccess.Client.PooledConCtx)
      poolName:NULL (System.String)
      bErrorOnOpen:false (System.Boolean)
      validateCon:0x0 (System.Int32)
      gridCR:0x0 (System.Int32)
      gridRLB:0x0 (System.Int32)
      dataSrc:NULL (System.String)
      metaPool:0x1 (System.Int32)
      origLifeTime:000000007fffef40 (System.TimeSpan) VALTYPE (MT=00000642784769d8, ADDR=000000007fffef40)
         _ticks:0x0 (System.Int64)
      origPoolDecSize:0x1 (System.Int32)
      origMinPoolSize:0x0 (System.Int32)
      exceptMsg:NULL (System.String)
      m_conPooler:NULL (Oracle.DataAccess.Client.ConPooler)
   m_counter:000000007ffff108 (Oracle.DataAccess.Client.Counter)
      total:0x0 (System.Int32)
      potentialTotal:0x0 (System.Int32)
      threadWait:0x0 (System.Int32)
      totalAvailable:0x0 (System.Int32)
      bOwnedByCPCtx:false (System.Boolean)
   m_skipDecrement:false (System.Boolean)
   m_cpCtx:NULL (Oracle.DataAccess.Client.CPCtx)
   m_rlbGravCounter:0x0 (System.Int32)
   m_attemptedRequests:0.000000 (System.Single)
   m_bSynchronizeStack:false (System.Boolean)

No se como lo veis vosotros, pero a mi esto me encanta. Normalmente “pierdo” mucho tiempo explorando los objetos con una sucesión casi interminable de !dumpobject, y este pequeño comando me ahorra muchísimo tiempo.

Hay más comandos de extensión interesantes en las SOSEX, como los relacionados con los breakpoints en código administrado, la búsqueda de cadenas en el volcado o la inspección de ensamblados, pero los más interesantes y prácticos para mi, hasta el momento, han sido estos que os he descrito. Espero que los disfrutéis y que esta entrada os sirva para ahorrar tiempo y pasarlo aun mejor en vuestras sesiones de depuración.

En resumen…

Esta librería ha pasado a formar parte de mi kit de depuración hasta el punto que, en el 95% de los casos, al abrir un volcado de memoria en el WinDbg sigo la misma rutina:

  1. .reload /v /f
  2. .loadby sos mscorwks
  3. .load sosex
  4. ¡Empezamos a depurar!

No podía dejar pasar la oportunidad de recomendaros su uso, y a la vez, aprovechar el artículo para hablar de la extensiones de WinDbg. ¡Espero que lo hayáis disfrutado!

PS: Thanks Steve! I owe you a beer… or a full six-pack!:)

Rock Tip:

Hoy os traigo una buena noticia; vamos a tener la suerte de recibir a los californianos Tesla en nuestras tierras, ya que este Martes 23 actuarán en Barcelona, y el Miércoles 24 en Madrid, en la sala Heineken. Allí espero estar mañana a la noche, disfrutando de temazos como Paradise, Stir It Up, Modern Day Cowboy

Precisamente este último tema me pareció apropiado como Rock Tip para éste artículo; no lo puedo evitar, cuando abro el WinDbg e inicio una sesión de depuración, me veo a mi mismo en un camino polvoriento y pedregoso, embarrado desde las botas camperas hasta el sombrero de cowboy, con la seis cuerdas a la espalda, y mis armas listas para la acción. ¿Flipado? Si… pero ¿y lo bien que me lo paso? :)

En este caso mis armas son mis herramientas, y las SOSEX son una de las últimas adiciones a mi arsenal de depuración. Pensar en las SOSEX como arma me dio la idea de emplear el ‘Stick to Your Guns’ de Bon Jovi para este post, pero luego recordé que Tesla tocan esta semana en España y que aun no habían aparecido en ningún Rock Tip de este, vuestro blog :)

Por cierto, si alguno de vosotros va a ver a los chicos de Jeff Keith este Miércoles en Madrid avisadme, y ya puestos os podéis estirar y invitar a una cervecilla ¿no? :)

Keep Rockin’!

Posted: 23/6/2009 19:33 por Pablo Alvarez | con 3 comment(s) |
Archivado en: ,
Another Day: Sesión de Depuración y Optimización en Barcelona

… y seguimos con la pequeña gira sobre Depuración y Optimización que estamos realizando este año los integrantes del DOT Team de Plain Concepts. Después de Santander, Bilbao, A Coruña y Madrid, le llega el turno a la Ciudad Condal, donde tendré el placer de presentar una sesión sobre Depuración y Optimización Avanzada de aplicaciones con WinDbg.

El evento se realizará el próximo día 17 de Junio en las oficinas de Microsoft en Barcelona, en horario de 16:00 a 18:00. Lo cierto es que, si fuera por mi, estaríamos hablando una semana entera sobre el asunto; los que ya me conocéis sabéis la gran razón que tiene esa señora madre mía cuando dice que yo no callo ni debajo del agua. Aun así, intentaremos aprovechar al máximo esas dos horitas. Los interesados podéis apuntaros en este enlace: http://msevents.microsoft.com/CUI/EventDetail.aspx?EventID=1032417766&Culture=es-ES

Como siempre, ¡se aceptan invitaciones a cervecitas! XDD ¡Nos vemos en Barcelona!

Rock Tip:

Otro día más presentando mis juguetes favoritos de depuración, otro día más de charlita de internals de .NET y de Windows. Por eso me pareció muy interesante como Rock Tip para esta entrada el ‘Another Day’, uno de los temas mas conocidos de los increíbles Dream Theater. Esta banda americana de metal progresivo combinan de un modo espectacular el virtuosismo de sus músicos (todos ellos salidos del Berklee College of Music!) con una musicalidad poco común en este género. 

Este tema en cuestión apareció en el espectacular Images And Words, de 1992. Un disco muy, pero que muy recomendable para todos los amantes de la buena música y del virtuosismo. Por otra parte estamos de enhorabuena, ya que los chicos de Dream Theater acaban de publicar su último trabajo, el Black Clouds & Silver Linings.

Gimme Three Steps: Creando nuestro Servidor de Símbolos

Hace unos días, conversando con Rodri y con Jose Luis, surgió la necesidad de crear un documento interno de Plain Concepts acerca de la utilización de symstore para la creación de un servidor de símbolos a nivel de empresa. Al momento nos dimos cuenta de que esto podía interesar a mas geeks como nosotros, así que he decidido crear una guía muy breve para la creación de un servidor de símbolos básico.

¡Espero que os resulte interesante!

¿Un Servidor de Símbolos? ¿Para que quiero yo eso?

NOTA: En esta entrada no voy a explicar que son los símbolos, ni para que nos sirven, etc. Todo eso está explicado en múltiples artículos de la MSDN, en la documentación de los depuradores correspondientes y entradas de blog tan magníficas como esta. Y no es por que sea mía :)

Como ya sabréis los que me conocéis personalmente, para mi una sesión de depuración post-mortem es como la quema de iglesias para los blackmetaleros nórdicos; una fuente de diversión inagotable. Sin embargo siempre hay momentos frustrantes, y casi todos ellos tienen que ver con la carencia de símbolos apropiados, o el echo de que WinDbg no puede localizarlos adecuadamente.

Para facilitar la vida a nuestros depuradores y herramientas varias que necesiten acceder a esta información simbólica de depuración vamos a construir un servidor de símbolos donde se almacenaran tanto los símbolos de nuestras aplicaciones como los que nos descarguemos de otros servidores, como el servidor de símbolos públicos de Microsoft (http://msdl.microsoft.com/download/symbols).

Construyendo nuestro Servidor de Símbolos

Vamos a necesitar de tres simples pasos para construir el servidor de símbolos:

  • Obtener un lugar físico donde almacenar los símbolos:

Esta parte es la mas sencilla. Necesitamos un lugar donde almacenar los ficheros .pdb, para lo que crearemos un directorio en algún servidor accesible a nivel de nuestra organización y compartiremos esta carpeta. Así de simple :)

En el resto del articulo supondremos que hemos creado un share llamado Symbols en el servidor DevSrv01. Por tanto, el servidor de símbolos se encontrará en \\DevSer01\Symbols.

  • Configurar las herramientas para que utilicen ese lugar como servidor de símbolos:

Ahora debemos instruir a nuestra aplicación de que busque los símbolos en nuestro servidor concreto. En el caso de WinDbg podemos recurrir directamente a la configuración de la ruta de búsqueda de símbolos desde File –> Symbol File Path… o Ctrl+S. Desde ahí podemos establecer la ruta, que en nuestro ejemplo bien podría ser “SRV*\\DevSrv01\Symbols*http://msdl.microsoft.com/download/symbols”, indicando que el servidor de símbolos estará en nuestro servidor, y que también buscará en el servidor público de símbolos de Microsoft.

NOTA: Para mas información respecto a las cadenas de búsqueda de símbolos, recomiendo mirar la documentación de las Debugging Tools For Windows.

image

A medida que vayamos recargando símbolos (por ejemplo, mediante .reload en WinDbg), buscara la presencia de la versión correcta de los mismos en el servidor de símbolos (\\DevSrv01\Symbols) y, caso de no encontrarlos, iria al siguiente elemento en la cadena de búsqueda y los descargaría, copiandolos en el servidor \\DevSrv01\Symbols; de este modo, la segunda vez que fuera necesario cargar los símbolos, estos ya se encontrarían en nuestro nuevo y flamante servidor.

Una alternativa más práctica es emplear la variable de entorno _NT_SYMBOL_PATH, estableciéndola a nuestra cadena de búsqueda de símbolos. Prácticamente todas las aplicaciones que hace uso de los símbolos intentan buscar primero en esa variable de entorno, como es el caso de WinDbg, adplus, etc… Sin embargo, hay una notable excepción: el Process Explorer de SysInternals. Como seguramente sabréis, ésta magnifica herramienta también puede emplear los símbolos para generar volcados de memoria, ver la información de los call stacks de los diferentes threads de un proceso en ejecución, etc. En esta herramienta tendremos que establecer el servidor de símbolos manualmente, ya que no lee de _NT_SYMBOL_PATH. ¡Avisados estais! :)

  • Poblar el servidor de símbolos con cada nueva build:

Como ya sabréis, el mayor problema de los servidores de símbolos es mantener el orden dentro del caos que suponer tener múltiples versiones de un mismo módulo. Con cada nueva compilación, las direcciones de memoria de los distintos objetos pueden cambiar, asi como los offset, etc. Si intentamos depurar un proceso o un volcado de memoria con una versión incorrecta de los módulos los resultados pueden ser imprevisibles.

Os voy a comentar un ejemplo típico de depuración con símbolos incorrectos que seguro que os suena a más de uno: ¿alguna vez habéis realizado una depuración paso a paso con un depurador integrado en el entorno de desarrollo, y habéis comprobado que, en cierto momento, la línea que estáis ejecutando apunta a una línea inexistente o en blanco? Eso generalmente se debe a la utilización de unos .PDBs antiguos. Por ejemplo, se han agregado unas cuantas líneas de código a un método, pero al depurar empleamos la información de cuando ese método ocupaba menos, etc. Ala.. ¡un nuevo misterio resuelto! xD

Para evitar estos problemas, lo mejor es asegurarnos de que, cada vez que realizamos una nueva compilación, copiamos los nuevos .PDB al servidor de símbolos. La idea es buena, pero ahora tenemos que ver como la implementamos; daros cuenta que no puedo copiar directamente el fichero .pdb porque habría colisión de nombres. Si tengo un ensamblado llamado miEnsamblado.exe, y lo compilo cinco veces, tendré cinco ficheros miEnsamblado.pdb. Hay que buscar un mecanismo que permita almacenarlos sin que se sobrescriban, y haciendo posible que una herramienta que consuma los símbolos pueda coger el adecuado para una versión concreta.

Esto se consigue a través de una estructura de directorios especial en el servidor, basada en un hash del modulo, que no vamos a explicar en detalle en esta entrada. Lo que si os diré es que, gracias a una pequeña utilidad llamada symstore, que se distribuye con las propias Debugging Tools for Windows, podemos agregar nuevos .PDBs a nuestro servidor y automática se colocarán correctamente.

Un ejemplo de uso de symstore sería el siguiente:

symstore add /r /f c:\sources\aplicacion\bins\*.* /s \\DevSrv01\Symbols /t "Aplicacion 1" /v "Build 123"

En ese ejemplo agregamos al servidor todos los símbolos que se encuentran en la ruta definida, especificando el nombre de producto (/t) y la versión (/v). Para ver todos los parámetros, nuevamente recomiendo recurrir a la documentación de las Debugging Tools for Windows.

Ahora solo necesitamos automatizar el proceso después de la build, ya sea mediante una acción post-build, msbuild, o vuestro mecanismo favorito :)

Resumen

En este articulo no hemos entrado en profundidad en ninguno de los puntos; no hemos explicado que son los símbolos y para que valen, ni la sintaxis de la ruta de búsqueda de símbolos, ni como se genera el hash de cada versión de los símbolos y como éste se emplea para estructurarlos en el sistema de ficheros, etc. No, ese no era el objetivo de esta entrada del blog. El objetivo era, única y exclusivamente, contaros que se puede hacer y daros unas indicaciones básicas de cómo lograrlo; abriros un poco el apetito y de paso, publicar algo de lo que estamos haciendo internamente en Plain Concepts.

¡Espero que os haya sido de utilidad! Keep Rockin’!

Rock Tip:

Allá por 1973 Lynyrd Skynyrd publicaron su primer disco, su gran debut, “pronounced 'lĕh-'nérd 'skin-'nérd”; este disco incluía temazos como el Simple Man (para mi una de las mejores canciones de toda la historia… así de simple ;)) y el Free Bird, recientemente revitalizado gracias al Guitar Hero.

En aquel álbum aparecía también el tema que protagoniza el rock tip de este articulo; Gimme Three Steps. En realidad, la historia que cuenta esta canción no tiene mucho que ver con este artículo; esos tres pasos de los que habla la canción son los que le pide una chica a su captor para escapar corriendo de él. La letra es muy buena, espectacular, pero yo hago una reinterpretación y me quedo con los tres simples pasos que necesitamos para montar nuestro servidor de símbolos mediante symstore.

Bueno chicos, este fue el rock tip de hoy… ya veis que tengo el día sureño! :)

Posted: 15/4/2009 10:05 por Pablo Alvarez | con 2 comment(s) |
Archivado en: ,
Calling On You: Sesión de Depuración y Optimización en A Coruña

Después de pasar una tarde genial en Bilbao con los chicos de Artalde.NET hablando sobre depuración avanzada con WinDbg, ahora le toca el turno a otra ciudad norteña; el grupo de usuarios de A Coruña (.NUGG) ha tenido a bien invitarme a hablar durante un par de horillas sobre uno de mis temas favoritos: la depuración y optimización de aplicaciones usando WinDbg y algún que otro juguetito :) El evento será el próximo Viernes 24 en la Facultad de Informática de A Crouña.

Aquí podéis acceder a la pagina de inscripción al evento y consultar los detalles del mismo: https://msevents.microsoft.com/cui/eventdetail.aspx?eventid=1032412774&culture=es-es y ya sabéis, si estáis por cerca de la Coruña y os apetece dedicar un par de horas a descubrir herramientas y técnicas de depuración avanzada y charlar un poquillo sobre internals de .NET, no dejéis de pasaros por el evento.

Y ya aprovechando el post, tengo que confesaros una cosa: cuando me plantee la idea de recorrer diferentes grupos de usuarios de .NET para hablar principalmente de WinDbg pensé que, o bien directamente la idea fuera descartada por los grupos, o bien no tendríamos afluencia de gente. Y una vez más, como viene siendo habitual en mi para este tipo de previsiones, me equivoque de mala manera :) Hasta el momento me he encontrado con gran asistencia y, lo que es mejor aun, multitud de preguntas y comentarios, tanto síncronamente (en los propios eventos) como asíncronamente (por correo, blog, etc.). De verdad, ¡muchas gracias a todos por vuestra participación e interés!

Rock Tip:

No es la primera vez que los heavies cristianos Stryper hacen acto de presencia por aquí en este humilde blog, y seguramente no sea la última tampoco; ya sabéis como va esto… el blog es mío y traigo a quien me apetece xD En este caso, se trata del que, para mi, es uno de sus mejores temas: ‘Calling on You’,  aparecido en su discazo ‘To Hell With the Devil’ de 1986. Si no los conocéis, pegadles un orejazo. Encontrareis muy buenas melodías, técnica a patadas en todos los instrumentos y, sobre todo, una voz principal y unos coros que no os dejaran indiferentes.

Me pareció un rock tip apropiado para este post, ya que es un pequeño llamamiento para que vengáis a acompañarnos en el evento. Sea como sea, el Viernes 24 volverá a sonar el Calling on You en A Coruña :)

Keep Rockin’!

Posted: 14/4/2009 17:47 por Pablo Alvarez | con no comments |
Archivado en: ,,
Enemy In Me: Sesión de Depuración y Optimización en Bilbao

Como ya comentó Ibon en su blog, este miércoles voy a tener la oportunidad de pasar un magnifico rato con los chicos de Artalde.NET hablando de uno de mis temas favoritos: la depuración avanzada de aplicaciones .NET.

Pasaremos un ratito entretenido (¡o eso espero!) hablando de WinDbg y su uso para detectar bugs esquivos y problemas de rendimiento; por el camino discutiremos ciertos detalles de la implementación de .NET e internals que de seguro nos resultarán útiles para hacer código mas robusto, estable y eficiente. Y después… tapitas y pinchitos por Bilbao!! No se a vosotros, pero a mi el plan me suena de maravilla :)

Así que ya sabéis, si estáis por Bilbao este Miércoles y os apetece bajar a las trincheras, no dejéis de registraros aquí y pasar a hacernos una visitilla.

NOTA: A la finalización del evento subiré aquí mismo los materiales del mismo.

NOTA2: Ya ha finalizado el evento, y con el retraso que me caracteriza (¡sorry!) os pongo el enlace a la descarga de las presentaciones de la sesión. Aprovecho también para dar las gracias a todos los asistentes: ¡que bien me cuidáis en Bilbao!

Rock Tip:

Como dice el titulo de este gran tema de los Vains of Jenna, muchas veces el enemigo esta en nosotros mismos; esta frase me parece muy apropiada para las sesiones de depuración, sobre todo cuando nos toca depurar nuestro propio código. Por ello, este rock tip va para esta banda de sleaze rock tan poco conocida pero tan interesante.

Enjoy, and Keep rockin’!!!

The Hunter: Cazando bloqueos e interbloqueos

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:

  1. 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.
  2. 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.

Posted: 7/2/2009 17:53 por Pablo Alvarez | con 11 comment(s) |
Archivado en: ,,
Children of the Damned: Cuidado con vuestras aplicaciones MDI

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

  1. Abrimos la aplicación y comprobamos el estado de la memoria en vacio.
  2. Abrimos un formulario, trabajamos un poquito con el.
  3. Cerramos el formulario.
  4. 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

  1. 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 :)
  2. Cada vez que invocáis a GC.Collect(), Dios mata a un gatito.
  3. 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!.

Posted: 2/2/2009 18:25 por Pablo Alvarez | con 26 comment(s) |
Archivado en: ,,
Weekend Warrior: 'Depurando hasta la Saciedad' en el DevCamp

Este fin de semana, como ya sabréis casi todos, se ha celebrado la primera 'iteración' del DevCamp; el nuevo evento de comunidad promovido por DPE de Microsoft. He tenido la enorme suerte de poder asistir y colaborar con la charla 'Depurando hasta la Saciedad', que pretendió ser un recorrido rápido a WinDbg en entornos nativos y administrados.

Evidentemente nadie puede enseñar a depurar con WinDbg en 45 minutos, por lo que la idea de la sesión fue simplemente dar a conocer la herramienta y, sobre todo, las técnicas de depuración post-mortem, así como explicar en que escenarios son prácticamente la única solución. Si he conseguido esto, me doy totalmente por satisfecho con la sesión... a pesar de no seguir ninguno de los consejos que Mr. Carmona nos dio a continuación... (ya podías haber dado tu sesión primero, macho! XDD).

Lamentablemente poco después de la comida tuve que marchar, ya que no me encontraba del todo bien y además tenía (y aun tengo!) mucho trabajo atrasado para el fin de semana, por lo que no pude atender al resto de sesiones (¡lo siento!) ni socializar un poquillo más; espero que lo pasarais genial y que vayais publicando en geeks.ms el resumen del resto del sábado y la actividad del domingo!

Aquí os dejo los materiales de la sesión, que en este caso se trata exclusivamente de las PPTs empleadas, ya que los volcados de memoria y los símbolos ocuparían demasiado y, por otra parte, se pueden obtener (y es lo recomendable) durante la ejecución de las demos de Tess.

Por último, agradecer a los chicos y chicas de DPE de Microsoft, y especialmente a David Salgado, por el fantástico 'marrón' que ha sido sustituirle :)

Rock Tip:

No es mi tema favorito de los Iron Maiden, pero ese 'Weekend Warrior' parece muy apropiado para todos los que este fin de semana nos reunimos en DevCamp de Guadalajara. Un tema que apareció en su fenomenal, aunque muy criticado,  'Fear of the Dark', de 1992 y que a pesar de no ser un gran éxito de los chicos de Dickinson, me parece bastante correcto y con un estribillo genial, con unas armonizaciones en la parte melódica del solo 100% Maiden.

En fin... voy a seguir currando, que a pesar de ser las 22:45h del domingo, aún queda mucho fin de semana! A weekend warrior lately... :)

Keep Rockin'

Für Immer: The Return of the WeakReference

¿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'!

Posted: 7/11/2008 23:55 por Pablo Alvarez | con 13 comment(s) |
Archivado en: ,,
Delivering the Goods: Materiales 'Up to Speed with SQL 2008'

Como ya anuncié en otra entrada anterior del blog, ayer tuve la suerte de pasar un par de horas hablando de SQL Server 2008 con los asistentes al evento realizado por el grupo de usuarios de .NET de Madrid (MAD.NUG). La verdad es que disfruté como siempre con las preguntas y comentarios que se realizaron durante la sesión, y también como siempre, me quedé con ganas de contar muchas mas cosas :) Pero bueno, los que me conocéis sabéis que eso se debe al mero hecho de que no me callo ni debajo del agua!

Por otra parte nos queda pendiente un post acerca de XML en las bases de datos... ¡no se me olvida! Pero antes tengo un post interesante de depuración en la recámara, que espero poder publicar este mismo fin de semana.

Por último, y más importante, aprovecho el post para dejaros los materiales y agradeceros a todos los asistentes vuestra presencia y preguntas, y como no a los chicos de MAD.NUG el hacerme un huequito. Os responderé a vuestros correos a lo largo del fin de semana, ¡palabra! :)

Rock Tip:

Hoy considero apropiado el temazo 'Delivering the Goods' de los Judas Priest. En concreto, os paso el vídeo de un momento épico: una versión en directo a pachas entre dos de los mejores vocalistas de la historia... Rob Halford y Sebastian 'nenaza' Bach!

We Will Rock You: Evento sobre SQL Server 2008 en MAD.NUG

En una nueva demostración de mi proverbial despiste, vengo aprisa y corriendo a postear en mi blog mi próximo evento, aunque un poquillo tarde, ya que será este mismo jueves! Los chicos del grupo de usuarios de .NET de Madrid (MAD.NUG) me han invitado a dar una pequeña sesión sobre novedades en SQL Server 2008, por lo que os invito a todos los que tengais la tarde del miércoles libre a que nos acompañéis durante unas horas; estoy negociando el poner un 'circulo de la muerte' para organizar peleas de gladiadores entre desarrolladores y administradores para animar el asunto! :)

A continuación os dejo la información del evento:

SQL Server 2008

Lugar: Oficinas de Microsoft en La Finca, Madrid
Fecha: 6 de noviembre de 2008
Horario: 19:00 a 21:00 horas 

A pesar de que el lanzamiento de SQL Server 2008 se ha producido ya hace algunos meses, aún son muchas las áreas oscuras del producto, el desconocimiento de sus nuevas características, mejoras, etc. Como ya sucediera con SQL Server 2005, y como con cualquier producto o tecnología nueva, pasará bastante tiempo hasta que asimilemos y empleemos con naturalidad las novedades, y pasen a formar parte de nuestro arsenal del día a día.

En esta sesión vamos a dar un repaso a las novedades de SQL Server 2008: desde el desarrollo a la administración, desde el motor de almacenamiento a Business Intelligence. Recorreremos algunas de las características más conocidas y, cómo no, haremos hincapié en las menos conocidas. Las aburridas PPTs de rigor irán acompañadas de demostraciones prácticas sobre los nuevos tipos de datos, la MERGE, tablas como parámetros, optimización, y un poquito de administración también.

Por supuesto, la sesión contará con su apartado de preguntas y respuestas, por lo que os animamos a que vengáis con vuestra batería de cuestiones preparadas desde casa para hacer tiro al blanco con el ponente.

Agenda

1.- Introducción a SQL Server 2008
2.- Novedades para Desarrolladores
    - Nuevos Tipos de Datos
       - Datos espaciales
       - Fechas y Horas
       - Estructuras Jerárquicas
    - Operación MERGE
    - Mejoras al XML
    - Mejoras a los tipos de CLR
    - Otras mejoras: TVP, iFTS, Sync Framework
3.- Novedades de Administración
    - Policy-Based Administration
    - Resource Governor
4.- Novedades del Motor de Almacenamiento
    - Compresión de Datos
    - Transparent Data Encryption
    - Vardecimal
5.- Business Intelligence en SQL Server 2008
    - Integration Services
    - Reporting Services
    - Analysis Services

Rock Tip:

No podía ser de otra manera. Lo sé desde el pasado sábado, 25 de Octubre. No importaba de que fuera a tratar mi siguiente post en en geeks.ms (tengo en la recamará 'esperas en
SQL Server', continuar la serie de WinDbg o una nueva serie sobre los derviches giróvagos y su relación con el macrocosmos órfico), pero tenía claro que el rock tip sería una alusión al espectacular concierto que Queen + Paul Rodgers tuvieron a bien darnos en Madrid.

Y cuando digo 'espectacular', no me refiero a lo bien que tocaron (... y que bien que tocaron, oye!), ni a lo más o menos acertado de su repertorio (... pero que repertoriooooooigaaaa!), ni a lo mejor o peor que fuera su montaje y puesta en escena (pantalla espectacular, bolica de discoteca que hacia estrellicas...). Fue espectacular, sobre todo, porque poder estar ahí, al ladito de Mr. May, de Mr. Taylor y de Mr. Rodgers es todo un lujo, pero aún lo es más pudiéndo compartirlo con Octavio, Dennis, Popi, Jose, Juan y Cris... y como no, con Freddie. Por que no nos engañemos, Freddie estuvo ahí esa noche, con nosotros :)

No os voy a poner links al grupo, ni a los temas.. sería casi insultante. Tampoco voy a decir que fuera lo mismo que verlos con Freddie sobre el escenario, porque no es así. Pero si os diré, a quienes no hayáis tenido la oportunidad de oírles con Paul Rodgers, que le deis una oportunidad al chaval (¿?), el tío lo hizo muy pero que muy bien, ¡increíble la voz que tiene ese tío con sus 60 añazos encima!

PD: Octavio, tío, te debo una cerveza por descubrirme a Free, Bad Company y a ese pedazo de vocalista y músico que es Paul Rodgers!

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

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:

revoluciona

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

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

Scheduler para una única CPU

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.

sched2

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:

resultado1

¿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.

Lists1

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 Sched3habilitado. 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

Coming of Age: SQL Server 2008 es RTM!

¡Pero que amables son los chicos de Microsoft! ¡y que atentos oiga! Parece que a modo de regalo de cumpleaños anticipado para mi persona se han decidido a sacar la versión definitiva de SQL Server 2008. Oh Yeah!!

Lamentablemente no creo que pueda ponerle las manos encima hasta el fin de semana, pero aprovecho para avisaros y que vayáis posteando por aquí vuestras primeras impresiones! Yo ya os adelanto que una de las primeras cosas que quiero probar es el nuevo visualizador de datos y resultados de queries espaciales.

Ya sabes, directos a la MSDN para descargarlo! Keep Rockin'!

Rock Tip:

SQL Server 2008 se nos hace mayor, y con la RTM ya ha llegado a la mayoría de edad... así que nada mejor que celebrarlo con aquel 'Coming of Age' de los impresionantes, tremendisimos Damn Yankes!

Por cierto, para los que no pinchéis en los hipervínculos, solo deciros que Damn Yankees fue un supergrupo montado por excéntrico guitarrista Ted Nugent, Tommy Shaw de Styx, ese gradnisimo Jack Blades de Night Ranger, y un tal Michael Cartellone, que nadie sabía de donde salió pero no lo hizo nada mal (y ahora esta girando con los actuales Lynyrd Skynyrd)... espero que esta alineación os haga al menos interesaros por su espectacular album homónimo. Muy, pero muy recomendable.

Out of Time: A vueltas con los planes compilados en SQL Server 2008

Dicen por ahí que rectificar es de sabios... así que aquí va mi momento de sabiduría del día: en la entrada anterior compartía con vosotros algunas de las sorpresas que me he ido encontrado en la RC0 de SQL Server 2008, y también os decía que debido al poquito tiempo que me queda libre estas semanas, seguramente no podría postear mucho más sobre el producto a corto plazo. Pues bien, heme aquí, humillándome y escribiendo una entrada sobre una nueva característica de SQL Server 2008 :)

La verdad es que no he podido evitarlo, realmente me parece que este va a ser otro de esos detalles 'pequeños' pero que pueden marcar una diferencia importante; en este caso a nivel de rendimiento. Vamos para allá...

Optimización para consultas Ad Hoc

El otro día, mientras leía los Books Online (la documentación del producto) de SQL Server 2008 RC0 me tropecé, como quien no quiere la cosa, con la característica que os voy a comentar ahora. Nada mas leerla me vino a la mente el artículo sobre el ciclo de vida de las consultas y el pequeño y bonito debate que se abrió en los comentarios, y me parece que complementa muy bien lo comentado en su momento en aquella entrada, por lo que no puedo resistirme a comentarla brevemente por aquí.

Haciendo un poco de memoria...

¿Recordáis el problema de las consultas ad hoc en SQL Server? Comentábamos que éstas, al contrario que los procedimientos almacenados y que las consultas parametrizadas, no tenían en cuenta los parámetros a la hora de almacenar y reutilizar su plan de ejecución (para una explicación detallada, echádle un vistazo al post antes referido).

Vamos a ver un ejemplo sobre la base de datos AdventureWorks:

USE AdventureWorks
GO

-- Limpiamos la Cache de planes de ejecucion
DBCC FREEPROCCACHE
GO

-- Ejecutamos esta consulta 5 veces
SELECT *
FROM Sales.SalesOrderDetail
WHERE UnitPrice = 5.70
GO

-- Ejecutamos esta consulta 5 veces
SELECT *
FROM Sales.SalesOrderDetail
WHERE UnitPrice = 21.98
GO

-- Miramos nuestros planes de ejecucion en la cache de planes
SELECT
    usecounts,
    size_in_bytes,
    cacheobjtype,
    objtype
FROM sys.dm_exec_cached_plans
WHERE objtype = 'Adhoc'

Como podéis ver, la demo se compone de los siguientes pasos:

  1. Limpiamos la Caché de Procedimientos Almacenados:

    Inicialmente limpiamos la caché de planes de ejecución mediante el comando DBCC FREEPROCCACHE, con el único objetivo de facilitarnos luego la búsqueda de los planes que se han generado por las consultas de la demo. Por razones evidentes, no debemos ejecutar este comando en un servidor de producción.
  2. Ejecutamos una consulta con dos parámetros diferentes:

    A continuación lanzamos una consulta sobre AdventureWorks. Como podéis ver, lanzamos la misma consulta con dos parámetros, ejecutando 5 veces cada una de ella.

    En un mundo ideal SQL Server sería lo suficientemente inteligente como para detectar que son la misma consulta pero con diferentes parámetros, y que su plan de ejecución no va a variar ya que es trivial. ¡¡Vamos a ver si es así!!

  3. Monitorizamos la Cache de planes de ejecución:

    ¿Vivimos en ese mundo ideal? ¿Cómo podemos comprobarlo? Lo primero que se me ha ocurrido es dar un par de palmadas al aire a ver si por arte de magia aparecía una cerveza fresquita aquí la lado, pero no ha funcionado. Mmmm.. me tomaré eso como un primer indicio de que no vivimos en un mundo ideal :(

    El segundo indicio lo sacamos de la vista de administración dinámica sys.dm_exec_cached_plans, en la que podremos observar como, al contrario de lo que sucede con los procedimientos almacenados o las consultas parametrizadas, los planes de ejecución no se han reutilizado. Como se puede ver en la siguiente captura de pantalla, tenemos dos planes de ejecución con 5 ejecuciones cada uno.

Planes de Ejecucion

Bien, hasta aquí nada nuevo bajo el sol, ya que se trata del comportamiento por defecto de SQL Server 2005 y SQL Server 2008. Sin embargo os prometí que os traería novedades, y aqui vienen...

Let's Get Rocked!! Optimize for Ad Hoc Workload

Los planes de ejecución consumen memoria... ¡y no poca! Como podemos ver en la captura de pantalla, en el caso los planes de ejecución del ejemplo anterior cada uno de los planes se lleva 24576Kb... ¡24 Kb, 3 páginazas por plan, nada más y nada menos! Y eso que son planes pequeñitos...

Esto puede plantear problemas en un escenario lamentablemente muy común; aplicaciones que lanzan consultas ad-hoc directamente contra nuestro servidor. A no ser que siempre se repitan las consultas con los mismos parámetros, cosa bastante improbable, el número de planes de ejecución en la caché crecerá vertiginosamente, dando lugar a problemas de presión de memoria, que a su vez obligará a sacar planes 'antiguos', que en ultima instancia (y para terminar con nuestra cadena de males) implicará que se tengan que recompilar con mucha mayor frecuencia los planes de ejecución, con el aumento de coste de CPU asociado.

En SQL Server 2008 aparece una nueva opción de configuración del servidor, llamada 'optimize for ad hoc workloads', que viene a mejorar el comportamiento del servidor en este tipo de escenarios. La idea principal es que, cuando se lance una consulta ad hoc no parametrizada contra el servidor, éste no almacene el plan de ejecución completo. En su lugar, almacenara un pequeño 'stub', muy liviano.

Este stub sirve para poder almacenar una entrada en la caché de planes de ejecución, de modo que el servidor sepa que esa consulta ya se ha ejecutado alguna vez en el sistema. Lo bueno de este mecanismo es que el stub ocupa muy poca memoria, lo malo es que el stub no es un plan de ejecución. Por tanto en su siguiente ejecución, hay que volver a compilar la consulta.

Como optimización adicional, siempre que una consulta se ejecuta por segunda vez, SQL Server supone que esta consulta va a ejecutarse más veces con el mismo parámetro, por lo que, de algún modo, promociona su plan de ejecución, y en lugar del stub almacena su plan compilado real.

Vamos a ver un pequeño ejemplo:

-- Habilitamos la opcion de 'optimize for ad hoc workloads'
sp_configure 'show advanced options',1
GO
sp_configure 'optimize for ad hoc workloads',1
RECONFIGURE
GO

-- Limpiamos la cache de planes de ejecucion
DBCC FREEPROCCACHE
GO

-- Vamos a hacer las demos sobre AdventureWorks
USE AdventureWorks
GO

-- Vamos a ver una consulta auto parametrizada
SELECT *
FROM Sales.SalesOrderDetail
WHERE UnitPrice = 5.70
GO

-- Vemos ahi el plan stub para la consulta
SELECT
    usecounts,
    size_in_bytes,
    cacheobjtype,
    objtype
FROM sys.dm_exec_cached_plans
WHERE objtype = 'Adhoc'

-- Vamos a ver como, para la consulta autoparametriazada, no se nos
-- crea un plan real: vemos como la consulta tiene como query_plan NULL
SELECT sql.text, p.query_plan
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(sql_handle) sql
CROSS APPLY sys.dm_exec_query_plan(plan_handle) p
WHERE text NOT LIKE '%sys_dm_exec%' AND text NOT LIKE '%msparam_0%'
ORDER BY qs.EXECUTION_COUNT DESC
GO

-- Deshabilitamos la opcion y volvemos a hacer las pruebas para ver
-- como no se generan los stubs
sp_configure 'show advanced options',1
GO
sp_configure 'optimize for ad hoc workloads',0
RECONFIGURE
GO

Como vemos en la demo, al mirar la caché de planes de ejecución nos encontramos con lo siguiente:

plans2

Es interesante resaltar que el stub del plan de ejecución ocupa solamente 336 bytes ( 1 página)... ¡una gran diferencia respecto al tamaño del plan de ejecución real!

Si además tratamos de ver cual es el plan de ejecución almacenado para esa entrada en la caché, veremos que nos devuelve NULL:

plan3

Como vemos, de cara a minimizar el consumo de CPU, de memoria (en la caché de procedimientos), incluso de un modo indirecto, de E/S (menos paginas, menos fallos de página), este mecanismo tiene un aspecto genial. Eso si, se recomienda emplearlo solo en los servidores que sean atacados por aplicaciones que hagan uso masivo de consultas ad-hoc, y no empleen tantos procedimientos almacenados ni queries parametrizadas.

Y ahora, los deberes ;)

Para terminar, os animo a que hagais pruebas en vuestros entornos o aplicaciones. Yo aún no he podido sacar tiempo para probarlo en condiciones y estudiar su rendimiento sobre ningún producto, pero en el momento que pueda hacer una comparativa os lo haré saber.

Si me gustaría que, si os animáis a hacer las pruebas, me comentéis por aquí vuestros resultados. Realmente ha sido una característica que me ha gustado mucho, y tengo interés por ver su adopción y resultados :)

Rock Tip:

Es la primera vez que escojo un tema de los noruegos Wig Wam para acompañar una entrada de mi blog; en este caso se trata de 'Out of Time', un medio tiempo bestial, de impecable factura, y que deja claro el buen nivel instrumental y compositivo de esta banda, a pesar de la continua autoparodia que hacen de si mismos sus componentes.

Lo cierto es que todos los chicos de Wig Wam (Glam, Teeny, Flash y Sporty) ya tenían bastante experiencia antes de decidirse a montar un grupo a medio camino entre el homenaje y la parodia de las grandes bandas de hard rock, AOR y glam de los años ochenta y primeros noventa, ¡y eso se nota! Sin embargo, no saltaron a la luz pública principalmente gracias a su participación en Eurovision en 2005, con su temazo 'In My Dreams'. A partir de entonces su vida se ha convertido en un no-parar de estadios con decenas de miles de asistentes, y de hoteles con cientos de grouppies dispuestas cada noche... o eso dicen ellos! :) Sea como sea, esta claro que son un grupo muy divertido y recomendable!

He escogido esta canción principalmente por mi falta de tiempo estos días, que me están poniendo difícil cumplir con mis compromisos personales y profesionales; aún así, mejor que sea por esto que no por lo que comenta la letra de la cancion (un reo condenado a muerte que se queda sin tiempo, muy en la onda del 'Halloweed be Thy Name' de mis Iron Maiden del alma) ;)
The Last Mile: Esos pequeños detalles en SQL Server 2008 RC0

¡Albricias! ¡Albricias! ¡Que toquen las campanas! ¡Que corra la voz!... bueno, he de admitir que llego un poco tarde para daros la noticia, pero con gran regocijo, júbilo y satisfacción me uno a Miguel y Jorge para dar la bienvenida a la última release de evaluación de SQL Server 2008: la RC0.

Como ya sabréis, cuando un producto pasa de CTP (Community Technological Preview) a RC (Release Candidate), podemos dar por supuesto que todas las características definitivas del producto están implementadas, y ya solo se procederá a los ajustes y corrección de bugs para asegurar la calidad del producto antes de salir al mercado y de que se ponga en producción. Pero lo importante para nosotros es que ya podemos jugar con la practica totalidad de sus características, ir formándonos en el producto, estudiando que características podemos aplicar a nuestros entornos, etc...

Durante estos días creo (y espero) que se escribirán cantidad de artículos relacionados con las grandes características, como el Policy-Based Management, Capture Data Change, el almacenamiento FILESTREAM, etc... Lamentablemente no creo que yo pueda aportar mucho a corto plazo; en este momento la verdad es que lo que menos tengo es tiempo para escribir una entrada en el blog acerca de ninguna de estas características, y menos de hacerlo de una manera suficientemente digna.

Sin embargo, desde el domingo he estado jugando un poco con esta versión RC0, y he encontrado muchos 'pequeños detalles' que me han encantado y que me gustaría compartir con vosotros, así que vamos allá...

Depuración Integrada

La primera sorpresa agradable es la posibilidad de depurar código TSQL directamente desde la interfaz del SQL Server Management Studio. Si bien es cierto que ya podíamos hacerlo desde el Visual Studio, no deja de ser práctico e interesante el poder realizar la depuración, consultar variables locales y watches, así como el call stack del SQL desde el entorno que utilizamos tan a menudo para desarrollar nuestros procedimientos y consultas.

No se a vosotros, pero a mi el mero hecho de ver en la barra de menú principal del SSMS un menú llamado Debug ya me hace feliz :)

Recomendaciones de Índices en el Plan de Ejecución

No se si se apreciará bien en la captura de pantalla que os adjunto, pero si os fijáis en la ventana de abajo (la que muestra el plan de ejecución), veréis que en la caja de texto nos aparece una línea en verde. Bien, esa línea nos indica que nos vendría bien un índice determinado: si pulsamos con el botón derecho y le pedimos información adicional sobre el índice, nos llega a generar el script que tendriamos que ejecutar para implementar el índice.

En mi ejemplo, el script sería el siguiente:

/*
Faltan detalles del índice de SQLQuery2.sql - (local)\SQLExpress.Performance (DEMOSTENES\Plain Concepts (53))
El procesador de consultas estima que la implementación del
siguiente índice podría mejorar el costo de la consulta en un 46.7053%.
*/

/*
USE [Performance]
GO
CREATE NONCLUSTERED INDEX [<Name of Missing Index, sysname,>]
ON [dbo].[Orders] ([orderdate])
INCLUDE ([custid],[empid],[shipperid])
GO
*/

Cómo se puede ver, ¡hasta nos realiza la estimación de la mejora de rendimiento en caso de implementar el índice!

ExecutionPlan

No se como lo veréis vosotros, pero a mi estos detalles pequeños me encantan; en este caso, la tecnología no es nueva... en el fondo esto consulta unas DMVs que nos muestran esta información de índices no utilizados, etc. que es lo que emplea el Database Engine Tuning Advisor para darnos sus recomendaciones sobre índices. Por lo tanto, nada nuevo bajo el sol. Sin embargo, lo que me fascina es el hecho de que esté integrado en el SSMS, que es desde donde yo suelo lanzar el 80% de mis consultas en tiempo de desarrollo. De éste modo tenemos la oportunidad de ver estos mensajes de advertencia sobre nuestras políticas de índices antes de llegar a fases mas tardías de análisis y optimización. 

Monitor de Actividad

El monitor de actividad, ese gran desconocido. Lo cierto es que yo no lo empleaba; generalmente, para ver la actividad de los diferentes procesos de SQL Server recurría a los conocidos sp_who y sp_who2, y desde la versión 2005 también a diferentes DMVs e informes del servidor.

Sin embargo, ¡puede que hasta yo mismo me vuelva un adepto del monitor de actividad y las interfaces gráficas de administración! He estado jugando con al Monitor de Actividad que viene con la versión RC0 y he de decir que estoy gratísimamente sorprendido. No solo nos muestra de un vistazo rápido el estado de todos los procesos, sino también de las consultas mas costosas ejecutadas recientemente sobre el servidor, las esperas por recursos (waitstats), uso de E/S sobre los ficheros de la base de datos y más información de un modo muy conveniente y práctico, en la linea del nuevo Performance Monitor de Windows Vista y Windows Server 2008.

Os pongo una pequeña captura de pantalla para que veáis el aspecto que tiene:

ActivityMonitor 

Conclusiones

Vaya por delante que este post no ha pretendido ser exhaustivo sobre nuevas características de SQL Server 2008 RC0. No se trata de un artículo de 'Primeras Impresiones', sino de una oportunidad de compartir con vosotros un par de cositas que me he encontrado :)

Cuando comencé a trastear con el producto me encontré con estos detalles (y alguno más); estaba esperando ponerme a explorar iFTS principalmente, así como otras características de mayor peso, pero finalmente preferí perderme con estos detalles (que normalmente no reciben exposición en artículos y blogs) y compartirlos con vosotros. Espero que este post, aunque no haya seguido mi línea, os sirva al menos para conocer algunos pequeños desconocidos y para abriros el apetito por SQL Server 2008 RC0.

Por cierto, si os animas a trastear con él, podéis descargarlo desde el este enlace. Enjoy!

Rock Tip:

Esta vez me gustaría dedicar el post a todo el grupo de producto de SQL Server; a pesar de que esta release ha tenido un tiempo de desarrollo relativamente corto (¡sobre todo si lo comparamos con el de SQL Server 2005!), no dejan de ser unos años de esfuerzo, cariño y dedicación que dentro de muy poquito culminarán con el 'nacimiento' de la versión RTM. Por ello, este post lo acompaño del tema 'The Last Mile', de Cinderella. Un poquito más... una milla mas, y podremos empezar a poner SQL Server 2008 en producción como locos ;)

Posted: 12/6/2008 20:35 por Pablo Alvarez | con no comments |
Archivado en:
These Days: Un día en la vida de una consulta...

Es de sobra conocida por todos la frase que nos enseña que aquel que no conoce la historia está condenado a repetirla. En mi caso, a pesar de ser un apasionado de la historia, debo ser tonto como un cepillo, porque voy a repetir un error garrafal: voy a abrir múltiples frentes. Con esto no me refiero a que vaya a adoptar un modo berserker y vaya a salir a la calle a liarme a manotazo limpio con el primero que me encuentre hasta abrirle la frente, sino que me he decidido a empezar una nueva serie de artículos, en este caso dedicados a la identificación y resolución de problemas de rendimiento en SQL Server.

Espero que esto no me quite demasiado tiempo para la serie sobre depuración, pero creo que es la mejor forma de abordar los artículos acerca del rendimiento en SQL Server. Estuve dándole unas vueltas y creo que organizándolo de este modo podré darle la continuidad y el trasfondo teórico que quiero, algo que no podría hacer si lo organizara como artículos sueltos de 'tips and tricks'.

Así que, sin más preámbulos, y como dirían 'Les Luthiers', vamos a 'principiar' por el principio...

El lenguaje SQL

Aquí conviene recordar un detalle que, a pesar de ser evidente, muchas veces no tenemos en cuenta. El lenguaje SQL es un lenguaje declarativo: el usuario solicita al servidor unos datos determinados, pero no le indica cómo se deben obtener estos datos, ni que algoritmos se emplearán para su extracción, etc... Eso lo decidirá el propio motor de la base de datos que, tal como veremos en éste post, tiene a su disposición una serie de metadatos y estructuras (índices, estadísticas, etc...) que le ayudan a obtener estos datos solicitados del modo más eficiente posible.

Si en lugar de usar un lenguaje como TSQL empleáramos un lenguaje imperativo, como C++ o C#, nosotros tendríamos que especificar paso a paso las operaciones para extraer los datos; el algoritmo empleado para obtener los datos que queremos. Tendríamos que recorrer listas, árboles, aplicar nuestros amados Quick Sort y demás...

¿Cómo se procesan las consultas?

En el siguiente diagrama trataré de representar una simplificación del ciclo de vida de una consulta de SQL Server, desde el momento en que la consulta llega al servidor hasta el momento en que se retorna el resultado al cliente:

EsquemaEjecucionConsultas

Como podéis ver por la simplicidad del diagrama, no vamos a entrar a estudiar las internalidades del procesado de consultas; mi objetivo aquí es establecer una base que luego vayamos extendiendo en sucesivas entradas de este blog. Para poder realizar esta simplificación, me tomaré algunas licencias por lo que lo que voy a comentar aquí debajo no es correcto al 100%, pero la idea de funcionamiento es la misma.

Dicho esto, vamos a ver que sucede en cada una de las etapas descritas en el diagrama:

  • Parseado de la Consulta:

En esta fase se evalúa la sentencia T-SQL que se pretende ejecutar y se comprueba que no tenga errores de sintaxis, que la semántica sea correcta (es decir, que si intenta acceder a una tabla llamada Contactos, esa tabla exista y se tenga acceso a ella), etc.. Como salida del parser, se obtiene una versión de la consulta 'limpia' y normalizada, que describe, de modo no ambiguo, QUE datos quiere obtener el usuario.

Bien, ese 'qué' ya está decidido y comprendido por SQL Server; ahora lo que necesita es el CÓMO obtener los datos. Esto vendrá definido por el Plan de Ejecución. ¡Oh, el Plan de Ejecución! Ésta palabra será clave para nosotros en tantos y tantos escenarios de optimización, sobre todo desde un punto de vista del desarrollo. En resumen, el plan de ejecución será una especie de lista que describirá paso a paso como obtener la información solicitada: que tablas iremos a buscar, que índices emplearemos, como uniremos los datos de unas tablas con otras, etc.

Bien, hecha pues la introducción a los planes de ejecución, os puedo comentar que en éste punto se comprueba también si esa consulta ya se ejecutó anteriormente y si se almacenó un plan de ejecución para ella. Si es así, SQL Server ejecuta directamente los pasos dictados por ese plan de ejecución y devuelve los resultados al cliente.

Si no hubiera un plan de ejecución cacheado, pasaríamos a la siguiente etapa...

  • Compilación/Optimización:

Aquí es donde empieza lo divertido. Recordemos, por enésima vez, que SQL es un lenguaje declarativo; eso quiere decir que al contrario de los lenguajes imperativos, como C++, donde le suministramos al ordenador una serie de pasos para obtener un resultado, en SQL le pedimos a la máquina unos resultados (e.j: dame todos los contactos que vivan en España y tengan mas de 30 años), pero la manera de obtener estos resultados es cosa del servidor. Si va a iterar por todos los elementos de la tabla, si va a usar un índice u otro, o ninguno, si primero va a filtrar por nacionalidad o por edad, esas son decisiones que el SQL Server va a tomar por nosotros.

Por ello SQL Server compila muchas veces cada consulta, generando con cada compilación un plan de ejecución. Al final, el compilador se decidirá por el más eficiente de los múltiples planes generados, y pasará a la siguiente etapa.

¿Y cómo sabe SQL Server cual es el plan mas eficiente? Pues porque los planes de ejecución estiman determinados parámetros, cómo el número de filas que va a devolver cada operación, el coste estimado de CPU, lecturas y escrituras estimadas, etc. para cada una de las operaciones de lo componen. Sumando estas estimaciones puede obtener un índice que le sirve para identificar que planes son mejores que otros, con lo que la elección se reduce (casi siempre) a seleccionar el plan con el índice más bajo.

  • Almacenamiento del Plan de Ejecución:

Cuando el SQL Server se ha decidido por el plan mas eficiente, se suele proceder a almacenar este plan de ejecución en una caché de planes de ejecución para que la próxima vez que se lance la consulta no se tenga que recompilar.

Esta caché se almacena en una zona especial del Buffer Pool de SQL Server, y evidentemente es un recurso finito. Hay que evitar tener demasiados planes de ejecución cacheados para que no se nos sature y SQL Server tenga que eliminar planes 'validos' para hacer sitio a planes de ejecución nuevos... pero esa es otra historia ;)

Un poco de práctica: procedimientos almacenados vs. consultas ad hoc

Para ver todo esto en la práctica, me vais a permitir que me ponga mi disfraz de Cazadores de Mitos (¡¡me pido a Jamie!! ¡De mayor quiero dejarme un bigote como el suyo!) y rebusque en el folklore de SQL Server... un segundito...

Un segundito más....

¡Aquí está! Mito número 208: "Las consultas ad-hoc son menos eficientes que los procedimientos almacenados"... Según el mito, las consultas ad-hoc son, por un motivo u otro, menos eficientes que la misma consulta encapsulada dentro de un procedimiento almacenado. ¿será verdad? ¿será mentira? Vamos a verlo...

NOTA: Este pequeño ejemplo práctico esta orientado a SQL Server 2005 y 2008; en versiones anteriores no funcionará debido a la ausencia de las DMV's (vistas de administración dinámicas) que vamos e emplear.

Vamos a empezar creando unos datos de prueba:

CREATE DATABASE PruebaPlanesEjecucion
GO
USE PruebaPlanesEjecucion
GO

CREATE TABLE dbo.Persona
(
ID INT IDENTITY PRIMARY KEY NOT NULL,
Nombre NVARCHAR(40) NOT NULL
)

INSERT INTO dbo.Persona VALUES ('Juan')
INSERT INTO dbo.Persona VALUES ('Pepe')
INSERT INTO dbo.Persona VALUES ('Arturo')
INSERT INTO dbo.Persona VALUES ('Wenceslao')
INSERT INTO dbo.Persona VALUES ('Miguel Angel')

En el artículo hablábamos de los planes de ejecución para las consultas SQL. Pues bien, vamos a aprovechar para ver el plan de ejecución de una consulta sobre nuestros datos de pruebas. Para ello escribimos la siguiente consulta:

SELECT * FROM dbo.Persona WHERE id = 2

Seleccionamos la consulta y, en lugar de ejecutarla con CTRL+E o F5, pulsamos CTRL+L; esto nos mostrará el plan de ejecución estimado para la consulta; otro día hablaremos de las diferencias entre los planes estimados y reales. El resultado que obtendremos será algo parecido a este:

plan1

Como se aprecia en al captura, desde el SQL Server Management Studio (SSMS) podemos ver gráficamente el plan de ejecución de nuestra consulta. Hay más maneras de verlo, pero generalmente ésta es la más práctica.

Comentábamos que SQL Server tiene una caché de los planes de ejecución, que podemos consultar mediante una select sobre la DMV sys.dm_exec_cached_plans. En mi máquina de pruebas me devuelve 193 filas, esto es, 193 planes de ejecución cacheados, lo que hace muy complicado identificar rápidamente que plan corresponde a la consulta que hemos lanzado.

Para ayudarnos a identificar el plan de ejecución en esta prueba, vamos a hacer algo que NO debemos hacer en producción; vamos a limpiar la caché de planes de ejecución. Así será fácil identificar la consulta que acabamos de lanzar, pero repito que éstos experimentos deben quedarse para nuestras máquinas de pruebas.

DBCC FREEPROCCACHE
GO
SELECT * FROM dbo.Persona WHERE ID = 2
SELECT usecounts, cacheobjtype,objtype FROM sys.dm_exec_cached_plans

procCache

Podemos ver que en la cache tenemos tres planes: el nuestro es el que tiene de objtype 'Adhoc' y que, como podemos ver en su columna usecounts, solo se ha ejecutado una única vez.

Vamos a hacer una prueba: vamos a volver a eliminar la cache (DBCC FREEPORCCACHE) y vamos a ejecutar 10 veces seguidas la misma consulta(nada avanzado aquí, simplemente seleccionamos la query y pulsamos F5 10 veces... que estoy vago hasta para hacer un bucle ;)).

procCache2

Comprobamos como, efectivamente, aparece un plan de ejecución que se ha reutilizado 10 veces: ese es nuestro plan!

Hablando de nuestro plan... ¿os acordáis de él? Era un plan muy, pero que muy simple. Por tanto, cabría suponer que si cambiamos el parámetro que pasamos a la where (el ID) por otro valor diferente, el plan de ejecución debería ser el mismo. De hecho, os animo a que lo comprobéis, cambiando la consulta y mirando su plan de ejecución; veréis que es idéntico. 

Ok, siendo el plan de ejecución es el mismo, si ahora ejecutáramos 10 veces deberíamos ver el plan con un usecounts de 20, ¿no? ¡Pues no! Vamos a hacer la prueba:

DBCC FREEPROCCACHE
GO
-- Ejecutamos esta 10 veces
SELECT * FROM dbo.Persona WHERE ID = 2
-- Ejecutamos esta otra 10 veces
SELECT * FROM dbo.Persona WHERE ID = 4
-- Miramos a ver que tenemos...
SELECT usecounts, cacheobjtype,objtype FROM sys.dm_exec_cached_plans

¿Que resultado obtenemos? Pues como se ve en la siguiente captura, no se esta reaprovechando el plan de ejecución, en su lugar tenemos dos planes de ejecución diferentes (aunque virtualmente idénticos), cada uno con 10 ejecuciones.

procCache3

Esto es significativo: si cada vez que cambiamos de parámetro a nuestras consultas tiene que recompilar el plan y generar uno nuevo, tenemos al menos dos problemas: el coste adicional de CPU asociado a las recompilaciones, y el incremento de planes en la cache, que podrá alcanzar su limite de tamaño y tener que sacar planes de ejecución para hacer sitio a los nuevos.

Vamos a ver que sucede si implementamos esta consulta como un procedimiento almacenado:

-- Vamos a implementar esta consulta como un procedimiento almacenado
CREATE PROCEDURE testProc
    @id INT
AS
BEGIN
    SELECT * FROM dbo.Persona WHERE ID = @id
END

DBCC FREEPROCCACHE
GO
-- Ejecutamos esta 10 veces
testProc 2
-- Ejecutamos esta otra 10 veces
testProc 4

SELECT usecounts, cacheobjtype,objtype FROM sys.dm_exec_cached_plans

 

procCache4

Como podemos ver, finalmente conseguimos que se reutilice el plan de ejecución, ya que el numero de ejecuciones total es 20.

Volviendo al mito... ¿son las consultas ad-hoc menos eficientes que los procedimientos almacenados? Visto lo visto, podemos concluir que el mito es... ¡CIERTO! :) ¿Quiere esto decir que debemos usar procedimientos almacenados para todo? No, ni mucho menos; no todo en esta vida es rendimiento :) Pero esa también es otra historia...

Por cierto, para que no tengáis que andar copiando y pegando del blog, os adjunto un demoscript con toda demostración.

Conclusiones:

Si habéis llegado hasta aquí, mi más sincera enhorabuena :) Ha sido una entrada bastante extensa, con bastante chicha si los conceptos son desconocidos. Hemos revisado el ciclo de vida de la consulta, hemos introducido el concepto de plan de ejecución y hemos hecho un ejercicio sobre reutilización de planes de ejecución bastante interesante... ¡casi nada!

Estoy convencido de que la mayor parte de vosotros ya estabais familiarizados con todos los conceptos descritos en éste articulo. De todos modos, para mi es importante tener un artículo de introducción al que poder hacer referencia desde otros posts de contenido más avanzado que sin duda aparecerán en este blog en breves.

Por tanto, si sois nuevos a SQL Server y su optimización, ¡gracias por haber llegado hasta aquí! Espero vuestros comentarios y dudas al respecto. Y si ya teníais experiencia en SQL Server y en la optimización, ¡espero poder contentaros en pocas semanas con entradas más interesantes y enriquecedoras!

¡Hasta pronto!

Rock Tip:

La razón por la que he elegido el tema 'These Days' (de mis Bon Jovi de toda la vida) para éste post es que estos días, últimamente, he explicado el funcionamiento básico del Query Processor y el Query Optimizer en muchas ocasiones; parece que es mi tema de moda, y es lo que me ha impulsado a iniciar esta sesión respecto a la optimización de consultas.

Respecto a la canción en si, os diré que le tengo un gran cariño: el segundo concierto al que fui en mi vida fue precisamente un concierto de Bon Jovi, en la gira de presentación del These Days allá por el 96. Fue, sin duda, uno de los mejores días de mi vida, y uno de los mejores conciertos que nadie pueda soñar con ver. No se trata, ni de lejos, de mi tema favorito de ellos; es más, muchos estaréis de acuerdo conmigo en que éste el albúm marca el comienzo de su declive. Sin embargo le tengo mucho cariño, quizá por aquel concierto. Haber visto a Jon y Richie cantando las canciones de cowboy en acústico te marca para toda la vida; quizá a ese momento le debo mi afición a las botas camperas :)

Más artículos Página siguiente >