Wyjaśnienie pliku wyjściowego HPROF

Pierwsza sekcja pliku zawiera ogólne informacje nagłówkowe, takie jak wyjaśnienie opcji, praw autorskich i zastrzeżeń. Poniżej przedstawiono podsumowanie każdego wątku.

Dane wyjściowe można zobaczyć po użyciu programu HPROF z prostym programem, pokazanego w następujący sposób. Ten program testowy tworzy i uruchamia dwa wątki na krótki czas. Na podstawie danych wyjściowych można zobaczyć, że dwa wątki o nazwie apples , a następnie oranges zostały utworzone po wygenerowanym przez system wątku main . Oba wątki kończą się przed wątkiem main . Dla każdego wątku wyświetlana jest nazwa jego adresu, identyfikatora, nazwy i grupy wątków. Istnieje możliwość wyświetlenia kolejności, w jakiej wątki zaczynają się i kończą.

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)

Sekcja Dane wyjściowe śledzenia zawiera regularne informacje o śledzeniu stosu. Głębokość każdego śledzenia może być ustawiona, a każdy ślad ma unikalny identyfikator:

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)

Dane śledzenia zawierają pewną liczbę ramek, a każda ramka zawiera nazwę klasy, nazwę metody, nazwę pliku i numer wiersza. W poprzednim przykładzie można zobaczyć, że numer wiersza 1188 z Locale.java (który znajduje się w metodzie toLowerCase ) został wywołany z funkcji convertOldISOCodes() w tej samej klasie. Te dane śledzenia są przydatne w przypadku śledzenia ścieżki wykonywania programu. Jeśli zostanie ustawiona opcja monitora, generowany jest zrzut monitora, który wygląda jak w poniższym przykładzie:

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

Pierwsza część zrzutu monitora zawiera listę wątków, w tym pozycję śledzenia, która identyfikuje kod wykonywany przez wątek. Dla każdego wątku istnieje również status wątku, w którym:

R-Runnable (Wątek jest w stanie uruchomić, gdy dany użytkownik ma szansę)
S-Zawieszone (wątek został zawieszony przez inny wątek)
CW-warunek oczekiwania (wątek oczekuje)
MW-Oczekiwanie na monitor (monitor oczekuje)

Następnie wyświetlana jest lista monitorów wraz z ich właścicielami oraz wskazanie, czy na nie czekają wątki.

The Heapdump to następna sekcja. Informacje te zawierają listę różnych obszarów pamięci i przedstawiają sposób ich przydzielania:

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 informuje, że pamięć jest przydzielana dla klasy. Numer szesnastkowy następujący po nim jest adresem, w którym przydzielana jest pamięć.

Następnie jest to nazwa klasy, po której następuje odwołanie do śledzenia. Te informacje umożliwiają odwołanie do danych wyjściowych śledzenia i informacje o tym, kiedy klasa jest wywoływana. Jeśli odwołano się do tego konkretnego śledzenia, można uzyskać numer wiersza instrukcji, która doprowadziła do utworzenia tego obiektu. Wyświetlane są także adresy stałych w tej klasie, a w poprzednim przykładzie adres definicji klasy dla nadklasy. Obie klasy są elementem potomnym tej samej nadklasy (z adresem 11504e8). Patrząc dalej za pomocą danych wyjściowych, można wyświetlić tę definicję klasy i nazwę. Jest to klasa Object (klasa, z której dziedziczy się każda klasa). Maszyna JVM ładuje całą hierarchię nadklasy, zanim będzie mogła korzystać z podklasy. Dlatego też definicje klas dla wszystkich nadklas są zawsze obecne. Istnieją również wpisy dotyczące obiektów (OBJ) i macierzowych (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)

Jeśli dla opcji sterta zostanie ustawiona wartość sites lub all , zostanie wyświetlona lista wszystkich obszarów pamięci masowej przydzielonych przez kod. Parametr all łączy w sobie dump i sites. Ta lista jest uporządkowana począwszy od ośrodków, które przydzielały najwięcej pamięci:

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

W tym przykładzie śledzenie 300055 zostało przydzielone 5.27% łącznej przydzielonej pamięci. Ta wartość procentowa jest liczbą 49192 bajtów.

Opcja cpu umożliwia profilowanie informacji o procesorze. Jeśli parametr cpu jest ustawiony na próbki, dane wyjściowe zawierają wyniki okresowych próbek pobranych w trakcie wykonywania kodu. W każdej próbce rejestrowana jest przetwarzana ścieżka kodowa, a raport jest podobny do następującego:

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

Użytkownik może sprawdzić, czy bigMethod() był odpowiedzialny za 76.28% czasu wykonywania procesora i był uruchamiany 501 razy z 714 próbek. Jeśli używane są identyfikatory śledzenia, można wyświetlić dokładną trasę, która została wywołana do wywołania tej metody.