Web Application Out Of Memory: blocco nel Finalizer thread
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 mscorwks
0:000> !finalizequeue
SyncBlocks to be cleaned up: 33
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
------------------------------
Heap 0
generation 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 1
generation 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 Unfrozen
hildEBP RetAddr
1e6afd8 7c822124 ntdll!KiFastSystemCallRet
1e6afdc 7c83970f ntdll!NtWaitForSingleObject+0xc
1e6b018 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+0xf
1e6b0d0 61ca9fa9 oraclient10!kpuhhalo+0x30a
1e6b0f4 61cf32c7 oraclient10!kpucHTtoIL+0x185[…cutting…]
1e6fc98 79f01747 mscorwks!Thread::DoADCallBack+0xcd
1e6fcb8 79f04a71 mscorwks!Thread::DoADCallBack+0x322
1e6fcc4 79f04b01 mscorwks!ManagedThreadBase::FinalizerAppDomain+0x25
1e6fd20 79efe5b4 mscorwks!SVR::GCHeap::TraceGCSegments+0x251
1e6fda8 79efe70a mscorwks!SVR::GCHeap::TraceGCSegments+0x2f6
1e6fdc0 79ef3207 mscorwks!SVR::GCHeap::FinalizerThreadWorker+0xe7
1e6fdd4 79ef31a3 mscorwks!Thread::DoADCallBack+0x32a
1e6fe68 79ef30c3 mscorwks!Thread::ShouldChangeAbortToUnload+0xe3
1e6fea4 79fb9643 mscorwks!Thread::ShouldChangeAbortToUnload+0x30a
1e6fecc 79fb960d mscorwks!ManagedThreadBase_NoADTransition+0x32
1e6fedc 79fd0c91 mscorwks!ManagedThreadBase::FinalizerBase+0xd
1e6ff14 79f95a2e mscorwks!SVR::GCHeap::FinalizerThreadStart+0xbb
1e6ffb8 77e66063 mscorwks!Thread::intermediateThreadProc+0x49
1e6ffec 00000000 kernel32!BaseThreadStart+0x34
30 Id: 848.1008 Suspend: 0 Teb: 7ff37000 Unfrozen
ildEBP RetAddr
ece664 7c822124 ntdll!KiFastSystemCallRet
ece668 7c83970f ntdll!NtWaitForSingleObject+0xc
ece6a4 7c839620 ntdll!RtlpWaitOnCriticalSection+0x19c
ece6c4 1406a5af ntdll!RtlEnterCriticalSection+0xa8
RNING: Stack unwind information not available. Following frames may be wrong.
ece6d0 61ce8250 oracore10!sltsmna+0xf
ece77c 61c2772e oraclient10!kpulunli+0x10ffc
ece794 13f84ec5 oraclient10!OCILobLocatorAssign+0x14
ece7bc 13f86cd6 OraOps10+0x4ec5
ece7f4 13f8eb57 OraOps10+0x6cd6
ece7f8 12f0e400 OraOps10!OpsDacGetLen+0x87
ece7fc 1959b7b0 0x12f0e400
ece800 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> !critlist
CritSec 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> !clrstack
OS 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
Senior Support Engineer
EMEA IIS and Web Developer Support Team