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
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
11. Repositář se zdrojovými kódy všech demonstračních i testovacích příkladů
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í a 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:
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:
# | Zdrojový soubor/skript | Umístění souboru v repositáři |
---|---|---|
1 | ArrayTest1.java | http://icedtea.classpath.org/people/ptisnovs/jvm-tools/file/83f13c381bc0/jit/ArrayTest1.java |
2 | ArrayTest2.java | http://icedtea.classpath.org/people/ptisnovs/jvm-tools/file/83f13c381bc0/jit/ArrayTest2.java |
3 | ArrayTest3.java | http://icedtea.classpath.org/people/ptisnovs/jvm-tools/file/83f13c381bc0/jit/ArrayTest3.java |
12. Odkazy na Internetu
- Open Source ByteCode Libraries in Java
http://java-source.net/open-source/bytecode-libraries - ASM Home page
http://asm.ow2.org/ - Seznam nástrojů využívajících projekt ASM
http://asm.ow2.org/users.html - ObjectWeb ASM (Wikipedia)
http://en.wikipedia.org/wiki/ObjectWeb_ASM - Java Bytecode BCEL vs ASM
http://james.onegoodcookie.com/2005/10/26/java-bytecode-bcel-vs-asm/ - BCEL Home page
http://commons.apache.org/bcel/ - Byte Code Engineering Library (před verzí 5.0)
http://bcel.sourceforge.net/ - Byte Code Engineering Library (verze >= 5.0)
http://commons.apache.org/proper/commons-bcel/ - BCEL Manual
http://commons.apache.org/bcel/manual.html - Byte Code Engineering Library (Wikipedia)
http://en.wikipedia.org/wiki/BCEL - BCEL Tutorial
http://www.smfsupport.com/support/java/bcel-tutorial!/ - Bytecode Engineering
http://book.chinaunix.net/special/ebook/Core_Java2_Volume2AF/0131118269/ch13lev1sec6.html - Bytecode Outline plugin for Eclipse (screenshoty + info)
http://asm.ow2.org/eclipse/index.html - Javassist
http://www.jboss.org/javassist/ - Byteman
http://www.jboss.org/byteman - Java programming dynamics, Part 7: Bytecode engineering with BCEL
http://www.ibm.com/developerworks/java/library/j-dyn0414/ - The JavaTM Virtual Machine Specification, Second Edition
http://java.sun.com/docs/books/jvms/second_edition/html/VMSpecTOC.doc.html - The class File Format
http://java.sun.com/docs/books/jvms/second_edition/html/ClassFile.doc.html - javap – The Java Class File Disassembler
http://docs.oracle.com/javase/1.4.2/docs/tooldocs/windows/javap.html - javap-java-1.6.0-openjdk(1) – Linux man page
http://linux.die.net/man/1/javap-java-1.6.0-openjdk - Using javap
http://www.idevelopment.info/data/Programming/java/miscellaneous_java/Using_javap.html - Examine class files with the javap command
http://www.techrepublic.com/article/examine-class-files-with-the-javap-command/5815354 - aspectj (Eclipse)
http://www.eclipse.org/aspectj/ - Aspect-oriented programming (Wikipedia)
http://en.wikipedia.org/wiki/Aspect_oriented_programming - AspectJ (Wikipedia)
http://en.wikipedia.org/wiki/AspectJ - EMMA: a free Java code coverage tool
http://emma.sourceforge.net/ - Cobertura
http://cobertura.sourceforge.net/ - jclasslib bytecode viewer
http://www.ej-technologies.com/products/jclasslib/overview.html