Debugging avanzado en .NET – Parte 2

En la primera parte de este serie de artículos (http://blogs.msdn.com/latamarchitectnewsletter/archive/2007/06/08/debugging-avanzado-en-net.aspx o http://shockbyte.net/debugging-avanzado-en-net/debugging-avanzado-en-dotnet-parte-1/) he explicado conceptos generales sobre el diagnostico de aplicaciones y he mostrado como utilizar herramientas poco conocidas pero muy útiles a la hora resolver errores difíciles de reproducir por métodos más tradicionales. Ahora utilizaremos estos conceptos y herramientas para diagnosticar un problema de memoria.

La administración de memoria en .NET es responsabilidad del Garbage Collector. Este componente del CLR es el encargado de eliminar automáticamente de memoria los objetos que ya no son más utilizados, liberando de esta tarea al programador. Por ese motivo a diferencia de las aplicaciones no manejadas, donde la mayoría de la veces el consumo excesivo de memoria se debe a que el programador se ha olvidado de liberar algún recurso, en .NET un leak de memoria se produce generalmente por dos motivos: existen objetos que continúan referenciados haciendo que el GC no pueda recolectarlos, o se utilizan recursos no manejados y no se liberan adecuadamente. Por lo tanto el análisis de problemas de memoria en .NET se resume a determinar por qué motivo el GC no libera memoria.

Para un mayor detalle sobre el funcionamiento del GC y la administración de memoria en .NET recomiendo leer los siguientes artículos:

·         Garbage Collection: Automatic Memory Management in the Microsoft .NET Framework (http://msdn.microsoft.com/msdnmag/issues/1100/GCI/)

·         Garbage Collection—Part 2: Automatic Memory Management in the Microsoft .NET Framework (http://msdn.microsoft.com/msdnmag/issues/1200/GCI2/)

Durante el desarrollo de este articulo diagnosticaremos cual es el problema por el cual una aplicación termina inesperadamente por falta de memoria. Para esto utilizaremos como ejemplo una aplicación WinForm escrita en .NET Framework 2.0 llamada MemoryCrashProblem, y supondremos que no disponemos del código fuente de esta aplicación. Esta aplicación tiene dos botones, el primero de ellos crea y destruye objetos de 20 MB, y el segundo botón llama al método GC.Collect para forzar que los objetos que no están siendo utilizados se eliminen de la memoria.

Pero este simple programa tiene un problema. Si lo ejecutamos y abrimos el Task Manager en la solapa Process y seleccionamos las columnas Memory – Working Set y Memory – Private Working Set, podemos observar que siempre que presionamos el primer botón la cantidad de memoria utilizada aumenta, por más que los objetos se crean e inmediatamente se eliminan. La cantidad de memoria utilizada tampoco disminuye al forzar la recolección de basura mediante el segundo botón.

Si continuamos presionando el primer botón luego de un tiempo obtendremos una excepción del tipo System.OutOfMemoryException. Esta excepción se produce cuando una alocación de memoria falla, en la mayoría de los casos por que ya no hay más memoria disponible. Luego de producirse la excepción el programa termina abruptamente.

En el diagnóstico de problemas de memoria en aplicaciones .NET los contadores de performance son herramientas fundamentales. Para diagnosticar cual es el problema de nuestra aplicación registraremos los siguientes contadores:

·         Grupo .NET CLR LocksAndThreads:

o   Current Queue Length: Este contador muestra el número total de threads que actualmente están esperando para adquirir algún lock manejado en la aplicación. Este contador solo muestra el último valor observado.

o   Total # of Contentions: Muestra el número total de tiempo que cualquier thread ha tratado sin éxito de adquirir un lock manejado.

Los valores combinados de estos dos contadores nos dicen si hay gran cantidad threads esperando la resolución de locks por mucho tiempo. Una gran cantidad de threads en espera de la resolución de locks, además de ser un posible problema de contención, puede ser el causante de un problema de memoria por que los recursos que utiliza cada thread no se liberan nunca.

·         Grupo .NET CLR Memory

o   # Byte in all Heaps: Este contador es la suma de otros cuatro contadores: Gen 0 Heap Size, Gen 1 Heap Size, Gen 2 Heap Size y Large Object Heap Size. Muestra la cantidad de memoria virtual en bytes actualmente alocada en los heaps manejados. Si este contador crece sostenidamente indica que existe una leak de memoria en código manejado.

o   # GC Handles: Muestra la cantidad actual de GC handles en uso. Los GC handles son handles a recursos externos al CLR y al entorno manejado. Los GC handles no ocupan una gran cantidad de memoria manejada, pero si ese contador crece en conjunto con el contador Private Bytes es probable que existan referencias a recursos no manejados que no se están liberando causando un leak de memoria.

o   Gen X Collections: Estos contadores indican la cantidad de veces que se ejecuto la recolección de basura en cada generación.

o   # Induced GC: Indica el número de veces que se ha llamado explícitamente al método GC.Collect. Utilizar el método GC.Collect no es una buena práctica pero generalmente se utiliza en el proceso de diagnostico.

o   # of Pinned Objects: Este contador muestra el número de pinned objects encontrados desde la última recolección. Un pinned object es un objeto que el GC no se puede mover en la memoria. Los pinned objects son usualmente objetos pasados como punteros a código no manejado y se encuentran “fijos” (pinned) porque si el GC los mueve, durante la fase de compactación en la recolección, el código no manejado que los utiliza no podría encontrarlos y se provocaría una situación de corrupción de memoria. Normalmente no debería haber muchos pinned objects si no se utiliza mucho código no manejado. Si existen muchos pinned objects se puede estar dando una situación en donde hay muchas estructuras de código no manejados que no se liberan o que se liberan pero no se hace unpinning de los pinned objects que se usan para acceder a ellas. Los pinned objects son especialmente negativos por que al no poder compactarse tienden a fragmentar el espacio de direcciones de los heaps manejados, por lo tanto aunque sean relativamente pocas la cantidad de estructuras no manejadas que se utilizan la fragmentación puede provocar el leak.

o   # of Sink Blocks in use: Este contador muestra el número actual de sync blocks en uso. Los sync blocks son estructuras que se utilizan para almacenar información de sincronización y metada cuando se hace COM interop. Los sync blocks ocupan memoria. Si este contador crece sostenidamente puede indicar un uso excesivo de primitivas de sincronización, lo que puede indicar que existen cuello de botella en la aplicación.

o   # Total committed Bytes y #Total reserved Bytes: El primero muestra el número total de memoria virtual (en bytes) que actualmente está asignada a heaps de .NET. El segundo muestra el total de memoria virtual (en bytes) reservada actualmente por el proceso .NET. Si el contador #Total Reserved Bytes crece continuamente en forma significativamente más grande que el contador # Total committed Bytes quiere decir que el GC necesita asignar segmentos de memoria más largos que los que tiene reservados, lo que indica que existe fragmentación en la utilización de memoria. Esta situación se puede deber a que el GC tiene problemas para compactar los heaps debido a que existen gran cantidad de pinned objects, o a que simplemente hay gran cantidad de objetos pequeños que no se liberan por que todavía están referenciados. En crecimiento sostenido del contador #Total reserved Bytes indica fragmentación del espacio de direcciones de memoria virtuales, y generalmente esta situación se debe a que existe una utilización alta de código no manejado.

o   Finalization Survivors: Muestra la cantidad de objetos manejados que no fueron eliminados de la memoria lo el GC debido que están esperando que se termine de ejecutar su finalizador. Si hay muchos objetos esperando finalización el leak de memoria se debe probablemente a que el código de finalización de estos objetos no termina de ejecutar por algún motivo.

o   Gen X Heap Size: Indica el tamaño (en bytes) del heap de cada generación. Si el valor del contador Gen 2 Heap Size es muy grande esto indica que hay muchos objetos que están vivos por mucho tiempo y pie eso fueron promovidos hasta la generación 2. Como el heap de generación 2 se recolecta cada menos tiempo que los de generación 0 y 1 esta situación puede provocar que haya objetos que continúen en memoria mucho tiempo aunque no se esté utilizando más.

o   Large Object Heap Size: En .NET los objetos que ocupan más de 85kb se ubican directamente en heap especial de llamado Large Object Heap. La diferencia de este heap con los generación 0, 1 y 2 es que este heap puede no compactarse (esto depende del modo de ejecución del GC) y se recolecta luego de la recolección de generación 2. Por estos motivos los objetos grandes tienen a permanecer en memoria por mucho tiempo aunque no se estén utilizando. Esto hace que la aplicaciones que utilizan objetos grandes tiendan a consumir cantidades crecientes de memoria. Moraleja: ¡nunca usar objetos grandes¡.

·         Grupo Process:

o   Virtual Bytes: Indica el tamaño actual de la memoria virtual (en bytes) consumida por el proceso (asignada y reservada).

o   Private Bytes: Indica el tamaño actual (in bytes) de la memoria virtual asignada al proceso.

o   Threads Count: Muestra el número de threads actualmente actives en el proceso.

o   % Processor Time: Indica el porcentaje de tiempo que el procesador gasta en la ejecución del proceso.

Estos contadores nos permiten determinar si el leak de memoria se produce en código manejado o código no manejado. Si los valores de Virtual Bytes son similares a los valores de # Bytes in all Heaps el leak se está produciendo en código manejado, de lo contrario es un leak en código no manejado.

La siguiente figura muestra los valores de estos contadores luego de utilizar la aplicación de ejemplo por algún tiempo:

Lo primero que se observa al comparar los contadores # Bytes in all Heaps y Virtual Bytes es que casi toda la memoria virtual consumida por proceso es memoria manejada.

Luego se observa un consumo elevando y creciente de memoria en el Large Object Heap, de hecho casi toda la memoria comprometida se encuentra en este heap.

También se observa que el consumo de memoria es siempre creciente, aun cuando presionemos el botón Free memory, que fuerza la recolección de memoria llamando al método GC.Collect.

Utilicemos un vuelco de memoria para ver por qué se produce esto.

En la primera parte de esta serie de artículos se he explicado los procedimientos y herramientas para tomar un vuelco de memoria. También he explicado cómo utilizar WinDbg y SOS para leer vuelcos de memoria.

Para diagnosticar el problema que sufre nuestra aplicación de ejemplo tomamos un vuelco de memoria del proceso al momento de que termine inesperadamente, y luego lo abrimos utilizando WinDbg con la extensión SOS cargada.

El primer comando que utilizaremos es !threads: este comando nativo de WinDbg nos muestra información de los threads no manejados de la aplicación.

Al ejecutar el comando !threads observamos que contienen frames manejados. El primero es un thread es de tipo STA, probablemente el thread principal de una aplicación WinForm. El segundo thread es el que ejecuta el código de los finalizadores de los objetos, y está bloqueado.

El siguiente comando de SOS que utilizaremos es !clrstack: este comando nos muestra el stack trace del código manejo del thread manejado en el que actualmente estamos parados.

Realizando una inspección más detallada del stack de cada thread manejado (ejecutando el comando !clrstack utilizado el comodín ~*e para ejecutarlo en todos los threads y no solamente en el actual), es posible observar:

·         El thread 0 es el hilo principal de una aplicación WinForm.

·         El thread 1 se encuentra probablemente ejecutando código no manejado del debugger.

·         El thread 2 ejecuta código del finalizador de objetos. En este caso el hilo se encuentra bloqueado aparentemente debido a una llamada explícita al método Sleep dentro del método Finalize() del objeto CacheItem

Para obtener más información sobre el aparente bloqueo utilizaremos el comando nativo de WinDbg kb: este comando muestra el stack trace no manejado del thread no manejado en el que actualmente estamos parados.

Con la información que nos brinda kb (ejecutado con el comodín ~* kb 2000 para listar los stack trace de los primeros 2000 threads)

·         El thread 0 es el punto de entrada de la aplicación WinForm.

·         El thread 1 es un thread para el debugger.

·         El thread 2 efectivamente se encuentra en espera, bloqueando de esta manera el hilo del finalizador de objetos.

El bloqueo parecería realizado en forma explícita desde el código. A continuación utilizaremos el comando !u para analizar el método Finalize() del objeto CacheItem para intentar comprender el motivo del bloqueo.

El comando !u nos muestra el código desensamblado de un método manejado que se encuentre dentro del vuelco de memoria. El comando !u recibe como parámetro una numero hexadecimal conocida como method descriptor. Para obtener el method descriptor se utiliza el comando !Name2EE, este comando recibe como parámetros el nombre del archivo donde se encuentra el método y el full type name del mismo. En nuestro caso el comando es !Name2EE MemoryCrashProblem.exe CrashProblem.CacheItem.Finalize

Mirando el resultado del comando !u resulta sencillo comprender que el bloqueo fue realizado en forma explícita (intencionalmente), con un código C# similar a este:

Para completar nuestro análisis utilizaremos algunos comandos para analizar en más profundidad la aplicación observando el heap manejado para identificar qué objetos consumen la mayor cantidad de memoria. El comando !dumheap –stat nos muestra una estadística de todos los objetos que están en memoria, su cantidad y cuanto ocupan.

De acuerdo al resumen presentado por el comando anterior, se observa claramente un consumo de memoria muy elevado para objetos del tipo array de bytes.

El comando !dumheap también permite listar cada objeto en memoria individualmente. El modificar –type lista los objetos de un determinado tipo.

Utilizaremos este comando para ver que excepciones se encuentran en el vuelco de memoria a la ser tomado.

Encontramos una excepción del tipo OutOfMemoryException, sin embargo debemos ignorar dichas excepciones ya que son creadas por el CLR en caso de ser necesarias. Es lógico pensar que si no hay memoria suficiente no se podrá reservar para crear el objeto OutOfMemoryException, es por este motivo que se crean al iniciar la aplicación).

Si filtramos el Stack para objetos del tipo array de bytes observamos lo siguiente:

La gran mayoría se encuentra residente en el Large Object Heap, y consume 1.1 GB de memoria aprox. en total (hay varios objetos que ocupan 20 MB), esto es un síntoma claro de consumo ineficiente de memoria.

El siguiente paso sería identificar si estos objetos están referenciados por otros.

Para investigar un poco mas esta situación utilizamos el comando de SOS !objsize -v para obtener el tamaño total del grafo de objetos en el stack y de esa manera identificar qué objetos mantienen referencias válidas a segmentos grandes de memoria.

El resultado nos muestra que los objetos CacheItem son los que ocupan mayor tamaño. Vemos que hay objetos CacheItem de 20 Mb y otros de 12 bytes, esto quiere decir que los objetos CacheItem contienen tiene a otros referencia objetos que ocupan distinto tamaño.

Investigamos nuevamente el objeto CacheItem en el heap utilizando ¡dumpheap.

Se listan 85instancias en memoria la mayoría en Gen 2 (debido a quese han mantenido vivos a través de sucesivas recolecciones). Elegimos un objeto cualquiera (en este caso el segundo en la lista) y listamos su información y miembros utilizando el comando !do.

Vemos que el objeto tiene una propiedad de instancia llamada _data:

Utilizando !do sobre la dirección de la variable _data vemos que es de tipo array de bytes, y que ocupa un segmento de 20 MB.

De esta manera concluimos que los objetos CacheItem conservan referencias a objetos array de bytes de tamaño considerable (200 KB y 20 MB). Pero a pesar de que se los objetos CacheItem se destruyen explícitamente en el código de la aplicación nunca son liberados de memoria por el GC debido a hay código en el finalizador del objeto que bloquea el thread de finalización del GC.

Durante el desarrollo de este artículo hemos visto como utilizar contadores de performance, WinDbg y SOS para diagnosticar un problema real de consumo excesivo de memoria producido por un bloqueo en el código de finalización de un objeto. Existen muchas otra situaciones por las que una aplicación .NET puede consumir memoria en forma excesiva y que serian imposibles de cubrir, pero espero que este articulo sirva al lector como punto de partida al proceso de análisis de información de diagnostico post-mortem.