Advanced Debugging

1. AdvancedDebugging PlainConcepts Luis Guerrero Developer Advisor Blog: www.luisguerrero.net Email: lguerrero@plainconcetps.com

2. Definiciones La polilla

3. Depurar es el proceso de encontrar errores de software • Es aplicable a software y hardware • Hay diferentes niveles de depuración • Nosotros vamos a ver la depuración de aplicaciones .net

4. Herramientas para la depuración Espada y cota de malla

5. WinDBG • Nativo • Kernel • Administrado (con SOS) • Visual Studio • Nativo • Administrador • Mixto: administrado + nativo + sos

6. Configuración básica del entorno de depuración • Crear la variable de entorno NT_SYMBOL_PATH • SRV*c:\symbols*http://msdl.microsoft.com/download/symbols • Configurar los símbolos para WinDBG • En VS2008 SP1 configurar el referencesourcecode • (Enable.netframeworksourceStepping) • Cargar sos • .load sos • .loadbysosmscorwks • Usar .cmdtree

7. Laboratorio 1 Debugging 101

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

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

10. Para realizar varias peticiones a la vez • tinyget -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

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

12. 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)

13. Necesitamos mostrar todos los objetos que estan esperando a que se libere un bloqueo (salir de una región critica) • !syncblk 0:028> !syncblk Index SyncBlockMonitorHeld Recursion Owning Thread Info SyncBlock Owner 7 018b6c2c 19 1 0ed5f8c8 1058 28 066affdc System.Object ----------------------------- Total 53 CCW 2 RCW 3 ComClassFactory 0 Free 27 • Cambiamos al thread que está ahora bloqueando el objeto (System.Object) para ver que está haciendo realmente. • ~28s

14. 0:028> !clrstack OS 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.RequestNotificationStatusByRef) 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]

15. 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 threas usando el comando !gcrootde sos, que nos permite ver cuales son los gcroots de un objeto, que son básicamente que objetos lo referencian. • !gcroot 066affdc

16. Comandos útiles • k : muestra la información de la pila nativa actual • b : muestra los tres primero parámetros de las funciones • .loadbysosmscorwks(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

17. Q&A ?

18. Laboratorio 2 Crash

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

20. 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 

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

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

23. 0:015> !dso -verify OS Thread Id: 0xfcc (15) ESP/REG ObjectName 0e5af904 025e4a88System.NullReferenceException 0e5af908 025e4a88System.NullReferenceException 0e5af950 025e4a88System.NullReferenceException 0e5af968 025e4a88System.NullReferenceException 0e5af9bc 025e4a88System.NullReferenceException 0e5af9cc 025e4a88System.NullReferenceException 0e5afa68 0258c2ccSystem.NullReferenceException 0e5afa6c 025e3cbc System.Byte[] 0e5afa88 025e4a88System.NullReferenceException 0e5afa8c 025e3cbc System.Byte[] 0e5afa9c 025e3cbc System.Byte[] 0e5afbc0 0652f3cc Review

24. 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 Exceptionobject: 0258c2cc Exceptiontype: System.NullReferenceException Message: Objectreferencenot set toaninstance of anobject. InnerException: <none> StackTrace (generated): SP IP Function 0E5AF860 0E6B0F74App_Code_etrlku9h!Review.Finalize()+0x14 StackTraceString: <none> HResult: 80004003

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

26. ¿Por qué se lanza esta excepción que nadie controla? • Cual es la mejor manera de finalizar a un objeto • CriticalFinalizerObject

27. Q&A ?

28. Laboratorio 3 MemoryManagment

29. En este laboratorio vamos a intentar solucionar un problema de fuga de memoria (memoryleak) 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

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

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

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

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

34. 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)

35. 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 allHeaps

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

37. 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)

38. 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.String MethodTable: 5c9808ec EEClass: 5c73d64c Size: 20018(0x4e32) bytes (C:\Windows\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll) String: http://blogs.msdn.com/tom Fields: MT Field Offset Type VT AttrValueName 5c982b38 4000096 4 System.Int32 1 instance 10001 m_arrayLength 5c982b38 4000097 8 System.Int32 1 instance 25 m_stringLength 5c9815cc 4000098 c System.Char 1 instance 68 m_firstChar 5c9808ec 4000099 10 System.String 0 sharedstaticEmpty >> Domain:Value 01cac948:024f01d0 01cddff0:024f01d0 << 5c98151c 400009a 14 System.Char[] 0 sharedstaticWhitespaceChars >> Domain:Value 01cac948:024f0728 01cddff0:064f0964 <<

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

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

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

42. Q&A ?

43. Depuración extrema VS2008 + SOS Cuando no hay otra manera

44. Hay momentos en los que necesitamos, por la razón que sea, acceder a variables internas del framework porque estamos atascados en un problema y no somos capaces de avanzar. • Podemos acceder a toda la información de todos los tipos del framework desde Visual Studio.

45. Hay que distinguir dos casos: • Si el tipo que estamos buscando está dentro del RefecenceSourceCode del .NET Framework • O no tenemos el código fuente de .NET Framework o de ensamblados terceros.

46. ReferenceSourceCode • Microsoft proporciona a través de Visual Studio acceso al código fuente a través de una licencia Microsoft Reference Source License (Ms-RSL) • http://www.microsoft.com/resources/sharedsource/referencesourcelicense.mspx • A partir del SP1 de Visual Studio 2008 la integración es casi perfecta. • Podemos depurar por el codigo fuente igual que si fuera codigo de nuestra aplciación

47. ReferenceSourceCode • Los ensamblados que se redistribuyen con .NET Framework están optimizados para versiones release (Microsoft lo llama RedBits) así que si intentamos con VS explorar un tipo desde la ventana de watch los desplazamientos de las estructuras internas no corresponden con la versión del código fuente, además de que los ensamblados principales del framewokr están ngeneados (ngen) • Hay una manera de hacer que tanto VS como nuestras aplicaciones .NET no carguen las imágenes nativas (ni) y jiteemos (JIT) todo el código del framework

48. ReferenceSourceCode • Esto nos va a permitir ver todo los tipos que estén dentro del código fuente. set COMPLUS_ZapDisable=1 cd /d "%ProgramFiles%\Microsoft Visual Studio 9.0\Common7\ide\" start devenv.exe exit

49. VS2008 + SOS + Depuración Mixta • La otra manera de acceder a la información de los tipos del framework, es a través de una depuración mixta de una aplicación administrada • Con la ventana de Dissasembly para ver el codigo fuente en X86 y con la ventana del Inmediato para invocar comando de SOS vamos a poder explorar todos los objetos de .NET framework !do • Hay que tener en cuenta que las varibles locales se almacenan en la pila en EPB + offset

50. Q&A ?