In uno dei miei post precedenti, Sempre chiamare il metodo Dispose!, avevo trattato un di un crash che avveniva per una exception generata all’interno del metodo Dispose.
Siccome il codice non chiamava esplicitamente la Dispose, questa era chiamata dal Garbage Collector in fase di Finalizzazione. Avvenendo dunque l’eccezione al di fuori del contesto di una pagina (appunto nel Finalizer thread) il processo andava in crash come spiegato da questo articolo:
Unhandled exceptions cause ASP.NET-based applications to unexpectedly quit in the .NET Framework 2.0
Nel vecchio post anticipai anche che, se anziché avere una eccezione che avesse mandato in crash il processo, avessimo avuto un blocco all’interno della dispose, allora questo avrebbe comportato un blocco del finalizer thread e quindi an un aumento continuo della memoria con problemi prolungati di performance e instabilità per l’applicazione.
Promisi che ne avrei parlato in futuro, ed ecco il caso opportuno.
Per l’appunto, in questo caso ci troviamo ad investigare un aumento repentino e inatteso della memoria che avviene senza segni premonitori e senza che vi sia un aumento del volume di utenti che accedono al sito.
L’action plan è sempre il medesimo in questi casi: si monitorano i seguenti contatori col Performance Monitor e si prendono dei memory dumps.
• Performance Object : Process - Counters : Private Bites, %Privilaged Time, %User Time, %Processor Time, ID Process - Instances : any existing inentinfo.exe, w3wp.exe, aspnet_wp.exe and dllhost.exe • Performance Object : Processor - Counters : Processor Time - Instances : _Total• Performance Object : Memory - Counters : Committed Bytes• Performance Object : .NET CLR Memory - Counters : All Counter • Performance Object : .NET CLR LOADING – Counters : Bytes in Loader Heap, Current AppDomains, Current Assemblies• Performance Object : ASP.NET vX.X- Counters : All Counter (where vX.X is the version you are running on)• Performance Object : ASP.NET Apps vx.x- Counters : All Counter (where vX.X is the version you are running on)• Performance Object : Active Server Pages Counters : All (only if ASP application are involved)
Tralascio qui l’analisi del PerfMon e passo a ciò che si è scoperto nei dumps. Una delle prime cose cose che faccio quando vedo che il GC non riesce a rilasciare la memoria, è guardare se le coda di finalizzazione è pulita oppure se ha numerosi oggetti accodati, usando il comando !finalizequeue della sos extension:
0:000> .loadby sos mscorwks0:000> !finalizequeueSyncBlocks to be cleaned up: 33MTA Interfaces to be released: 0STA Interfaces to be released: 0----------------------------------------------------------------Heap 0generation 0 has 0 finalizable objects (48f722b0->48f722b0)generation 1 has 1 finalizable objects (48f722ac->48f722b0)generation 2 has 2211 finalizable objects (48f70020->48f722ac)Ready for finalization 327435 objects (48f722b0->490b1edc)------------------------------Heap 1generation 0 has 0 finalizable objects (40c6379c->40c6379c)generation 1 has 4 finalizable objects (40c6378c->40c6379c)generation 2 has 3547 finalizable objects (40c60020->40c6378c)Ready for finalization 396582 objects (40c6379c->40de6c34)
Come si vede abbiamo migliaia di oggetti pronti per la finalizzazione che attendono in coda che il finalizer thread processi il loro metodo Dispose. Può capitare di trovare qualche oggetto in coda anche quanto tutto va bene, semplicemente perché un dump non è altro che una fotografia istantanea e in quell’istante è possibile che qualche oggetto sia in attesa di essere finalizzato. Ma quando vediamo migliaia di oggetti in coda la cosa diventa sospetta e lascia pensare che il finalizer non riesce a fare il proprio lavoro.
Vediamo allora lo stack dei thread usando il comando ~*kp. Passandoli tutti si vede che c’è ne sono due che sono fermi su delle Critical Section e sotto mostro solo quei due:
17 Id: 848.8cc Suspend: 0 Teb: 7ffa6000 UnfrozenhildEBP RetAddr 1e6afd8 7c822124 ntdll!KiFastSystemCallRet1e6afdc 7c83970f ntdll!NtWaitForSingleObject+0xc1e6b018 7c839620 ntdll!RtlpWaitOnCriticalSection+0x19c** ERROR: Symbol file could not be found. Defaulted to export symbols for oracore10.dll - 1e6b038 1406a5af ntdll!RtlEnterCriticalSection+0xa8** ERROR: Symbol file could not be found. Defaulted to export symbols for oraclient10.dll - ARNING: Stack unwind information not available. Following frames may be wrong.1e6b044 61ca25e2 oracore10!sltsmna+0xf1e6b0d0 61ca9fa9 oraclient10!kpuhhalo+0x30a1e6b0f4 61cf32c7 oraclient10!kpucHTtoIL+0x185[…cutting…]1e6fc98 79f01747 mscorwks!Thread::DoADCallBack+0xcd1e6fcb8 79f04a71 mscorwks!Thread::DoADCallBack+0x3221e6fcc4 79f04b01 mscorwks!ManagedThreadBase::FinalizerAppDomain+0x251e6fd20 79efe5b4 mscorwks!SVR::GCHeap::TraceGCSegments+0x2511e6fda8 79efe70a mscorwks!SVR::GCHeap::TraceGCSegments+0x2f61e6fdc0 79ef3207 mscorwks!SVR::GCHeap::FinalizerThreadWorker+0xe71e6fdd4 79ef31a3 mscorwks!Thread::DoADCallBack+0x32a1e6fe68 79ef30c3 mscorwks!Thread::ShouldChangeAbortToUnload+0xe31e6fea4 79fb9643 mscorwks!Thread::ShouldChangeAbortToUnload+0x30a1e6fecc 79fb960d mscorwks!ManagedThreadBase_NoADTransition+0x321e6fedc 79fd0c91 mscorwks!ManagedThreadBase::FinalizerBase+0xd1e6ff14 79f95a2e mscorwks!SVR::GCHeap::FinalizerThreadStart+0xbb1e6ffb8 77e66063 mscorwks!Thread::intermediateThreadProc+0x491e6ffec 00000000 kernel32!BaseThreadStart+0x3430 Id: 848.1008 Suspend: 0 Teb: 7ff37000 UnfrozenildEBP RetAddr ece664 7c822124 ntdll!KiFastSystemCallRetece668 7c83970f ntdll!NtWaitForSingleObject+0xcece6a4 7c839620 ntdll!RtlpWaitOnCriticalSection+0x19cece6c4 1406a5af ntdll!RtlEnterCriticalSection+0xa8RNING: Stack unwind information not available. Following frames may be wrong.ece6d0 61ce8250 oracore10!sltsmna+0xfece77c 61c2772e oraclient10!kpulunli+0x10ffcece794 13f84ec5 oraclient10!OCILobLocatorAssign+0x14ece7bc 13f86cd6 OraOps10+0x4ec5ece7f4 13f8eb57 OraOps10+0x6cd6ece7f8 12f0e400 OraOps10!OpsDacGetLen+0x87ece7fc 1959b7b0 0x12f0e400ece800 00000000 0x1959b7b0
17 Id: 848.8cc Suspend: 0 Teb: 7ffa6000 UnfrozenhildEBP RetAddr 1e6afd8 7c822124 ntdll!KiFastSystemCallRet1e6afdc 7c83970f ntdll!NtWaitForSingleObject+0xc1e6b018 7c839620 ntdll!RtlpWaitOnCriticalSection+0x19c** ERROR: Symbol file could not be found. Defaulted to export symbols for oracore10.dll - 1e6b038 1406a5af ntdll!RtlEnterCriticalSection+0xa8** ERROR: Symbol file could not be found. Defaulted to export symbols for oraclient10.dll - ARNING: Stack unwind information not available. Following frames may be wrong.1e6b044 61ca25e2 oracore10!sltsmna+0xf1e6b0d0 61ca9fa9 oraclient10!kpuhhalo+0x30a1e6b0f4 61cf32c7 oraclient10!kpucHTtoIL+0x185
[…cutting…]1e6fc98 79f01747 mscorwks!Thread::DoADCallBack+0xcd1e6fcb8 79f04a71 mscorwks!Thread::DoADCallBack+0x3221e6fcc4 79f04b01 mscorwks!ManagedThreadBase::FinalizerAppDomain+0x251e6fd20 79efe5b4 mscorwks!SVR::GCHeap::TraceGCSegments+0x2511e6fda8 79efe70a mscorwks!SVR::GCHeap::TraceGCSegments+0x2f61e6fdc0 79ef3207 mscorwks!SVR::GCHeap::FinalizerThreadWorker+0xe71e6fdd4 79ef31a3 mscorwks!Thread::DoADCallBack+0x32a1e6fe68 79ef30c3 mscorwks!Thread::ShouldChangeAbortToUnload+0xe31e6fea4 79fb9643 mscorwks!Thread::ShouldChangeAbortToUnload+0x30a1e6fecc 79fb960d mscorwks!ManagedThreadBase_NoADTransition+0x321e6fedc 79fd0c91 mscorwks!ManagedThreadBase::FinalizerBase+0xd1e6ff14 79f95a2e mscorwks!SVR::GCHeap::FinalizerThreadStart+0xbb1e6ffb8 77e66063 mscorwks!Thread::intermediateThreadProc+0x491e6ffec 00000000 kernel32!BaseThreadStart+0x34
30 Id: 848.1008 Suspend: 0 Teb: 7ff37000 UnfrozenildEBP RetAddr ece664 7c822124 ntdll!KiFastSystemCallRetece668 7c83970f ntdll!NtWaitForSingleObject+0xcece6a4 7c839620 ntdll!RtlpWaitOnCriticalSection+0x19cece6c4 1406a5af ntdll!RtlEnterCriticalSection+0xa8RNING: Stack unwind information not available. Following frames may be wrong.ece6d0 61ce8250 oracore10!sltsmna+0xfece77c 61c2772e oraclient10!kpulunli+0x10ffcece794 13f84ec5 oraclient10!OCILobLocatorAssign+0x14ece7bc 13f86cd6 OraOps10+0x4ec5ece7f4 13f8eb57 OraOps10+0x6cd6ece7f8 12f0e400 OraOps10!OpsDacGetLen+0x87ece7fc 1959b7b0 0x12f0e400ece800 00000000 0x1959b7b0
Si nota come entrambi i thread siano fermi su una RtlpWaitOnCriticalSection. Altra cosa interessante da notare è che il thread 17 è proprio il Finalizer thread. A questo punto possiamo usare il comando !CritList della estensione SieExtPub scaricabile da Internet:
0:000> !critlistCritSec at 1499f478. Owned by thread 30. Deadlocked on CritSec 14d04e70. Waiting Threads: 17 CritSec at 14d04e70. Owned by thread 17. Deadlocked on CritSec 1499f478. Waiting Threads: 30
Si vede chiaramente che il thread 17 è in attesa che venga rilasciata una critical section aperta dal thread 30. Ma a sua volta il thread 30 è bloccato, e non potrà mai rilasciare la sua critical section, perché è a sua volta bloccato su un’altra critical section che era stata aperta in precedenza proprio dal thread 17.
Dunque i due thread si bloccano a vicenda. Siamo difronte al tipico caso di deadlock.
Guardiamo in fine il managed callstack del thread 17:
0:017> !clrstackOS Thread Id: 0x8cc (17)ESP EIP 01e6f8e8 7c82ed54 [InlinedCallFrame: 01e6f8e8] Oracle.DataAccess.Client.OpsDac.Dispose(IntPtr, IntPtr, IntPtr, IntPtr, Oracle.DataAccess.Client.OpoMetValCtx*, Oracle.DataAccess.Client.OpoDacValCtx*, Oracle.DataAccess.Client.OpoSqlValCtx*, Int32)01e6f8e4 14d489fe Oracle.DataAccess.Client.OracleDataReader.Dispose(Boolean)01e6f950 14d97065 Oracle.DataAccess.Client.OracleDataReader.Finalize()01e6fc1c 79fbcca7 [ContextTransitionFrame: 01e6fc1c] 01e6fcec 79fbcca7 [GCFrame: 01e6fcec]
Come ci aspettavamo si tratta proprio del finalizer thread che sta chiamando il metodo Dispose su degli oggetti Oracle e lo sta facendo perché il metodo Dispose non era stato preventivamente chiamato dal codice dell’applicazione una volta terminato di usare tali oggetti. Questo deadlock sarebbe stato pressoché indolore e la massa di utenti non avrebbero subito disservizi se fosse avvenuto al di fuori del finalizer thread.
In questo caso invece il deadlock a causato il blocco della finalizzazione con repentina crescita della memoria e instabilità dell’applicazione.
La morale dunque è sempre quella: mai dimenticarsi di chiamare Dispose.
Alla prossima
Stefano Pronti Senior Support Engineer EMEA IIS and Web Developer Support Team