Nyáron két érdekes és nehéz esetem is volt ügyfeleknél, mindkettőhöz memory dumpokat is kellett elemezni WinDbg-gal. Elmesélem az elsőt.

Ebben teljesen kiszámíthatatlan módon felment a webszerver cpu-ja 100%-ra, és nagyon belassult a kiszolgálás raja. A procit a w3wp.exe vitte el, azaz nem valami megőrült vírusirtó vagy egyéb más ártalmas processz. Sajnos az elején ez a tény, hogy nagy cpuval jár együtt a belassulás nem volt még egyértelmű, így nem ebbe az irányba kezdődött a nyomozás.

DynaTrace agent fel volt telepítve a szerverekre (okos kis cucc), ami alapján látszottak a kérésekhez tartozó stack trace-ek és .NET statisztikák is. Az alapján vagy a webapp -> web service hívások voltak lassúak, vagy a GC vitt el túl sok időt. A hálózati és szerviz problémát egy idő után ki lehetett zárni, mivel a szerviz oldalon pár ms alatt lefutottak a hívások. A .NET hálózati traceinget is bekapcsoltuk, hogy webapp oldalról milyen időkkel mennek a hívások, de ebben minden infó benne volt, csak a timestampek nem. Nesze semmi fogd meg jól.

A GC ügyre nem tudtam semmit mondani. Egészen pontosan a DynaTrace Suspensiönt mutatott, azaz valamire várakoztak a szálak. A doksija szerint ez általában GC-re várakozást jelent. Általában. A .NET GC perfmon counterek ezt nem erősítették meg. A hálózatra és egyéb IO-ra várakozás külön tétel volt a listán, így a suspension oka rejtély maradt. A memory dumpok nem segítettek, mivel mind olyankor készült, amikor már rendben volt a gép, apppol recycling miatt.

Szerencsére a tesztelő kolléga nagyon lelkesen segítkezett, és a tesztjeivel sikerült reprodukálni a problémát. Hogy pontosabban lássuk, mi történik, felraktunk egy gépet a staging szerverre, így úgy tudtunk mérni profilerrel, mi történik a worker processzben.

Amikor végre sikerült reprodukálni a hibát, végre saját szememmel láttam, hogy a cpuk kiülnek 100%-ra, és odaragadnak. Annyira le volt terhelve a gép, hogy nem is lehetett használni a profilert, task managerben el kellett vennem a processor affinity-n keresztül pár procit a w3wptől, hogy a visual studio egyáltalán meg tudjon nyekkenni.

A profiler már közelebb vitt a problémához, az idő zöme a Dictionary.FindEntry metódusában ment el.
Ezt hívja a TryGetValue, a ContainsKey és az Indexer, ez a fő kereső része. Mivel a Dictionary arról híres, hogy igen gyors, arra gondoltam csak azért megy el itt annyi idő, mert végtelen cilusba kerül a Dictionaryt hívó kód, valamilyen kódszervezési hiba miatt. Ezért raktunk a kódba egy számlálót, hányszor hívják meg a Dictionary-t piszkáló metódust, és kilogoltuk a % 1000000-dik hívást. Vártunk, vártunk, de nem keletkezett log.

Ekkor némi guglizás után találtam rá erre a cikkre. És ekkor minden összeállt. A Dictionary nem thread safe, csak olvasásra. Ha több szál egyszerre írja és olvassa is, akkor beakadhat végtelen ciklusba a FindEntry metódus!!!

Ez itt kérem a szopóroller:

for (int i = buckets[hashCode % buckets.Length]; i >= 0; i = entries[i].next) 
{
    if (entries[i].hashCode == hashCode && comparer.Equals(entries[i].key, key)) return i;
}

Ez a for soha nem ér véget, extrém ritka versenyhelyzet esetén. Aljas, nem?

Mi a megoldás? Meg kell írni a kódot thread safe-re, lock-kal és egyebekkel.

A DynaTrace suspension idő ebből következően a thread cpura várakozást jelenette, annyira le volt fogva minden cpu, hogy az os kénytelen volt elvenni magot a szálaktól, ez látszott suspensionként a riportokban. Tessék békén hagyni szegény GC-t, mindig ő a bűnbak. :)

Mit tennék másképp, hogy a következő esetben célratörőbben találjam meg a problémát?

1. Sokkal szigorúbban oda kell figyelni a makró adatok rögzítésére. A performance counterek nagyon jó hátteret adnak, de ehhez tényleg napokig futtatni kell a perfmont, és megőrizni a logokat a nyomozás végéig.

2. Semmit nem kell elhinni, mindent magunknak kell megnézni. Pl., hogy a dump tényeg akkor készült-e, amikor még fennállt a hiba, másképp könyékig turkálhatunk a dumpban, nem lesz benne semmi érdekes.

3. Ha sikerül azonosítani a hiba indikátorát, pl. nagy cpu, lassú lapvégrhajtás, exceptionök, stb., akkor automatikus dumpokat kell készíteni, nem embereket zaklatni ezzel. A Debug Diagnostic Tool v2.0 erre van kitalálva.

4. Nagy erőfeszítéseket kell tenni, hogy rerpodukálni lehessen a hibát olyan környezetben, ahol van Visual Studio, így debugger és profofiler. A dump egy pillanatot kap el, memória és néha cpu elemzésre is jó, de mivel csak egy pillanat látszik belőle, nehéz összerakni a nagy képet.

Could you hire me? Contact me if you like what I’ve done in this article and think I can create value for your company with my skills.