Depuración Avanzada con WinDbg y VS 2010la de verdad ;)

Pablo Álvarez DovalDebugging & Optimization Team Lead (@Plain Concepts)

pablod@plainconcepts.com

www.codecamp.es

Presentación

• ¿Quién soy yo?• ¿Quiénes sois vosotros?

• Depuración Avanzada• Consultad en casa el otro juego de slides ;)

• Solo tenemos una hora…• Necesitamos algo Simple

www.codecamp.es

Agenda

• Depuración Avanzada:– Introducción a la Depuración Nativa con WinDbg– Depuración de Código .NET con WinDbg– Depuración con Visual Studio 2010

www.codecamp.es

¿Para que complicarnos la vida?

Laboratorio 1: Pero que feo es WinDbg…

www.codecamp.es

Laboratorio 1: WinDbg

• Descarga gratuita – http://

www.microsoft.com/whdc/devtools/debugging• Veremos un escenario de depuración en vivo:

notepad.exe– Invasive/Non Invasive– Call Stacks, símbolos, …– Comandos (x, bp, …)

www.codecamp.es

Símbolos

• Los símbolos hacen que el call stack sea útil:

– Sin símbolos:

– Con símbolos:

kernel32!+136aa

kernel32!CreateFileW+0x35f

www.codecamp.es

Servidores de Símbolos

• Utiliza el sistema de ficheros como base de datos para símbolos

• Ejemplos:\\Symbols\ntdll.pdb\3B5EDCA52\ntdll.pdb\\Symbols\ntdll.pdb\380FCC4F2\ntdll.pdb

Laboratorio 2: No puedo vivir sin SQL Server

www.codecamp.es

Laboratorio 2: Depuración Postmortem

• Un cliente tiene un problema con su SQL Server 2000, manifestado con errores 17883 en el log del SQL Server

• Al producirse los errores 17883, SQL Server genera automáticamente un volcado de memoria para su posterior estudio

…

2004-05-27 13:01:40.10 server Error: 17883, Severity: 1, State: 0

2004-05-27 13:01:40.10 server Process 59:0 (834) UMS Context 0x125ABD80 appears to be non-yielding on Scheduler 1.

…

www.codecamp.es

Laboratorio 2: ¿Que hemos aprendido?

• Depuración de un volcado de memoria– En una arquitectura diferente (x86)

• Empleo de extensiones (SIEExtPub.dll)• Que ni los chicos de Microsoft están libres de

pecado

www.codecamp.es

Agenda

• Depuración Avanzada:– Introducción a la Depuración Nativa con WinDbg– Depuracion de Código .NET con WinDbg– Depuración con Visual Studio 2010

www.codecamp.es

Depuración de Código .NET

• WinDbg es un depurador Nativo

• Para depurar código .NET hay que usar extensiones:– SOS.dll

• Extensión muy recomendable:– SOSEX v2, de Steve Johnson

Laboratorio 3: Depuración con SOS

www.codecamp.es

Laboratorio 3: Depuración con SOS

• Para empezar a depurar se tiene que tener claro que algo mal ocurre.

• En los sucesivos ejemplos vamos a depurar una web en ASP.NET con diferentes tipos de errores cometidos durante su desarrollo.

• Identificaremos el problema y trataremos de aislarlo.

www.codecamp.es

Laboratorio 3: Depuración con SOS

• Si hacemos una petición a http://localhost/BuggyBits/FeaturedProducts.aspx vemos que la pagina tarda +5 seg en ejecutarse.

• Si hacemos varias peticiones a la web con varios tabs, vemos que la web se bloquea.

www.codecamp.es

Laboratorio 3: Depuración con SOS

• Para realizar varias peticiones a la veztinyget -srv:localhost

-uri:/BuggyBits/FeaturedProducts.aspx -threads:30 -loop:50

• Una vez que tenemos todas la peticiones bloqueadas hacemos un dump del proceso (w3wp.exe)

adplus –hang –pn w3wp.exe –quiet

• Ahora es el momento de empezar con WinDBG

www.codecamp.es

Laboratorio 3: Depuración con SOS

• Pasos a seguir:~* kb 2000 (pila de todos los threads del proceso)~* e !clrstack (pila .net de todas los threads)

www.codecamp.es

Laboratorio 3: Depuración con SOS

• En casi todas los threads hay llamadas a esté método– System.Threading.Monitor.Enter(System.Object)

• Menos en un thread que hay una llamada a – System.Threading.Thread.SleepInternal(Int32)

• Es muy posible que haya un deadlock (hay que investigar)

www.codecamp.es

Laboratorio 3: Depuración con SOS

• Necesitamos mostrar todos los objetos que estan esperando a que se libere un bloqueo (salir de una región critica)– !syncblk

0:028> !syncblkIndex SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner 7 018b6c2c 19 1 0ed5f8c8 1058 28 066affdc System.Object-----------------------------Total 53CCW 2RCW 3ComClassFactory 0Free 27

www.codecamp.es

Laboratorio 3: Depuración con SOS

0:028> !clrstackOS Thread Id: 0x1058 (28)ESP EIP 0ffee0e0 76f89a94 [HelperMethodFrame: 0ffee0e0] System.Threading.Thread.SleepInternal(Int32)0ffee134 0e8c0fc5 DataLayer.GetFeaturedProducts()0ffee170 0e8c0e1f FeaturedProducts.Page_Load(System.Object, System.EventArgs)0ffee1fc 5b46a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)0ffee20c 59802344 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)0ffee220 597fb864 System.Web.UI.Control.OnLoad(System.EventArgs)0ffee234 597fb8a3 System.Web.UI.Control.LoadRecursive()0ffee24c 597f7954 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)0ffee3a4 597f7584 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)0ffee3dc 597f74b1 System.Web.UI.Page.ProcessRequest()0ffee414 597f7446 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)0ffee420 597f7422 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)0ffee434 0e8c0355 ASP.featuredproducts_aspx.ProcessRequest(System.Web.HttpContext)0ffee438 597fd8f6 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()0ffee46c 597d132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)0ffee4ac 59dc494f System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)0ffee4b0 59dbd8e8 [InlinedCallFrame: 0ffee4b0] 0ffee550 59da6981 System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)0ffee5c0 59e7a3ca System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)0ffee5c4 59e798e7 [InlinedCallFrame: 0ffee5c4] 0ffeeb18 01792904 [NDirectMethodFrameStandalone: 0ffeeb18] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr,

System.Web.RequestNotificationStatus ByRef)0ffeeb28 59e7a461 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)0ffeebac 59e798e7 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)0ffeecac 01792904 [ContextTransitionFrame: 0ffeecac]

www.codecamp.es

Laboratorio 3: Depuración con SOS

• Efectivamente todos los threads esperan a que se libere el bloqueo de un objeto de tipo Object, podemos ver el código fuente para verificarlo.

• Además podemos asegurarnos de que ese objeto es el que usan todos los threads usando el comando !gcroot de sos, que nos permite ver cuales son los gcroots de un objeto, que son básicamente que objetos lo referencian.– !gcroot 066affdc

www.codecamp.es

Laboratorio 3: Comandos Útiles

• k : muestra la información de la pila nativa actual– b : muestra los tres primero parámetros de las funciones

• .loadby sos mscorwks (carga sos en WinDbg)• !clrstack : muestra la información de la pila

administrada• !syncblk : muestra información sobre los bloqueos– lock(obj) { }

• !gcroot : muestra cuales son los objetos que referencian a este objeto

Laboratorio 4: Crash

www.codecamp.es

Laboratorio 4: Crash

• Navegamos por http://localhost/BuggyBits/Reviews.aspx, pulsamos el botón de Refresh. Pasados unos segundos el proceso w3wp.exe se estrella.

• En el registro del sistema encontramos una entrada de porque se ha estrellado.

• Es un problema bastante grave pues puede afectar a otros dominios de aplicación que se encuentren en ese proceso

• Tenemos que crear un dump completo de la aplicación para ver porque se estrella.

www.codecamp.es

Laboratorio 4: Crash

• Volvemos a navegamos por http://localhost/BuggyBits/Reviews.aspx, pero ahora no pulsamos en el botón de refresh.

• Hay que iniciar adplus para hacer un dump del proceso cuando se estrelle.– adplus -crash -pn w3wp.exe– Aparece una ventana nueva en la barra de tareas.

• Pulsamos refresh y el proceso se estrella

www.codecamp.es

Laboratorio 4: Crash

• El código nativo nos indica que estamos ante el finalizador de la clase, y es aquí donde se ha generado la excepción.

• La pila administrada no proporciona mucha información.

• Se sabe que es un NullReferenceExcepcion, gracias a !pe

www.codecamp.es

Laboratorio 4: Crash

• Con el comando !dso, nos permite ver las variables locales de todos los frames de la pila.

• En la lista hay muchos objetos del tipo NullReferenceExcepcion y podemos encontrar un objeto del tipo Review

www.codecamp.es

Laboratorio 4: Crash

0:015> !dso -verifyOS Thread Id: 0xfcc (15)ESP/REG Object Name0e5af904 025e4a88 System.NullReferenceException0e5af908 025e4a88 System.NullReferenceException0e5af950 025e4a88 System.NullReferenceException0e5af968 025e4a88 System.NullReferenceException0e5af9bc 025e4a88 System.NullReferenceException0e5af9cc 025e4a88 System.NullReferenceException0e5afa68 0258c2cc System.NullReferenceException0e5afa6c 025e3cbc System.Byte[]0e5afa88 025e4a88 System.NullReferenceException0e5afa8c 025e3cbc System.Byte[]0e5afa9c 025e3cbc System.Byte[]0e5afbc0 0652f3cc Review

www.codecamp.es

Laboratorio 4: Crash

• Obtenemos la información de la excepción a través del comando !pe 0258c2cc, que nos muestra el método que lanzo la excepción.

0:015> !pe 0258c2cc Exception object: 0258c2ccException type: System.NullReferenceExceptionMessage: Object reference not set to an instance of an object.InnerException: <none>StackTrace (generated): SP IP Function 0E5AF860 0E6B0F74 App_Code_etrlku9h!Review.Finalize()+0x14

StackTraceString: <none>HResult: 80004003

www.codecamp.es

Laboratorio 4: Crash

• Ya sabemos que la excepción la ha lanzado el objeto Review ahora podemos saber cual es la línea que lanzo la excepción en caso de que no tengamos el código fuente disponible.

• SOS incluye un comando !u, que permite desensamblar la memoria y ver el codigo X86 generado por el JIT con información extra a partir de la información de depuración.

• El comando !u, acepta la dirección de memoria del bloque de código, que la podemos obtener del EIP.

www.codecamp.es

Laboratorio 4: Crash

• ¿Por qué se lanza esta excepción que nadie controla?

• Cual es la mejor manera de finalizar a un objeto

• CriticalFinalizerObject

Laboratorio 5: Gestión de Memoria

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• En este laboratorio vamos a intentar solucionar un problema de fuga de memoria (memory leak) de una pagina ASP.NET.

• Lo más importante para resolver este tipo de problemas es saber que efectivamente nuestra aplicación tiene fugas de memoria.

• La única herramienta que hay para esto es ver la evolución de la memoria a través del tiempo con los contadores de rendimiento

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Navegamos por http://localhost/BuggyBits/Links.aspx y vemos que ocurre.

• En principio la aplicación funciona correctamente, tenemos que estresarla de alguna manera para simular un carga alta.

• tinyget -srv:localhost -uri:/BuggyBits/Links.aspx -loop:4000

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Ahora si observamos como el proceso reserva mucha memoria.

• Con los contadores de rendimiento podemos observar cual es el tipo de reserva que hace.

• En el resultado de los contadores de rendimiento hay que observar el resultado de la memoria de Win32 así como la memoria de .NET

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Con el proceso (w3wp.exe) en este estado hay que hacer un dump para poder analizar el porque de esta fuga de memoria.

• adplus -hang -pn w3wp.exe –quiet

• Es el momento de empezar con WinDbg

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Hay que ver el estado de la memoria para el proceso – !address –summary

www.codecamp.es

Laboratorio 5: Gestión de Memoria

0:000> !address -summary ProcessParametrs 001f1588 in range 001f0000 002f0000 Environment 01c16128 in range 01c10000 01d10000

-------------------- Usage SUMMARY -------------------------- TotSize ( KB) Pct(Tots) Pct(Busy) Usage 36c73000 ( 897484) : 42.80% 86.79% : RegionUsageIsVAD 40e1d000 ( 1063028) : 50.69% 00.00% : RegionUsageFree 73b4000 ( 118480) : 05.65% 11.46% : RegionUsageImage 57b000 ( 5612) : 00.27% 00.54% : RegionUsageStack 16000 ( 88) : 00.00% 00.01% : RegionUsageTeb c1a000 ( 12392) : 00.59% 01.20% : RegionUsageHeap 0 ( 0) : 00.00% 00.00% : RegionUsagePageHeap 1000 ( 4) : 00.00% 00.00% : RegionUsagePeb 0 ( 0) : 00.00% 00.00% : RegionUsageProcessParametrs 0 ( 0) : 00.00% 00.00% : RegionUsageEnvironmentBlock Busy: 3f1d3000 (1034060 KB)

-------------------- Type SUMMARY -------------------------- TotSize ( KB) Pct(Tots) Usage 40e1d000 ( 1063028) : 50.69% : <free> 817c000 ( 132592) : 06.32% : MEM_IMAGE 1974000 ( 26064) : 01.24% : MEM_MAPPED 356e3000 ( 875404) : 41.74% : MEM_PRIVATE

-------------------- State SUMMARY -------------------------- TotSize ( KB) Pct(Tots) Usage 38237000 ( 919772) : 43.86% : MEM_COMMIT 40e1d000 ( 1063028) : 50.69% : MEM_FREE 6f9c000 ( 114288) : 05.45% : MEM_RESERVE

Largest free region: Base 3a0a0000 - Size 1e1f0000 (493504 KB)

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Se ha visto que casi la mayoría de la memoria del proceso viene de la sección de RegionUsageIsVAD ¿Porque?

• Examinamos los heaps de GC– !eeheap –gc

• Tenemos dos GC Heaps• Comparamos la memoria total del GC Heap con

#Bytes in all Heaps

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Ahora queremos saber cuantos objetos hay en el heap, de que tipo son y cuanta memoria ocupan.– !dumpheap –stat

• ¿Cuantos objetos hay en total en los dos heaps?– 140786

• El objeto que más aparece en la pila es System.String– 44375 instancias– 721004504 TotalSize

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Después aparece memoria libre, StringBuilders y objetos del tipo Link. Estos objeto de tipo Link (recordar la web que estamos depurando) son los que representar un link.– !dumpheap -type Link– !dumpmt 0e781684 – !do 34d96fb0 – !objsize 34d96fb0

• Observamos que este objeto (Link) tiene dos campos– url (StringBuilder) (offset 4)– name (string) (offset 8)

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Observamos que la mayoría de las cadenas estan entre un tamaño de 20000 y 25000 (ensayo y error), así que vamos a ver cuales son esos strings– !dumpheap -mt <string MT> -min 20000 -max 25000

• Cogemos cualquier objeto y vemos el contenido– !do 35458344

0:000> !do 35458344 Name: System.StringMethodTable: 5c9808ecEEClass: 5c73d64cSize: 20018(0x4e32) bytes (C:\Windows\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)String: http://blogs.msdn.com/tomFields: MT Field Offset Type VT Attr Value Name5c982b38 4000096 4 System.Int32 1 instance 10001 m_arrayLength5c982b38 4000097 8 System.Int32 1 instance 25 m_stringLength5c9815cc 4000098 c System.Char 1 instance 68 m_firstChar5c9808ec 4000099 10 System.String 0 shared static Empty >> Domain:Value 01cac948:024f01d0 01cddff0:024f01d0 <<5c98151c 400009a 14 System.Char[] 0 shared static WhitespaceChars >> Domain:Value 01cac948:024f0728 01cddff0:064f0964 <<

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Resulta que todas las cadenas que se utilizan para generar la lista de string no están siendo recolectadas con el GC, así que tenemos que encontrar que otros objetos hacen referencia a estas cadenas– !gcroot 35458344

• Parece ser que el objeto está referencia por un tipo Link, pero que este se encuentra en la cola de finalización– !finalizequeue

• Parece que todos los objetos están en la cola de finalización pero no se están recolectando.

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• Hay que encontrar el thread finalizador para ver que está haciendo. El thread finalizador está marcado con Finalizer– !threads

• Cambiamos al thread finalizador– ~15s– Kb 2000– !clrstack

www.codecamp.es

Laboratorio 5: Gestión de Memoria

• El objeto Link en el finalizador tiene un Thread.Sleep que está haciendo que se bloquee el finalizador durante 5 segundos lo que hace que no se recolecten los objetos con la velocidad deseable.

• Hacer cualquier operación de bloqueo en el finalizador es extremadamente peligroso pues puede hacer que nuestro thread de finalización se bloquee y no podamos ser capaces de recolectar los objetos no utilizados.

Laboratorio 6: CLR 4.0

www.codecamp.es

Novedades en CLR 4.0

• Ahora se encuentra en CLR.DLL

• Soporte DML• Nuevas extensiones:– !ThreadState, !DumpSigElem, !FindRoots, !

ListNearObj (lno), !HistRoot, y muchos más…

.loadby sos clr

www.codecamp.es

Agenda

• Depuración Avanzada:– Introducción a la Depuración Nativa con WinDbg– Depuracion de Código .NET con WinDbg– Depuración con Visual Studio 2010

www.codecamp.es

¡¿De verdad hemos llegado aquí?!

• No me creo que hayamos llegado aquí con tiempo suficiente…

www.codecamp.es

Algunos Truquillos

• Bueno, ya que lo hemos conseguido, veamos algunos truquillos:– SOS desde el VS.NET– Análisis de Volcados de Memoria desde VS2010– Depurador Histórico– Parallel Tasks/Call Stacks

www.codecamp.es

Lo que no hemos visto…

• Depuración en modo Kernel• Generación Programática de Dumps• Servidores de Símbols• Vistazo en Profundidad de SOS• Ingeniería Inversa y Desensamblado• …

www.codecamp.es

Recursos

• En Plain Concepts– http://www.geeks.ms/blogs/palvarez– http://www.geeks.ms/blogs/rcorral– http://www.geeks.ms/blogs/luisguerrero

• En MSDN:– http://blogs.msdn.com/tess/

• En papel…– Microsoft Windows Internals, 5th Ed.

[Mark E. Russinovich and David A. Solomon]Microsoft Press.

– Debugging Applications for Microsoft .NET and Microsoft Windows[John Robbins]Microsoft Press.

¿Preguntas ?

Recuerda que en www.codecamp.es podrás encontrar todo el material de las sesiones del CodeCamp