java -Xprof profiler

Zpracovala: Marta Václavíková
Vedoucí projektu, korektury, závěrečná revize: Pavel Herout

Volba -Xprof programu java spouští mimo jiné profiler. To je program, který pomáhá určit, kde zkoumaný program tráví nejvíce času.
Pro správnou činnost využívá program java technologii HotSpot. HotSpot běží pokaždé zároveň se spuštěným programem (vláknem), profiler vypíše na obrazovku po skončení programu (vlákna) informace o běhu programu.

Obsah

• Syntaxe
• Popis profileru
• Popis výstupu profileru
• Příklad použítí profileru
• Zdroje

Syntaxe

java -Xprof soubor_class

Popis profileru

Profiler se spouští pomocí volby -Xprof, u které je uváděno, že se jedná o nestandardní parametr příkazu java, který se může změnit bez upozornění v dalších verzích.
(Je to pravděpodobně alibistické varování, protože v posledních verzích SDK vždy byl a je i v nejnovější JKD1.5.0.)

Pozor na skutečnost, že se zkoumá využití procesoru (CPU) (tedy hlavně rychlost běhu programu), ne paměť (tj. paměťové nároky programu).

Způsob profilace

Pravidelně zkoumá runtime zásobník (běžící metody). Intervaly mezi kontrolou zásobníku jsou v porovnání s aktivitami zkoumaného programu dostatečně dlouhé, takže časové poměry běhu programu jsou narušeny pouze velmi málo. Navíc není zásobník zkoumán celý, jen metoda na vrcholu (právě běžící), což je další urychlení.

Na tento profiler je třeba pohlížet jako na pomocný a jednoduchý, ale snadno dostupný prostředek, který poskytne pouze základní informaci. Pro skutečně detailní prověření programu je pak vhodné použít specializovaný nástroj (např. Borland Optimizeit.)

Důvody omezeného použití profileru

• každé vlákno je profilováno odděleně, neexistuje kombinovaná informace o běhu aplikace
• je identifikována pouze vrchní metoda ze zásobníku, není zde žádná informace o kontextu volání metod
• je profilováno jen vykonávání metod, ne vytváření objektů, garbage collection, problémy vláken
• JVM musí obsahovat HotSpot (což je ale v novějších verzích SDK samozřejmostí)

Nejčastější použití je při profilace jednoduchých aplikací.

Popis výstupu profileru

Profiler popisuje metody, které jsou nejvíce používány během života vlákna.

• interpretované (interpreted) - metody vykonávané interpretem bytecodu
• kompilované (compiled) - metody překládané kompilátorem z bytecodu do strojového kódu
• stub metody (které se při pokusech dosud nikdy nepodařilo nasimulovat, takže je ani nelze dost dobře popsat ;-))

Metody jsou vypisovány podle druhů v oddělených odstavcích. Ve výpisu nemusí být uvedeny všechny typy metod.

Každý výpis daného druhu metody je uveden ve dvou sloupečcích. V prvním sloupci jsou uvedeny dané metody, ve druhém sloupečku jsou "native" metody volané danými metodami. Poslední řádka ukazuje podíl všech metod na celkovém času běhu programu.

Na konci výpisu jsou uvedeny informace, jak dlouho je vlákno blokováno a čas strávený voláním metod.

Příklad použití příkazu -Xprof při ladění kódu

V příkladu je uvedena metoda vypocet2(), která zabírá nejvíce času běhu programu.

Zdrojový kód testované třídy:

public class TestProfileru {
   public static void vypocet1() {
      int celkem = 0;
      for(int i=0; i < 1000; i++){
         celkem += i;	
      }
      System.out.println("Suma 1 = " + celkem);
    }
  public static void vypocet2() {
      int celkem = 0;
      for(int i=0; i < 10000000; i++){
        celkem += i;	
      }
      System.out.println("Suma 2 = " + celkem);
   }	
   public static void main(String[] args) {
      vypocet1();
      vypocet2();
      vypocet1();
   }
}

Po spuštění přeložené třídy příkazem java -Xprof TestProfileru se vypíší následující informace:

Z výstupu je vidět, že metoda vypocet1() je natolik málo využívaná (pouhých 11.1 % času), že optimalizátoru HotSpot nestála za to, aby ji kompiloval.
To je v přímém protikladu s časově náročnou metodou vypocet2(), která spotřebovala více než polovinu času výpočtu (55.6 % času) a proto ji HotSpot převedl do strojového kódu, optimalizoval a spouštěl jako kompilovanou.
O přesnosti zkoumání si můžeme učinit představu z řádky Flat profile of 0.23 secs (9 total ticks): main
která nám říká, že profiler v průběhu výpočtu trvajícím 0,23 sekund provedl celkem 9 měření. (To je v naprostém souladu s tvrzením, že profiler zatěžuje výpočet opravdu minimálně.)

Po opětovném spuštění (ale s využitím technologie HotSpot server) se vypíše:

Zde je vidět, že přesnost výsledků klesla, protože profiler provedl jen 5 měření. Výpočet byl časově tak krátký, že se Hotspot ani nenamáhal s optimalizací či kompilováním.

Poznámka:
Může se stát, že spustí-li se jedna aplikace naprosto stejným příkazem několikrát, struktury výpisů se budou lišit. Zaznamenané metody bývají různé, stejně jako jejich procentuální podíl, protože profiler zkoumá vrchol zásobníku v různém čase. Ostatní informace jako blokování vlákna, čas volání metod jsou ve výpisu uvedeny jen v jiném pořadí.

Zdroje

http://www.javaperformancetuning.com

http://java.sun.com/docs/books/performance/1st_edition/html/JPAppHotspot.fm.html