Explication du fichier de sortie HPROF

La première section du fichier contient des informations d'en-tête générales, telles que l'explication des options, le copyright et les rejets de responsabilités, Le résumé associé à chaque unité suit.

Vous pouvez afficher la sortie après avoir utilisé HPROF avec un programme simple, comme suit. Ce programme de test crée et exécute deux unités d'exécution sur une courte période. Dans la sortie, vous pouvez voir que les deux unités d'exécution appelées apples et oranges ont été créées après l'unité d'exécution main générée par le système. Les deux unités d'exécution se terminent avant l'unité d'exécution main. L'adresse, l'identificateur, le nom et le nom de groupe de l'unité d'exécution sont indiqués. Vous pouvez identifier l'ordre de début et de fin des unités d'exécution.

THREAD START (obj=11199050, id = 1, name="Signal dispatcher", group="system")
THREAD START (obj=111a2120, id = 2, name="Reference Handler", group="system")
THREAD START (obj=111ad910, id = 3, name="Finalizer", group="system")
THREAD START (obj=8b87a0, id = 4, name="main", group="main")
THREAD END (id = 4)
THREAD START (obj=11262d18, id = 5, name="Thread-0", group="main")
THREAD START (obj=112e9250, id = 6, name="apples", group="main")
THREAD START (obj=112e9998, id = 7, name="oranges", group="main")
THREAD END (id = 6)
THREAD END (id = 7)
THREAD END (id = 5)

La section de sortie de trace contient des informations de trace de pile standard. La profondeur de chaque trace peut être définie et chaque trace a un ID unique :

TRACE 5:
	java/util/Locale.toLowerCase(Locale.java:1188)
	java/util/Locale.convertOldISOCodes(Locale.java:1226)
	java/util/Locale.<init>(Locale.java:273)
	java/util/Locale.<clinit>(Locale.java:200)

Une trace contient un nombre de cadres et chaque cadre contient le nom de classe, le nom de la méthode, le nom de fichier et le numéro de ligne. Dans l'exemple précédent, vous pouvez constater que le numéro de ligne 1 188 de Locale.java (dans la méthode toLowerCase) a été appelé depuis la fonction convertOldISOCodes() dans la même classe. Ces traces sont utiles pour suivre le chemin d'exécution du programme. Si vous définissez l'option de moniteur, un vidage de moniteur similaire à l'exemple suivant est généré :

MONITOR DUMP BEGIN
    THREAD 8, trace 1, status: R
    THREAD 4, trace 5, status: CW
    THREAD 2, trace 6, status: CW
    THREAD 1, trace 1, status: R
    MONITOR java/lang/ref/Reference$Lock(811bd50) unowned
	waiting to be notified: thread 2
    MONITOR java/lang/ref/ReferenceQueue$Lock(8134710) unowned
	waiting to be notified: thread 4
    RAW MONITOR "_hprof_dump_lock"(0x806d7d0)
	owner: thread 8, entry count: 1
    RAW MONITOR "Monitor Cache lock"(0x8058c50)
	owner: thread 8, entry count: 1
    RAW MONITOR "Monitor Registry lock"(0x8058d10)
	owner: thread 8, entry count: 1
    RAW MONITOR "Thread queue lock"(0x8058bc8)
	owner: thread 8, entry count: 1
MONITOR DUMP END
MONITOR TIME BEGIN (total = 0 ms) Thu Aug 29 16:41:59 2002
MONITOR TIME END

La première partie du vidage de moniteur contient la liste des unités d'exécution, notamment l'entrée de trace qui identifie le code exécuté par l'unité d'exécution. L'état de chaque unité d'exécution est également indiqué comme suit :

R (Runnable) : l'unité d'exécution peut être exécutée lorsqu'elle le peut
S (Suspended) : l'unité d'exécution a été suspendue par une autre
CW (Condition Wait) : l'unité d'exécution attend
MW (Monitor Wait) : le moniteur d'exécution attend

Ensuite, figure la liste des moniteurs et de leurs propriétaires et des informations indiquant si des unités d'exécution y sont en attente.

La section suivante est le vidage de tas. Elle contient la liste des différentes zones de mémoire et indique la manière dont elles sont allouées :

CLS 1123edb0 (name=java/lang/StringBuffer, trace=1318)
	super		111504e8
	constant[25]	8abd48
	constant[32]	1123edb0
	constant[33]	111504e8
	constant[34]	8aad38
	constant[115]	1118cdc8
CLS 111ecff8 (name=java/util/Locale, trace=1130)
	super		111504e8
	constant[2]	1117a5b0
	constant[17]	1124d600
	constant[24]	111fc338
	constant[26]	8abd48
	constant[30]	111fc2d0
	constant[34]	111fc3a0
	constant[59]	111ecff8
	constant[74]	111504e8
	constant[102]	1124d668
	...
CLS 111504e8 (name=java/lang/Object, trace=1)
	constant[18]	111504e8

CLS indique que de la mémoire est allouée à une classe. La valeur hexadécimale qui suit est l'adresse d'allocation de la mémoire.

Ensuite, figure le nom de la classe suivie d'une référence de trace. Utilisez ces informations pour référencer la sortie de trace et déterminer quand la classe est appelée. En vous référant à cette trace, vous pouvez obtenir le numéro de ligne de l'instruction qui a généré la création de l'objet. Les adresses des constantes dans cette classe sont aussi indiquées et, dans l'exemple précédent, l'adresse de la définition de classe de la superclasse est aussi spécifiée. Les deux classes sont des enfants de la même superclasse (avec l'adresse 11504e8). Si vous analysez davantage la sortie, vous pouvez identifier la définition et le nom de la classe. Il s'agit de la classe Object (une classe dont hérite chaque classe). La machine virtuelle Java charge l'ensemble la hiérarchie de superclasses pour pouvoir utiliser une sous-classe. Ainsi, les définitions de classe de toutes les superclasses sont toujours présentes. Il existe également des entrées pour Objects (OBJ) et Arrays (ARR) :

OBJ 111a9e78 (sz=60, trace=1, class=java/lang/Thread@8b0c38)
	name		111afbf8
	group		111af978
	contextClassLoader	1128fa50
	inheritedAccessControlContext	111aa2f0
	threadLocals	111bea08
	inheritableThreadLocals	111bea08
ARR 8bb978 (sz=4, trace=2, nelems=0, elem type=java/io/ObjectStreamField@8bac80)

Si vous affectez à heap la valeur sites ou all, vous obtenez également la liste de chaque zone de mémoire allouée par le code. Le paramètre all combine dump et sites. Les sites qui allouent le plus de mémoire figurent en haut de la liste :

SITES BEGIN (ordered by live bytes) Tue Feb 06 10:54:46 2007
          percent          live          alloc'ed  stack class
 rank   self  accum     bytes objs     bytes  objs trace name
    1 20.36% 20.36%    190060   16    190060    16 300000 byte[]
    2 14.92% 35.28%    139260 1059    139260  1059 300000 char[]
    3  5.27% 40.56%     49192   15     49192    15 300055 byte[]
    4  5.26% 45.82%     49112   14     49112    14 300066 byte[]
    5  4.32% 50.14%     40308 1226     40308  1226 300000 java.lang.String
    6  1.62% 51.75%     15092  438     15092   438 300000 java.util.HashMap$Entry
    7  0.79% 52.55%      7392   14      7392    14 300065 byte[]
    8  0.47% 53.01%      4360   16      4360    16 300016 char[]
    9  0.47% 53.48%      4352   34      4352    34 300032 char[]
   10  0.43% 53.90%      3968   32      3968    32 300028 char[]
   11  0.40% 54.30%      3716    8      3716     8 300000 java.util.HashMap$Entry[]
   12  0.40% 54.70%      3708   11      3708    11 300000 int[]
   13  0.31% 55.01%      2860   16      2860    16 300000 java.lang.Object[]
   14  0.28% 55.29%      2644   65      2644    65 300000 java.util.Hashtable$Entry
   15  0.28% 55.57%      2640   15      2640    15 300069 char[]
   16  0.27% 55.84%      2476   17      2476    17 300000 java.util.Hashtable$Entry[]
   17  0.25% 56.08%      2312   16      2312    16 300013 char[]
   18  0.25% 56.33%      2312   16      2312    16 300015 char[]
   19  0.24% 56.57%      2224   10      2224    10 300000 java.lang.Class

Dans cet exemple, la trace 300055 a alloué 5,27 % du total de mémoire allouée. Ce pourcentage correspond à 49 192 octets.

L'option cpu fournit des informations de profilage sur l'UC. Si vous affectez à cpu la valeur samples, la sortie contient le résultat des échantillons périodiques générés au cours de l'exécution du code. Pour chaque échantillon, le chemin de code exécuté est enregistré et un rapport, tel que celui présenté ci-dessous, est généré :

CPU SAMPLES BEGIN (total = 714) Fri Aug 30 15:37:16 2002
rank   self  accum   count trace method
1 76.28% 76.28% 501 77 MyThread2.bigMethod
2 6.92% 83.20% 47 75 MyThread2.smallMethod
...
CPU SAMPLES END

Vous constatez que bigMethod() représente 76,28 % de l'exécution UC et que la méthode a été exécuté 501 fois sur 714 échantillons. Si vous utilisez les ID de trace, vous pouvez identifier la route exacte de l'appel de cette méthode.