Diagnostiquer les problèmes d'exécution courants avec hprof

Des fuites de mémoire et des blocages et des porcs CPU, oh là là! Les développeurs d'applications Java sont souvent confrontés à ces problèmes d'exécution. Ils peuvent être particulièrement intimidants dans une application complexe avec plusieurs threads exécutant des centaines de milliers de lignes de code - une application que vous ne pouvez pas expédier car elle grandit en mémoire, devient inactive ou engloutit plus de cycles de processeur qu'elle ne le devrait.

Ce n'est un secret pour personne que les outils de profilage Java ont eu un long chemin à parcourir pour rattraper leurs homologues de langue alternative. De nombreux outils puissants existent maintenant pour nous aider à retrouver les coupables derrière ces problèmes courants. Mais comment développer la confiance en votre capacité à utiliser efficacement ces outils? Après tout, vous utilisez les outils pour diagnostiquer un comportement complexe que vous ne comprenez pas. Pour aggraver votre situation, les données fournies par les outils sont raisonnablement complexes et les informations que vous recherchez ou que vous recherchez ne sont pas toujours claires.

Face à des problèmes similaires lors de ma précédente incarnation en tant que physicien expérimental, j'ai créé des expériences de contrôle avec des résultats prévisibles. Cela m'a aidé à gagner en confiance dans le système de mesure que j'ai utilisé dans des expériences qui ont généré des résultats moins prévisibles. De même, cet article utilise l'outil de profilage hprof pour examiner trois applications de contrôle simples qui présentent les trois problèmes courants répertoriés ci-dessus. Bien qu'il ne soit pas aussi convivial que certains outils commerciaux sur le marché, hprof est inclus avec le JDK Java 2 et, comme je vais le démontrer, peut diagnostiquer efficacement ces comportements.

Courir avec hprof

Exécuter votre programme avec hprof est facile. Appelez simplement l'environnement d'exécution Java avec l'option de ligne de commande suivante, comme décrit dans la documentation de l'outil JDK pour le lanceur d'application Java:

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

Une liste de sous-options est disponible avec l' [:help]option affichée. J'ai généré les exemples de cet article en utilisant le port Blackdown du JDK 1.3-RC1 pour Linux avec la commande de lancement suivante:

java -classic -Xrunhprof: tas = sites, cpu = échantillons, profondeur = 10, moniteur = y, thread = y, doe = y MemoryLeak 

La liste suivante explique la fonction de chaque sous-option utilisée dans la commande précédente:

  • heap=sites: Indique à hprof de générer des traces de pile indiquant où la mémoire a été allouée
  • cpu=samples: Indique à hprof d'utiliser l'échantillonnage statistique pour déterminer où le processeur passe son temps
  • depth=10: Indique à hprof d'afficher les traces de pile de 10 niveaux de profondeur, au plus
  • monitor=y: Indique à hprof de générer des informations sur les moniteurs de contention utilisés pour synchroniser le travail de plusieurs threads
  • thread=y: Indique à hprof d'identifier les threads dans les traces de pile
  • doe=y: Demande à hprof de produire un vidage des données de profilage à la sortie

Si vous utilisez JDK 1.3, vous devez désactiver le compilateur HotSpot par défaut avec l' -classicoption. HotSpot a son propre profileur, appelé via une -Xprofoption, qui utilise un format de sortie différent de celui que je vais décrire ici.

L'exécution de votre programme avec hprof laissera un fichier appelé java.hprof.txtdans votre répertoire de travail; ce fichier contient les informations de profilage collectées lors de l'exécution de votre programme. Vous pouvez également générer un vidage à tout moment pendant l'exécution de votre programme en appuyant sur Ctrl- \ dans la fenêtre de votre console Java sous Unix ou Ctrl-Break sous Windows.

Anatomie d'un fichier de sortie hprof

Un fichier de sortie hprof comprend des sections décrivant diverses caractéristiques du programme Java profilé. Il commence par un en-tête qui décrit son format, dont l'en-tête prétend être sujet à changement sans préavis.

Les sections Thread et Trace du fichier de sortie vous aident à déterminer quels threads étaient actifs lors de l'exécution de votre programme et ce qu'ils ont fait. La section Thread fournit une liste de tous les threads démarrés et terminés pendant la durée de vie du programme. La section Trace comprend une liste de traces de pile numérotées pour certains threads. Ces numéros de trace de pile sont référencés dans d'autres sections de fichier.

Les sections Heap Dump et Sites vous aident à analyser l'utilisation de la mémoire. Selon la heapsous - option que vous choisissez lorsque vous démarrez la machine virtuelle (VM), vous pouvez obtenir un vidage de tous les objets actifs dans le tas Java ( heap=dump) et / ou une liste triée de sites d'allocation qui identifie les objets les plus fortement alloués ( heap=sites).

Les sections Exemples de CPU et Temps CPU vous aident à comprendre l'utilisation du CPU; la section que vous obtenez dépend de votre cpusous - option ( cpu=samplesou cpu=time). CPU Samples fournit un profil d'exécution statistique. Le temps CPU inclut des mesures du nombre de fois qu'une méthode donnée a été appelée et de la durée d'exécution de chaque méthode.

Les sections Monitor Time et Monitor Dump vous aident à comprendre comment la synchronisation affecte les performances de votre programme. Monitor Time indique la durée pendant laquelle vos threads subissent des conflits pour les ressources verrouillées. Monitor Dump est un instantané des moniteurs actuellement utilisés. Comme vous le verrez, Monitor Dump est utile pour trouver des blocages.

Diagnostiquer une fuite de mémoire

En Java, je définis une fuite de mémoire comme un échec (généralement) involontaire de déréférencement des objets ignorés afin que le garbage collector ne puisse pas récupérer la mémoire qu'ils utilisent. Le MemoryLeakprogramme du Listing 1 est simple:

Liste 1. Programme MemoryLeak

01 import java.util.Vector; 02 03 classe publique 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 = nouveau ConsumerContainer (); 11 12 while (objectHolder.size () <MAX_CONSUMERS) {13 System.out.println ("Allocating object" + 14 Integer.toString (objectHolder.size ()) 15); 16 objectHolder.add (nouveau MemoryConsumer ()); 17 essayez {18 Thread.currentThread (). Sleep (SLEEP_BETWEEN_ALLOCS); 19} catch (InterruptedException ie) {20 // Ne rien faire. 21} 22} // pendant. 23} // main. 24 25} // Fin de MemoryLeak. 26 27 / ** Classe conteneur nommée pour contenir les références d'objets. * / 28 class ConsumerContainer étend Vector {} 29 30 / ** Classe qui consomme une quantité fixe de mémoire. * / 31 class MemoryConsumer {32 public static final int MEMORY_BLOCK = 1024;33 octets publics [] memoryHoldingArray; 34 35 MemoryConsumer () {36 memoryHoldingArray = nouvel octet [MEMORY_BLOCK]; 37} 38} // Fin de MemoryConsumer.

Lorsque le programme s'exécute, il crée un ConsumerContainerobjet, puis commence à créer et à ajouter des MemoryConsumerobjets d'au moins 1 Ko à cet ConsumerContainerobjet. Garder les objets accessibles les rend indisponibles pour le garbage collection, simulant une fuite de mémoire.

Examinons certaines parties du fichier de profil. Les premières lignes de la section Sites montrent clairement ce qui se passe:

SITES BEGIN (triés par octets actifs) Mon Sep 3 19:16:29 2001 percent live alloué stack class rank auto accum bytes objs bytes objs trace name 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 Mémoire Consommateur 4 0,16% 98,23% 16388 1 16388 1 1295 [C 5 0,16% 98,38% 16388 1 16388 1 1304 [C ...

Il existe 10 000 objets de type byte[]( [Ben langage VM) ainsi que 10 000 MemoryConsumerobjets. Les tableaux d'octets occupent 10 280 000 octets, donc apparemment il y a une surcharge juste au-dessus des octets bruts que chaque tableau consomme. Étant donné que le nombre d'objets alloués est égal au nombre d'objets vivants, nous pouvons conclure qu'aucun de ces objets n'a pu être récupéré. Ceci est conforme à nos attentes.

Autre point intéressant: la mémoire déclarée consommée par les MemoryConsumerobjets n'inclut pas la mémoire consommée par les tableaux d'octets. Cela montre que notre outil de profilage n'expose pas de relations de confinement hiérarchiques, mais plutôt des statistiques classe par classe. Ceci est important à comprendre lors de l'utilisation de hprof pour identifier une fuite de mémoire.

Maintenant, d'où viennent ces tableaux d'octets qui fuient? Notez que les MemoryConsumerobjets et les tableaux d'octets font référence aux traces 1994et 1995dans la section Trace suivante. Et voilà, ces traces nous indiquent que les MemoryConsumerobjets ont été créés dans la méthode de la MemoryLeakclasse main()et que les tableaux d'octets ont été créés dans le constructeur ( ()méthode en VM-speak). Nous avons trouvé notre fuite de mémoire, les numéros de ligne et tout:

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

Diagnostiquer un porc CPU

Dans le listing 2, une BusyWorkclasse demande à chaque thread d'appeler une méthode qui régule le fonctionnement du thread en faisant varier son temps de veille entre les périodes d'exécution de calculs gourmands en CPU:

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 ... 

Notez que les appels à la BusyWork.computeAndSleep()méthode prennent 8,13 pour cent, 0,43 pour cent et 0,11 pour cent pour les Workaholic, WorkingStiffet les Slouchdiscussions, respectivement. Nous pouvons dire de quels threads il s'agit en examinant les traces référencées dans la colonne de trace de la section CPU Samples ci-dessus (rangs 4, 10 et 19) dans la section Trace suivante: