Explicação do Arquivo de Saída do HPROF

A primeira seção do arquivo contém informações gerais de cabeçalho, como uma explicação das opções, copyright e renúncias de responsabilidade. Um resumo de cada encadeamento é exibido em seguida.

É possível ver a saída após usar HPROF com um programa simples, mostrado da seguinte forma. Este programa de teste cria e executa dois encadeamentos para um tempo curto. Da saída, é possível ver que os dois encadeamentos chamados apples e oranges foram criados após o encadeamento main gerado pelo sistema. Ambos os encadeamentos terminam antes do encadeamento main. Para cada encadeamento, seu endereço, identificador, nome e nome do grupo de encadeamentos são exibidos. É possível ver a ordem na qual os encadeamentos iniciam e terminam.

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)

A seção de saída de rastreio contém informações regulares de rastreio de pilha. A espessura de cada rastreio pode ser configurada e cada rastreio tem um ID exclusivo:

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)

Um rastreio contém diversos quadros e cada quadro contém o nome da classe, o nome do método, o nome do arquivo e o número da linha. No exemplo anterior, é possível ver que o número da linha 1188 de Locale.java (que está no método toLowerCase) foi chamado a partir da função convertOldISOCodes() na mesma classe. Esses rastreios são úteis para seguir o caminho de execução de seu programa. Se a opção monitor for configurada, um dump do monitor será produzido, semelhante a este exemplo:

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

A primeira parte do dump do monitor contém uma lista de encadeamentos, incluindo a entrada de rastreio que identifica o código que o encadeamento executou. Há também um status de encadeamento para cada encadeamento em que:

R — Executável (o encadeamento pode ser executado quando tem chance)
S — Suspenso (o encadeamento foi suspenso por outro encadeamento)
CW — Espera de Condição (o encadeamento está aguardando)
MW — Espera do Monitor (o monitor está esperando)

Em seguida, há uma lista de monitores juntamente com seus proprietários e uma indicação de se há algum encadeamento esperando nos mesmos.

O Heapdump é a próxima seção. Essas informações contêm uma lista das diferentes áreas de memória e mostra como elas são alocadas:

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 informa que memória está sendo alocada para uma classe. O número hexadecimal que segue é o endereço onde essa memória está alocada.

Em seguida, está o nome da classe seguido por uma referência de rastreio. Use essas informações para efetuar referência cruzada da saída de rastreio e ver quando a classe é chamada. Se você se referir a esse rastreio específico, poderá obter o número da linha da instrução que orienta a criação desse objeto. Os endereços das constantes nessa classe também são exibidos e, no exemplo anterior, o endereço da definição de classe para a superclasse. Ambas as classes são um filho da mesma superclasse (com endereço 11504e8). Verificando ainda mais a saída, é possível ver essa definição de classe e o nome. É a classe Object (uma classe da qual toda classe herda). A JVM carrega a hierarquia inteira da superclasse antes de poder usar uma subclasse. Assis, definições de classe para todas as classes sempre estão presentes. Há também entradas para Objetos (OBJ) e Matrizes (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)

Se você configurar a opção heap como sites ou all, obterá uma lista de cada área de armazenamento alocada por seu código. O parâmetro all combina dump e sites. Essa lista é ordenada iniciando com os sites que alocam a maior parte da memória:

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

Neste exemplo, Trace 300055 alocou 5,27% da memória total alocada. Essa porcentagem acaba sendo 49192 bytes.

A opção cpu fornece informações de criação de perfil sobre o processador. Se a opção cpu for configurada para amostras, a saída conterá os resultados das amostras periódicas obtidas durante a execução do código. Em cada amostra, o caminho do código que está sendo processado é registrado e um relatório é produzido, semelhante 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

Você pode ver que bigMethod() foi responsável por 76,28% do tempo de execução do processador e estava sendo executado 501 vezes das 714 amostras. Se você usar os IDs de rastreio, poderá ver a rota exata que levou à chamada desse método.