Diagnostiser almindelige runtime-problemer med hprof

Hukommelse lækker og blokerer og CPU-svin, åh min! Java-applikationsudviklere står ofte over for disse runtime-problemer. De kan være særligt skræmmende i en kompleks applikation med flere tråde, der løber gennem hundreder af tusinder af kodelinjer - et program, du ikke kan sende, fordi det vokser i hukommelsen, bliver inaktivt eller spiser flere CPU-cyklusser, end det burde.

Det er ingen hemmelighed, at Java-profileringsværktøjer har haft en lang vej til at indhente deres alternative modparter. Der findes nu mange kraftfulde værktøjer, der hjælper os med at finde de skyldige bag disse almindelige problemer. Men hvordan udvikler du tillid til din evne til at bruge disse værktøjer effektivt? Når alt kommer til alt bruger du værktøjerne til at diagnosticere kompleks adfærd, som du ikke forstår. For at sammensætte din situation er de data, der leveres af værktøjerne, forholdsvis komplekse, og de oplysninger, du ser på eller efter, er ikke altid klare.

Da jeg stod over for lignende problemer i min tidligere inkarnation som eksperimentel fysiker, oprettede jeg kontroleksperimenter med forudsigelige resultater. Dette hjalp mig med at få tillid til det målesystem, jeg brugte i eksperimenter, der genererede mindre forudsigelige resultater. Tilsvarende bruger denne artikel hprof-profileringsværktøjet til at undersøge tre enkle kontrolapplikationer, der udviser de tre almindelige problemadfærd, der er anført ovenfor. Selvom det ikke er så brugervenligt som nogle kommercielle værktøjer på markedet, er hprof inkluderet i Java 2 JDK og kan, som jeg vil demonstrere, effektivt diagnosticere denne adfærd.

Kør med hprof

Det er nemt at køre dit program med hprof. Påkald simpelthen Java-runtime med følgende kommandolinjemulighed som beskrevet i dokumentationen til JDK-værktøjet til Java-applikationsstarteren:

java -Xrunhprof [: help] [: =, ...] MyMainClass 

En liste over underoptioner er tilgængelig med [:Hjælp] den viste mulighed. Jeg genererede eksemplerne i denne artikel ved hjælp af Blackdown-porten på JDK 1.3-RC1 til Linux med følgende startkommando:

java -classic -Xrunhprof: heap = sites, cpu = samples, depth = 10, monitor = y, thread = y, doe = y MemoryLeak 

Følgende liste forklarer funktionen af ​​hver underoption, der blev brugt i den forrige kommando:

• bunke = steder: Fortæller hprof at generere stakspor, der angiver, hvor hukommelsen blev allokeret
• cpu = prøver: Fortæller hprof at bruge statistisk sampling til at bestemme, hvor CPU'en bruger sin tid
• dybde = 10: Fortæller hprof at vise stakkspor 10 niveauer dybt, højst
• monitor = y: Fortæller hprof at generere oplysninger om konfliktmonitorer, der bruges til at synkronisere arbejdet i flere tråde
• tråd = y: Fortæller hprof at identificere tråde i stakspor
• doe = y: Fortæller hprof at producere et dump af profildata ved afslutning

Hvis du bruger JDK 1.3, skal du deaktivere standard HotSpot-kompilatoren med -klassisk mulighed. HotSpot har sin egen profil, påkrævet gennem en -Xprof option, der bruger et outputformat, der er forskelligt fra det, jeg beskriver her.

Hvis du kører dit program med hprof, efterlades en fil, der hedder java.hprof.txt i din arbejdsmappe; denne fil indeholder de profileringsoplysninger, der er indsamlet, mens dit program kører. Du kan også generere et dump til enhver tid, mens dit program kører ved at trykke på Ctrl- \ i dit Java-konsolvindue på Unix eller Ctrl-Break på Windows.

Anatomi af en hprof-outputfil

En hprof-outputfil indeholder sektioner, der beskriver forskellige egenskaber ved det profilerede Java-program. Det starter med en overskrift, der beskriver dens format, som overskriften hævder kan ændres uden varsel.

Udgangsfilens tråd- og sporafsnit hjælper dig med at finde ud af, hvilke tråde der var aktive, da dit program kørte, og hvad de gjorde. Trådafsnittet indeholder en liste over alle tråde, der er startet og afsluttet i programmets levetid. Trace sektionen indeholder en liste over nummererede stak spor for nogle tråde. Disse staksporingsnumre krydsrefereres i andre filafsnit.

Afsnittene Heap Dump og Sites hjælper dig med at analysere hukommelsesforbrug. Afhængigt af bunke suboption, du vælger, når du starter den virtuelle maskine (VM), kan du få et dump af alle levende objekter i Java-bunken (bunke = dump) og / eller en sorteret liste over tildelingssteder, der identificerer de mest allokerede objekter (bunke = steder).

Afsnittene CPU-prøver og CPU-tid hjælper dig med at forstå CPU-udnyttelse; det afsnit, du får, afhænger af dit cpu suboption (cpu = prøver eller cpu = tid). CPU-prøver giver en statistisk udførelsesprofil. CPU-tid inkluderer målinger af, hvor mange gange en given metode blev kaldt, og hvor lang tid hver metode tog at udføre.

Sektionerne Monitor Time og Monitor Dump hjælper dig med at forstå, hvordan synkronisering påvirker dit programs ydeevne. Monitor Time viser, hvor meget tid dine tråde oplever strid om låste ressourcer. Monitor Dump er et øjebliksbillede af skærme, der aktuelt er i brug. Som du kan se, er Monitor Dump nyttig til at finde deadlocks.

Diagnostiser en hukommelseslækage

I Java definerer jeg en hukommelseslækage som en (normalt) utilsigtet mangel på fjernelse af kasserede objekter, så affaldssamleren ikke kan genvinde den hukommelse, de bruger. Det Hukommelsestab program i liste 1 er simpelt:

Liste 1. MemoryLeak-program

01 import java.util.Vector; 02 03 offentlig klasse MemoryLeak {04 05 offentlig statisk ugyldig hoved (String [] args) {06 07 int MAX_CONSUMERS = 10000; 08 int SLEEP_BETWEEN_ALLOCS = 5; 09 10 ConsumerContainer objectHolder = ny ConsumerContainer (); 11 12 mens (objectHolder.size () <MAX_CONSUMERS) {13 System.out.println ("Allocating object" + 14 Integer.toString (objectHolder.size ()) 15); 16 objectHolder.add (ny MemoryConsumer ()); 17 prøv {18 Thread.currentThread (). Sleep (SLEEP_BETWEEN_ALLOCS); 19} fange (InterruptedException ie) {20 // Gør intet. 21} 22} // mens. 23} // hoved. 24 25} // Slut på MemoryLeak. 26 27 / ** Navngivet containerklasse til at indeholde objektreferencer. * / 28 klasse ConsumerContainer udvider Vector {} 29 30 / ** Klasse, der bruger en fast mængde hukommelse. * / 31 klasse MemoryConsumer {32 offentlig statisk endelig int MEMORY_BLOCK = 1024; 33 public byte [] memoryHoldingArray; 34 35 MemoryConsumer () {36 memoryHoldingArray = ny byte [MEMORY_BLOCK]; 37} 38} // Afslut MemoryConsumer. 

Når programmet kører, opretter det et Forbrugercontainer objekt, og begynder derefter at oprette og tilføje MemoryConsumer objekter mindst 1 KB i størrelse til det Forbrugercontainer objekt. At holde objekterne tilgængelige gør dem utilgængelige til affaldsindsamling og simulerer en hukommelseslækage.

Lad os se på udvalgte dele af profilfilen. Sites-sektionens første par linjer viser tydeligt, hvad der sker:

SITES BEGIN (ordnet efter live bytes) man sep 3 19:16:29 2001 procent live allokeret stak klasse rang selv akkumulerer byte objs bytes objs spor navn 1 97,31% 97,31% 10280000 10000 10280000 10000 1995 [B 2 0,39% 97,69% 40964 1 81880 10 1996 [L; 3 0,38% 98,07% 40000 10000 40000 10000 1994 MemoryConsumer 4 0,16% 98,23% 16388 1 16388 1 1295 [C 5 0,16% 98,38% 16388 1 16388 1 1304 [C ... 

Der er 10.000 genstande af typen byte [] ([B i VM-tale) samt 10.000 MemoryConsumer genstande. Byte-arrays optager 10.280.000 bytes, så der er tilsyneladende overhead lige over de rå byte, som hver matrix bruger. Da antallet af tildelte objekter er lig med antallet af levende objekter, kan vi konkludere, at ingen af ​​disse objekter kunne blive indsamlet skrald. Dette er i overensstemmelse med vores forventninger.

Et andet interessant punkt: hukommelsen rapporteret at blive fortæret af MemoryConsumer objekter inkluderer ikke den hukommelse, der forbruges af byte-arrays. Dette viser, at vores profilværktøj ikke udsætter hierarkiske indeslutningsforhold, men snarere klassevis-statistik. Dette er vigtigt at forstå, når du bruger hprof til at lokalisere en hukommelseslækage.

Hvor kom disse utætte byte-arrays nu fra? Bemærk, at MemoryConsumer objekter og byte-array referencespor 1994 og 1995 i det følgende sporingsafsnit. Se, disse spor fortæller os, at MemoryConsumer objekter blev oprettet i Hukommelsestab klassens hoved () metode, og at byte-arrays blev oprettet i konstruktøren (() metode i VM-speak). Vi har fundet vores hukommelseslækage, linjenumre og alt:

TRACE 1994: (thread = 1) MemoryLeak.main (MemoryLeak.java:16) TRACE 1995: (thread = 1) MemoryConsumer. (MemoryLeak.java:36) MemoryLeak.main (MemoryLeak.java:16) 

Diagnostiser en CPU-hog

I liste 2 er a BusyWork klasse har hver trådkald en metode, der regulerer, hvor meget tråden fungerer ved at variere dens søvntid mellem anfald af udførelse af CPU-intensive beregninger:

Liste 2. CPUHog-program

01 / ** Hovedklasse til kontroltest. * / 02 offentlig klasse CPUHog {03 offentlig statisk ugyldig hoved (String [] args) {04 05 Tråd sludret, workingStiff, workaholic; 06 slouch = ny Slouch (); 07 workingStiff = ny WorkingStiff (); 08 arbejdsnarkoman = ny Workaholic (); 09 10 slouch.start (); 11 workingStiff.start (); 12 workaholic.start (); 13} 14} 15 16 / ** Lav CPU-udnyttelsestråd. * / 17 klasse Slouch udvider tråd {18 public Slouch () {19 super ("Slouch"); 20} 21 offentlig ugyldig kørsel () {22 BusyWork.slouch (); 23} 24} 25 26 / ** Medium CPU-udnyttelsestråd. * / 27 klasse WorkingStiff udvider tråd {28 offentlig WorkingStiff () {29 super ("WorkingStiff"); 30} 31 public void run () {32 BusyWork.workNormally (); 33} 34} 35 36 / ** Høj CPU-udnyttelsestråd. * / 37 klasse Workaholic udvider tråd {38 offentlig Workaholic () {39 super ("Workaholic"); 40} 41 public void run () {42 BusyWork.workTillYouDrop (); 43} 44} 45 46 / ** Klasse med statiske metoder til at forbruge forskellige mængder 47 * CPU-tid. * / 48 klasse BusyWork {49 50 offentlig statisk int callCount = 0; 51 52 offentlig statisk ugyldig slouch () {53 int SLEEP_INTERVAL = 1000; 54 computeAndSleepLoop (SLEEP_INTERVAL); 55} 56 57 offentligt statisk ugyldigt arbejde Normalt () {58 int SLEEP_INTERVAL = 100; 59 computeAndSleepLoop (SLEEP_INTERVAL); 60} 61 62 offentlig statisk ugyldig workTillYouDrop () {63 int SLEEP_INTERVAL = 10; 64 computeAndSleepLoop (SLEEP_INTERVAL); 65} 66 67 privat statisk ugyldig computeAndSleepLoop (int sleepInterval) {68 int MAX_CALLS = 10000; 69 mens (callCount <MAX_CALLS) {70 computeAndSleep (sleepInterval); 71} 72} 73 74 privat statisk ugyldig computeAndSleep (int sleepInterval) {75 int COMPUTATIONS = 1000; 76 dobbelt resultat; 77 78 // Beregn. 79 callCount ++; 80 for (int i = 0; i <COMPUTATIONS; i ++) {81 result = Math.atan (callCount * Math.random ()); 82} 83 84 // Søvn. 85 prøv {86 Thread.currentThread (). Sleep (sleepInterval); 87} fange (InterruptedException ie) {88 // Gør intet. 89} 90 91} // Afslut computeAndSleep. 92} // Afslut BusyWork. 

Der er tre tråde - Workaholic, WorkingStiffog Slouch - hvis arbejdsetik varierer efter størrelsesorden, at dømme efter det arbejde, de vælger at udføre. Undersøg profilens CPU-prøver sektion vist nedenfor. De tre højest rangerede spor viser, at CPU'en brugte det meste af sin tid på at beregne tilfældige tal og buetangenser, som vi kunne forvente:

CPU-PRØVER BEGIN (total = 935) Tirsdag 4. september 20:44:49 2001 rang selv akkumuleringssporingsmetode 1 39,04% 39,04% 365 2040 java / util / Tilfældig. Næste 2 26,84% 65,88% 251 2042 java / util / Tilfældig. næsteDobbelt 3 10,91% 76,79% 102 2041 java / lang / StrictMath.atan 4 8,13% 84,92% 76 2046 BusyWork.computeAndSleep 5 4,28% 89,20% 40 2050 java / lang / Math.atan 6 3,21% 92,41% 30 2045 java / lang / Matematik tilfældig 7 2,25% 94,65% 21 2051 java / lang / Matematik tilfældig 8 1,82% 96,47% 17 2044 java / util / Tilfældig næste 9 1,50% 97,97% 14 2043 java / util / Tilfældig næste Dobbelt 10 0,43% 98,40% 4 2047 BusyWork.computeAndSleep 11 0,21% 98,61% 2 2048 java / lang / StrictMath.atan 12 0,11% 98,72% 1 1578 java / io / BufferedReader.readLine 13 0,11% 98,82% 1 2054 java / lang / Tråd. Sove 14 0,11% 98,93% 1 1956 java / sikkerhed / PermissionCollection.setReadOnly 15 0,11% 99,04% 1 2055 java / lang / Thread.sleep 16 0,11% 99,14% 1 1593 java / lang / String.valueOf 17 0,11% 99,25% 1 2052 java / lang / Matematik tilfældig 18 0,11% 99,36% 1 2049 java / util / Random.nextDouble 19 0,11% 99,47% 1 2031 BusyWork.computeAndSleep 20 0.11% 99.57% 1 1530 sun / io / CharToByteISO8859_1.convert ... 

Bemærk, at opkald til BusyWork.computeAndSleep () metode optager 8,13 procent, 0,43 procent og 0,11 procent for Workaholic, WorkingStiffog Slouch tråde, henholdsvis. Vi kan fortælle, hvilke tråde disse er ved at undersøge de spor, der henvises til i CPU-prøver-sektionens sporkolonne ovenfor (rangerer 4, 10 og 19) i følgende sporingsafsnit: