Pohled pod kapotu JVM – základy optimalizace aplikací naprogramovaných v Javě (2)

Pavel Tišnovský 17. 9. 2013

V dnešní části seriálu o programovacím jazyce Java i o virtuálním stroji Javy se již podruhé budeme zabývat způsobem optimalizace aplikací naprogramovaných v Javě. Velký vliv na výkonnost aplikací běžících v JVM mají JIT (Just-In-Time) překladače, takže se dnes seznámíme se základy jejich nastavování a sledování.

Obsah

1. Role JIT překladače na výkonnost aplikací naprogramovaných v Javě

2. Jednoduchý benchmark – vytvoření a naplnění pole celých čísel

3. Doba běhu benchmarku pro režim interpretru, JIT překladače typu klient a JIT překladače typu server

4. Je JIT překladač typu server vždy nejvýhodnější?

5. Práh při němž se spustí JIT překlad

6. Nastavení prahu, při němž se spustí JIT překlad

7. Několik možností sledování JIT překladu

8. Použití volby -XX:+PrintCompilation

9. Použití volby -XX:+LogCompilation

10. Využití nástroje jstat

11. Repositář se zdrojovými kódy všech demonstračních i testovacích příkladů

12. Odkazy na Internetu

1. Role JIT překladače na výkonnost aplikací naprogramovaných v Javě

V předchozí části tohoto seriálu jsme si řekli, jakým způsobem (resp. přesněji řečeno na jakých úrovních) je možné provádět optimalizaci aplikací naprogramovaných v Javě. Na nejvyšší úrovni lze provádět optimalizace samotných algoritmů (vylepšení časové či prostorové složitosti, podpora pro více vláken atd.), dále je možné vyladit JIT překladač, správce paměti a v neposlední řadě je možné v některých případech nezanedbatelně zvýšit výkonnost aplikací některými nízkoúrovňovými optimalizacemi. V odůvodněných případech je dokonce možné „rezignovat“ na to, aby celá aplikace byla naprogramována jen a pouze v Javě a napsat část aplikace například v C či C++ – Javovská část a C/C++ část spolu budou komunikovat přes rozhraní JNI (Java Native Interface), které je sice navržené poněkud nešikovně (prý naschvál, aby vývojáři JNI používali skutečně jen v nejnutnějších případech :-), ale pracuje spolehlivě a nezávisle na použité architektuře a operačním systému.

Dnes si řekneme základní informace o tom, jakým způsobem pracují takzvané JIT (Just-In-Time) překladače, protože právě volba vhodného JIT překladače a nastavení jeho parametrů mohou mít nezanedbatelný vliv na to, jak se bude Javovská aplikace chovat. Z předchozí části již víme, že v JVM vždy existuje interpret bajtkódu a potom většinou jeden až dva typy JIT překladačů z bajtkódu do nativního kódu – takzvaný JIT klient a JIT server. Bajtkód, do něhož jsou přeložena těla jednotlivých metod, se nejprve pouze interpretuje, což je relativně pomalé, zejména v porovnání se skutečným přeloženým (kompilovaným) kódem. Právě fakt, že všechny metody jsou při spuštění JVM zpočátku interpretovány, způsobuje relativně pomalé spouštění virtuálního stroje Javy, což je patrné především při spouštění aplikací na desktopech uživatelů (u serverových aplikací je tato počáteční „zahřívací“ fáze v naprosté většině případů zanedbatelná, dokonce platí, že čím déle je kód interpretován, tím kvalitnější bude jeho překlad).

2. Jednoduchý benchmark – vytvoření a naplnění pole celých čísel

Aby bylo možné vzájemně porovnat výkonnost a účinnost interpretru i obou typů JIT překladačů, použijeme následující (velmi jednoduchý) benchmark. Ten při svém spuštění několikrát zavolá metodu ArrayTest2.test(), v níž je vytvořeno pole celých čísel s 5000 prvky, které jsou naplněny hodnotami 0..4999. Velikost tohoto pole nebyla zvolena náhodně, jak si ostatně vysvětlíme v navazujících kapitolách. Samotná metoda ArrayTest2.test() je spuštěna ve smyčce, přičemž počet opakování této smyčky je zadán při startu aplikace na příkazové řádce. Navíc se před každým spuštěním vynutí běh správce paměti a následně program počká jednu sekundu na dokončení jeho běhu. Ve skutečnosti sice není zaručeno, že GC (správce paměti) skutečně proběhne, s využitím volby -verbose:gc je ale možné se přesvědčit o tom, že v našem jednoduchém benchmarku tomu tak skutečně je:

/**
  * Velmi jednoduchy benchmark - pruchod polem
  */
public class ArrayTest2 {
    // velikost pole pouziteho v testu
    public static final int ARRAY_SIZE = 5000;
 
    public static void main(String[] args) throws InterruptedException {
        // nacist pocet opakovani testu
        final int iter = Integer.parseInt(args[0]);
 
        // priblizny celkovy cas behu testu
        // (bez GC a cekani na dokonceni GC)
        long total_time = 0;
 
        // provest zadany pocet testu
        for (int i = 0; i < iter; i++) {
            // pro jistotu nejdrive provedeme GC
            // a pockame na jeho dokonceni (nepresne!)
            System.gc();
            Thread.sleep(1000);
 
            // provest test a zmerit cas behu testu
            long t1 = System.nanoTime();
            test();
            long t2 = System.nanoTime();
            long delta_t = t2 - t1;
 
            // vypis casu pro jeden test
            System.out.format("Round #%2d  time: %,12d ns\n", i, delta_t);
 
            // vypocet celkoveho casu behu vsech testu
            total_time += delta_t;
        }
        System.out.format("Total time: %,d ns\n", total_time);
 
    }
 
    /**
      * Vlastni test, kde se prochazi polem a postupne se
      * naplnuji jednotlive prvky tohoto pole.
      */
    private static void test() {
        int[] array = new int[ARRAY_SIZE];
        final int length = array.length;
        for (int i = 0; i < length; i++) {
            array[i] = i;
        }
    }
 
}

3. Doba běhu benchmarku pro režim interpretru, JIT překladače typu klient a JIT překladače typu server

Při spuštění virtuálního stroje Javy máme možnost specifikovat, zda se má použít jen interpret, nebo jeden ze dvou JIT překladačů. K tomu slouží volby -Xint, -client a -server. Podívejme se nyní, co se stane v případě, že zvolíme pouhé jediné opakování metody ArrayTest2.test() a přitom budeme přepínat mezi interpretrem, JIT serverem a JIT klientem:

java -Xint ArrayTest2 1
Round # 0  time:      362 616 ns
Total time: 362 616 ns
 
java -client ArrayTest2 1
Round # 0  time:      379 377 ns
Total time: 379 377 ns
 
java -server ArrayTest2 1
Round # 0  time:      453 689 ns
Total time: 453 689 ns

Výsledky možná mohou být překvapivé, protože zatímco interpret a JIT client běžely přibližně stejnou dobu, u JIT serveru je doba běhu aplikace delší a nikoli kratší.

Co se stane ve chvíli, kdy se bude smyčka s benchmarkem opakovat pětkrát? Opět není problém si to vyzkoušet:

java -Xint ArrayTest2 5
Round # 0  time:      371 276 ns
Round # 1  time:      357 308 ns
Round # 2  time:      392 457 ns
Round # 3  time:      360 940 ns
Round # 4  time:      365 409 ns
Total time: 1 887 390 ns
 
java -client ArrayTest2 5
Round # 0  time:      380 495 ns
Round # 1  time:      981 688 ns
Round # 2  time:       63 696 ns
Round # 3  time:       50 845 ns
Round # 4  time:       62 857 ns
Total time: 1 539 581 ns
 
java -server ArrayTest2 5
Round # 0  time:      447 823 ns
Round # 1  time:      476 039 ns
Round # 2  time:   36 634 265 ns
Round # 3  time:       56 152 ns
Round # 4  time:       55 873 ns
Total time: 37 670 152 ns

Rychlost interpretru zůstala přibližně stejná – každá iterace proběhla za zhruba stejnou dobu, případné výchylky jsou způsobeny vnějšími vlivy (další procesy, I/O operace probíhající na pozadí…). Zajímavější je situace u JIT klienta. Tam můžeme vidět, že první běh trval zhruba stejně dlouho, jako u interpretru, druhá iterace byla znatelně delší a třetí až pátá iterace naopak mnohem rychlejší. Ve skutečnosti je tomu tak, že v první iteraci byla smyčka čistě interpretována, ve druhé iteraci se spustil JIT překlad a další iterace již probíhaly nad přeloženým kódem. Podobně je tomu o JIT serveru, až na některé rozdíly – JIT překlad byl spuštěn až ve třetí iteraci a trval výrazně delší dobu, naproti tomu již další iterace (přeložená smyčka) probíhaly nejrychleji.

Aby bylo zřejmé, že se nejedná o náhodu, zkusme si smyčku s benchmarkem zopakovat desetkrát:

java -Xint ArrayTest2 10
Round # 0  time:      364 012 ns
Round # 1  time:      358 425 ns
Round # 2  time:      359 263 ns
Round # 3  time:      363 733 ns
Round # 4  time:      362 616 ns
Round # 5  time:      358 145 ns
Round # 6  time:      359 263 ns
Round # 7  time:      360 940 ns
Round # 8  time:      362 895 ns
Round # 9  time:      359 542 ns
Total time: 3 608 834 ns
 
java -client ArrayTest2 10
Round # 0  time:      379 937 ns
Round # 1  time:    1 000 127 ns
Round # 2  time:       64 533 ns
Round # 3  time:       61 461 ns
Round # 4  time:       63 974 ns
Round # 5  time:       64 533 ns
Round # 6  time:       65 651 ns
Round # 7  time:       63 975 ns
Round # 8  time:       63 695 ns
Round # 9  time:       64 813 ns
Total time: 1 892 699 ns
 
java -server ArrayTest2 10 
Round # 0  time:      447 822 ns
Round # 1  time:      473 804 ns
Round # 2  time:   36 713 605 ns
Round # 3  time:       56 711 ns
Round # 4  time:       53 638 ns
Round # 5  time:       54 475 ns
Round # 6  time:       53 917 ns
Round # 7  time:       53 639 ns
Round # 8  time:       54 477 ns
Round # 9  time:       55 315 ns
Total time: 38 017 403 ns

Vidíme, že schéma zůstalo zachováno – interpret stále běží stejnou rychlostí 360 µs/benchmark, JIT klient první iteraci taktéž interpretoval a po překladu (trval přibližně 1ms) je již rychlost rovna 63 µs/benchmark. JIT server má sice rychlejší přeložený kód (54 µs/benchmark), ovšem taktéž výrazně delší překlad a pomalejší interpret.

Dále se zvyšující počet iterací již toto schéma nijak nenaruší:

java -Xint ArrayTest2 20
Round # 0  time:      355 352 ns
Round # 1  time:      359 822 ns
Round # 2  time:      360 940 ns
Round # 3  time:      359 543 ns
Round # 4  time:      362 057 ns
Round # 5  time:      360 662 ns
Round # 6  time:      361 498 ns
Round # 7  time:      362 616 ns
Round # 8  time:      360 381 ns
Round # 9  time:      359 822 ns
Round #10  time:      359 263 ns
Round #11  time:      362 616 ns
Round #12  time:      367 644 ns
Round #13  time:      360 102 ns
Round #14  time:      359 542 ns
Round #15  time:      360 661 ns
Round #16  time:      364 013 ns
Round #17  time:      361 778 ns
Round #18  time:      360 381 ns
Round #19  time:      360 381 ns
Total time: 7 219 074 ns
 
java -client ArrayTest2 20
Round # 0  time:      385 524 ns
Round # 1  time:      997 613 ns
Round # 2  time:       63 974 ns
Round # 3  time:       63 695 ns
Round # 4  time:       64 254 ns
Round # 5  time:       63 416 ns
Round # 6  time:       64 254 ns
Round # 7  time:       63 415 ns
Round # 8  time:       64 254 ns
Round # 9  time:       63 975 ns
Round #10  time:       53 638 ns
Round #11  time:       54 477 ns
Round #12  time:       65 092 ns
Round #13  time:       64 254 ns
Round #14  time:       64 534 ns
Round #15  time:       59 224 ns
Round #16  time:       63 695 ns
Round #17  time:       63 695 ns
Round #18  time:       65 092 ns
Round #19  time:       64 254 ns
Total time: 2 512 329 ns
 
java -server ArrayTest2 20
Round # 0  time:      445 587 ns
Round # 1  time:      482 463 ns
Round # 2  time:   36 704 106 ns
Round # 3  time:       60 063 ns
Round # 4  time:       45 536 ns
Round # 5  time:       53 917 ns
Round # 6  time:       55 034 ns
Round # 7  time:       56 432 ns
Round # 8  time:       53 359 ns
Round # 9  time:       55 034 ns
Round #10  time:       47 771 ns
Round #11  time:       57 828 ns
Round #12  time:       53 917 ns
Round #13  time:       53 080 ns
Round #14  time:       55 034 ns
Round #15  time:       56 711 ns
Round #16  time:       54 476 ns
Round #17  time:       52 521 ns
Round #18  time:       52 242 ns
Round #19  time:       55 594 ns
Total time: 38 550 705 ns

4. Je JIT překladač typu server vždy nejvýhodnější?

Připomeňme si nyní, jak vlastně JIT překladače pracují. Velmi důležité je, že oba typy překladačů se spouští až na základě požadavku interpretru – bajtkód každé metody je tedy nejdříve relativně pomalu interpretován a teprve poté, pokud se daná metoda volá často nebo pokud se některá smyčka v metodě opakuje po zadanou mez, se metoda či jen její často opakovaná smyčka přeloží. Přitom platí, že překladač typu client je navržen takovým způsobem, že velmi jednoduše a tudíž i rychle danou sekvenci instrukcí bajtkódu přeloží na základě „šablony“ obsahující (velmi zjednodušeně řečeno) sekvenci strojových instrukcí pro každou instrukci bajtkódu. Provádí se přitom je minimální množství optimalizací, takže od tohoto typu překladače nelze čekat žádné zázraky. To jsme ostatně viděli již z měření v předchozí kapitole – první běh benchmarku proběhl v režimu interpretru, poté byl proveden překlad (během druhého volání benchmarku) a následně byl spouštěn již přeložený kód.

Naproti tomu překladač typu server již dokáže provádět různé lokální i globální optimalizace a taktéž stráví větší množství času s alokací registrů mikroprocesoru pro potřeby uložení lokálních proměnných, mezivýsledků výpočtů atd. atd. Ovšem aby tento typ překladače pracoval skutečně efektivně, musí mít k dispozici větší množství informací o dynamických vlastnostech metody/smyčky – a tyto informace získá opět z interpretru. Zjednodušeně řečeno to znamená, že čím vícekrát je metoda/smyčka zpracována pomalým interpretrem, tím lepší informace má k dispozici optimalizující JIT překladač, takže se dostáváme do poněkud paradoxní situace, že pro dlouhotrvající aplikace je výhodnější, když jsou nějaký čas provozovány jen v režimu interpretru. Opět jsme to viděli v předchozí kapitole – JIT server má poněkud pomalejší a déle pracující interpret (ten totiž zaznamenává více informací), překlad taktéž trvá déle, ale výsledný přeložený kód je rychlejší, než při použití JIT klienta.

Ovšem zde se dostáváme k důležité otázce – je skutečně vždy výhodnější, aby byl použit JIT server? Zkusme si náš demonstrační příklad spustit pro sto iterací a sledovat kumulativní časy běhu jednotlivých benchmarků (tj. vlastně jak dlouho aplikace běží, pokud odečteme vliv GC):

Iter Interpret Client JIT Server JIT
1 00 359 544 0 379 378 00 463 467
2 00 719 367 1 383 137 00 940 622
3 01 081 703 1 446 274 37 659 255
4 01 445 716 1 510 808 37 713 451
5 01 806 377 1 575 341 37 771 280
6 02 165 640 1 639 874 37 829 109
7 02 524 903 1 703 569 37 873 808
8 02 890 313 1 767 265 37 931 078
9 03 248 738 1 829 564 37 987 230
10 03 609 398 1 892 142 38 042 825
11 03 972 014 1 955 837 38 100 933
12 04 330 718 2 019 812 38 156 526
13 04 692 775 2 084 066 38 216 310
14 05 052 318 2 135 749 38 271 624
15 05 415 213 2 199 724 38 328 056
16 05 775 593 2 263 977 38 386 444
17 06 134 576 2 327 113 38 435 053
18 06 494 957 2 392 205 38 489 529
19 06 856 177 2 453 945 38 542 609
20 07 128 838 2 517 082 38 597 924
21 07 489 219 2 581 616 38 655 752
22 07 848 484 2 646 149 38 708 272
23 08 125 893 2 710 123 38 762 190
24 08 485 436 2 773 260 38 816 107
25 08 845 537 2 836 955 38 873 377
26 09 204 242 2 901 768 38 927 294
27 09 565 740 2 963 787 38 980 374
28 09 928 076 3 027 203 39 035 408
29 10 287 619 3 090 339 39 091 560
30 10 648 279 3 155 152 39 145 757
31 11 011 454 3 217 171 39 199 674
32 11 370 158 3 282 263 39 253 311
33 11 731 098 3 346 797 39 311 419
34 12 091 199 3 411 052 39 365 615
35 12 455 770 3 475 585 39 419 532
36 12 815 313 3 540 118 39 472 053
37 13 174 577 3 604 092 39 529 323
38 13 541 662 3 668 067 39 582 681
39 13 902 323 3 730 924 39 636 599
40 14 175 822 3 794 619 39 690 237
41 14 535 644 3 859 431 39 748 624
42 14 894 349 3 923 406 39 803 659
43 15 256 406 3 986 263 39 858 134
44 15 616 228 4 049 958 39 911 771
45 15 977 447 4 108 905 39 967 085
46 16 336 431 4 173 718 40 020 444
47 16 700 723 4 236 574 40 076 038
48 17 060 824 4 299 711 40 130 234
49 17 420 646 4 361 730 40 187 224
50 17 781 586 4 425 145 40 242 259
51 18 143 643 4 490 237 40 295 897
52 18 503 744 4 553 652 40 350 374
53 18 863 566 4 618 464 40 407 365
54 19 223 388 4 682 159 40 458 769
55 19 586 842 4 746 133 40 515 202
56 19 947 223 4 811 226 40 568 560
57 20 307 046 4 873 803 40 625 550
58 20 669 104 4 938 057 40 680 305
59 21 031 161 5 001 194 40 732 826
60 21 394 056 5 066 286 40 790 934
61 21 754 437 5 130 820 40 845 131
62 22 114 260 5 195 073 40 899 049
63 22 476 596 5 258 768 40 952 688
64 22 836 418 5 321 905 41 008 840
65 23 197 637 5 386 717 41 062 757
66 23 557 459 5 449 854 41 114 160
67 23 919 516 5 513 829 41 168 916
68 24 286 042 5 577 525 41 224 509
69 24 645 026 5 641 220 41 277 309
70 25 007 084 5 706 033 41 330 667
71 25 369 980 5 769 448 41 384 304
72 25 729 244 5 820 013 41 441 853
73 26 091 022 5 883 708 41 494 094
74 26 450 844 5 948 521 41 547 732
75 26 814 299 6 013 334 41 605 840
76 27 174 401 6 076 749 41 652 774
77 27 535 061 6 140 444 41 707 250
78 27 895 162 6 204 699 41 760 888
79 28 257 219 6 265 879 41 814 805
80 28 617 879 6 330 133 41 872 354
81 28 977 143 6 393 548 41 925 712
82 29 337 245 6 457 802 41 972 645
83 29 702 374 6 520 379 42 020 696
84 30 061 918 6 583 515 42 076 568
85 30 422 858 6 647 770 42 133 838
86 30 782 959 6 793 877 42 189 153
87 31 145 575 6 858 131 42 246 144
88 31 506 515 6 921 547 42 305 649
89 31 866 616 6 986 080 42 353 700
90 32 226 438 7 050 893 42 411 808
91 32 589 333 7 114 868 42 466 284
92 32 951 111 7 179 680 42 524 113
93 33 310 374 7 243 934 42 578 310
94 33 672 152 7 308 188 42 633 066
95 34 033 930 7 372 722 42 688 939
96 34 393 473 7 436 696 42 744 812
97 34 759 720 7 499 274 42 799 288
98 35 119 263 7 561 293 42 854 043
99 35 482 717 7 625 546 42 906 563
100 35 842 819 7 689 241 42 954 055

Výsledky jsou pro větší názornost převedeny do grafu:

Z grafu plynou zajímavé údaje. Interpret pracuje stále stejným způsobem a čas běhu roste lineárně s počtem iterací, tedy nic překvapivého. JIT client je pro dvě iterace pomalejší než interpret (kvůli překladu), nicméně poté již interpret hravě překovává. U JIT serveru je situace odlišná – ten má sice (po překladu!) rychlejší smyčku benchmarku (menší sklon žlutého průběhu za kolenem), nicméně čas překladu je tak velký, že pro 100 iterací již JIT server nepřekoná ani pomalost interpretru! To je vhodné mít na paměti zejména při spouštění aplikací běžících po krátkou dobu.

5. Práh při němž se spustí JIT překlad

Ve třetíve čtvrté kapitole jsme viděli, že každý kód je nejdříve interpretován a teprve poté může být proveden jeho překlad. Jak však JVM určí, který kód se má přeložit? Nepřekládá se všechen kód, protože (což jsme opět viděli) je to mnohdy velmi drahá operace, jenž se někdy ani nemusí vyplatit. Podrobnosti si řekneme někdy příště (i s ukázkami zdrojových kódu Hotspotu :-) ovšem zjednodušeně řečeno je možné říci, že interpret si počítá vstupy do metod, tj. počet volání metody a taktéž si u jednotlivých smyček pamatuje celkový počet iterací. Jakmile se metoda volá velmi často, popř. pokud se u některé smyčky dosáhne určité hranice, je proveden překlad. Nicméně aktuální běh metody je stále interpretován (až do instrukce return), stejně jako aktuální iterace smyčky. Implicitně je u smyček nastavena hranice 1500 iterací (JIT client), popř. 10000 iterací (JIT server). Tyto údaje lze získat následovně:

java -client -XX:+PrintFlagsFinal -version |grep "intx CompileThreshold"
     intx CompileThreshold                          = 1500            {pd product}
java -server -XX:+PrintFlagsFinal -version |grep "intx CompileThreshold"
     intx CompileThreshold                          = 10000           {pd product}

Nyní již začínají předchozí výsledky dávat větší smysl. JIT klient provedl první volání benchmarku v režimu interpretru, kdy se dosáhl mezní počet iterací. Proto došlo k překladu testovací metody (druhý běh byl znatelně pomalejší) a další iterace již volaly přeložený kód. Naproti tomu u JIT serveru byl překlad odložen až na třetí iteraci, a to proto, že velikost pole a tím pádem i počet opakování vnitřní smyčky byl nastaven na 5000.

6. Nastavení prahu, při němž se spustí JIT překlad

Práh, při němž se spustí JIT překlad, je dokonce možné řídit, což se nám ještě bude v dalších částech tohoto seriálu hodit. Pro změnu hranice iterací, po jejímž dosažení se překlad spustí, se používá přepínač -XX:CompileThreshold=xxx. Podívejme se nyní, jak nastavení tohoto přepínače ovlivní místo, v němž dojde k překladu:

Překlad bude proveden ihned, již při první iteraci, navíc se přeloží mnoho dalšího kódu:

java -client -XX:CompileThreshold=1 ArrayTest2 10
Round # 0  time:    1 491 530 ns
Round # 1  time:       54 476 ns
Round # 2  time:       58 667 ns
Round # 3  time:       55 594 ns
Round # 4  time:       55 034 ns
Round # 5  time:       54 476 ns
Round # 6  time:       55 035 ns
Round # 7  time:       53 080 ns
Round # 8  time:       53 359 ns
Round # 9  time:       62 018 ns
Total time: 1 993 269 ns

Dtto, ale některé další metody jsou přeloženy později:

java -client -XX:CompileThreshold=10 ArrayTest2 10
Round # 0  time:      836 140 ns
Round # 1  time:      790 324 ns
Round # 2  time:       61 181 ns
Round # 3  time:       63 137 ns
Round # 4  time:       48 609 ns
Round # 5  time:       64 812 ns
Round # 6  time:       62 857 ns
Round # 7  time:       63 138 ns
Round # 8  time:       54 756 ns
Round # 9  time:       62 298 ns
Total time: 2 107 252 ns

Podobné předchozímu:

java -client -XX:CompileThreshold=100 ArrayTest2 10
Round # 0  time:      884 470 ns
Round # 1  time:      738 361 ns
Round # 2  time:       63 695 ns
Round # 3  time:       64 533 ns
Round # 4  time:       64 254 ns
Round # 5  time:       58 667 ns
Round # 6  time:       64 533 ns
Round # 7  time:       62 298 ns
Round # 8  time:       61 739 ns
Round # 9  time:       60 343 ns
Total time: 2 122 893 ns
java -client -XX:CompileThreshold=1000 ArrayTest2 10
Round # 0  time:      385 524 ns
Round # 1  time:      982 806 ns
Round # 2  time:       63 975 ns
Round # 3  time:       65 930 ns
Round # 4  time:       63 136 ns
Round # 5  time:       63 416 ns
Round # 6  time:       64 812 ns
Round # 7  time:       64 813 ns
Round # 8  time:       52 521 ns
Round # 9  time:       64 253 ns
Total time: 1 871 186 ns

Zde je již JIT překlad „odsunut“ dále v čase:

java -client -XX:CompileThreshold=10000 ArrayTest2 10
Round # 0  time:      377 422 ns
Round # 1  time:      378 540 ns
Round # 2  time:    2 329 904 ns
Round # 3  time:       64 813 ns
Round # 4  time:       65 650 ns
Round # 5  time:       65 092 ns
Round # 6  time:       65 930 ns
Round # 7  time:       64 534 ns
Round # 8  time:       65 371 ns
Round # 9  time:       65 651 ns
Total time: 3 542 907 ns
java -client -XX:CompileThreshold=20000 ArrayTest2 10
Round # 0  time:      386 641 ns
Round # 1  time:      381 055 ns
Round # 2  time:      383 847 ns
Round # 3  time:      381 054 ns
Round # 4  time:    2 318 172 ns
Round # 5  time:       62 019 ns
Round # 6  time:       60 343 ns
Round # 7  time:       60 901 ns
Round # 8  time:       63 416 ns
Round # 9  time:       64 814 ns
Total time: 4 162 262 ns
java -client -XX:CompileThreshold=40000 ArrayTest2 10
Round # 0  time:      380 216 ns
Round # 1  time:      386 362 ns
Round # 2  time:      381 892 ns
Round # 3  time:      381 055 ns
Round # 4  time:      428 546 ns
Round # 5  time:      292 217 ns
Round # 6  time:      386 083 ns
Round # 7  time:      381 613 ns
Round # 8  time:    2 315 657 ns
Round # 9  time:       66 489 ns
Total time: 5 400 130 ns

Nyní je hranice nastavena na tak vysokou hodnotu, že se žádný JIT ani nestihne provést:

java -client -XX:CompileThreshold=100000 ArrayTest2 10
Round # 0  time:      379 098 ns
Round # 1  time:      381 054 ns
Round # 2  time:      381 332 ns
Round # 3  time:      383 289 ns
Round # 4  time:      381 053 ns
Round # 5  time:      382 451 ns
Round # 6  time:      382 730 ns
Round # 7  time:      384 126 ns
Round # 8  time:      379 936 ns
Round # 9  time:      382 172 ns
Total time: 3 817 241 ns

7. Několik možností sledování JIT překladu

Bylo by zajisté vhodné mít k dispozici nějakou možnost sledování, kdy dojde k zavolání JIT překladače a jaké metody (či jejich části) vlastně budou přeloženy. I tuto funkci nám virtuální stroj Javy samozřejmě nabízí, a to dokonce v několika variantách, které si stručně popíšeme v navazujících kapitolách. Jen pro připomenutí si řekněme, že podobné funkce nám JVM nabízí i v oblasti sledování činnosti správce paměti, což je taktéž důležitá oblast, kterou je nutné při nasazování především dlouhotrvajících serverových aplikací monitorovat; viz též vybrané předchozí díly tohoto seriálu:

8. Použití volby -XX:+PrintCompilation

Pro postupný tisk seznamu metod, které jsou JIT překladačem kompilovány, lze využít volbu -XX:+PrintCompilation; aby ovšem byla tato volba dostupná, je ji nutné zkombinovat s volbou -XX:+UnlockDiagnosticVMOptions, která všechny „nadstandardní“ diagnostické výpisy povoluje. Podívejme se, jak vypadá výstup při použití této dvojice voleb:

java -client -XX:+UnlockDiagnosticVMOptions -XX:+PrintCompilation ArrayTest2 20
     86    1             java.lang.String::hashCode (55 bytes)
     93    2             java.lang.String::charAt (29 bytes)
     99    3             java.lang.String::indexOf (70 bytes)
   1116    4             java.lang.Object::<init> (1 bytes)
   1129    5             java.lang.String::indexOf (166 bytes)
   1132    6             sun.nio.cs.SingleByte$Decoder::decode (11 bytes)
   1134    7             java.lang.CharacterData::of (120 bytes)
   1135    8             java.lang.CharacterDataLatin1::getProperties (11 bytes)
   1136    9             java.lang.String::toLowerCase (472 bytes)
   1141   10             java.lang.Character::toLowerCase (9 bytes)
   1142   11             java.lang.CharacterDataLatin1::toLowerCase (39 bytes)
   1143   12   !         java.io.BufferedReader::readLine (304 bytes)
   1158   13             sun.nio.cs.SingleByte$Decoder::decodeArrayLoop (154 bytes)
   1162   14             java.lang.String::lastIndexOf (52 bytes)
   1163   15             java.lang.String::equals (81 bytes)
   1164   16             java.lang.AbstractStringBuilder::ensureCapacityInternal (16 bytes)
   1165   17             java.lang.AbstractStringBuilder::append (29 bytes)
   1174   18             java.io.BufferedInputStream::getBufIfOpen (21 bytes)
   1175   19  s          java.io.BufferedInputStream::read (49 bytes)
Round # 0  time:      387 200 ns
 
   2197   20             ArrayTest2::test (27 bytes)
 
Round # 1  time:    1 061 029 ns
Round # 2   3219   21     n       java.lang.System::arraycopy (0 bytes)   (static)
  time:       64 254 ns
Round # 3  time:       66 489 ns
Round # 4  time:       64 813 ns
Round # 5  time:    6264   22             java.lang.String::length (6 bytes)
      64 533 ns
Round # 6  time:       65 092 ns
Round # 7  time:       52 799 ns
Round # 8  time:       65 092 ns
Round # 9  time:       63 416 ns
Round #10  time:       65 092 ns
Round #11  time:       63 695 ns
Round #12  time:       64 813 ns
Round #13  time:       65 092 ns
  15378   23             java.util.regex.Matcher::reset (83 bytes)
Round #14  time:       65 371 ns
Round #15  time:       63 975 ns
Round #16  time:       64 813 ns
Round #17  time:       64 533 ns
Round #18  time:       64 812 ns
Round #19  time:   20447   24             java.lang.Math::min (11 bytes)
      64 812 ns
Total time: 2 601 725 ns

Z výpisu je patrné, že se kromě JIT překladu naší benchmarkové metody ArrayTest2.test() došlo i k překladu dalších metod, které se buď přímo či nepřímo v aplikaci používají.

9. Použití volby -XX:+LogCompilation

Alternativně je možné použít volbu -XX:+LogCompilation, která však neprovede tisk informací o překladu na standardní výstup, ale vytvoří namísto toho soubor pojmenovaný hotspot.log (jméno i umístění souboru je však možné změnit). V tomto souboru jsou uloženy všechny důležité informace o JIT překladači ve formě vhodné pro zpracování dalšími nástroji:

java -client -XX:CompileThreshold=20000 -XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation ArrayTest2 10

Jak je z následujícího výpisu patrné, je celý soubor uložen v XML:

<?xml version='1.0' encoding='UTF-8'?>
<hotspot_log version='160 1' process='3000' time_ms='1379194481069'>
<vm_version>
<name>
Java HotSpot(TM) Client VM
</name>
<release>
23.25-b01
</release>
<info>
Java HotSpot(TM) Client VM (23.25-b01) x86 JRE (1.7.0_25-b17), built on Jun 21 2013 13:06:48 by "java_re"
</info>
</vm_version>
<vm_arguments>
<args>
-XX:CompileThreshold=20000 -XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation
</args>
<command>
ArrayTest2 10
</command>
<launcher>
SUN_STANDARD
</launcher>
<properties>
java.vm.specification.name=Java Virtual Machine Specification
java.vm.version=23.25-b01
java.vm.name=Java HotSpot(TM) Client VM
java.vm.info=mixed mode, sharing
java.vm.specification.vendor=Oracle Corporation
java.vm.specification.version=1.7
java.vm.vendor=Oracle Corporation
sun.java.command=ArrayTest2 10
sun.java.launcher=SUN_STANDARD
</properties>
</vm_arguments>
<tty>
<writer thread='1972'/>
<make_not_compilable thread='1972' method='java/lang/invoke/CallSite setTargetNormal (Ljava/lang/invoke/MethodHandle;)V' bytes='6' count='0' iicount='0' stamp='0.045'/>
<make_not_compilable thread='1972' method='java/lang/invoke/CallSite setTargetVolatile (Ljava/lang/invoke/MethodHandle;)V' bytes='6' count='0' iicount='0' stamp='0.045'/>
<writer thread='312'/>
<thread_logfile thread='312' filename='hs_c312_pid3000.log'/>
<writer thread='1972'/>
 
<task_queued compile_id='1' method='ArrayTest2 test ()V' bytes='27' count='5' backedge_count='10000' iicount='0' stamp='5.245' comment='count' hot_count='5'/>
 
<writer thread='312'/>
 
<nmethod compile_id='1' compiler='C1' entry='0x00a00a00' size='668' address='0x00a00908' relocation_offset='208' insts_offset='248' stub_offset='504' scopes_data_offset='540' scopes_pcs_offset='584' dependencies_offset='664' oops_offset='536' method='ArrayTest2 test ()V' bytes='27' count='5' backedge_count='10000' iicount='0' stamp='5.247'/>
 
<writer thread='3800'/>
<destroy_vm stamp='10.325'/>
<tty_done stamp='10.326'/>
</tty>
<compilation_log thread='312'>
<start_compile_thread thread='312' process='3000' stamp='0.113'/>
 
<task compile_id='1' method='ArrayTest2 test ()V' bytes='27' count='5' backedge_count='10000' iicount='0' stamp='5.245'>
 
<task_done success='1' nmsize='288' count='5' backedge_count='10000' stamp='5.247'/>
</task>
</compilation_log>
<hotspot_log_done stamp='10.326'/>
</hotspot_log>

Co všechna hlášení znamenají (nmethod…) si řekneme příště.

10. Využití nástroje jstat

Další možnost, jak získat nějaké informace o JIT překladu, spočívá ve využití standardního nástroje jstat, s nímž jsme se již v tomto seriálu setkali. Tento nástroj použijeme na mírně modifikovaný benchmark nazvaný ArrayTest3. Jediný rozdíl oproti předchozímu příklad ArrayTest2 spočívá v tom, že na konci běhu benchmarku se počká na stisk klávesy:

/**
  * Velmi jednoduchy benchmark - pruchod polem
  */
public class ArrayTest3 {
    // velikost pole pouziteho v testu
    public static final int ARRAY_SIZE = 5000;
 
    public static void main(String[] args) throws InterruptedException, java.io.IOException {
        // nacist pocet opakovani testu
        final int iter = Integer.parseInt(args[0]);
 
        // priblizny celkovy cas behu testu
        // (bez GC a cekani na dokonceni GC)
        long total_time = 0;
 
        // provest zadany pocet testu
        for (int i = 0; i < iter; i++) {
            // pro jistotu nejdrive provedeme GC
            // a pockame na jeho dokonceni (nepresne!)
            System.gc();
            Thread.sleep(1000);
 
            // provest test a zmerit cas behu testu
            long t1 = System.nanoTime();
            test();
            long t2 = System.nanoTime();
            long delta_t = t2 - t1;
 
            // vypis casu pro jeden test
            System.out.format("Round #%2d  time: %,12d ns\n", i, delta_t);
 
            // vypocet celkoveho casu behu vsech testu
            total_time += delta_t;
        }
        System.out.format("Total time: %,d ns\n", total_time);
 
        // cekat na stisk klavesy
        System.in.read();
 
    }
 
    /**
      * Vlastni test, kde se prochazi polem a postupne se
      * naplnuji jednotlive prvky tohoto pole.
      */
    private static void test() {
        int[] array = new int[ARRAY_SIZE];
        final int length = array.length;
        for (int i = 0; i < length; i++) {
            array[i] = i;
        }
    }
 
}

Po překladu testovací příklad normálně spustíme:

java -client -XX:CompileThreshold=20000 ArrayTest3 10

Jakmile se objeví zpráva o celkovém času běhu, je nutné v jiném terminálu (konzoli) spustit příkaz jps a získat tak identifikátor procesu s JVM:

jps
 
3088 Jps
6502 ArrayTest3

Následně použijeme ono číslo 6502 při zavolání nástroje jstat:

widgety

jstat -compiler 6502
 
Compiled Failed Invalid   Time   FailedType FailedMethod
       1      0       0     0,00          0
 
jstat -printcompilation 6502
Compiled  Size  Type Method
       1     27    1 ArrayTest3 test

Způsob dalšího – velmi podrobného – sledování funkce JIT překladače si uvedeme příště.

11. Repositář se zdrojovými kódy všech demonstračních i testovacích příkladů

Následuje – v tomto seriálu již tradiční – kapitola s odkazy na zdrojové kódy. V následující tabulce najdete odkazy na prozatím nejnovější verze obou benchmarků i demonstračního příkladu použitého minule:

12. Odkazy na Internetu

  1. Open Source ByteCode Libraries in Java
    http://java-source.net/open-source/bytecode-libraries
  2. ASM Home page
    http://asm.ow2.org/
  3. Seznam nástrojů využívajících projekt ASM
    http://asm.ow2.org/users.html
  4. ObjectWeb ASM (Wikipedia)
    http://en.wikipedia.org/wi­ki/ObjectWeb_ASM
  5. Java Bytecode BCEL vs ASM
    http://james.onegoodcooki­e.com/2005/10/26/java-bytecode-bcel-vs-asm/
  6. BCEL Home page
    http://commons.apache.org/bcel/
  7. Byte Code Engineering Library (před verzí 5.0)
    http://bcel.sourceforge.net/
  8. Byte Code Engineering Library (verze >= 5.0)
    http://commons.apache.org/pro­per/commons-bcel/
  9. BCEL Manual
    http://commons.apache.org/bcel/ma­nual.html
  10. Byte Code Engineering Library (Wikipedia)
    http://en.wikipedia.org/wiki/BCEL
  11. BCEL Tutorial
    http://www.smfsupport.com/sup­port/java/bcel-tutorial!/
  12. Bytecode Engineering
    http://book.chinaunix.net/spe­cial/ebook/Core_Java2_Volu­me2AF/0131118269/ch13lev1sec6­.html
  13. Bytecode Outline plugin for Eclipse (screenshoty + info)
    http://asm.ow2.org/eclipse/index.html
  14. Javassist
    http://www.jboss.org/javassist/
  15. Byteman
    http://www.jboss.org/byteman
  16. Java programming dynamics, Part 7: Bytecode engineering with BCEL
    http://www.ibm.com/develo­perworks/java/library/j-dyn0414/
  17. The JavaTM Virtual Machine Specification, Second Edition
    http://java.sun.com/docs/bo­oks/jvms/second_edition/html/VMSpec­TOC.doc.html
  18. The class File Format
    http://java.sun.com/docs/bo­oks/jvms/second_edition/html/Clas­sFile.doc.html
  19. javap – The Java Class File Disassembler
    http://docs.oracle.com/ja­vase/1.4.2/docs/tooldocs/win­dows/javap.html
  20. javap-java-1.6.0-openjdk(1) – Linux man page
    http://linux.die.net/man/1/javap-java-1.6.0-openjdk
  21. Using javap
    http://www.idevelopment.in­fo/data/Programming/java/mis­cellaneous_java/Using_javap­.html
  22. Examine class files with the javap command
    http://www.techrepublic.com/ar­ticle/examine-class-files-with-the-javap-command/5815354
  23. aspectj (Eclipse)
    http://www.eclipse.org/aspectj/
  24. Aspect-oriented programming (Wikipedia)
    http://en.wikipedia.org/wi­ki/Aspect_oriented_program­ming
  25. AspectJ (Wikipedia)
    http://en.wikipedia.org/wiki/AspectJ
  26. EMMA: a free Java code coverage tool
    http://emma.sourceforge.net/
  27. Cobertura
    http://cobertura.sourceforge.net/
  28. jclasslib bytecode viewer
    http://www.ej-technologies.com/products/jclas­slib/overview.html
Našli jste v článku chybu?
Vitalia.cz: 5 důvodů, proč jet na výlov rybníka

5 důvodů, proč jet na výlov rybníka

DigiZone.cz: Světový pohár v přímém přenosu na ČT

Světový pohár v přímém přenosu na ČT

DigiZone.cz: Jaká je Swisscom TV Air Free

Jaká je Swisscom TV Air Free

Lupa.cz: Co všechno je Facebook schopný cenzurovat?

Co všechno je Facebook schopný cenzurovat?

DigiZone.cz: Digi Slovakia zařazuje stanice SPI

Digi Slovakia zařazuje stanice SPI

Lupa.cz: Blíží se konec Wi-Fi sítí bez hesla?

Blíží se konec Wi-Fi sítí bez hesla?

DigiZone.cz: Technisat připravuje trojici DAB

Technisat připravuje trojici DAB

Vitalia.cz: Voda z Vltavy před a po úpravě na pitnou

Voda z Vltavy před a po úpravě na pitnou

Podnikatel.cz: Letáky? Lidi zuří, ale ony stále fungují

Letáky? Lidi zuří, ale ony stále fungují

DigiZone.cz: Regionální tele­vize CZ vysílá "Mapu úspěchu"

Regionální tele­vize CZ vysílá "Mapu úspěchu"

DigiZone.cz: DVB-T2 ověřeno: seznam TV zveřejněn

DVB-T2 ověřeno: seznam TV zveřejněn

Vitalia.cz: Antibakteriální mýdla nepomáhají, spíš škodí

Antibakteriální mýdla nepomáhají, spíš škodí

Měšec.cz: „Ukradli“ jsme peníze z bezkontaktních karet

„Ukradli“ jsme peníze z bezkontaktních karet

Lupa.cz: Patička e-mailu závazná jako vlastnoruční podpis?

Patička e-mailu závazná jako vlastnoruční podpis?

Vitalia.cz: Tradiční čínská medicína a rakovina

Tradiční čínská medicína a rakovina

DigiZone.cz: Parlamentní listy: kde končí PR...

Parlamentní listy: kde končí PR...

Podnikatel.cz: Nemá dluhy? Zjistíte to na poště

Nemá dluhy? Zjistíte to na poště

Root.cz: Hořící telefon Samsung Note 7 zapálil auto

Hořící telefon Samsung Note 7 zapálil auto

Lupa.cz: Cimrman má hry na YouTube i vlastní doodle

Cimrman má hry na YouTube i vlastní doodle

Lupa.cz: Další Češi si nechali vložit do těla čip

Další Češi si nechali vložit do těla čip