Surviving the Night

El blog de Pablo Doval sobre .NET, SQL, WinDbg...

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: ,
Comparte este post:

Comentarios

Rodrigo Corral ha opinado:

Pedazo de post titán... desde que tu y Luis comentasteis esta extensión en la lista interna del DOT se ha hecho imprescindible para mi... tendré siempre este post de resumen a mano.

¡Excelente!

# June 23, 2009 9:40 PM

Pablo Alvarez ha opinado:

¡Gracias tio! Me alegro que te gustara.. ahora solo falta ver si alguien pica y me invita a esa cerveza!

¡un abrazote!

# June 24, 2009 1:36 PM

Cristina González ha opinado:

Como siempre un post excelente :) Mereces que te invite a una cerveza! Cachiiis! Ya piqué ;)

# June 24, 2009 3:48 PM