Traza de asp.net y el consumo de memoria

El siguiente caso a presentar está relacionado con el alto consumo de memoria de una aplicación. Como el título lo dice, está relacionado con el uso de la traza de asp.net (trace en web.config.)


El escenario era similar a lo descrito ahora. La aplicación analizada empezaba a consumir memoria y aunque tenía momentos donde la liberaba, la impresión general era que en el largo plazo, siempre subía. Este es un típico comportamiento de un memory leak o pérdida de memoria; la tendencia al alza, aunque con momentos donde baja un poco.


Como ya es tradición, un dump del proceso y mi amigo [windbg] nos darían las pistas necesarias. También nos apoyamos en performance monitor, pero hay veces que ya sabes que es una pérdida de memoria y éste no te dirá mucho más de lo que ya sabes.


Con el dump en mis manos, hacemos una revisión del proceso afectado y el estado de la memoria virtual del éste.


Recolección de información general


Tamaño del dump: ~300 MB. No es muy grande, pero tampoco es descartable. Tradicionalmente se espera a que la memoria privada del proceso llegue al menos hasta 500 MB para declararlo como sospechoso.


Información del proceso:





System Uptime: 180 days 15:52:41.140
Process Uptime: 0 days 2:08:23.000
Kernel time: 0 days 0:00:13.000
User time: 0 days 0:08:48.000

El sistema operativo lleva corriendo 180 días sin reiniciarse. El proceso en cuestión lleva del orden de 2 horas y 8 minutos corriendo y que ha consumido 13 segundos en modo privilegiado (kernel) y 8 minutos y 48 segundos en modo usuario.

Con 8 minutos de procesamiento ya llegó a 300 MB. Interesante.







El estado de la memoria virtual concuerda con el tamaño del dump, reflejado gráficamente en la imagen de la derecha, la cual pueden pinchar para agrandar.

Efectivamente hay aproximadamente 300 MB de memoria virtual, de los cuales casi 190 son de memoria manejada.


Memoria manejada


Haciendo una revisión de los heaps del GC, obtenemos la información de la siguiente lista. El servidor tiene 4 procesadores por lo que se crean cuatro heaps del GC, cada uno con sus propias generaciones, heaps efímeros y heaps de objetos grandes.





Number of GC Heaps: 4
——————————
Heap 0 (0x000d01c8)
generation 0 starts at 0x121135c8
generation 1 starts at 0x12109a44
generation 2 starts at 0x102d0030
ephemeral segment allocation context: none
segment begin allocated size reserved
0x102d0000 0x102d0030 0x121135d4 0x01e435a4(31,733,156) 0x00d79000
Large object heap starts at 0x202d0030
segment begin allocated size reserved
0x202d0000 0x202d0030 0x205d2168 0x00302138(3,154,232) 0x00cdd000
Heap Size 0x2245770(35,936,112)
——————————
Heap 1 (0x000d08d8)
generation 0 starts at 0x16009a28
generation 1 starts at 0x15eaacac
generation 2 starts at 0x142d0030
ephemeral segment allocation context: none
segment begin allocated size reserved
0x142d0000 0x142d0030 0x16009a34 0x01d39a04(30,644,740) 0x014c7000
Large object heap starts at 0x212d0030
segment begin allocated size reserved
0x212d0000 0x212d0030 0x21449a38 0x00179a08(1,546,760) 0x00e66000
Heap Size 0x1f2b4a0(32,683,168)
——————————
Heap 2 (0x000d13d8)
generation 0 starts at 0x24461404
generation 1 starts at 0x243e6e2c
generation 2 starts at 0x182d0030
ephemeral segment allocation context: none
segment begin allocated size reserved
0x182d0000 0x182d0030 0x1998c7dc 0x016bc7ac(23,840,684) 0x028ef000
0x242d0000 0x242d0030 0x24461410 0x001913e0(1,643,488) 0x033c4000
Large object heap starts at 0x2a2d0030
segment begin allocated size reserved
0x2a2d0000 0x2a2d0030 0x2a2d0030 0x00000000(0) 0x047df000
Heap Size 0x198fb8c(26,803,084)
——————————

Heap 3 (0x000d1ca0)
generation 0 starts at 0x087954cc
generation 1 starts at 0x083dd820
generation 2 starts at 0x1c2d0030
ephemeral segment allocation context: none
segment begin allocated size reserved
0x1c2d0000 0x1c2d0030 0x1df48b8c 0x01c78b5c(29,854,556) 0x02310000
0x08330000 0x08330030 0x087954d8 0x004654a8(4,609,192) 0x01fff000
Large object heap starts at 0x232d0030
segment begin allocated size reserved
0x232d0000 0x232d0030 0x2344ed50 0x0017ed20(1,568,032) 0x00e61000
0x0edc0000 0x0edc0030 0x0f195f40 0x003d5f10(4,022,032) 0x00c2a000
Heap Size 0x277ac50(41,397,328)
——————————
Reserved segments:
——————————
GC Heap Size 0x827b3ec(136,819,692)

De esta información se puede ver que hay muchos objetos en generación 2, lo que significa que hay objetos que no se han liberado y han ido envejeciendo más de lo necesario.


¿Qué hay en la memoria?


Haciendo un vaciado estadístico de los objetos, utilizando [windbg] y sos, obtenemos un listado como el de a continuación, donde se ha eliminado parte del comienzo y sólo se ha dejado el final, que contiene la información relevante para el caso.





MT        Count TotalSize Class Name
…..<recortado por el bien de esta página>…
0x028665f0 22,807 273,684 System.Xml.Xsl.EndEvent
0x02784adc 14,800 296,000 System.Data.DataRowCollection
0x027844dc 14,800 296,000 System.Data.DataRowBuilder
0x027862d4 14,911 298,220 System.Data.ColumnQueue
0x02782a74 11,824 331,072 System.ComponentModel.CollectionChangeEventHandler
0x0230159c 14,866 356,784 System.Xml.NameTable/Entry
0x02925aec 7,847 408,044 System.Xml.Xsl.XsltCompileContext
0x02926bfc 11,589 417,204 System.Xml.XPath.XPathChildIterator
0x02863d04 8,692 417,216 System.Xml.XPath.ChildrenQuery
0x027846d4 14,800 473,600 System.Data.RecordManager
0x0278001c 14,800 473,600 System.Data.ConstraintCollection
0x027842e4 14,913 477,216 System.ComponentModel.PropertyDescriptorCollection
0x0280cddc 16,754 670,160 System.Xml.XPath.XPathWhitespace
0x0280c924 10,044 682,992 System.Xml.XPath.XPathElement
0x02866564 22,807 729,824 System.Xml.Xsl.BeginEvent
0x0252ebe4 14,800 769,600 System.Data.DataColumnCollection
0x79bda488 14,813 888,780 System.Threading.ReaderWriterLock
0x79bab93c 17,498 909,896 System.Collections.Hashtable
0x02923770 28,877 924,064 System.Xml.DocumentXPathNavigator
0x027882e4 40,203 964,872 System.Data.Common.StringStorage
0x0280cba4 21,157 1,015,536 System.Xml.XPath.XPathAttribute
0x0278489c 29,600 1,184,000 System.Data.DataRelationCollection/DataTableRelationCollection
0x01ba2c28 17,561 2,839,896 System.Collections.Hashtable/bucket[]
0x0252e4b0 14,800 3,433,600 System.Data.DataTable
0x79ba2ee4 145,618 3,494,832 System.Collections.ArrayList
0x0278670c 54,976 3,518,464 System.Data.DataColumnPropertyDescriptor
0x01ba2964 24,879 5,024,760 System.Int32[]
0x0278513c 136,364 5,454,560 System.Data.DataRow
0x0252f5d0 54,760 7,009,280 System.Data.DataColumn
0x01ba26b0 1,262 8,513,840 System.Byte[]
0x000cff48 2,829 14,897,824 Free
0x79b94638 238,884 23,296,388 System.String
0x01ba209c 235,235 40,966,392 System.Object[]
Total 1,509,853 objects, Total size: 136,798,976

Existe un poco más de 1,5 millones de objetos en memoria, que consumen cerca de 136 MB, similar al resultado entregado en la lista anterior.


De esos 1,5 millones de objetos, existe una gran cantidad de strings y arreglos de objeto, como también de filas de datos y columnas de datos. Este comportamiento se presenta cuando se han creado Datasets y no se han liberado.


Un DataSet contiene filas y columnas, y en cada celda encontramos objetos de los tipos básicos como strings, enteros, decimales, objetos, etc. Por lo tanto, estos objetos que se ven al final no viven solos sino que están referenciados desde otro objeto, como podría ser un dataset. No significa que todos estén referenciados, pero con 136 mil filas (DataRow) y 54 mil columnas (DataColumn), varios de esos miles de objetos si lo están.


¿Cuantos DataSets hay?





MT         Count TotalSize Class Name
0x0252ce84 1,597 127,760 System.Data.DataSet
Total 1,597 objects, Total size: 127,760

Bueno, tomemos uno al azar y veamos donde nos lleva. Elegimos el objeto en la posición de memoria 0x0834d148.





Name: System.Data.DataSet
MethodTable 0x0252ce84
EEClass 0x0275b43c
Size 80(0x50) bytes
GC Generation: 2
mdToken: 0x0200003b (c:\windows\assembly\gac\system.data\1.0.5000.0__b77a5c561934e089\system.data.dll)
FieldDesc*: 0x0252c4b4
MT Field Offset Type Attr Value Name
0x0252c23c 0x4000583 0x4 CLASS instance 0x00000000 site
0x0252c23c 0x4000584 0x8 CLASS instance 0x00000000 events
0x0252c23c 0x4000582 0 CLASS shared static EventDisposed
>> Domain:Value 0x000c4ac8:NotInit 0x00138380:0x1c331c58 <<
0x0252ce84 0x40003d3 0xc CLASS instance 0x15cee704 defaultViewManager
0x0252ce84 0x40003d4 0x10 CLASS instance 0x0834d198 tableCollection
0x0252ce84 0x40003d5 0x14 CLASS instance 0x0834d220 relationCollection
0x0252ce84 0x40003d6 0x18 CLASS instance 0x00000000 extendedProperties
0x0252ce84 0x40003d7 0x1c CLASS instance 0x1c331c30 dataSetName
0x0252ce84 0x40003d8 0x20 CLASS instance 0x102d0224 _datasetPrefix
0x0252ce84 0x40003d9 0x24 CLASS instance 0x102d0224 namespaceURI
0x0252ce84 0x40003da 0x40 System.Boolean instance 0 caseSensitive
0x0252ce84 0x40003db 0x28 CLASS instance 0x1c2e69c8 culture
0x0252ce84 0x40003dc 0x41 System.Boolean instance 1 enforceConstraints
0x0252ce84 0x40003dd 0x42 System.Boolean instance 0 fInReadXml
0x0252ce84 0x40003de 0x43 System.Boolean instance 0 fInLoadDiffgram
0x0252ce84 0x40003df 0x44 System.Boolean instance 0 fTopLevelTable
0x0252ce84 0x40003e0 0x45 System.Boolean instance 0 fInitInProgress
0x0252ce84 0x40003e1 0x46 System.Boolean instance 1 fEnableCascading
0x0252ce84 0x40003e2 0x47 System.Boolean instance 0 fIsSchemaLoading
0x0252ce84 0x40003e3 0x2c CLASS instance 0x00000000 rowDiffId
0x0252ce84 0x40003e4 0x48 System.Boolean instance 0 fBoundToDocument
0x0252ce84 0x40003e5 0x30 CLASS instance 0x00000000 onPropertyChangingDelegate
0x0252ce84 0x40003e6 0x34 CLASS instance 0x00000000 onMergeFailed
0x0252ce84 0x40003e7 0x38 CLASS instance 0x00000000 onDataRowCreated
0x0252ce84 0x40003e8 0x3c CLASS instance 0x00000000 onClearFunctionCalled
0x0252ce84 0x40003e9 0 CLASS shared static zeroTables
>> Domain:Value 0x000c4ac8:NotInit 0x00138380:0x1c331c20 <<

Mmm, nada más que un dataset. No se si podría haber encontrado otra cosa [:)]. Veamos el nombre de éste, en la posición 0x1c331c30 (línea blanca arriba).





String: NewDataSet

[:s]. El nombre genérico no da pistas para encontrar alguna parte del código que lo esté creando. Vemos entonces quién lo está apuntando.





Scan Thread 10 (0x1cac)
Scan Thread 16 (0xa00)
Scan Thread 17 (0x1908)
Scan Thread 5 (0xa0c)
Scan Thread 4 (0x1dcc)
Scan Thread 19 (0x1a6c)
Scan Thread 3 (0x1584)
Scan Thread 2 (0x444)
Scan Thread 20 (0x15f4)
ESP:36ff548:Root:0x1c6b59a8(System.Threading.Thread)->0x15cecad4(System.Runtime.Remoting.Messaging.IllogicalCallContext)->0x15cecae0(System.Collections.Hashtable)->0x15cecb14(System.Collections.Hashtable/bucket[])->0x15cec81c(System.Web.HttpContext)->0x15cec608(System.Web.Hosting.ISAPIWorkerRequestInProcForIIS6)->0x182d81c4(System.Web.HttpWorkerRequest/EndOfSendNotification)->0x14339e70(System.Web.HttpRuntime)->0x182d7fac(System.Web.Util.Profiler)->0x14358454(System.Collections.ArrayList)->0x1d89d7b0(System.Object[])->0x834d148(System.Data.DataSet)
Scan Thread 22 (0x1098)
Scan Thread 24 (0xcd8)
…..<recortado por el bien de esta página>…
Scan Thread 67 (0x1938)
Scan Thread 54 (0x618)
Scan HandleTable 0xc9ec0
Scan HandleTable 0xcd008
Scan HandleTable 0x147008

El thread 20, que está procesando un requerimiento en la extensión ISAPI de asp.net en IIS6 (System.Web.Hosting.ISAPIWorkerRequestInProcForIIS6) tiene una referencia fuerte al objeto. Vemos también un HashTable, el Contexto y Runtime de http, los cuales se pueden considerar normales en el ciclo de vida de un requerimiento web.


Sin embargo, hay un invitado especial en esta lista de referencias. Éste es System.Web.Util.Profiler, del cual no hay mucha información disponible, pero después de examinarlo, ya podemos inferir de quién se trata. Veamos su contenido.





Name: System.Web.Util.Profiler
MethodTable 0x021c49d0
EEClass 0x0215912c
Size 28(0x1c) bytes
GC Generation: 2
mdToken: 0x0200029d (c:\windows\assembly\gac\system.web\1.0.5000.0__b03f5f7f11d50a3a\system.web.dll)
FieldDesc*: 0x021c4704
MT Field Offset Type Attr Value Name
0x021c49d0 0x4001076 0x8 System.Int32 instance 1478 _requestNum
0x021c49d0 0x4001077 0xc System.Int32 instance 7500 _requestsToProfile
0x021c49d0 0x4001078 0x4 CLASS instance 0x14358454 _requests
0x021c49d0 0x4001079 0x14 System.Boolean instance 0 _pageOutput
0x021c49d0 0x400107a 0x15 System.Boolean instance 1 _isEnabled
0x021c49d0 0x400107b 0x16 System.Boolean instance 1 _oldEnabled
0x021c49d0 0x400107c 0x17 System.Boolean instance 0 _localOnly
0x021c49d0 0x400107d 0x10 System.Int32 instance 0 _outputMode

Recordando las propiedades de la traza de asp.net, podemos ver asombrosas similitudes con las propiedades. Veamos la definición de la traza en el archivo web.config. La información oficial dice:





<trace
enabled=”true|false”
localOnly=”true|false”
pageOutput=”true|false”
requestLimit=”integer”
mostRecent=”true|false”
writeToDiagnosticsTrace=”true|false”
traceMode=”SortByTime|SortByCategory”
/>

El dump dice que la traza estaba habilitada (_isEnabled), no estaba local (_localOnly), que tenía marcado para almacenar hasta 7.500 requerimientos (segunda línea blanca) y que habían 1478 almacenados (primera línea blanca). El resto de las propiedades las pueden chequear ustedes. Recordemos que habían 1597 DataSets en memoria.


El objeto _requests es un System.Collections.ArrayList y los 1478 objetos dentro suman casi la totalidad de memoria manejada, que si bien recordarán, sumaba cerca de 136 MB.





sizeof(0x14358454) = 91,258,512 (0x5707e90) bytes (System.Collections.ArrayList)

Entonces, la condición de memoria elevada, se da en parte porque hay ~90 MB de objetos referenciados por la traza de asp.net. También hay una cantidad de importante de memoria (~70 MB) consumida por dlls y ensamblados (ver la primera imagen.)


Conclusiones


Las conclusiones que se pueden obtener en este caso son:




  1. No todos las pérdidas de memoria son producto de errores en la codificación.



  2. Si vas a habilitar la traza en producción, recuerda deshabilitarla una vez que termines.



  3. También, si no vas a poder leer la información de 7500 trazas, configúralo para que almacene menos.


Saludos,
Patrick

9 Replies to “Traza de asp.net y el consumo de memoria”

  1. Excelete post y mejor analisis.

    Una de las cosas que me sorprende, es la habilidad de esta herramienta que usas, Debugging Tool For Windows, al parecer tiene mucho que decir de nuestras aplicaciones, voy a tratar de ver como lograstes que te entregase toda esa informacion..

    Otra cosa, me extraño que no incluyeses una cuarta conclusion respecto de no utilizar DataSet (jeje)

    Saludos,
    Rodrigo

  2. jajaja…así es…. primero, muchas gracias por las felicitaciones.

    debugging tools + sos es impresionante. No necesitas nada más para saber la verdad de las cosas..

    y sí, podría haber colocado un par más, pero cuando haces análisis te debes guíar por la información objetiva.

    El que yo deteste los datasets por los motivos que tu sabes, no hará que la aplicación tenga estos problemas 🙂

    Saludos y siempre un gusto tenerlo por aquí. ¿cuándo lo veremos escribiendo?

    Patrick.

  3. Primero que nada, felicitaciones por tan excelente post.

    Ahora, te comento: soy algo nuevo en esto de tracear info de procesos, obtener dumps, analizarlos y demás y tengo la imperiosa necesidad de llevar a cabo estas acciones en una aplicación web de la cual participo del desarrollo.

    Me bajé e instalé el Debugging Tools for Windows, pero no logro llegar al nivel de detalle que vos mostras acá.

    Solo me attacheo al WP de ASPNET y me tira una chorrera de información que en realidad mucho no me dice (o no se interpretarlo correctamente, lo cual tambien es muy probable =P).

    De verdad me seria muy útil lograr “ver” de alguna forma si me están quedando colgados en algún lado objetos de algún tipo, ya que, si bien los WP no están ni a la mitad de los 500Mb que mencionas para considerarlos “sospechosos”… la gente de tecnología del cliente nos reclama el alto consumo de memoria de estos.

    Sin más, te saludo muy atentamente.

    Diego Cañizares, BSAS, Argentina

  4. Buenas, muy buen trabajo debugando el proceso!
    Una cosa que puede que te dé alguna pista más. El error de SWorkingProccess normalmente está asociado a cuando un usuario cierra el navegador cuando todavía no ha acabado de generarse la página y está renderizando con el buffer activado. Es imposible evitarlo, pero se puede llegar a liberar la memoria si cazas la excepción dentro del global.asax.
    No sé si te habré ayudado o confundido! Un saludo

  5. Hola.
    Sigo tu blog interesantisimo!! La realidad es que por mi trabajo , y por mi gran interes por este tema de analizar los dump de los procesos , tengo suma necesidad de saber como analizarlos.
    Hoy por hoy en mi trabajo ( administrador del IIS )tengo problemas con una aplicacion que se cuelga y llegue al punto de tener que analizar si o si , ya que si no los programadores y yo , no tenemos mas que tocar.
    Estoy usando el debugdiag 1.1 , me tira un analisis que no tengo manera de justificarlo ya que no entiendo bien el porque de ese analisis.
    No encuentro informacion que me ayude a como empezar de cero a comprenderlos y analizarlos.
    Si podes brindarme informacion como lograrlo realmente te lo agradeceria.
    Desde ya muchas gracias.

  6. Sergio,

    Lamentablemente la pregunta que me haces no es fácil de responder. Si tu estas en cero, es bastante el camino que tienes que recorrer. Para nada imposible, pero si es extenso.

    Hay tipos de problemas que requieren saber más y otros menos. Por ejemplo, aplicaciones con 100% de uso de CPU son las más simples de resolver. Un par de dumps, debugdiag o windbg y listo.

    Aplicaciones con consumo de memoria elevado, si es código manejado, no debiera ser difícil, pero para código no manejado, es considerablemente más difícil, y requiere seguir una serie de pasos para poder hacer troubleshooting. Debugdiag puede ser tan útil como inútil en este caso.

    Finalmente, crash o hangs, ufff, es todo un mundo. Si tienes el reporte de debug diag, mándamelo para verlo y avanzamos.

    Si realmente quieres aprender de esto y estás dispuesto a invertir una cantidad interesante de tiempo (un par de años en mi caso), te recomiendo comenzar con el libro Windows Internals de Rusinovich y Solomon. Una vez que se tiene la base de cómo funciona Windows, el análisis de dumps se simplifica bastante porque aprendes a interpretar muchas cosas y descartar otras que sabes que son “normales”.

    Sin querer desanimarte, si tus expectativas son aprender a hacer esto en 1 mes, es una ambición utópica.

    Saludos,

    Patrick

Leave a Reply

Your email address will not be published. Required fields are marked *