Диагностицирайте често срещаните проблеми по време на работа с hprof

Изтичане на памет и блокировки и процесори, о! Разработчиците на Java приложения често се сблъскват с тези проблеми по време на изпълнение. Те могат да бъдат особено обезсърчаващи в сложно приложение с множество нишки, преминаващи през стотици хиляди редове код - приложение, което не можете да изпратите, защото расте в паметта, става неактивно или поглъща повече цикли на процесора, отколкото би трябвало.

Не е тайна, че инструментите за профилиране на Java са изминали дълъг път, за да настигнат своите колеги на алтернативен език. Сега съществуват много мощни инструменти, които ни помагат да проследим виновниците зад тези често срещани проблеми. Но как да развиете увереност във вашата способност да използвате ефективно тези инструменти? В края на краищата използвате инструментите за диагностика на сложно поведение, което не разбирате. За да усложните тежкото си положение, данните, предоставени от инструментите, са сравнително сложни и информацията, която търсите или търсите, не винаги е ясна.

Когато се сблъсках с подобни проблеми в предишното си превъплъщение като експериментален физик, създадох контролни експерименти с предвидими резултати. Това ми помогна да придобия увереност в системата за измерване, която използвах в експерименти, които генерираха по-малко предвидими резултати. По същия начин тази статия използва инструмента за профилиране hprof, за да изследва три прости приложения за управление, които показват трите често срещани проблемни поведения, изброени по-горе. Въпреки че не е толкова лесен за ползване, колкото някои търговски инструменти на пазара, hprof е включен в Java 2 JDK и, както ще покажа, може ефективно да диагностицира това поведение.

Стартирайте с hprof

Стартирането на вашата програма с hprof е лесно. Просто извикайте времето за изпълнение на Java със следната опция за командния ред, както е описано в документацията на инструмента JDK за стартовия панел на Java приложения:

java -Xrunhprof [: помощ] [: =, ...] MyMainClass 

Наличен е списък на подопциите с [:help]показаната опция. Генерирах примерите в тази статия, като използвах порта Blackdown на JDK 1.3-RC1 за Linux със следната команда за стартиране:

java -classic -Xrunhprof: heap = сайтове, cpu = проби, дълбочина = 10, monitor = y, thread = y, doe = y MemoryLeak 

Следващият списък обяснява функцията на всяка подопция, използвана в предишната команда:

  • heap=sites: Казва на hprof да генерира следи от стека, указващи къде е разпределена паметта
  • cpu=samples: Казва на hprof да използва статистическа извадка, за да определи къде процесорът прекарва времето си
  • depth=10: Казва на hprof да показва следи от стека най-много на 10 нива
  • monitor=y: Казва на hprof да генерира информация за монитори на спорове, използвани за синхронизиране на работата на множество нишки
  • thread=y: Казва на hprof да идентифицира нишки в следи от стека
  • doe=y: Казва на hprof да създаде дъмп от профилиращи данни при излизане

Ако използвате JDK 1.3, трябва да изключите компилатора по подразбиране HotSpot с -classicопцията. HotSpot има собствен профилир, извикан чрез -Xprofопция, която използва изходен формат, различен от този, който ще опиша тук.

Стартирането на вашата програма с hprof ще остави файл, извикан java.hprof.txtвъв вашата работна директория; този файл съдържа информацията за профилиране, събрана, докато програмата ви работи. Можете също така да генерирате дамп по всяко време, докато програмата ви работи, като натиснете Ctrl- \ в прозореца на вашата Java конзола в Unix или Ctrl-Break в Windows.

Анатомия на изходен файл hprof

Изходният файл hprof включва раздели, описващи различни характеристики на профилираната Java програма. Започва с хедър, който описва своя формат, за който хедърът твърди, че подлежи на промяна без предизвестие.

Разделите Thread and Trace на изходния файл ви помагат да разберете кои нишки са били активни, когато програмата ви се е изпълнявала и какво са правили. Разделът Thread предоставя списък на всички нишки, стартирани и прекратени по време на живота на програмата. Разделът за проследяване включва списък с номерирани проследявания на стека за някои нишки. Тези номера на проследяване на стека са препратени към други файлови раздели.

Разделите Heap Dump и Sites ви помагат да анализирате използването на паметта. В зависимост от heapизбраната от вас опция, когато стартирате виртуалната машина (VM), можете да получите дъмп на всички живи обекти в Java heap ( heap=dump) и / или сортиран списък с сайтове за разпределение, който идентифицира най-силно разпределените обекти ( heap=sites).

Разделите за процесори и раздели на процесора ви помагат да разберете използването на процесора; Разделът, който ще получите, зависи от вашата cpuопция ( cpu=samplesили cpu=time). CPU Samples предоставя статистически профил на изпълнение. Времето на процесора включва измервания на това колко пъти е бил извикан даден метод и колко време е необходимо на всеки метод за изпълнение.

Разделите Monitor Time и Monitor Dump ви помагат да разберете как синхронизацията влияе върху производителността на вашата програма. Monitor Time показва колко време вашите нишки изпитват спорове за заключени ресурси. Monitor Dump е моментна снимка на мониторите, които се използват в момента. Както ще видите, Monitor Dump е полезен за намиране на задънени улици.

Диагностицирайте изтичане на памет

В Java определям изтичането на памет като (обикновено) непреднамерен провал на пренасочване на изхвърлени обекти, така че събирачът на боклук да не може да възстанови използваната от тях памет. В MemoryLeakпрограмата на Обява 1 е проста:

Листинг 1. Програма MemoryLeak

01 импортиране java.util.Vector; 02 03 публичен клас MemoryLeak {04 05 public static void main (String [] args) {06 07 int MAX_CONSUMERS = 10000; 08 int SLEEP_BETWEEN_ALLOCS = 5; 09 10 ConsumerContainer objectHolder = нов ConsumerContainer (); 11 12 while (objectHolder.size () <MAX_CONSUMERS) {13 System.out.println ("Разпределяне на обект" + 14 Integer.toString (objectHolder.size ()) 15); 16 objectHolder.add (нов MemoryConsumer ()); 17 опитайте {18 Thread.currentThread (). Sleep (SLEEP_BETWEEN_ALLOCS); 19} catch (InterruptedException т.е.) {20 // Не правете нищо. 21} 22} // докато. 23} // главен. 24 25} // Край на MemoryLeak. 26 27 / ** Именуван клас контейнер за съхраняване на препратки към обекти. * / 28 клас ConsumerContainer разширява Vector {} 29 30 / ** Клас, който консумира фиксирано количество памет. * / 31 клас MemoryConsumer {32 публичен статичен финал int MEMORY_BLOCK = 1024;33 публичен байт [] memoryHoldingArray; 34 35 MemoryConsumer () {36 memoryHoldingArray = нов байт [MEMORY_BLOCK]; 37} 38} // Край на MemoryConsumer.

Когато програмата се стартира, тя създава ConsumerContainerобект, след което започва да създава и добавя MemoryConsumerобекти с размер поне 1 KB към този ConsumerContainerобект. Поддържането на обектите достъпни ги прави недостъпни за събиране на боклук, симулирайки изтичане на памет.

Нека да разгледаме избрани части от файла на профила. Първите няколко реда на раздела Сайтове ясно показват какво се случва:

САЙТОВЕ НАЧАЛО (подредени по байтове на живо) Пон. Септември 3 19:16:29 2001 процента на живо разпределен стек клас ранг самостоятелно натрупване байтове objs байтове objs име на проследяване 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 Потребител на памет 4 0,16% 98,23% 16388 1 16388 1 1295 [C 5 0,16% 98,38% 16388 1 16388 1 1304 [C ...

Има 10 000 обекта от тип byte[]( [Bвъв VM-говорене), както и 10 000 MemoryConsumerобекта. Байтовите масиви заемат 10 280 000 байта, така че очевидно има режийни точно над суровите байтове, които всеки масив консумира. Тъй като броят на разпределените обекти е равен на броя на живите обекти, можем да заключим, че нито един от тези обекти не може да бъде събран. Това е в съответствие с нашите очаквания.

Друг интересен момент: паметта, за която се съобщава, че се консумира от MemoryConsumerобектите, не включва паметта, консумирана от байтовите масиви. Това показва, че нашият инструмент за профилиране не излага йерархични връзки за ограничаване, а по-скоро статистика по клас. Това е важно да се разбере, когато се използва hprof за определяне на изтичане на памет.

Сега, откъде идват тези течащи байтови масиви? Забележете, че MemoryConsumerобектите и байтовите масиви се позовават на следи 1994и 1995в следващия раздел Trace Ето, тези следи ни казват, че MemoryConsumerобектите са създадени в метода на MemoryLeakкласа main()и че байтовите масиви са създадени в конструктора ( ()метод в VM-speak). Открихме изтичането на паметта, номерата на редовете и всичко:

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

Диагностицирайте процесора

В листинг 2 BusyWorkклас има метод за извикване на всяка нишка, който регулира колко работи нишката, като променя времето си на заспиване между пристъпите на извършване на интензивни изчисления на процесора:

Listing 2. CPUHog program

01 /** Main class for control test. */ 02 public class CPUHog { 03 public static void main(String[] args) { 04 05 Thread slouch, workingStiff, workaholic; 06 slouch = new Slouch(); 07 workingStiff = new WorkingStiff(); 08 workaholic = new Workaholic(); 09 10 slouch.start(); 11 workingStiff.start(); 12 workaholic.start(); 13 } 14 } 15 16 /** Low CPU utilization thread. */ 17 class Slouch extends Thread { 18 public Slouch() { 19 super("Slouch"); 20 } 21 public void run() { 22 BusyWork.slouch(); 23 } 24 } 25 26 /** Medium CPU utilization thread. */ 27 class WorkingStiff extends Thread { 28 public WorkingStiff() { 29 super("WorkingStiff"); 30 } 31 public void run() { 32 BusyWork.workNormally(); 33 } 34 } 35 36 /** High CPU utilization thread. */ 37 class Workaholic extends Thread { 38 public Workaholic() { 39 super("Workaholic"); 40 } 41 public void run() { 42 BusyWork.workTillYouDrop(); 43 } 44 } 45 46 /** Class with static methods to consume varying amounts 47 * of CPU time. */ 48 class BusyWork { 49 50 public static int callCount = 0; 51 52 public static void slouch() { 53 int SLEEP_INTERVAL = 1000; 54 computeAndSleepLoop(SLEEP_INTERVAL); 55 } 56 57 public static void workNormally() { 58 int SLEEP_INTERVAL = 100; 59 computeAndSleepLoop(SLEEP_INTERVAL); 60 } 61 62 public static void workTillYouDrop() { 63 int SLEEP_INTERVAL = 10; 64 computeAndSleepLoop(SLEEP_INTERVAL); 65 } 66 67 private static void computeAndSleepLoop(int sleepInterval) { 68 int MAX_CALLS = 10000; 69 while (callCount < MAX_CALLS) { 70 computeAndSleep(sleepInterval); 71 } 72 } 73 74 private static void computeAndSleep(int sleepInterval) { 75 int COMPUTATIONS = 1000; 76 double result; 77 78 // Compute. 79 callCount++; 80 for (int i = 0; i < COMPUTATIONS; i++) { 81 result = Math.atan(callCount * Math.random()); 82 } 83 84 // Sleep. 85 try { 86 Thread.currentThread().sleep(sleepInterval); 87 } catch (InterruptedException ie) { 88 // Do nothing. 89 } 90 91 } // End computeAndSleep. 92 } // End BusyWork. 

There are three threads -- Workaholic, WorkingStiff, and Slouch -- whose work ethics vary by orders of magnitude, judging by the work they choose to do. Examine the profile's CPU Samples section shown below. The three highest ranked traces show that the CPU spent most of its time calculating random numbers and arc tangents, as we would expect:

CPU SAMPLES BEGIN (total = 935) Tue Sep 4 20:44:49 2001 rank self accum count trace method 1 39.04% 39.04% 365 2040 java/util/Random.next 2 26.84% 65.88% 251 2042 java/util/Random.nextDouble 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/Math.random 7 2.25% 94.65% 21 2051 java/lang/Math.random 8 1.82% 96.47% 17 2044 java/util/Random.next 9 1.50% 97.97% 14 2043 java/util/Random.nextDouble 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/Thread.sleep 14 0.11% 98.93% 1 1956 java/security/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/Math.random 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 ... 

Имайте предвид, че повиквания към BusyWork.computeAndSleep()метода заемат 8,13%, 0,43% и 0,11% за Workaholic, WorkingStiffи Slouchнишките, съответно. Можем да разберем кои нишки са това, като изследваме следите, посочени в колоната за проследяване на раздела CPU Samples по-горе (класи 4, 10 и 19) в следващия раздел Trace: