La oss utforske tråddumper og analysen av dem.
Vi skal se på hvordan tråddumper bidrar til å avdekke problemer, samt noen analyseverktøy som kan være nyttige.
Hva er en tråd?
En prosess er et aktivt dataprogram som kjører i datamaskinens minne. Den kan utføres av en eller flere prosessorer. Prosessen er representert i minnet med viktig data som lagringsplasser for variabler, filhåndtak, programteller, registre og signaler, blant annet.
En prosess kan bestå av flere lette underprosesser som kalles tråder. Dette muliggjør parallellitet, hvor en prosess deles opp i flere tråder. Dette forbedrer ytelsen. Alle trådene innenfor en prosess deler samme minneområde og er gjensidig avhengige.
Tråddumper
Når en prosess er i gang, kan vi observere den aktuelle utførelsestilstanden til trådene i prosessen ved hjelp av tråddumper. En tråddump utgjør et øyeblikksbilde av alle aktive tråder på et gitt tidspunkt mens et program kjører. Den inneholder relevant informasjon om tråden og dens nåværende tilstand.
Moderne applikasjoner benytter ofte mange tråder. Hver tråd krever visse ressurser og utfører spesifikke oppgaver relatert til prosessen. Dette kan forbedre applikasjonens ytelse da tråder kan utnytte tilgjengelige CPU-kjerner.
Det finnes likevel kompromisser. For eksempel kan det oppstå en situasjon der flere tråder ikke samarbeider effektivt, noe som kan føre til vranglås. Ved feil kan tråddumper brukes for å undersøke trådenes tilstand.
Tråddump i Java
En JVM-tråddump viser tilstanden til alle tråder som tilhører en prosess på et bestemt tidspunkt. Den inneholder trådens stabel, presentert som et stabelspor. Siden den er i ren tekst, kan innholdet lagres for senere undersøkelser. Analyse av tråddumper kan være nyttig for:
- Optimalisering av JVM-ytelse
- Optimalisering av applikasjonsytelse
- Diagnostisering av problemer, for eksempel vranglås eller trådkonkurranse
Generering av tråddumper
Det finnes ulike metoder for å generere tråddumper. Under er noen JVM-baserte verktøy som kan kjøres fra kommandolinjen (CLI-verktøy) eller /bin-mappen (GUI-verktøy) i Java-installasjonskatalogen.
La oss se nærmere på dem.
#1. jStack
Den enkleste måten å generere en tråddump på, er å bruke jStack. Dette verktøyet følger med JVM og kan brukes fra kommandolinjen. Vi trenger PID (prosess-ID) til prosessen vi ønsker å generere tråddump for. For å finne PID, kan vi bruke jps-kommandoen som vist under.
jps -l
jps viser en liste over alle Java-prosess-ID-er.
På Windows
C:\Program Files\Java\jdk1.8.0_171\bin>jps -l
47172 portal
6120 sun.tools.jps.Jps
C:\Program Files\Java\jdk1.8.0_171\bin>På Linux
[[email protected] ~]# jps -l
1088 /opt/keycloak/jboss-modules.jar
26680 /var/lib/jenkins/workspace/kyc/kyc/target/kyc-1.0.jar
7193 jdk.jcmd/sun.tools.jps.Jps
2058 /usr/share/jenkins/jenkins.war
11933 /var/lib/jenkins/workspace/admin-portal/target/portal-1.0.jar
[[email protected] ~]#
Som vi ser, får vi en liste over alle Java-prosesser som kjører. Første kolonne viser lokal VM-ID for den kjørende Java-prosessen, og andre kolonne viser navnet på applikasjonen. For å generere tråddump, bruker vi jStack-programmet med flagget «-l» som lager en fullstendig liste over tråddumpen. Vi kan også sende utdataene til en tekstfil etter eget ønske.
jstack -l 26680
[[email protected] ~]# jstack -l 26680
2020-06-27 06:04:53
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.221-b11 mixed mode):
"Attach Listener" #16287 daemon prio=9 os_prio=0 tid=0x00007f0814001800 nid=0x4ff2 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"logback-8" #2316 daemon prio=5 os_prio=0 tid=0x00007f07e0033000 nid=0x4792 waiting on condition [0x00007f07baff8000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006ca9a1fc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- None
"logback-7" #2315 daemon prio=5 os_prio=0 tid=0x00007f07e0251800 nid=0x4791 waiting on condition [0x00007f07bb0f9000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006ca9a1fc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- None
#2. jvisualvm
Jvisualvm er et GUI-verktøy som hjelper oss med å feilsøke, overvåke og profilere Java-applikasjoner. Det følger med JVM og kan startes fra /bin-mappen i Java-installasjonen. Det er intuitivt og enkelt i bruk. Blant andre funksjoner, lar det oss også ta tråddumper for en spesifikk prosess.
For å vise tråddump for en gitt prosess, kan vi høyreklikke på programmet og velge «Thread Dump» fra kontekstmenyen.
#3. jcmd
JCMD er et kommandolinjeverktøy som følger med JDK, og brukes for å sende diagnostiske kommandoer til JVM.
Det virker kun på den lokale maskinen hvor Java-applikasjonen kjører. Det kan brukes for å kontrollere Java Flight Recordings, samt diagnostisere og feilsøke JVM- og Java-applikasjoner. Vi kan bruke Thread.print kommandoen i jcmd for å få en liste over tråddumper for en bestemt prosess, angitt med PID.
Her er et eksempel på hvordan vi kan bruke jcmd:
jcmd 28036 Thread.print
C:\Program Files\Java\jdk1.8.0_171\bin>jcmd 28036 Thread.print
28036:
2020-06-27 21:20:02
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):
"Bundle File Closer" #14 daemon prio=5 os_prio=0 tid=0x0000000021d1c000 nid=0x1d4c in Object.wait() [0x00000000244ef000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Unknown Source)
at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:403)
- locked <0x000000076f380a88> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:339)
"Active Thread: Equinox Container: 0b6cc851-96cd-46de-a92b-253c7f7671b9" #12 prio=5 os_prio=0 tid=0x0000000022e61800 nid=0xbff4 waiting on condition [0x00000000243ee000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076f388188> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x0000000021a7b000 nid=0x2184 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread3" #9 daemon prio=9 os_prio=2 tid=0x00000000219f5000 nid=0x1300 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x00000000219e0000 nid=0x48f4 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x00000000219df000 nid=0xb314 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x00000000219db800 nid=0x2260 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x00000000219d9000 nid=0x125c waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x00000000219d8000 nid=0x834 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000001faf3000 nid=0x36c0 in Object.wait() [0x0000000021eae000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000076f390180> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(Unknown Source)
- locked <0x000000076f390180> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(Unknown Source)
at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)
"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000005806000 nid=0x13c0 in Object.wait() [0x00000000219af000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000076f398178> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Unknown Source)
at java.lang.ref.Reference.tryHandlePending(Unknown Source)
- locked <0x000000076f398178> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
"main" #1 prio=5 os_prio=0 tid=0x000000000570e800 nid=0xbf8 runnable [0x0000000000fec000]
java.lang.Thread.State: RUNNABLE
at java.util.zip.ZipFile.open(Native Method)
at java.util.zip.ZipFile.<init>(Unknown Source)
at java.util.zip.ZipFile.<init>(Unknown Source)
at java.util.zip.ZipFile.<init>(Unknown Source)
at org.eclipse.osgi.framework.util.SecureAction.getZipFile(SecureAction.java:307)
at org.eclipse.osgi.storage.bundlefile.ZipBundleFile.getZipFile(ZipBundleFile.java:136)
at org.eclipse.osgi.storage.bundlefile.ZipBundleFile.lockOpen(ZipBundleFile.java:83)
at org.eclipse.osgi.storage.bundlefile.ZipBundleFile.getEntry(ZipBundleFile.java:290)
at org.eclipse.equinox.weaving.hooks.WeavingBundleFile.getEntry(WeavingBundleFile.java:65)
at org.eclipse.osgi.storage.bundlefile.BundleFileWrapper.getEntry(BundleFileWrapper.java:55)
at org.eclipse.osgi.storage.BundleInfo$Generation.getRawHeaders(BundleInfo.java:130)
- locked <0x000000076f85e348> (a java.lang.Object)
at org.eclipse.osgi.storage.BundleInfo$CachedManifest.get(BundleInfo.java:599)
at org.eclipse.osgi.storage.BundleInfo$CachedManifest.get(BundleInfo.java:1)
at org.eclipse.equinox.weaving.hooks.SupplementerRegistry.addSupplementer(SupplementerRegistry.java:172)
at org.eclipse.equinox.weaving.hooks.WeavingHook.initialize(WeavingHook.java:138)
at org.eclipse.equinox.weaving.hooks.WeavingHook.start(WeavingHook.java:208)
at org.eclipse.osgi.storage.FrameworkExtensionInstaller.startActivator(FrameworkExtensionInstaller.java:261)
at org.eclipse.osgi.storage.FrameworkExtensionInstaller.startExtensionActivators(FrameworkExtensionInstaller.java:198)
at org.eclipse.osgi.internal.framework.SystemBundleActivator.start(SystemBundleActivator.java:112)
at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:815)
at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1)
at java.security.AccessController.doPrivileged(Native Method)
at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:808)
at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:765)
at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1005)
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.initWorker(EquinoxBundle.java:190)
at org.eclipse.osgi.container.SystemModule.init(SystemModule.java:99)
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle.init(EquinoxBundle.java:272)
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle.init(EquinoxBundle.java:257)
at org.eclipse.osgi.launch.Equinox.init(Equinox.java:171)
at org.eclipse.core.runtime.adaptor.EclipseStarter.startup(EclipseStarter.java:316)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:251)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:661)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:597)
at org.eclipse.equinox.launcher.Main.run(Main.java:1476)
"VM Thread" os_prio=2 tid=0x000000001fae8800 nid=0x32cc runnable
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000005727800 nid=0x3264 runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000005729000 nid=0xbdf4 runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x000000000572a800 nid=0xae6c runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x000000000572d000 nid=0x588 runnable
"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x000000000572f000 nid=0xac0 runnable
"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x0000000005730800 nid=0x380 runnable
"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x0000000005733800 nid=0x216c runnable
"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x0000000005734800 nid=0xb930 runnable
"VM Periodic Task Thread" os_prio=2 tid=0x0000000021a8d000 nid=0x2dcc waiting on condition
JNI global references: 14
C:\Program Files\Java\jdk1.8.0_171\bin>
#4. JMC
JMC står for Java Mission Control. Det er et GUI-verktøy med åpen kildekode som følger med JDK. Det brukes til å samle inn og analysere Java-applikasjonsdata.
Det kan startes fra /bin-mappen i Java-installasjonen. Java-administratorer og -utviklere bruker verktøyet for å samle detaljert lavnivåinformasjon om JVM og applikasjonens oppførsel. Det muliggjør detaljert og effektiv analyse av data samlet inn av Java Flight Recorder.
Når jmc startes, vises en liste over Java-prosesser som kjører på den lokale maskinen. Det er også mulig å koble til eksterne prosesser. For en spesifikk prosess, kan man høyreklikke og velge «Start Flight Recording», og deretter sjekke tråddumper i fanen «Threads».
#5. jconsole
jconsole er et Java Management Extension-verktøy som brukes for overvåkning og behandling.
Det inneholder også et sett forhåndsdefinerte operasjoner på JMX-agenten som brukeren kan utføre. Det lar brukeren analysere stabelsporinger av et aktivt program. Det kan startes fra /bin-mappen i Java-installasjonen.
Ved hjelp av jconsole GUI-verktøyet kan vi inspisere stabelsporingen for hver tråd når vi kobler den til en kjørende Java-prosess. I fanen «Threads» kan vi se navnet på alle aktive tråder. For å avdekke vranglås, kan vi klikke på «Detect Deadlock» nederst til høyre i vinduet. Hvis en vranglås finnes, vises den i en ny fane; ellers vil det meldes at det ikke er en vranglås.
#6. ThreadMxBean
ThreadMXBean er grensesnittet for administrasjon av trådsystemet til Java Virtual Machine, som tilhører java.lang.Management-pakken. Det brukes hovedsakelig for å avdekke tråder som har havnet i vranglås, og for å få detaljer om disse.
Vi kan programmatisk bruke ThreadMxBean-grensesnittet for å fange tråddumper. Metoden getThreadMXBean() fra ManagementFactory brukes for å få en instans av ThreadMXBean-grensesnittet. Den returnerer antall aktive tråder, både demoner og ikke-demoner. ManagementFactory er en fabrikkklasse som skaffer de administrerte bønner for Java-plattformen.
private static String getThreadDump (boolean lockMonitors, boolean lockSynchronizers) {
StringBuffer threadDump = new StringBuffer (System.lineSeparator ());
ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean ();
for (ThreadInfo threadInfo : threadMXBean.dumpAllThreads (lockMonitors, lockSynchronizers)) {
threadDump.append (threadInfo.toString ());
}
return threadDump.toString ();
}Manuell analyse av tråddumper
Analyse av tråddumper kan være svært nyttig for å finne problemer i flertrådede prosesser. Problemer som vranglås, trådkonkurranse og overdreven CPU-bruk kan løses ved å visualisere tilstanden til individuelle tråddumper.
Optimal gjennomstrømning kan oppnås ved å korrigere tilstanden til hver tråd etter analyse av tråddumpen.
Hvis en prosess bruker mye CPU, kan vi for eksempel finne ut om en enkelt tråd er den som bruker mest CPU. Hvis det er en slik tråd, konverterer vi LWP-nummeret til et heksadesimalt tall. Deretter kan vi fra tråddumpen finne tråden med nid som er lik det tidligere funne heksadesimale tallet. Ved å se på stabelsporet til tråden, kan vi finne årsaken til problemet. La oss først finne prosess-ID-en til tråden ved hjelp av kommandoen nedenfor.
ps -mo pid,lwp,stime,tid,cpu -C java
[[email protected] ~]# ps -mo pid,lwp,stime,time,cpu -C java
PID LWP STIME TIME %CPU
26680 - Dec07 00:02:02 99.5
- 10039 Dec07 00:00:00 0.1
- 10040 Dec07 00:00:00 95.5
La oss se på en del av tråddumpen under. For å få tråddump for prosess 26680, bruk jstack -l 26680
[[email protected] ~]# jstack -l 26680
2020-06-27 09:01:29
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.221-b11 mixed mode):
"Attach Listener" #16287 daemon prio=9 os_prio=0 tid=0x00007f0814001800 nid=0x4ff2 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
.
.
.
.
.
.
.
"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f085814a000 nid=0x6840 in Object.wait() [0x00007f083b2f1000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000006c790fbd0> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
Locked ownable synchronizers:
- None
"VM Thread" os_prio=0 tid=0x00007f0858140800 nid=0x683f runnable
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f0858021000 nid=0x683b runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f0858022800 nid=0x683c runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f0858024800 nid=0x683d runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f0858026000 nid=0x683e runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007f08581a0000 nid=0x6847 waiting on condition
JNI global references: 1553
La oss nå se hva vi kan utforske ved hjelp av tråddumper. Tråddumper kan virke overveldende på grunn av mengden informasjon, men det kan være ganske enkelt å forstå hvis vi tar det stegvis. La oss begynne med første linje:
2020-06-27 09:01:29
Full thread dump Java HotSpot(TM) 64-bit server VM (25.221-b11 mixed mode):
Dette viser tidspunktet for når dumpen ble generert, og informasjon om JVM-en som ble brukt. Deretter kommer listen over tråder, hvor den første er ReferenceHandler-tråden.
Analysere blokkerte tråder
Ved analyse av tråddumplogger under, ser vi at den har avdekket tråder med status BLOKKERT, noe som gjør ytelsen til applikasjonen treg. Hvis vi finner de BLOKKERTE trådene, kan vi prøve å trekke ut informasjon om låsene trådene prøver å få tilgang til. Ved å analysere stabelsporet fra