Analyza Heap Dumpov - Debuggovanie JXColl

Java programatorov odbremenuje od starosti spojenych s manualnou alokaciou a dealokaciou pamate pre objekty, aby sa mohli sustredit na riesenie samotneho problemu. O dealokaciu pamate sa tu stara Garbage Collector, ktory moze byt implementovany rozne. Vacsinou nevyuzivane objekty odstranuje az vtedy ked sa zaplnenie pamate blizi maximalnej hranici. Robi to preto, aby prilisne nespomaloval chod aplikacie. Svoju pracu robi dobre, ale predsa mozu nastat situacie, kedy chybou programatora vznikne takzvany Memory Leak. Pri memory leaku sa objekty vytvoria no nikdy nie su oznacene ako nepotrebne a ostavaju v pamati pocas celeho behu aplikacie, aj ked ich uz nikdy nebudeme potrebovat. Pri memory leaku nam nepomoze ani explicitne volanie Garbage Collectora pomocou System.gc(). GC tieto objekty neodstrani, lebo stale na ne existuje referencia.

Pri rieseni problemu s JXColl sme sa spociatku domnievali ze problem je s PacketCache , kedze do nej moze byt vlozeny len konecny pocet paketov (v JXColl momentalne 25). Tato cache je implementovana ako ArrayBlockingQueue . To znamena ze ak je cache plna, vlozenie je blokujuca operacia, a teda je tu predpoklad mnozenia sa paketov este pred cache. Avsak to ze PacketListener ktory prijima pakety je len jeden data sa sice mozu hromadit, ale este pred JXColl a to v operacnom systeme. Naviac profilaciou metod pomocou VisualVM sme zistili ze podstatne viac procesoroveho casu je straveneho pri citani z cache ako pri zapise do nej. To znamena ze JXColl viac caka na nove pakety v prazdnej PacketCache nez caka na vlozenie paketu do plnej PacketCache . Tento problem sme vylucili.

Zvalili sme to teda na Memory Leak. Pri analyze pamatovej narocnosti JXColl sme spociatku pouzivali nastroje ako Netbeans Profiler alebo VisualVM . Oba nastroje su vpodstate totozne, akurat VisualVM je stand-alone aplikacia. Umoznuje napojit sa na proces a zbierat informacie o nom.

Medzi zakladne funkcietychto nastrojov patri monitorovanie aktualeho stavu aplikacie, teda vyuzitie CPU a pamate, pocet loadnutych tried, zivych vlakien. V lubovolnom okamihu mozme spustit garbage collector (GC), ktory na zaklade svojho algoritmu urci, ktore objekty je mozne z pamate odstranit a uvolnit tak miesto. Mame k dispozicii aj realtime udaje o casoch stravenych v jednotlivych metodach a aktualny histogram vyuzitia pamate (profilacia). Pre kazdu triedu sa zobrazi pocet instancii tejto triedy v pamati, kolko pamate tieto instancie zaberaju, kolko roznych generacii objektov z danej triedy existuje (generacia – jeden cyklus GC).

Takisto mozme vytvorit obraz pamate – Heap Dump. Heap Dump je obraz pamate v jednom casovom okamihu vykonavania. VisualVM aj NetBeans Profiler ho vedia nacitat a v privetivej podobe zobrazit vo forme histogramu. Usporiadanie je od najviac zaberajucich instancii po najmensie podobne ako v live udajoch pri profilacii pamate, teda mame predstavu ktorych objektov je najviac. Ak su najvacsie objekty z JDK, ako napriklad java.lang.Object[] alebo byte[], tazko je povedat kde vznikaju a kde sa hromadia. Tento pripad sa vyskytol aj pri JXColl.

Ziskanie Heap Dumpu

Najlepsie zodpovedajuce data pre analyzu su zvycajne pri pade aplikacie. Vtedy su pamatove pomery evidentnejsie a jednoduchsie sa urcuje skutocny problem. Pomocou argumentu JVM

-XX:+HeapDumpOnOutOfMemoryError

vieme vytvorit Heap Dump pri vzniku chyby java.lang.OutOfMemoryError, teda ked dojde k vycerpaniu celej kapacity Heapu. Velkost Heapu vieme manualne nastavit pomocou argumentu

-mxXM

, kde X je maximalna velkost heapu v MB.

Cely prikaz v pre spustenie JXColl s tymito nastaveniami moze vyzerat naledovne:

java -XX:+HeapDumpOnOutOfMemoryError -mx6M -jar jxcoll.jar jxcoll.conf

Na mojom lokalnom stroji k tejto chybe doslo pri zapnutom stahovani torrentov a velkosti heapu 6 MB priblizne po 20 minutach, resp. 5000 spracovanych paketoch.

Analyza Heap Dumpu

Pri analyzovani tohto HeapDumpu vo VisualVM sme sice zistili ze objektom, ktory zabera najviac miesta je java.lang.Object[], druhym najvacsim byte[], no velmi nam to pri rieseni problemu nepomohlo. S poliami bajtov sa v JXColl pracuje takmer vsade.

Pomohol nam az nastroj Eclipse Memory Analyzer Tool, ktory okrem Histogramu umoznuje zobrazit aj tzv. Dominator Tree. Jeho dve zakladne charakteristiky:

• Na vrchole stromu je najvacsi objekt v Heape
• Vsetci potomkovia objektu v tomto strome su zadrzane v tomto objekte. To znamena, ze keby Garbage Collector tento objekt zlikvidoval, zlikvidoval by aj vsetkych jeho potomkov.

V prilozenom obrazku je vidiet ze najvacsim objektom je NetXMLParser , vramci neho najvacsim objektom je java.util.ArrayList. Tento je akumulacnym bodom, do neho sa pridavaju objekty ale uz sa z neho neodstranuju. ArrayList je vo vnutorne reprezentovany polom objektov preto ako potomka vidime java.lang.Object[]. Vidime ze kapacita tohto pola je uz takmer 300 000 a zabera okolo 1.2 MB.

Pri analyze zdrojoveho kodu aj s pomocou vypisu StackTrace pri pade JXColl sme sa zamerali na objekt triedy IPFixDataRecord . Zistilo sa ze objekt bol pouzivany nespravnym sposobom, pri ktorom sa neuvolnuje miesto z ArrayListu vramci instancie triedy IPFIXDataRecord .

StackTrace pri pade kolektora

Exception in thread "Net Parser" java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:2760)
at java.util.Arrays.copyOf(Arrays.java:2734)
at java.util.ArrayList.ensureCapacity(ArrayList .java:167)
at java.util.ArrayList.add(ArrayList .java:351)
at sk.tuke.cnl.bm.JXColl.IPFIX.IPFIXDataRecord.addFieldValue(IPFIXDataRecord .java:70)
at sk.tuke.cnl.bm.JXColl.NetXMLParser.parseIPFIX(NetXMLParser .java:192)
at sk.tuke.cnl.bm.JXColl.NetXMLParser.run(NetXMLParser .java:85)

Zhodnotenie

Vykonali sme potrebne zmeny v zdrojovom kode a pustili sme sa do testovania JXColl. Od utorka 30.3.2010 do dnesneho dna (pondelok 5.4.2010) do databazy pribudlo uz viac nez 1.5 miliona zaznamov pri velkosti Heapu 6MB – a stale bezi. Predchadzajuci kolektor vydrzal pri defaultnom nastaveni heapu (~ 50MB) priblizne 400 000 zaznamov.

Tomas a Ado

-- TomasVerescak - 06 Apr 2010