Salve a tutti.

Vediamo oggi un interessante caso di alta CPU.
Siamo di fronte ad una applicazione ASP.NET 2.0 che, pur funzionando bene solitamente, di tanto in tanto rallenta improvvisamente e la CPU si innalza al di sopra del 80% di utilizzo.

Come al solito generiamo dei log con Performance Monitor che ci mostrino l’andamento della CPU usata dal processo durante la giornata. I seguenti counters ci aiuteranno a capire se la CPU è in qualche modo correlata al carico in termini di utenti connessi (Requests Current), o con le Collection del Garbage Collector (%Time in GC), o ancora all’ammontare di bytes allocati nell’unità di tempo (Allocated Bytes/Sec), o ancora a vedere in quanto tempo mediamente vengono servite le richieste (Request Execution Time), e tanto altro.

•    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 : 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)


 

Con i Debugging Tools for Windows, eseguiamo il seguente comando quando la CPU risulta essere sotto stress:

cscript adplus.vbs -quiet -hang -r 3 30 -p <PID>   usando il PID del processo in questione

Questo comando genererà 3 memory dump alla distanza di 30 secondi l’uno, che andremo poi ad analizzare.

Come prima cosa eseguiremo il comando !runaway su tutti e 3 i dump. Questo comando ci dice quanti secondi CPU hanno usato i singoli thread a partire da quanto il processo è stato avviato. Per avere un dato significativo dobbiamo confrontare l’output del comando sui 3 dump e calcolare la differenza per capire quanti secondi sono stati spesi dai thread tra un dunmp e l’altro. Andremo ad analizzare i thread che hanno lavorato per più secondi.

Un esempio di output:

0:000> !runaway
User Mode Time
Thread Time
98:2fec 0 days 0:41:05.515
85:2cf0 0 days 0:40:58.109
93:904 0 days 0:39:08.484
103:1fd8 0 days 0:35:22.171
31:29a4 0 days 0:32:48.312
109:2924 0 days 0:31:10.515
23:16e0 0 days 0:29:10.953
113:79c 0 days 0:27:26.687
99:1424 0 days 0:17:58.750
94:1fa0 0 days 0:17:55.734
122:1898 0 days 0:13:23.593
123:26b4 0 days 0:12:54.312
117:ca4 0 days 0:12:44.343
114:23b4 0 days 0:12:12.406
100:2904 0 days 0:11:19.750
91:f24 0 days 0:09:45.593
125:f34 0 days 0:09:43.187
29:1088 0 days 0:09:35.406
37:22d0 0 days 0:09:34.515
83:1410 0 days 0:09:32.890

 

Nel caso che stiamo rivedendo, usando il comando SOS.ClrStack, vediamo il callstack managed (ossia .NET) dei thread più occupati:

0:98> !clrstack
OS Thread Id: 0x27dc (124)
ESP EIP
2f77ed24 795b3c5c System.Collections.Generic.Dictionary`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].FindEntry(Int32)
2f77ed3c 795b3835 System.Collections.Generic.Dictionary`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].ContainsKey(Int32)
2f77ed40 209f1932 MyApp.MyFunc1()
2f77ed58 209f1815 MyApp.MyFunc2()
2f77ed70 209f163e MyApp.MyFunc3(Boolean)
2f77ed80 209f1453 ASP.site_master.__BuildControlform1()
2f77ed90 209f0a7b ASP.site_master.__BuildControlTree(ASP.site_master)
2f77eda0 209f098c ASP.site_master.FrameworkInitialize()
2f77eda8 661565a0 System.Web.UI.UserControl.InitializeAsUserControlInternal()
2f77edb0 66345fd9 System.Web.UI.MasterPage.CreateMaster(System.Web.UI.TemplateControl, System.Web.HttpContext, System.Web.VirtualPath, System.Collections.IDictionary)
2f77ee04 66147cd1 System.Web.UI.Page.get_Master()
2f77ee0c 6614a137 System.Web.UI.Page.ApplyMasterPage()
2f77ee1c 6614de3e System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
2f77f018 6614d8c3 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
2f77f050 6614d80f System.Web.UI.Page.ProcessRequest()
2f77f088 6614d72f System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
2f77f090 6614d6c2 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
2f77f0a4 209f7545 ASP.MyPage_aspx.ProcessRequest(System.Web.HttpContext)
2f77f0a8 65fe6bfb System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
2f77f0dc 65fe3f51 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
2f77f11c 65fe7733 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
2f77f16c 65fccbfe System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
2f77f188 65fd19c5 System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
2f77f1bc 65fd16b2 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
2f77f1c8 65fcfa6d System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
2f77f3d8 79f047fd [ContextTransitionFrame: 2f77f3d8]
2f77f40c 79f047fd [GCFrame: 2f77f40c]
2f77f568 79f047fd [ComMethodFrame: 2f77f568]

 

Le funzioni dell’applicazione (che ho rinominato in MyApp.MyFunc) stanno lavorando con un oggetto Dictionary cercando un elemento:

System.Collections.Generic.Dictionary`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].FindEntry(Int32)

Già di per sé, se il Dictionary contenesse un numero molto elevato di Items, questa operazione potrebbe richiedere molta CPU. Nel nostro caso però l’oggetto sembrava avere solo pochi elementi.

Usando il comando !dso (sempre della SOS extension), è possibile vedere l’indirizzo del Dictionary (e di tutti gli altri oggetti usati dal thread, che però rimuovo dall’output sottostante):

0:022> !dso
OS Thread Id: 0x2c30 (22)
ESP/REG Object Name
esi 1728e9fc System.Collections.Generic.Dictionary`2

A questo punto possiamo vedere, tramite il comando !GCRoot, se questo oggetto è dichiarato come variabile locale del thread (avremo solo rooting che partono dal trhead local storage), oppure se è una varabile ‘strongly rooted’ che dunque sopravvive al thread ed ha application life scope.

Effettivamente il nostro Dictionary risulta essere strongly rooted, ed è inserito in una array di Objects. Tali array sono usate dal runtime per tenere traccia delle variabili statiche.

0:022> !gcroot 1728e9fc 
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
........
.cutting.
........
DOMAIN(09671470):HANDLE(Pinned):e5411ec:Root: 20120410(System.Object[])-> 1728e9fc(System.Collections.Generic.Dictionary`2

Dunque il nostro Dictionary è una variabile statica e come tale è accessibile da diversi thread contemporaneamente.

A questo punto, il dubbio che ci è sorto, è che l’accesso al Dictionary non fosse  sincronizzato opportunamente. Analizzando le funzioni che vi accedevano l’ipotesi è stata confermata.

In pratica quello che succedeva era che, mentre un thread lavorava con il Dizionario cercando un elemento, un altro thread accedeva anch’esso allo stesso Dizionario e ne cambiava il numero e la posizione degli elementi. Così facendo si creavano situazioni instabili e la ricerca di un elemento poteva andare avanti all’infinito usando tanta CPU.

D’altra parte la documentazione avverte sul fatto che la Classe dictionary non è threadsafe e chi la usa in ambiente multythreaded deve preoccuparsi della sincronizzazione:

http://msdn.microsoft.com/en-us/library/xfhwa508(VS.80).aspx

A Dictionary can support multiple readers concurrently, as long as the collection is not modified. Even so, enumerating through a collection is intrinsically not a thread-safe procedure. In the rare case where an enumeration contends with write accesses, the collection must be locked during the entire enumeration. To allow the collection to be accessed by multiple threads for reading and writing, you must implement your own synchronization.

 

E’ stato sufficiente sincronizzare gli accessi, racchiudendoli in un blocco Lock{}, per risolvere il problema.

Alla prossima

Stefano Pronti
Senior Support Engineer
EMEA IIS and Web Developer Support Team