Ukoliko se dovoljno dugo bavite programiranjem, velike su šanse da ste se barem jednom zaputili u rupu bez dna, tragom zecolikog baga koji vam uporno izmiče. I taman kad posegnete, sigurni da je potera gotova, on se ponovo daje u beg. Ovo je jedna takva priča.
Gde se troši najviše procesorskog vremena?
Za razliku od Alise, koja je sve vreme dremala, naš glavni junak vredno radi u pravoj pravcatoj zemlji čudesa. Pažljivo analizira performanse jednog velikog i složenog sistema. Operacije koje analizira traju dugo, predugo. Po svom uobičajenom ritmu, startuje PerfView i snima trag izvršavanja. Bez promene opcija, PerfView će snimiti nekoliko osnovnih grupa događaja sa kojima obično počinje svaka analiza, a među njima i CPU Samples, koji će svake milisekunde zabeležiti trenutni stack trace na svim procesorima. Iako neće uhvatiti svaki korak izvršenja programa, ovaj metod nam može dati odličnu procenu gde trošimo najviše procesorskog vremena. Ipak, mnoštvo podataka ne daje jasan odgovor na pitanje šta to radi sporo. Ni jedna grana poziva se ne ističe. Prateći trag nekoliko većih grupa ne uočava ništa što bi moglo da objasni ono što ga muči - zašto ove operacije traju tako dugo. Sticajem okolnosti postoji performance counter koji meri prosečan broj operacija u sekundi, ali iz toga podatka zasebno ne zaključuje mnogo. Naš junak otvara pregled svih metoda, pronalazi spornu operaciju po imenu (By Name view) i burgija dublje (right click, Drill Into). U novom prozoru sada gleda samo one odbirke koji se tiču te konkretne operacije. Među osnovnim sumarnim podacima u zaglavlju prozora pronalazi i Metric/Interval i primećuje da ima manje odbiraka nego što očekuje, imajući u vidu broj operacija u sekundi. Shvata da mu je potrebno još tragova, pa se vraća na lice mesta da obavi novo snimanje. Ovoga puta snimiće i Thread Time, neće mu promaći ni jedna milisekunda!
Šta je uzrok blokiranja?
Naoružan novi podacima ponovo pokreće pretragu po imenu i odmah sužava pogled na odbirke koji se tiču samo te operacije koju trenutno analizira (right click, Include Item). Sada Metric/Interval prikazuje veći odnos koji bolje odgovara očekivanom broju operacija u sekundi. Pri vrhu liste uočava stavku BLOCKED_TIME koja figuriše sa više od 40%! Da bi bolje prepoznao vrstu blokiranja, u zaglavlju prozora prvo poništava grupisanje (GroupPats). Tražeći najveće uzroke blokiranja prelazi na pregled grupisan prema pozivaocima (right click, Goto Item in Callers) koji mu daje bottom-up pregled na hijerarhiju poziva. Trag počinje vrlo kriptično: "ntoskrnl!?", "ntdll!?", "kernelbase!?", "mscorlib.ni!?", a onda odjednom nešto prepoznatiljivo - metoda iz modula koji analizira. Međutim, prva prepoznatljiva metoda ne donosi nikakve odgovore. U njoj se ne pominju nikakvi pozivi koji bi eventualno mogli rezultovati blokiranjem (npr. lock, Wait, EnterReadLock…). Umesto da razjasni, ovo samo dalje produbljava misteriju - šta je uzrok toliko blokiranja na koje potrošimo gotovo polovinu vremena.
Jednu gorku kafu kasnije naš junak pronalazi novog osumnjičenog - Garbage Collector (GC). Srećom poslednji snimak sadrži i podatke o njegovom kretanju, pa istraga može da se nastavi odmah. Vraća se u osnovni prozor i otvara Memory Group, GCStats. Bira odgovarajući proces i gleda kretanje osumnjičenog đubretara. Na prvi pogled uočava da je veliki deo vremena proces bio pauziran zbog GC-a. Nešto dalje u izveštaju nailazi na spisak svih njegovih akcija u tom periodu - nekoliko ciklusa u svakoj sekundi! To bi moglo objasniti zašto gotovo pola vremena proces čeka da đubretar uradi svoj posao. Srećom, GC je pažljivo zabeležio šta ga je pokrenulo u svakom konkretnom ciklusu i koliko dugo je blokirao proces, a za sve njih ovoga puta razlog je bio broj alokacija (AllocSmall). Na prvi pogled neočekivano otkriće. Sporna operacija nema potrebe da alocira mnogo novih podataka i radi uglavnom sa podacima koji već postoje u memoriji. Ko i zašto alocira toliko objekata? Nazad na glavni prozor po još tragova! U istoj grupi sa GCStats može se pronaći i nekoliko izveštaja o alokacijama. Jedan od njih je i "GC Heap Alloc Ignore Free" koji prikazuje alokacije nezavsno od toga da li su ti objekti još uvek "živi". Iako je baziran na odbircima i ne daje tačan podatak o alokacijama, u praksi se pokazalo da je vrlo blizu stvarnih vrednosti i više nego dovoljno da se identifikuju najveći potrošači. Naš detektiv otvara ovaj izveštaj za odgovarajući proces i u neverici zuri u pregled alociranih tipova. Na vrhu liste se nalazi enum! Da stvar bude još čudnija, procenjena ukupna veličina alociranih objekata prelazi 60GB za svega nekoliko minuta, preko 6 puta više od prvog sledećeg tipa na listi! Imajući u vidu da bi jedan takav objekat zauzeo približno 12B, to znači da se alocira preko 17 miliona takvih objekata svake sekunde! Da misterija bude veća, radi se o internom tipu koji se koristi u svega dve metode duboko u infrastrukturnom kodu. Kod vrlo jednostavan - dobijeni argument tog tipa uporedi sa konstantom istog tipa i izvrši odgovarajuću akciju. Nema nikakvih čudnih deklaracija koje bi zahtevale alokaciju na heap-u (boxing). Da bi otkrio šta se to skriva iza naizgled jednostavne metode moraće da zaviri dublje u najsitnije detalje. Za to koristi ILSpy koji mu daje detaljne korake koje izvršava virtuelna mašina svaki put kada se pozove sporna metoda. Na prvi pogled u oči upada uzrok svih ovih alokacija: "box …". Odmah zatim i uzrok boxing-a: "callvirt … System.Object::Equals(object)". Napokon! Iz ovoga lako izvlači i poslednji deo slagalice. Budući da enum nema posebno definisanu Equals metodu, koristi se osnovna Equals metoda koja je definisana za tip Object, a kako ona zahteva argument tačno tog tipa, prevodilac je bio prinuđen da spakuje konstantu sa kojom se poredi u poseban objekat na heap-u i to prosledi kao argument za Equals metodu. Da bi potvrdio svoj zaključak, naš glavni protagonista kreira malu konzolnu aplikaciju u kojoj vrši poređenje analogno onom koje je upravo analizirao. I zaista, ukoliko definiše konstantu tipa object koja se box-uje smo jednom i onda kao takva prosleđuje Equals metodi na poređenje, alokacije se prepolove. Međutim, pošto i dalje detektuje alokacije iako nema eksplicitnog poziva "box" instrukcije u IL kodu, pokušava da problem reši tako što umesto "Equals" koristi "==" i to se zapravo potvrđuje kao pravo rešenje. Osim što nema nepotrebnih alokacija, više nema ni "callvirt" instrukcije nego se poređenje vrši "ceq" instrukcijom koja je višestruko brža (što već može doći do izražaja ukoliko se ponavlja nekoliko desetina miliona puta svake sekunde). Srećan zbog uspešno rešene misterije naš glavni junak kratko proslavlja uz čokoladnu bombonu, a zatim se vraća na pregled alokacija i nastavlja potragu prateći sledeći tip po veličini i broju alokacija. Ne iznenađuje ga toliko što je to char[], ali ono što je neobično je metoda u kojoj se to javlja. Naime, radi se o metodi koja generiše xml dokument na bazi objektnog modela. Najveći deo generisanog teksta su predefinisani stringovi, kao što su nazivi oznaka (tags) ili fiksna obeležja (attributes). Budući da su oni već, iz drugih razloga, definisani kao konstante u odgovarajućim klasama, zašto se alocira i više nego što je konačna veličina fajlova koji se tako generišu. Malo istraživanje načina implementacije (referencesource) otkriva o čemu se radi. Ukoliko se koristi Console.Write ili StreamWriter.Write i kao argument prosledi string, tada će se prvo alocirati odgovarajući bafer char[] i u njega prekopirati sadržaj. Ukoliko se ovim metodama prosledi char[] argument, onda nema dodatne alokacije i kopiranja. Ovo važi i za WriteLine varijante. Budući da je samo promenio deklaraciju konstanti, brzo priprema i testira ovu ispravku i zaista potvrđuje da se char[] više ne pojavljuje ni u prvih 10. Rešen da iskoristi ovaj pobednički talas, pravi novu kafu i ponovo otvara pregled alokacija. Na vrhu liste poznata pomoćna klasa, vrlo jednostavne implementacije. U konstruktoru se uzima odgovarajući lock (ReaderWriterLockSlim), a u Dispose metodi se taj isti lock oslobađa. Deklarisani IDisposable interfejs pomaže, uz statičku analizu, da se period korišćenja lock-a označi upotebom using-a i spreči zaboravne da u svim situacijama oslobode lock. Osim toga, nudi praćenje vremena čekanja i zadržavanja lock-a. Iako je potpuno jasno zašto dolazi do ovih alokacija, malo je razočaravajuće da se za ovakav pomoćni objekat alocira nekoliko stotina megabajta koji odmah potom budu bačeni. Prvi instinkt ga navodi da proba da umesto klase koristi strukturu (struct). Kako je opet u pitanju samo promena deklaracije, brzo priprema ispravku i ponovo snima alokacije. Ali avaj, iako utemeljena na razumnoj pretpostavci, ispravka ipak ne daje željene rezultate. I dalje se ta pomoćna (sada već) struktura pojavljuje na vrhu liste alokacija.
Tragajući malo po beskrajnim prostranstvima interneta vrlo brzo nailazi na članak koji mu razjašnjava čitavu zavrzlamu. Naime, sticajem okolnosti implementacija donekle odstupa od specifikacije, što znači da ukoliko je promenljiva deklarisana kao "value type", tada ipak neće doći do boxing-a (kao što je navedeno u specifikaciji), što je srećna okolnost, jer on ne želi da dođe do toga. Ukoliko se promenljiva deklariše kao IDisposable, tada će se koristiti šablon za "reference type" koji podrazumeva eksplicitni poziv preko IDisposable interfejsa i time i boxing. Međutim, ovo ga navodi da još jednom razmotri način na koji se koristi ta pomoćna klasa. Budući da se strukture prenose po vrednosti, to znači da će Dispose zapravno biti pozvan na kopiji, pa nema načina da se osigura da će se pokušati oslobađanje lock-a samo jednom. Iako se trenutno koristi tako da to ne bi bio problem, pitanje je vremena kada će ipak doći do takvog problema, a tada ne bi voleo da bude zadužen za njegovo debagovanje.
Vreme izvršenja – skraćeno na pola
Nevoljno proglašava kraj optimizacije. Sa prve dve ispravke je već eliminisao preko 90% alokacija. Ovaj treći slučaj za sada obećava samo rizik, a nije sasvim izvesno kakav je dobitak u pitanju. Iako je jasno da se sada najviše alociraju ti pomoćni objekti, nije očigledno kako će se to odraziti na nešto što korisnik može da primeti. Da li će se vreme izvršavanja primetno skratiti? Verovatno neće. Da li će koristiti primetno manje memorije? Verovatno neće. Uprkos malom razočarenju zbog toga, ne može a da se ne oseti zadovoljno zbog ukupnog efekta - vreme izvršenja skraćeno na pola. Upravljanje memorijom u .NET-u je odmaklo daleko od vremena kada smo morali da direktno da baratamo svakom pojedinačnom lokacijom. Komfor koji uživamo često uzimamo zdravo za gotovo, što samo dokazuje koliko su sofisticirani i efikasni procesi koji nam to omogućavaju. Ipak, oni imaju neka ograničenja, a posledice neprimerene upotrebe često nisu očigledne. Iako ne treba preterivati u štedljivosti, domaćinsko raspolaganje dostupnom memorijom omogućava da maksimalno iskoristimo raspoložive resurse i obezbedimo najbolje performanse. Ovo je priča iz prakse koja ilustruje da čak i ekstremni slučajevi prekomernih alokacija nisu tako očigledni niti jednostavni za analizu, a mogu imati dramatične posledice i na vreme izvršavanja, a ne samo na zauzeće memorije. Naposletku najvažnije je da znamo kada da se zaustavimo. Kada se previše udubimo u detalje lako nam se može desiti da izgubimo iz vida širu sliku i da posledično neke neprimetne optimizacije "platimo na odloženo". Kao i sa klasičnim plaćanjem, uvek je jeftinije da prvo dovoljno uštedimo, a onda odmah platimo. Ovo se ogleda u kvalitetnom dizajnu i dobrim praksama koje su drugi za nas razvili na svojim greškama. A ako već to nismo u mogućnosti, onda barem da se postaramo da je ono što "kupujemo" vredno cene koju ćemo "platiti".
Zapošljavamo ljude baš kao što si ti
Ako ti je ova priča bila zanimljiva, ako se još uvek pitaš zašto bi neko koristio Equals da poredi enum, ako sve ovo možeš da uradiš jednom rukom, dok drugom piješ kafu, ili ako ne možeš, ali bi voleo da ovakve stvari radiš makar i iz hobija, onda je ovo prava prilika za tebe. . Schneider Electric zapošljava ljude baš kao što si ti ili naš glavni junak, a tebi ostavlja prostora da nađeš novi hobi. Trčanje zvuči zabavno, ali znajući tebe, ti ćeš verovatno odabrati orijentiring, jer voliš kad put moraš sam da otkriješ. Blog je pisao: Duško Mirković, Software Architect, Smart Data Operations Team, Schneider Electric Hub
