Sempre chiamare il metodo Dispose!
Un caso che ho gestito recentemente mi dà lo spunto per trattare questo argomento che di certo può interessare molti.
Tante volte per pigrizia o fretta si cerca di abbreviare la stesura del codice tralasciando alcuni aspetti che si reputano di importanza secondaria. Spesso una delle prime cose che si tende a dimenticare o tralasciare è chiamare il metodo .Dispose sugli oggetti che accedono a risorse unmanaged (“tanto poi ci pensa il Garbage Collector”).
Vediamo ora cosa è successo in questo caso.
Premessa: userò il debugger WinDbg ed alcuni comandi di debugging elementari, ma non partirò qui dalle basi. Per chi volesse partire dalle basi suggerisco di seguire una serie ti post che Carlo sta pubblicando, il primo lo trovate qui.
NOTA: le informazioni ottenute dal dump sotto mostrate sono state ottenute con un repro minimale e non con la reale applicazione del cliente.
L’applicazione in questione andava in crash diverse volte al giorno e nell’EventLog comparivano i seguenti eventi:
Event Type: Error
Event Source: Application Error
Event Category: (100)
Event ID: 1000
Date: 15/07/2009
Time: 23:16:55
User: N/A
Computer: XXXX
Description:
Faulting application w3wp.exe, version 6.0.3790.3959, faulting module kernel32.dll, version 5.2.3790.4480, fault address 0x0000bef7.
Ovviamente, quando questo succede, il workerprocess w3wp.exe che serve l’applicazione muore e tutte le sessioni degli utenti loggati vengono perse.
Il modo migliore per approcciarsi a questo tipo di problemi è prendere un crash dump: il debugger si attacca al processo e si mette in ascolto per dumpare la memoria al momento del crash.
I debugger che usiamo solitamente sono i Microsoft Debuggers Tools o DebugDiag.
Nel primo caso si può attaccare il debugger in crash mode al processo usando il seguente comando:
adplus -crash -pn w3wp.exe
Nel secondo caso invece, avendo DebugDiag una interfaccia visuale, si può seguire un Wizard per creare una ‘Crash Rule’
Aprendo il dump con WinDbg si vede subito che l’eccezione che ha generato il crash è una ‘managed exception’ ossia una eccezione .NET e non nativa
...................................................................................................................................
Loading unloaded module list
....
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(af8.16c0): CLR exception - code e0434f4d (first/second chance not available)
eax=013ff6ec ebx=e0434f4d ecx=00000001 edx=00000000 esi=013ff774 edi=01193920
eip=75429617 esp=013ff6ec ebp=013ff73c iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000202
La cosa è insolita. Infatti normalmente le eccezioni managed all’interno di una Web Application, anche se non vengono gestite dal codice dell’applicazione con Try/Cach block, non mandano in crash l’intero processo perché vengono gestite dal runtime.
A partire dal .NET Framework 2.0 però, nel caso una eccezione non gestita venga generata al di fuori dal contesto di processing di una pagina aspx, il runtime per scelta manda in crash l’intero processo.
Il seguente articolo spiega la cosa in dettaglio:
Unhandled exceptions cause ASP.NET-based applications to unexpectedly quit in the .NET Framework 2.0
Premesso che la cosa migliore è sempre individuare le cause dell’eccezione ed evitare che si verifichi, l’articolo suggerisce anche un paio di metodi alternativi per evitare il crash (tra cui tornare al comportamento precedente al framework 2.0).
Vediamo dunque se, come ci aspettiamo, questa eccezione è stata generata in un thread che non sta processando una pagina aspx.
Un thread che sta processando una pagina aspx si presenta simile al seguente esempio:
28 Id: af8.880 Suspend: 1 Teb: 7ff3f000 Unfrozen
ildEBP RetAddr Args to Child
9decd8 770c5e4c 75426872 00000001 0e9ded2c ntdll!KiFastSystemCallRet
9decdc 75426872 00000001 0e9ded2c 00000001 ntdll!NtWaitForMultipleObjects+0xc
9ded78 76cdf12a 0e9ded2c 0e9deda0 00000000 KERNELBASE!WaitForMultipleObjectsEx+0x100
9dedc0 505ffeaa 00000001 7ffdf000 00000000 kernel32!WaitForMultipleObjectsExImplementation+0xe0
9dee28 505ffadb 00000001 01158430 00000000 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0x6f
9dee48 505ffbe4 00000001 01158430 00000000 mscorwks!Thread::DoAppropriateAptStateWait+0x3c
9deecc 505ffc79 00000001 01158430 00000000 mscorwks!Thread::DoAppropriateWaitWorker+0x13c
9def1c 505ffdf9 00000001 01158430 00000000 mscorwks!Thread::DoAppropriateWait+0x40
9def78 504bc5b6 ffffffff 00000001 00000000 mscorwks!CLREvent::WaitEx+0xf7
9def8c 505bac6b ffffffff 00000001 00000000
mscorwks!CLREvent::Wait+0x17
9defdc 505bab2a ffffffff c45c4e6f 0597f934 mscorwks!SVR::GCHeap::FinalizerThreadWait+0xfb
9df078 01800c06 058c89e4 058c7828 0e9df0a4 mscorwks!GCInterface::RunFinalizers+0x99
9df088 65a0cf98 00000000 00000000 00000000 App_Web_sbh00zjd!_Default.Button2_Click(System.Object, System.EventArgs)+0x26 [C:\inetpub\wwwroot\Default.aspx.vb @ 16]
9df0a4 65a0cdff 00000000 00000000 00000000 System_Web_ni!System.Web.UI.WebControls.Button.OnClick(System.EventArgs)+0x70
9df0bc 65a0d03b 00000000 00000000 00000000 System_Web_ni!System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String)+0x6f
9df0c4 6530798e 00000000 00000000 00000000 System_Web_ni!System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String)+0xb
9df0cc 653078e5 00000000 00000000 00000000 System_Web_ni!System.Web.UI.Page.RaisePostBackEvent(System.Web.UI.IPostBackEventHandler, System.String)+0xe
9df0e4 65319dfe 00000000 00000000 00000000 System_Web_ni!System.Web.UI.Page.RaisePostBackEvent(System.Collections.Specialized.NameValueCollection)+0x25
9df238 65319674 00000000 00000000 00000000 System_Web_ni!System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)+0x61e
9df270 653195a1 00000000 00000000 00000000 System_Web_ni!System.Web.UI.Page.ProcessRequest(Boolean, Boolean)+0x84
fy checksum for App_Web_sbh00zjd.dll
9df088 65a0cf98 00000000 00000000 00000000 App_Web_sbh00zjd!_Default.Button2_Click(System.Object, System.EventArgs)+0x26 [C:\inetpub\wwwroot\Default.aspx.vb @ 16]
9df0a4 65a0cdff 00000000 00000000 00000000 System_Web_ni!System.Web.UI.WebControls.Button.OnClick(System.EventArgs)+0x70
9df0bc 65a0d03b 00000000 00000000 00000000 System_Web_ni!System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String)+0x6f
9df0c4 6530798e 00000000 00000000 00000000 System_Web_ni!System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String)+0xb
9df0cc 653078e5 00000000 00000000 00000000 System_Web_ni!System.Web.UI.Page.RaisePostBackEvent(System.Web.UI.IPostBackEventHandler, System.String)+0xe
9df0e4 65319dfe 00000000 00000000 00000000 System_Web_ni!System.Web.UI.Page.RaisePostBackEvent(System.Collections.Specialized.NameValueCollection)+0x25
9df238 65319674 00000000 00000000 00000000 System_Web_ni!System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)+0x61e
9df270 653195a1 00000000 00000000 00000000 System_Web_ni!System.Web.UI.Page.ProcessRequest(Boolean, Boolean)+0x84
Appare subito evidente la System.Web.UI.Page.ProcessRequest.
Ecco invece come si presenta il thread in cui si è verificata la nostra eccezione:
# 24 Id: af8.16c0 Suspend: 1 Teb: 7ffa3000 Unfrozen
ChildEBP RetAddr Args to Child
013ff8d8 5051bb1c e0434f4d 00000001 00000001 KERNELBASE!RaiseException+0x58
013ff938 506c88f4 018d546c 00000000 00000000 mscorwks!RaiseTheExceptionInternalOnly+0x2a8
013ff950 506c8966 018d546c 00000000 013ffad8 mscorwks!RaiseTheException+0x4e
013ff978 506c8997 00000000 01193920 d537276f mscorwks!RaiseTheException+0xc0
013ff9a4 506c89a5 018d546c 00000000 013ffae4 mscorwks!RealCOMPlusThrow+0x30
013ff9b4 50738ca7 018d546c cbfe44f3 509caad4 mscorwks!RealCOMPlusThrow+0xd
013ffae4 5073ac8a 00000000 013ffb1c 013ffb8c mscorwks!Thread::RaiseCrossContextException+0x41f
013ffb98 50581629 011c8450 505fdf92 013ffdb0 mscorwks!Thread::DoADCallBack+0x293
013ffbb8 50581615 013ffdb0 013ffc20 50581694 mscorwks!Thread::DoADCallBack+0x322
013ffbc4 50581694 011c8450 505816c6 013ffc04 mscorwks!ManagedThreadBase::FinalizerAppDomain+0x25
013ffc20 50608657 01193920 00000000 013ffca7 mscorwks!SVR::GCHeap::TraceGCSegments+0x251
013ffca8 50608928 00000000 00000000 013ffdb0 mscorwks!SVR::GCHeap::TraceGCSegments+0x2f6
013ffcc0 504c846f 013ffdb0 00000000 00000000 mscorwks!SVR::GCHeap::FinalizerThreadWorker+0xb7
013ffcd4 504c840b 013ffdb0 013ffd5c 505ceb7b mscorwks!Thread::DoADCallBack+0x32a
013ffd68 504c8331 013ffdb0 cbfe43b3 00000000 mscorwks!Thread::ShouldChangeAbortToUnload+0xe3
013ffda4 505308cc 013ffdb0 00000000 011c8450 mscorwks!Thread::ShouldChangeAbortToUnload+0x30a
013ffdcc 505308dd 50608889 00000008 013ffe14 mscorwks!ManagedThreadBase_NoADTransition+0x32
013ffddc 505324ab 50608889 cbfe4003 00000000 mscorwks!ManagedThreadBase::FinalizerBase+0xd
013ffe14 505e1ec9 00000000 00000000 00000000 mscorwks!SVR::GCHeap::FinalizerThreadStart+0xbb
013ffeb4 76ce1174 01158470 013fff00 770db3f5 mscorwks!Thread::intermediateThreadProc+0x49
Come si può facilmente vedere questo thread è utilizzato dal Garbage Collector e in particolare è il Finalizer thread. Quando il GC effettua una collection, il finalizer thread si occupa di finalizzare tutti gli oggetti che non lo sono ancora cosicché, alla collection successiva, la memoria possa essere effettivamente liberata.
Dunque l’eccezione è avvenuta nel Finalizer thread e ne possiamo avere conferma anche analizzando il dump da un punto di vista .NET managed.
Carichiamo prima la sos.dll extension nel debugger ed eseguiamo poi il comando !threads:
0:024> .loadby sos mscorwks0:024> !threads
ThreadCount: 7
UnstartedThread: 0
BackgroundThread: 7
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
PreEmptive GC Alloc Lock
ID OSID ThreadOBJ State GC Context Domain Count APT Exception
11 1 2c10 01192790 8220 Enabled 00000000:00000000 0118c170 0 Ukn
24 2 16c0 01193920 b220 Enabled 018d5c9c:018d5e2c 0118c170 0 MTA (Finalizer) System.Security.Cryptography.CryptographicException (018d546c)(Finalizer) System.Security.Cryptography.CryptographicException (018d546c)
26 3 1f80 011c7040 80a220 Enabled 00000000:00000000 0118c170 0 MTA (Threadpool Completion Port)
27 4 2b24 011c79d8 1220 Enabled 00000000:00000000 0118c170 0 Ukn
19 5 14f4 011d4140 880a220 Enabled 00000000:00000000 0118c170 0 MTA (Threadpool Completion Port)
28 6 880 01216db8 380b220 Enabled 00000000:00000000 011c8450 1 MTA (Threadpool Worker)
29 7 13b8 012194e8 180b220 Enabled 058c9740:058cb64c 0118c170 0 MTA (Threadpool Worker)
Da qui abbiamo conferma che si tratta del Finalizer thread, e abbiamo anche un’informazione aggiuntiva: si tratta di una CryptographicException.
Vediamo dunque lo stack managed del thread 24:
0:024> !clrstack
OS Thread Id: 0x16c0 (24)
ESP EIP
0404F37C 79514506 System.Security.Cryptography.CryptographicException.ThrowCryptogaphicException(Int32)
00000000 00000001 System.Security.Cryptography.SafeKeyHandle._FreeHKey(IntPtr)
0404F734 79524D26 System.Security.Cryptography.SafeKeyHandle.ReleaseHandle()
00000000 00000001 System.Runtime.InteropServices.SafeHandle.InternalFinalize()
0404FC10 79365DE2 System.Runtime.InteropServices.SafeHandle.Dispose(Boolean)
0404FC14 79365CFF System.Runtime.InteropServices.SafeHandle.Finalize()
Vediamo che viene chiamato il metodo Finalize che a sua volta chiama la Dispose e infine viene generata l’eccezione.
Discutendo questa cosa col cliente abbiamo poi capito perché il Dispose chiamato dal Finalizer andava in errore.
Il codice dell’applicazione, impersonando l’utente loggato, crea un RSACryptoServiceProvider e una coppia di chiavi. Il tutto avviene usando un thread che gira nel contesto dell’Impersonated User. La Dispose viene poi effettuata dal Finalizer il cui thread però non gira nel contesto dell’utente che aveva creato il provider. Ne consegue che il Finalizer non ha i diritti necessari a liberare tali risorse e va in errore.
Il problema non sarebbe accaduto se lo sviluppatore avesse aggiunto la chiamata alla Dispose non appena finito di utilizzare le risorse.
Occorre inoltre aggiungere e rimarcare che una eccezione che avviene nel Finalizer thread può avere conseguenze particolarmente gravi. In questo caso avevamo un’eccezione non gestita e il workerprocess andava in crash (per i motivi spiegati sopra e nell’articolo linkato). Il w3wp.exe veniva riavviato nel giro di pochi secondi con un impatto sul business relativamente breve.
Immaginiamo invece che il metodo Dispose per qualche motivo si fosse fermato su una critical section o su un altro tipo di lock. Se ciò avviene nel thread della pagina aspx che usa l’oggetto la cosa non avrebbe altre conseguenze se non quella di bloccare l’esecuzione della pagina in questione. Se invece la chiamata a Dispose fosse stata lasciata al Finalizer allora si sarebbe bloccato quest’ultimo e non sarebbe più riuscito a finalizzare gli oggetti da quel momento in poi. Dunque il GC non avrebbe più potuto liberare la memoria dalle risorse unmanaged non finalizzate. In questo caso avremmo avuto un subdolo e costatante incremento di utilizzo della memoria portando a instabilità e comportamenti inaspettati dell’applicazione.
Probabilmente avrò modo in un prossimo blog di mostrare qualche caso in cui il blocco del finalizer porta ad OutOfMemory.
Ciao a tutti e alla prossima
Stefano Pronti
Senior Support Engineer
EMEA IIS and Web Developer Support Team