Explicación del archivo de salida de HPROF

La primera parte del archivo contiene datos de cabecera generales como, por ejemplo, una explicación de las opciones, el copyright y las declaraciones de limitación de responsabilidad. A continuación aparece un resumen de cada hebra.

Puede ver la salida después de utilizar HPROF con un programa simple, que aparece de la siguiente forma. Este programa de prueba crea y ejecuta dos hebras durante un breve período de tiempo. En la salida, puede ver que se han creado dos hebras denominadas apples y luego oranges después de la hebra main generada por el sistema. Ambas hebras finalizan antes de la hebra de main. Para cada hebra, se muestran su dirección, identificador, nombre y nombre de grupo de hebras. Puede ver el orden en el que se inician y finalizan las hebras.

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 sección de salida de la hebra contiene información normal sobre el rastreo de la pila. La profundidad de cada rastreo se puede establecer y cada rastreo tiene un ID único:

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)

Un rastreo contiene diversos marcos, y cada marco contiene el nombre de clase, nombre de método, nombre de archivo y número de línea. En el examen anterior, puede ver que el número de línea 1188 de Locale.java (que está en el método toLowerCase) ha sido llamado desde la función convertOldISOCodes() de la misma clase. Estos rastreos son útiles a la hora de seguir la vía de acceso de ejecución del programa. Si establece la opción de supervisor, se produce un volcado de supervisor similar a este ejemplo:

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 primera parte del volcado de supervisor contiene una lista de hebras, que incluye la entrada de rastreo que identifica el código que ejecutó la hebra. También hay un estado de hebra para cada hebra, donde:

R (Runnable): Ejecutable (la hebra puede ejecutarse cuando tenga oportunidad)
S (Suspended): Suspendida (la hebra ha sido suspendida por otra hebra)
CW (Condition Wait): Condición de espera (la hebra está esperando)
MW (Monitor Wait): Espera de supervisor (el supervisor está esperando)

A continuación se muestra una lista de supervisores junto con sus propietarios y una indicación de si hay alguna hebra en espera en ellos.

El Heapdump es la siguiente sección. Esta información contiene una lista de las diferentes áreas de memoria, y muestra cómo se asignan:

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 le notifica que se está asignando memoria para una clase. El número hexadecimal que lo sigue es la dirección a la que se asigna dicha memoria.

A continuación está el nombre de clase seguido de una referencia de rastreo. Utilice esta información como referencia cruzada de la salida de rastreo y vea cuándo se llama a la clase. Si hace referencia a ese rastreo en particular, puede obtener el número de línea de la instrucción que le llevó a la creación de este objeto. Las direcciones de las constantes de esta clase también aparecen y, en el ejemplo anterior, la dirección de la definición de clase de la superclase. Ambas clases son un hijo de la misma superclase (con la dirección 11504e8). Si observa más la salida, podrá ver dicho nombre y definición de clase. Es la clase de objeto (una clase de la que se hereda cada clase). La JVM carga toda la jerarquía de superclases antes de utilizar una subclase. Por tanto, las definiciones de clase de todas las superclases siempre están presentes. También hay entradas para objetos (OBJ) y matrices (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 establece la opción heap en sites o all, obtendrá una lista de cada área de almacenamiento asignada por su código. El parámetro all combina dump y sites. Esta lista está ordenada empezando por los sitios que asignan más memoria:

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

En este ejemplo, el rastreo 300055 asignó 5,27% de la memoria asignada total. Este porcentaje es igual a 49192 bytes.

La opción cpu le ofrece información de perfiles sobre el procesador. Si cpu está establecida en samples, la salida contendrá los resultados de muestreos periódicos realizados durante la ejecución del código. En cada muestreo, se registra la vía de acceso procesada y se produce un informe similar a:

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

Puede ver que bigMethod() fue responsable del 76,28% del tiempo de ejecución del procesador y se ejecutó 501 veces cada 714 muestreos. Si utiliza los ID de rastreo, podrá ver la ruta exacta que llevó a que se llamase a este método.