Garbage Collections i Java heapen under belastning är en av de första områden man kan anpassa och justera för att få bättre prestanda. Denna artikel ger lite tips för hur man kan göra.
Det första man behöver är ett verktyg för att se och analysera heapens utnyttjande under ett prestandatest. Det finns flera sätt att göra detta, både i realtid via tex JConsole som ingår i JDK’n, via olika applikationsservrars verktyg eller genom att slå på GC loggning för JVM’n. Den senare är att föredra, då det är relativt generellt oberoende på vilken leverantör av JVM man använder, Oracle, IBM, m.fl. I princip alla VM kan logga GC statistik till en log fil. Denna log kan sedan analyseras manuellt för den inbitne GC specialisten, eller så använder man ett vertyg som GC Viewer för att analysera denna. I denna artikel tipsar vi just om detta verktyg och visar lite vad man får ut av detta.
Till att börja med kan man ladda ner den senaste versionen av GC Viewer (1.32 i skrivande stund) från GitHub. Verktyget är open source och man kan ladda ner färdiga binärer eller källkoden om man känner för att göra lite kompletteringar i verktyget. Hemsidan på GitHub hittar ni här, och binärer laddas ner från Wikin på samma sida:
Beroende på vilken leverantör av VM man har slår man på loggningen på olika sätt. Listan nedan visar hur man gör det för de VM och versioner som GC Viewer 1.32 stödjer;
- Sun / Oracle JDK 1.7 with option -Xloggc:<file> [-XX:+PrintGCDetails] [-XX:+PrintGCDateStamps] - Sun / Oracle JDK 1.6 with option -Xloggc:<file> [-XX:+PrintGCDetails] [-XX:+PrintGCDateStamps] - Sun JDK 1.4/1.5 with the option -Xloggc:<file> [-XX:+PrintGCDetails] - Sun JDK 1.2.2/1.3.1/1.4 with the option -verbose:gc - IBM JDK 1.3.1/1.3.0/1.2.2 with the option -verbose:gc - IBM iSeries Classic JVM 1.4.2 with option -verbose:gc - HP-UX JDK 1.2/1.3/1.4.x with the option -Xverbosegc - BEA JRockit 1.4.2/1.5 with the option -verbose:memory Best results are achieved with: -Xloggc:<file> -XX:+PrintGCDetails -XX:+PrintGCDateStamps
Verktyget visar sedan en rad olika statistiska värden för testet:
Ovan en bild av summerings fliken samt en graf över totala heap storleken (i detta fall 2G), tenured/oldgen heapen (går i lila) samt young heapen (gul). Tumregeln är att Young heapen ska vara cirka 1/3 – 1/4 i storlek jämnfört med Old/Tenured heapen. Det går då snabbt att göra en normal GC (flytta minne från young till old) och det kommer ta längre tid innan old gen måste rensas (Full GC).
De plottade linjerna i grafen är storleken på använt minne i respektive heap. Den gråa i den gula heapen (young gen) ser vi ökar och minskar väldigt ofta, detta är de normala GC som görs när young heapen blir full, och data som fortfarande används flyttas då till oldgen/tenured heapen istället för att raderas. Oldgen/tenured heapen är den som går i lila, och det är här som vi ser om man har ett minnesläckage eller inte, om denna ökar konstant efter varje rensning, vilket oftast inte görs förräns vid en Full GC.
Genom att studera young gen GC frekvensen i grafen över tid, ser vi även väldigt tydligt när vårt prestandatest börjar och slutar, vilket är cirka 20 minuter efter start av VM:et (början på log filen) samt sedan 8 timmar framåt. Grafens tidsaxel kan förstoras i valfri antal procent, i fallet ovan använder vi 20% för att få plats med de första 9 timmarna, så vi ser tiden för hela prestandatestet.
Summeringsfliken ger en sammanfattning för de viktigaste mätvärden att titta på. Antal fulla GC pauser tex, vilket pausar alla anrop under en ganska lång tid (dvs användare för längre svarstider). Även normala GC pauser ger användare längre svarstider, men dessa tar normalt sätt mycket kortare i tid än fulla GC.
Genomströmningen visar i procent hur mycket overhead GC arbetet står för. Den ska vara så nära 100% som möjligt, då den minskar ju mer overhead vi har i VM:et. Hög overhead visar på att vi har för lite tillgängligt minne, och VM:et spenderar för mycket tid på att hantera garbage. En tumregel är att denna inte ska vara under 98%.
Fördelningen mellan normala GC och antalet Fulla GC ska även vara så låg som möjligt för att undvika långa pauser som ger längre svarstider. Ovan gör vi 545 GC pauser totalt, varav endast 2 är fulla GC. Verktyget kan även i tidslinjen markera när en Full GC sker. När minnet börjar ta slut, gör VMet väldigt många fulla GC och mjoriteten av tiden börjar läggas på detta, man får då väldigt höga svarstider för användarna. Tiden som spenderas på GC kan man även se separat i verktyget, samt finns en särkild flik för denna;
Det gröna plottade mätvärdet i grafen ovan är tiden det tar att utföra en GC, vare sig den är normal, full eller en parallell CMS (Concurrent Mark Sweep) GC, då vi i detta fall använder den nya CMS Collectorn i Java. Den peaken som ses i grafen på över 2 sekunder är en Full GC. Dessa vill vi alltså minimera i antal under ett belastningstest, och genom att ställa in GC heaparnas storlek optimalt kan vi minska behovet eller anledningarna till att göra fulla GC.
Som sista analys kan man även i mer detalj analysera varje GC som görs och hur lång tid den tar i form av tabeller, samt visar fliken Minne i mer detalj hur mycket som rensas:
Ovan ser vi detalj fliken för de olika GC som utförs, vi ser bland annat att det görs 518 GC i young gen, 13 CMS GC (Concurrent Mark Sweep) samt 2 fulla GC (hela heapen rensas) samt statistik för hur lång tid de tar att utföra. Minnes fliken till höger ger dessutom information om hur mycket som rensas samt storleken före och efter och indikationer på hur mycket heaparna ökar i storlek.
Sammanfattningsvist visar grafen på minnesallokeringen i old/tenured heapen för detta test att den ökar konstant under de 8,5 timme som vi testar. Detta indikerar ett minnesläckage. Det har gjorts 13 parallella GC samt 2 fulla GC under testet, och de parallella verkar inte kunna hålla old/tenured heapen i schack, då den ökar konstant. Prestandatestet vi gjorde var dock för kort i tid (8 timmar) eller hade för låg last för att ett problem skulle hinna uppstå under testet. Inga anrop gick nämligen fel, och svarstiderna under testet visade inte på en ökning. Vi ser dock att i slutet på testet allokerar vi cirka 1G av de 1,5G som finns tillgängliga för oldgen/tenured heapen, och ytterligare en körning på 8 timmar borde i så fall visa om VM:et överlever situationen och börjar göra fler fulla GC för att rensa minnet. Eller så visar det på att fulla GC inte heller klarar att rensa heapen, och då hamnar vi istället i en situation där fler och fler fulla GC görs (vilket ger längre och längre svarstider för användarna), Genomströmningen och därmed GC Overhead ökar markant, samt hamnar vi till slut i ett läge där minnet tar slut, och vi hittar OutOfMemory exceptions i loggarna, och VM:et slutar att svara på anrop för användare (ger fel eller bara timeout) tills det har startats om. Dessa situationer blir rätt kostsamma att hantera i produktionsmiljön och de vill vi hitta tidigt så vi hinner lösa dem, alternativt planerar att hantera dem så snabbt som möjligt i produktion.
Fördelen med att analysera minnet på detta sätt är att vi har log filer som vi kan analysera i efterhand och även spara tillsammans med test resultaten för körningen, så att vi vid behov även kan göra analyser på tidigare körningar för att göra jämnförelser. Man kan med fördel även slå på GC loggningen i produktion då denna kostar väldigt lite resurser (dock lätt några gig disk space). Man kan då även jämnföra GC beteende i produktion med hur det betedde sig under prestandatester.
Analys av GC som ovan hjälper även till att svara på frågor som hur stor heap ska vi ha per VM, vilken fördelning mellan Perm, Young och Old/Tenured, vilken effekt ger parallell GC, eller olika Garbage Collectors på prestanda och svarstider, samt hur många VM ska vi ha per server för att optimalt utnyttja infrastrukturen och minnet.
Det är vid dessa tester viktigt att en virtuell användare i prestandatestet belastar systemet på rätt sätt (produktionslikt) avseende minnesutnyttjade. Det innebär bland annat att antalet sessioner, inloggningar, användande av funktioner och sessionens livstid under testet för en användare behöver stämma överens med riktiga användares beteenden så väl som möjligt.
Har ni frågor eller synpunkter eller behöver hjälp att komma igång med Java Heap GC analyser så kontakta oss gärna 🙂
