streamalism.org

1. Áttekintés

Ebben az oktatóanyagban megnézzük, hogyan lehet bekapcsolni a részletes szemétgyűjtést egy Java alkalmazásban. Először bemutatjuk, hogy mi a részletes szemétgyűjtés, és miért lehet hasznos.

Ezután megnézünk több különböző példát, és megismerkedünk a rendelkezésre álló különböző konfigurációs lehetőségekkel. Ezenkívül arra is összpontosítunk, hogyan értelmezzük a részletes naplóink ​​kimenetét.

Ha többet szeretne megtudni a Garbage Collection-ről (GC) és a rendelkezésre álló különböző megvalósításokról, olvassa el a Java szemétgyűjtőkről szóló cikkünket.

2. Rövid bemutatás a részletes szemétgyűjtésről

Sok kérdés hangolása és hibakeresése során gyakran szükséges a részletes szemétgyűjtési naplózás bekapcsolása, különösen a memóriaproblémák. Valójában egyesek azt állítják, hogy az alkalmazás állapotának szigorú figyelemmel kísérése érdekében mindig figyelemmel kell kísérnünk a JVM szemétgyűjtési teljesítményét.

Amint látni fogjuk, a GC napló nagyon fontos eszköz az alkalmazás halmának és GC konfigurációjának lehetséges fejlesztéseinek feltárásában. Minden GC esetén a GC napló pontos adatokat szolgáltat annak eredményeiről és időtartamáról.

Idővel ezeknek az információknak az elemzése segíthet jobban megérteni alkalmazásunk viselkedését, és hangolhatja alkalmazásunk teljesítményét. Ráadásul, a legjobb halomméretek, egyéb JVM opciók és alternatív GC algoritmusok megadásával segíthet a GC gyakoriságának és a gyűjtési idők optimalizálásában.

2.1. Egyszerű Java program

Egyszerű Java programmal fogjuk bemutatni, hogyan lehet engedélyezni és értelmezni a GC naplóinkat:

public class Alkalmazás {private static Map stringContainer = new HashMap (); public static void main (String [] args) {System.out.println ("Program indítása!"); String stringWithPrefix = "stringWithPrefix"; // Töltse be a Java kupacot 3 M java.lang.String-példányokkal (int i = 0; i <3000000; i ++) {String newString = stringWithPrefix + i; stringContainer.put (newString, newString); } System.out.println ("MAP méret:" + stringContainer.size ()); // Kifejezett GC! System.gc (); // Távolítson el 2 M-t a 3 M-ből (int i = 0; i <2000000; i ++) {String newString = stringWithPrefix + i; stringContainer.remove (newString); } System.out.println ("MAP méret:" + stringContainer.size ()); System.out.println ("A program vége!"); }}

Amint a fenti példában láthatjuk, ez az egyszerű program 3 milliót tölt be Húr példányok a Térkép tárgy. Ezután kifejezetten felhívjuk a szemétszedőt a System.gc ().

Végül eltávolítunk 2 milliót a Húr példányok a Térkép. Mi is kifejezetten használjuk System.out.println hogy a kimenet értelmezése könnyebb legyen.

A következő részben megnézzük, hogyan lehet aktiválni a GC naplózást.

3. Az „egyszerű” GC naplózás aktiválása

Kezdjük azzal, hogy futtatjuk programunkat és engedélyezzük a részletes GC-t a JVM indító argumentumainkon keresztül:

-XX: + UseSerialGC -Xms1024m -Xmx1024m -verbose: gc

A fontos érv itt a -verbose: gc, amely a legegyszerűbb formájában aktiválja a szemétszállítási információk naplózását. Alapértelmezés szerint a GC naplót írják stdout és minden fiatal generációs GC-hez és minden teljes GC-hez vonalat kell kiadnia.

Példánk céljából a soros szemétszedőt, a GC legegyszerűbb megvalósítását határoztuk meg az argumentumon keresztül -XX: + UseSerialGC.

Minimális és maximális halomméretet is beállítottunk 1024 MB-ra, de természetesen vannak még több JVM-paraméterek, amelyeket hangolni lehet.

3.1. A részletes kimenet alapvető megértése

Most nézzük meg az egyszerű program kimenetét:

A program kezdete! [GC (Allocation Failure) 279616K-> 146232K (1013632K), 0.3318607 sec] [GC (Allocation Failure) 425848K-> 295442K (1013632K), 0.4266943 sec] Térképméret: 3000000 [Full GC (System.gc ()) 434341K- > 368279K (1013632K), 0.5420611 sec] [GC (Allocation Failure) 647895K-> 368280K (1013632K), 0.0075449 sec] TÉRKÉP-méret: 1000000 A program vége!

A fenti kimenetben már sok hasznos információt láthatunk arról, hogy mi folyik a JVM-en belül.

Eleinte ez a kimenet elég ijesztőnek tűnhet, de most lépjünk végig lépésről lépésre.

Először is, láthatjuk, hogy négy gyűjtésre került sor, egy Full GC-re és három tisztító fiatal generációra.

3.2. A részletes kimenet részletesebben

Bontjuk le részletesebben a kimeneti sorokat, hogy pontosan megértsük, mi történik:

1. GC vagy Teljes GC – A szemétgyűjtés típusa sem GC vagy Teljes GC kisebb vagy teljes szemétszállítás megkülönböztetésére
2. (Kiosztási hiba) vagy (System.gc ()) - A gyűjtés oka - A kiosztási hiba azt jelzi, hogy az Edenben nem maradt több hely az objektumaink kiosztására
3. 279616K-> 146232K - A GC előtt és után elfoglalt halom memória (nyíllal elválasztva)
4. (1013632K) - A kupac jelenlegi kapacitása
5. 0,3318607 mp - A GC esemény időtartama másodpercben

Így ha az első sort vesszük, 279616K-> 146232K (1013632K) azt jelenti, hogy a GC csökkentette a foglalt halom memóriát 279616K nak nek 146232K. A halom kapacitás a GC idején volt 1013632K, és a GC elvette 0.3318607 másodpercig.

Bár az egyszerű GC naplózási formátum hasznos lehet, korlátozott részleteket tartalmaz. Például nem tudjuk megmondani, hogy a GC áthelyezett-e valamilyen tárgyat a fiatalokról az öreg generációkra, vagy mekkora volt a fiatal generáció teljes mérete az egyes gyűjtemények előtt és után.

Ezért a részletes GC naplózás hasznosabb, mint az egyszerű.

4. A „részletes” GC naplózás aktiválása

A részletes GC naplózás aktiválásához használjuk az argumentumot -XX: + PrintGCDetails. Ez további részleteket fog kapni az egyes GC-kről, például:

• A fiatal és az öreg generáció mérete az egyes GC előtt és után
• Az az idő, amelybe a GC megtörténik a fiatal és az idősebb generációban
• Az összes GC-ben promóciós objektumok mérete
• A teljes kupac méretének összefoglalása

A következő példában megtudjuk, hogyan lehet még részletesebb információkat rögzíteni a naplók kombinálásával -verbose: gc ezzel az extra érvvel.

Felhívjuk figyelmét, hogy a -XX: + PrintGCDetails a flag elavult a Java 9-ben, az új egységes naplózási mechanizmus javára (erről bővebben később). Egyébként is, új megfelelője -XX: + PrintGCDetails az a -Xlog: gc * választási lehetőség.

5. A „részletes” részletes kimenet értelmezése

Futtassuk újra a mintaprogramunkat:

-XX: + UseSerialGC -Xms1024m -Xmx1024m -verbose: gc -XX: + PrintGCDetails

Ezúttal a kimenet meglehetősen bőbeszédű:

A program kezdete! [GC (Allocation Failure) [DefNew: 279616K-> 34944K (314560K), 0.3626923 sec] 279616K-> 146232K (1013632K), 0.3627492 sec] [Times: user = 0.33 sys = 0.03, real = 0.36 sec] [GC (Allocation) Meghibásodás] [DefNew: 314560K-> 34943K (314560K), 0.4589079 mp] 425848K-> 295442K (1013632K), 0.4589526 mp] [Times: felhasználó = 0.41 sys = 0.05, valós = 0.46 mp] TÉRKÉP méret: 3000000 [Teljes GC ( System.gc ()) [Tenured: 260498K-> 368281K (699072K), 0.5580183 sec] 434341K-> 368281K (1013632K), [Metaspace: 2624K-> 2624K (1056768K)], 0.5580738 sec] [Times: user = 0,50 sys = 0,06, valós = 0,56 mp] [GC (allokációs hiba) [DefNew: 279616K-> 0K (314560K), 0.0076722 mp] 647897K-> 368281K (1013632K), 0.0077169 mp] [Times: felhasználó = 0.01 sys = 0.00, valós = 0,01 mp] MAP méret: 1000000 A program vége! Heap def új generációs összesen 314560K, használt 100261K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000) eden térben 279616K, 35% használt [0x00000000c0000000, 0x00000000c61e9370, 0x00000000d1110000) űrből 34944K, 0% használt [0x00000000d3330000, 0x00000000d3330188, 0x00000000d5550000) a térben 34944K, 0% használt [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000) tenured generációs összesen 699072K, használt 368281K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000) a tér 699072K, 52% használt [0x00000000d5550000, 0x00000000ebcf65e0, 0x00000000ebcf6600, 0x0000000100000000) Metaspace használt 2637K, kapacitás 4486K, elkötelezett 4864K, fenntartva 1056768K osztályterület használt 283K, kapacitás 386K, lekötött 512K, fenntartva 1048576K

Képesnek kell lennünk az összes elem felismerésére az egyszerű GC naplóból. De több új elem van.

Most vegyük figyelembe a kimenet új elemeit, amelyeket kék színnel emelünk ki a következő szakaszban:

5.1. Egy kisebb GC értelmezése a fiatal generációban

Kezdjük az új alkatrészek elemzésével egy kisebb GC-ben:

• [GC (Allocation Failure) [DefNew: 279616K-> 34944K (314560K), 0,3626923 mp] 279616K-> 146232K (1013632K), 0,3627492 mp] [Times: felhasználó = 0,33 sys = 0,03, valós = 0,36 mp]

Mint korábban, a vonalakat is részekre bontjuk:

1. DefNew - A használt szemétgyűjtő neve. Ez a nem annyira kézenfekvő név az egyszálas, a világot megállító szemétgyűjtőt jelenti, és ezzel tisztítják a fiatal generációt
2. 279616K-> 34944K - A fiatal generáció használata gyűjtés előtt és után
3. (314560K) - A fiatal generáció teljes mérete
4. 0,3626923 mp - Az időtartam másodpercben
5. [Idők: felhasználó = 0,33 sys = 0,03, valós = 0,36 mp] - A GC esemény időtartama különböző kategóriákban mérve

Most magyarázzuk el a különböző kategóriákat:

• felhasználó - A Garbage Collector által elfogyasztott teljes CPU-idő
• sys - Az OS-hívásokban eltöltött idő vagy a rendszereseményekre való várakozás
• igazi - Ez az összes eltelt idő, beleértve a más folyamatok által használt időszeleteket is

Mivel a példánkat a soros szemétgyűjtővel használjuk, amely mindig csak egyetlen szálat használ, a valós idejű idő megegyezik a felhasználói és a rendszeridők összegével.

5.2. Teljes GC értelmezése

Ebben az utolsó előtti példában azt látjuk, hogy egy nagy gyűjtemény (Full GC) esetében, amelyet a rendszerhívásunk váltott ki, a felhasznált gyűjtőt Bérelt.

Az utolsó további információ, amelyet látunk, a Metaspace:

[Metaspace: 2624K-> 2624K (1056768K)], 0,5580738 másodperc]

Metaspace egy új memóriahely a Java 8-ban, és a natív memória területe.

5.3. Java halom bontás elemzés

A kimenet utolsó része tartalmazza a halom lebontását, beleértve a memória lábnyomának összefoglalását a memória minden részéről.

Láthatjuk, hogy az Eden tér 35% -os, míg a Tenured 52% -os. A metaadatok és osztályterek összefoglalása is szerepel.

A fenti példák közül most már pontosan megérthetjük, hogy mi történt a memóriafogyasztással a JVM-en belül a GC eseményei alatt.

6. Dátum és idő információ hozzáadása

Nincs megfelelő napló dátum és idő információ nélkül.

Ez az extra információ nagyon hasznos lehet, ha a GC naplóadatokat össze kell kapcsolnunk más forrásokból származó adatokkal, vagy egyszerűen elősegítheti a keresést.

A következő két érvet adhatjuk hozzá, amikor alkalmazásunkat futtatjuk, hogy a dátum és idő információ megjelenjen a naplóinkban:

-XX: + PrintGCTimeStamps -XX: + PrintGCDateStamps

Minden sor az abszolút dátummal és idővel kezdődik, amikor azt megírták, majd egy időbélyegző, amely tükrözi a JVM indítása óta másodpercekben eltelt valós idejét:

2018-12-11T02: 55: 23.518 + 0100: 2.601: [GC (Kiosztás ...

Felhívjuk figyelmét, hogy ezeket a hangoló zászlókat eltávolították a Java 9-ből. Az új alternatíva:

-Xlog: gc * :: idő

7. Bejelentkezés egy fájlba

Mint már láthattuk, alapértelmezés szerint a GC naplót írják stdout. Praktikusabb megoldás egy kimeneti fájl megadása.

Ezt megtehetjük az argumentum használatával -Xloggc: hol fájl a kimeneti fájl abszolút elérési útja:

-Xloggc: /path/to/file/gc.log

A többi tuningjelzőhöz hasonlóan a Java 9 is elavulta az -Xloggc jelzőt az új egységes naplózás érdekében. Pontosabban: a fájlba való bejelentkezés alternatívája a következő:

-Xlog: gc: /path/to/file/gc.log

8. Java 9: ​​Egységes JVM naplózás

A Java 9-től kezdve a GC-vel kapcsolatos tuning zászlók többsége elavult az egységes naplózási opció mellett -Xlog: gc. A –részletes: gc opció azonban továbbra is működik Java 9-ben és újabb verzióban.

Például a Java 9-től kezdődően a -verbose: gc Az új egységes naplózási rendszer zászlaja:

-Xlog: gc

Ez naplózza az összes információs szintű GC naplót a standard kimenetre. Az is használható -Xlog: gc = szintaxis a naplószint megváltoztatásához. Például az összes hibakeresési szintű napló megtekintéséhez:

-Xlog: gc = hibakeresés

Mint korábban láttuk, a kimeneti célt a -Xlog: gc =: szintaxis. Alapértelmezés szerint a Kimenet van stdout, de megváltoztathatjuk stderr vagy akár egy fájl:

-Xlog: gc = debug: file = gc.txt

Ezenkívül lehetséges még néhány mező hozzáadása a kimenethez dekorátorok segítségével. Például:

-Xlog: gc = debug :: pid, idő, üzemidő

Itt kinyomtatjuk a folyamatazonosítót, az üzemidőt és az aktuális időbélyeget minden napló utasításban.

Ha további példákat szeretne látni az egységes JVM naplózásról, olvassa el a JEP 158 szabványt.

9. A Eszköz a GC naplók elemzéséhez

Időigényes és elég fárasztó lehet a GC-naplók szövegszerkesztővel történő elemzése. A JVM verziójától és a használt GC algoritmustól függően a GC napló formátuma eltérhet.

Van egy nagyon jó, ingyenes grafikus elemző eszköz, amely elemzi a szemétszállítási naplókat, számos mutatót szolgáltat a lehetséges szemétgyűjtési problémákról, sőt lehetséges megoldásokat is kínál ezekre a problémákra.

Feltétlenül nézze meg az Universal GC Log Analyzert!

10. Következtetés

Összefoglalva, ebben az oktatóanyagban részletesen feltártuk a részletes Java-s szemétgyűjtést.

Először azzal kezdtük, hogy bemutattuk, mi a szemetes begyűjtés, és miért érdemes használni. Ezután egy egyszerű Java alkalmazás segítségével több példát is megvizsgáltunk. Azzal kezdtük, hogy a GC naplózását a legegyszerűbb formájában engedélyeztük, mielőtt több részletes példát és a kimenet értelmezését kutattuk volna.

Végül számos további lehetőséget vizsgáltunk meg az idő- és dátumadatok naplózásához és az információk naplófájlba történő írásához.

A kód példák a GitHub oldalon találhatók.