Surviving the Night

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 FilesDebugging 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 FilesDebugging Tools for Windows (x64)winextext.dll]
    exts: image 6.11.0001.404, API 1.0.0, built Thu Feb 26 03:10:17 2009
        [path: C:Program FilesDebugging Tools for Windows (x64)WINXPexts.dll]
    uext: image 6.11.0001.404, API 1.0.0, built Thu Feb 26 03:10:20 2009
        [path: C:Program FilesDebugging Tools for Windows (x64)winextuext.dll]
    ntsdexts: image 6.1.7015.0, API 1.0.0, built Thu Feb 26 03:09:22 2009
        [path: C:Program FilesDebugging Tools for Windows (x64)WINXPntsdexts.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:demosDOTDemoThreadsMonitor.cs, line 63]
CLR Thread 5 is waiting at DemoThreading.Monitor.ReaderFunc()+0x15(IL)
[c:demosDOTDemoThreadsMonitor.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’!

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

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 \DevSer01Symbols.

• 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*\DevSrv01Symbols*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.

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 (\DevSrv01Symbols) y, caso de no encontrarlos, iria al siguiente elemento en la cadena de búsqueda y los descargaría, copiandolos en el servidor \DevSrv01Symbols; 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:sourcesaplicacionbins*.* /s \DevSrv01Symbols /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! 🙂

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’!

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’!!!

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 😛

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.

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

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’

¿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 😀 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’!

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!