Für Immer: The Return of the WeakReference
¿A que el titulo del post parece de una película de Hollywood? Bueno, pues por ahí van los tiros, y es que recientemente he tenido la oportunidad de tirar bastante de WinDbg para resolver problemas de rendimiento o estabilidad en algunos de nuestros clientes, y uno de estos escenarios ha sido particularmente interesante y lo he vivido casi como un episodio de CSI. ¡Y luego me preguntan por qué me gusta mi trabajo! :)
Si me gustaría dejar claro que este post no forma parte del tutorial de WinDbg que tenía empezado; voy a suponer ciertos conocimientos de la herramienta y de .NET ya que mi objetivo es compartir esta sesión de depuración con vosotros, y no utilizarlo como ejemplo de formación.
Ah... y al más puro estilo de las películas y series americanas, os diré que todos nombres han sido cambiados para preservar la identidad de los implicados. En este caso, si veis nombres de métodos o clases ridículas, simplemente achacadlo a mi falta de imaginación o creatividad.
Al turrón...
El problema
El cliente nos comenta que sus servicios presentan graves problemas de estabilidad, provocando que con cierta frecuencia (últimamente esta frecuencia era diaria) estos servicios dejaran de responder y tuvieran que reciclarse.
Evidentemente, lo que el cliente deseaba en este caso era localizar la raíz del problema y descubrir alguna solución o workaround para mejorar la disponibilidad de sus servicios.
El Análisis
Lo primero que hice fue capturar un volcado de memoria del proceso una vez que éste se encontraba detenido, mediante el script adplus.vbs en modo hang. Una vez con el volcado en mi poder, me senté a analizarlo con calma con el WinDbg.
Lo primero que hice fue examinar el estado de los hilos, y pude comprobar que multitud de ellos estaban detenidos en espera por otros recursos, como reflejaban las cimas de sus pilas con WaitForMultipleObjects y WaitForSingleObject. Me llamo especial atención este calll stack:
26 Id: fec.c20 Suspend: 1 Teb: 000007ff`fff7c000 Unfrozen
Child-SP RetAddr Call Site
00000000`0588fad8 00000000`77d6cffb ntdll!ZwWaitForMultipleObjects+0xa
00000000`0588fae0 00000000`77d6bb01 kernel32!WaitForMultipleObjectsEx+0x1cf
00000000`0588fc00 00000642`7f48455e kernel32!WaitForMultipleObjects+0x11
00000000`0588fc40 00000642`7f5e5fab mscorwks!SVR::WaitForFinalizerEvent+0x7e
00000000`0588fc70 00000642`7f498474 mscorwks
SVR::GCHeap::FinalizerThreadWorker+0x6b
00000000`0588fcb0 00000642`7f5ca069 mscorwks!FusionBind::VerifyBindingStringW+0x78
00000000`0588fd00 00000642`7f47297d mscorwks!EEClass::FindPropertyMethod+0x175
00000000`0588fdd0 00000642`7f45cc3a mscorwks
MDInternalRW::GetMethodSpecProps+0xc9
00000000`0588fe10 00000642`7f5eb824 mscorwks!ManagedThreadBase_NoADTransition+0x42
00000000`0588fe70 00000642`7f4545bc mscorwks!SVR::GCHeap::FinalizerThreadStart+0x74
00000000`0588feb0 00000000`77d6b6da mscorwks!Thread::intermediateThreadProc+0x78
00000000`0588ff80 00000000`00000000 kernel32!BaseThreadStart+0x3a
Se trata de un hilo especial, pues éste hilo se corresponde al finalizador, responsable de finalizar los objetos en las recolecciones de basura. ¿Como sabemos que es el finalizador? Es fácil, por el call stack... ¡métodos como el GCHeap::FinalizerThreadStart nos dan una buena pista! Aún así, si queremos asegurarnos podemos lanzar un !Threads, que en este caso devolvió la siguiente salida:
0:000> !threads
ThreadCount: 24
UnstartedThread: 0
BackgroundThread: 19
PendingThread: 0
DeadThread: 5
Hosted Runtime: yes
PreEmptive
ID OSID ThreadOBJ State GC ... APT Exception
16 1 12b8 00000000001563a0 1808220 Enabled ... MTA (Threadpool Worker)
26 2 c20 0000000000171c10 b220 Enabled ... MTA (Finalizer)
27 3 1244 00000000001799c0 1220 Enabled ... Ukn
28 4 efc 000000000019b010 80a220 Enabled ... MTA (Threadpool Completion Port)
14 7 13e8 000000000659c480 880a220 Enabled ... MTA (Threadpool Completion Port)
30 9 1248 00000000065bd650 200b220 Enabled ... MTA
31 b 7bc 00000000065897d0 200b220 Enabled ... MTA
32 d 9dc 0000000006618760 80a220 Enabled ... MTA (Threadpool Completion Port)
37 e c60 00000000065d83e0 180b220 Enabled ... MTA (Threadpool Worker)
40 11 2b4 00000000066718b0 180b220 Enabled ... MTA (Threadpool Worker)
41 12 162c 00000000065f7990 180b220 Enabled ... MTA (Threadpool Worker)
42 13 149c 00000000067692f0 180b220 Enabled ... MTA (Threadpool Worker)
43 14 1280 0000000009261760 180b220 Enabled ... MTA (Threadpool Worker)
44 15 a84 0000000006686060 180b220 Enabled ... MTA (Threadpool Worker)
45 19 14fc 00000000095e7880 200b220 Enabled ... MTA
46 5 e50 00000000092c2a40 200b220 Enabled ... MTA
47 1a a04 00000000066a4c60 200b220 Enabled ... MTA
48 16 11ec 0000000033046980 880b220 Enabled ... MTA (Threadpool Completion Port)
50 25 d64 000000002f4ca930 180b220 Enabled ... MTA (Threadpool Worker)
XXXX 18 0 000000002cb93a40 8801820 Enabled ... Ukn (Threadpool Completion Port)
XXXX 1d 0 0000000016b345f0 8801820 Enabled ... Ukn (Threadpool Completion Port)
XXXX 1b 0 00000000154fa520 8801820 Enabled ... Ukn (Threadpool Completion Port)
XXXX 20 0 00000001c0750a10 8801820 Enabled ... Ukn (Threadpool Completion Port)
XXXX 1e 0 00000001c0bc0010 8801820 Enabled ... Ukn (Threadpool Completion Port)
Como vemos, la salida nos muestra claramente que el hilo 26 es el finalizador, lo que confirma nuestra sospecha de antes.
Sabiendo que el finalizador está bloqueado no nos es difícil llegar a la conclusión de que la memoria no debe andar muy fina. Para ver su estado general, lanzamos un !dumpheap -stat, que nos devuelve la siguiente información:
0:031> !dumpheap -stat
------------------------------
Heap 0
total 1222297 objects
------------------------------
Heap 1
total 1273253 objects
------------------------------
Heap 2
total 1126040 objects
------------------------------
Heap 3
total 1243940 objects
------------------------------
Heap 4
total 1344846 objects
------------------------------
Heap 5
total 1194789 objects
------------------------------
Heap 6
total 1279943 objects
------------------------------
Heap 7
total 1137244 objects
------------------------------
total 9822352 objects
Statistics:
MT Count TotalSize Class Name
00000642bcf6ddd8 1 24 System.Web.Configuration.FormsProtectionEnum
(..)
000006428044b780 286785 36708480 XX.Contratos.Entidad.Maestros.CompaniaEntidad
0000064280564b40 389036 37347456 XX.Contratos.Entidad.Maestros.TipoBasicoEntidad
0000064278909f18 9736 37949592 System.Int32[]
(..)
000006427890a150 330357 117567984 System.Object[]
0000064280588ec0 235248 120446976 XX.Contratos.Entidad.Proveedores.FacturaProveedorEntidad
000000000015c1a0 368 182038624 Free
00000642788c1ad0 4208597 243318792 System.String
Total 9822352 objects
Fragmented blocks larger than 0.5 MB:
Addr Size Followed by
00000000a6d9fb88 67.6MB 00000000ab140920 System.Collections.ArrayList
00000000c63b7740 66.5MB 00000000ca63b0d0 System.ServiceModel.Activation.HostedHttpContext
He recortado mucho la salida del !dumpheap para que coja correctamente en el blog, y os he marcado los detalles mas relevantes. Por una parte, la gran cantidad de objetos que tenemos en todos los heaps, así como esos dos objetos enormes que tenemos en los Large Object Heaps (LOH). Y por último, y más significativo, es la gran cantidad de memoria que aparece como Free, que se corresponde con memoria que ha sido marcada para limpieza, pero que aun no ha sido recogida por el GC. Generalmente, un alto porcentaje (a partir de un 30%) de memoria Free vs. la memoria total de todos los heaps suele ser indicativo de problemas de fragmentación de memoria, a menudo producida por objetos pinned (objetos estáticos, que van a permanecer siempre en la misma posición en el managed heap).
Vamos a concretar un poco más mirando nuestra cola de finalización, con !FinalizeQueue:
0:031> !FinalizeQueue
SyncBlocks to be cleaned up: 0
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
------------------------------
Heap 0
generation 0 has 6 finalizable objects (000000002ff5c8c8->000000002ff5c8f8)
generation 1 has 15 finalizable objects (000000002ff5c850->000000002ff5c8c8)
generation 2 has 9480 finalizable objects (000000002ff4a010->000000002ff5c850)
Ready for finalization 0 objects (000000002ff5c8f8->000000002ff5c8f8)
------------------------------
Heap 1
generation 0 has 36 finalizable objects (00000000392f56d8->00000000392f57f8)
generation 1 has 13 finalizable objects (00000000392f5670->00000000392f56d8)
generation 2 has 10956 finalizable objects (00000000392e0010->00000000392f5670)
Ready for finalization 0 objects (00000000392f57f8->00000000392f57f8)
------------------------------
Heap 2
generation 0 has 42 finalizable objects (00000001c3cf9ee8->00000001c3cfa038)
generation 1 has 91 finalizable objects (00000001c3cf9c10->00000001c3cf9ee8)
generation 2 has 11334 finalizable objects (00000001c3ce39e0->00000001c3cf9c10)
Ready for finalization 0 objects (00000001c3cfa038->00000001c3cfa038)
------------------------------
Heap 3
generation 0 has 109 finalizable objects (00000001c3d23208->00000001c3d23570)
generation 1 has 15 finalizable objects (00000001c3d23190->00000001c3d23208)
generation 2 has 12986 finalizable objects (00000001c3d09bc0->00000001c3d23190)
Ready for finalization 0 objects (00000001c3d23570->00000001c3d23570)
------------------------------
Heap 4
generation 0 has 8 finalizable objects (00000001c3af48b8->00000001c3af48f8)
generation 1 has 64 finalizable objects (00000001c3af46b8->00000001c3af48b8)
generation 2 has 12035 finalizable objects (00000001c3adcea0->00000001c3af46b8)
Ready for finalization 0 objects (00000001c3af48f8->00000001c3af48f8)
------------------------------
Heap 5
generation 0 has 71 finalizable objects (000000001f6c9070->000000001f6c92a8)
generation 1 has 87 finalizable objects (000000001f6c8db8->000000001f6c9070)
generation 2 has 11207 finalizable objects (000000001f6b2f80->000000001f6c8db8)
Ready for finalization 0 objects (000000001f6c92a8->000000001f6c92a8)
------------------------------
Heap 6
generation 0 has 146 finalizable objects (00000001c3c3a1c0->00000001c3c3a650)
generation 1 has 25 finalizable objects (00000001c3c3a0f8->00000001c3c3a1c0)
generation 2 has 12829 finalizable objects (00000001c3c21010->00000001c3c3a0f8)
Ready for finalization 0 objects (00000001c3c3a650->00000001c3c3a650)
------------------------------
Heap 7
generation 0 has 9 finalizable objects (00000001c3d4bd48->00000001c3d4bd90)
generation 1 has 26 finalizable objects (00000001c3d4bc78->00000001c3d4bd48)
generation 2 has 14299 finalizable objects (00000001c3d2fda0->00000001c3d4bc78)
Ready for finalization 0 objects (00000001c3d4bd90->00000001c3d4bd90)
Statistics:
MT Count TotalSize Class Name
00000642bcf589f8 1 24 System.Web.Configuration.ImpersonateTokenRef
0000064278963e28 1 24 System.Threading.OverlappedDataCache
00000642bcf4d948 1 32 System.Web.PerfInstanceDataHandle
00000642b78f1b28 1 32 Bid+AutoInit
00000642789b0608 1 32 System.Security.Cryptography.SafeHashHandle
00000642788cd1b8 1 32 Microsoft.Win32.SafeHandles.SafeFileMappingHandle
00000642788cd110 1 32 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle
0000064274f044d8 1 32 System.Net.SafeLocalFree
0000064274ee4c20 1 32 Microsoft.Win32.SafeHandles.SafeFileMapViewHandle
0000064274ee4ad0 1 32 Microsoft.Win32.SafeHandles.SafeFileMappingHandle
0000064274ee0598 1 32 Microsoft.Win32.SafeHandles.SafeProcessHandle
0000064278964118 1 40 System.Threading.RegisteredWaitHandleSafe
0000064278963da8 1 40 System.Threading.OverlappedDataCacheLine
0000064274ed8928 1 48 Microsoft.CSharp.CSharpCodeProvider
00000642bcf56b88 1 56 System.Web.Compilation.CompilationMutex
00000642802cd880 1 56 Microsoft.Practices.EnterpriseLibrary.Caching.Cache
00000642788ffea8 2 64 Microsoft.Win32.SafeHandles.SafePEFileHandle
00000642788e3160 2 64 System.Security.Cryptography.SafeProvHandle
0000064274ef89b0 2 64 System.Net.SafeCloseSocket+InnerSafeCloseSocket
0000064274f05b90 2 80 System.Net.SafeRegistryHandle
00000642788f9c68 3 96 Microsoft.Win32.SafeHandles.SafeTokenHandle
0000064274f05798 2 96 System.Net.SafeCloseSocketAndEvent
00000642bc59aea0 4 128 System.Transactions.SafeIUnknown
00000642802b2380 2 176 Oracle.DataAccess.Client.ConnectionPool
00000642788e1428 2 208 System.Runtime.Remoting.Contexts.Context
00000642802b9b00 8 256 Oracle.DataAccess.Types.OpoDecCtx
00000642802374c0 4 320 Microsoft.Practices.EnterpriseLibrary.Common.Configuration.Storage.ConfigurationChangeFileWatcher
00000642bcf4f7a0 7 392 System.Web.DirMonCompletion
00000642bc593f80 11 440 System.Transactions.FinalizedObject
00000642788d2110 14 448 Microsoft.Win32.SafeHandles.SafeRegistryHandle
0000064274eda4c0 10 480 System.CodeDom.Compiler.TempFileCollection
00000642bcf53138 14 560 System.Web.ProcessImpersonationContext
00000642788d5b40 10 640 System.Threading.ReaderWriterLock
00000642bcf4eb78 20 800 System.Web.ApplicationImpersonationContext
00000642788ec748 28 896 Microsoft.Win32.SafeHandles.SafeWaitHandle
00000642788c9250 28 896 Microsoft.Win32.SafeHandles.SafeFileHandle
00000642788ec928 28 1120 System.Threading.TimerBase
00000642bcf6f9f0 32 1280 System.Web.ClientImpersonationContext
0000064274ee3290 10 1680 System.Diagnostics.PerformanceCounter
00000642bc59af50 60 1920 System.Transactions.Oletx.CoTaskMemHandle
0000064278963bb8 16 1920 System.Threading.OverlappedData
00000642788c2360 21 2184 System.Threading.Thread
00000642802b6180 12 2496 Oracle.DataAccess.Client.OracleDataReader
00000642788df980 27 3240 System.IO.FileStream
00000642800c9200 190 6080 Oracle.DataAccess.Client.UTF8CommandText
00000642800c8a40 46 9936 Oracle.DataAccess.Client.OracleConnection
00000642800c6f00 55 14960 Oracle.DataAccess.Client.OracleCommand
00000642789a9290 1062 76464 System.Reflection.Emit.DynamicResolver
00000642bcf89bd0 7542 301680 System.Web.HttpResponseUnmanagedBufferElement
00000642800c90c0 8992 503552 Oracle.DataAccess.Client.MetaData
00000642788cf7d0 77605 2483360 System.WeakReference
Total 95889 objects
Wow!! A parte de la enorme cantidad de objetos en Generación 2 en todos los heaps, algo bastante alarmante de por si... ¡fijaros en esas 77605 instancias de System.WeakReferences pendientes de finalización!
Er... WeakReferences... mm... ¿de que no suenan? Bueno, a los geekeros de pro, seguro que nos trae a la mente estos dos geniales posts: Fugando Memoria con .NET y Un poco de WinDbg aplicado, de los grandes Rodrigo Corral y David Salgado :)
Mi primera pregunta fue ¿de dónde demonios salen todas esas WeakReferences? Tras tirar un poco del hilo con !GCRoot no encontré claramente su origen, por lo que saque la artillería pesada: La funcionalidad de 'buscar en toda la solución' de Visual Studio :D Pues bien... ninguna coincidencia con WeakReference. Fue entonces cuando se me encendió la bombillita y recordé que nuestro cliente empleaba Enterprise Library 3.0, así que fui raudo y veloz como una exhalación a buscar mi WeakReference perdida en la EntLib... y nada :(
Finalmente decidí dejarme de artillería pesada, y hacer las cosas bien nuevamente :_) Así que recurrí al comando !TraverseHeap, con el cual genere un fichero de salida con el cual alimenté al CLR Profiler. Gracias a esta jugada pude ver que las WeakReferences estaban siendo creadas en un módulo antiguo del cliente, reutilizado de una versión anterior de su producto. ¡Genial! Busco en el código de esa versión y... ¡ni rastro de la WeakReference!
Llegados a este punto la sesión de depuración ya se había convertido en algo personal; ahi estaba el volcado. Yo, cerca de él. Y entre nosotros dos, un viejo camino polvoriento, y una planta rodadora solitaria... (¡Hey... ya os dije que esto era una pelicula de Hollywood!). Decidí volver al dump y volcarme la .dll del cliente que contenía las WeakReferences a disco, gracias al comando .writemem, para así poder estudiarla con Reflector.
Una vez abierto el código con Reflector, pude comprobar como el constructor del objeto en cuestión contenía este código:
public Presupuesto(int CodigoCompañia)
{
ArrayList list = __ENCList;
lock (list)
{
__ENCList.Add(new WeakReference(this));
}
this.mCodigoPais = Program.PaisActual;
this.mCodigoCompañia = CodigoCompañia;
}
Er... ¿WTF? XD ¿Qué demonios es esa colección llamanda __ENCList y que está haciendo en nuestro modulo? ¡¡Pero si esa colección no esta en el código fuente del cliente!!
[Saco mi guía del autoestopista galáctico, leo el 'Don't Panic' e inmediatamente me siento reconfortado... procedamos...]
Una búsqueda por internet me hizo descubrir que esa colección __ENCList la crea automágicamente Visual Studio para Vb.NET en modo DEBUG, y en C# activando una opción llamada Edit And Continue. Si, señores y señoras, al parecer el Edit And Continue instrumenta el código. ¡En nuestro caso esta instrumentación acabó en producción ya que se desplegó la .DLL en modo DEBUG!
Conclusiones
La primera conclusión es clara y concisa... ¡repetid conmigo!
"No voy a poner en producción código compilado en modo DEBUG."
Bien, después de interiorizar esta frase y adquirir el firme propósito de repetirla 5 veces cada mañana al despertarnos durante un mes, podemos extraer otras conclusiones:
Si no fuera gracias a la captura del volcado de memoria, hubiera sido muy, pero que muy difícil dar con este problema. ¡Recordad que el código 'ofensor' no se encontraba ni siquiera en los fuentes del cliente! Solo pudimos 'cazarlo' porque recurrimos a la imagen en memoria del módulo, que no se correspondía con el código fuente.
- Invertir un tiempo en formar a nuestros desarrolladores en herramientas de depuración siempre compensa:
Si vais a acudir al Tech-Ed de Barcelona, me gustaría recordaros que Tess Ferrandez va a andar por ahí y va a dar un par de sesiones; podría ser un buen punto de partida para este tipo de formación en depuración avanzada. No hace falta que os la presente, a estas alturas todo el mundo conoce ya a la diosa del WinDbg!
Si no podéis acudir al Tech-Ed, no os preocupéis... siempre os quedará el DOT ;)
- No poner en producción código compilado en modo DEBUG.
¿Que la he dicho ya? Nunca está de más repetirlo.
Rock Tip:
En alemán Für Immer significa para siempre. Für Immer estaría nuestro finalizador esperando, bloqueado, y haciendo que la memoria reservada por nuestra aplicación creciera y creciera, Für Immer estaría nuestro cliente experimentando las continuas caídas del servicio, y 'Für Immer'... es también uno de los temas más conocidos de la magnísima señora Doro Pesch.
Nuestra amiga Dorotea es una de las más grandes féminas que pululan por el panorama del hard rock y heavy internacional. Su estilo es inconfundible; si bien hace poco os hablaba de Sandi Saraya y de su dulce voz, con Doro nos encontramos con un enfoque totalmente diferente, caracterizado por autentica actitud heavy y una voz con más fuerza y garra que muchisimos vocalistas masculinos. Desde sus tiempos en Warlock hasta sus últimos trabajos en solitario, nunca ha perdido un ápice de su estilo.. nunca se ha vendido. ¡Tan solo eso me hace quitarme mi sombrero de cowboy ante esta señora!
En serio, si os va el heavy o el hard rock y nunca habéis escuchado nada de Doro, Tio Doval os recomienda muy encarecidamente que no os perdáis su discografía. Os sugiero empezar con esto: 'All we Are'.
Keep Rockin'!