Låt oss utforska tråddumpar och metoder för att analysera dem.
Vi kommer också att undersöka hur de underlättar identifieringen av problem samt presentera några analysverktyg som kan vara användbara.
Vad är en tråd?
En process representerar ett datorprogram som laddas in i minnet och körs. Den kan drivas av en eller flera processorer. I minnet beskrivs en process med väsentlig information såsom lagring av variabler, filreferenser, programräknare, register och signaler.
En process kan delas upp i flera lättviktsprocesser, kallade trådar. Detta möjliggör parallellitet, där en process delas upp i flera trådar, vilket i sin tur leder till förbättrad prestanda. Trådar inom samma process delar samma minnesutrymme och är beroende av varandra.
Tråddumpar
Under en process körning kan vi observera det aktuella körningstillståndet för processens trådar med hjälp av tråddumpar. En tråddump ger en ögonblicksbild av alla trådar som är aktiva vid ett givet tillfälle under ett programs körning. Denna ögonblicksbild inkluderar relevant data om trådarna och deras aktuella status.
Moderna applikationer använder ofta ett stort antal trådar. Varje tråd kräver resurser och utför specifika uppgifter i samband med processen. Användningen av trådar kan optimera prestandan i applikationen genom att utnyttja tillgängliga CPU-kärnor.
Men det finns kompromisser. Ibland kan flera trådar ha svårigheter att koordinera med varandra, vilket kan leda till så kallade dödlägen. Vid fel kan tråddumpar användas för att detaljstudera trådarnas aktuella tillstånd.
Tråddumpar i Java
En JVM-tråddump (Java Virtual Machine) är en lista över alla trådar som ingår i processen vid ett specifikt tillfälle och deras tillstånd. Den innehåller information om trådarnas stack, presenterad som en stackspårning. Eftersom informationen är i klartext kan den sparas för framtida analys. Analys av tråddumpar kan hjälpa till att:
- Optimera JVM-prestanda.
- Optimera applikationsprestanda.
- Diagnostisera problem, som dödlägen eller trådkonflikter.
Skapa tråddumpar
Det finns flera metoder för att skapa tråddumpar. Här presenteras några JVM-baserade verktyg som kan köras antingen från kommandoraden/terminalen (CLI-verktyg) eller via /bin-mappen (GUI-verktyg) i Java-installationskatalogen.
Låt oss utforska dem.
#1. jStack
Det enklaste sättet att skapa en tråddump är genom att använda jStack. jStack ingår i JVM och kan användas via kommandoraden. För att göra detta behöver vi PID (process-ID) för processen som vi vill generera tråddumpen för. PID kan erhållas med kommandot jps enligt följande:
jps -l
Kommandot jps listar alla aktiva Java-process-ID:n.
På Windows
C:Program FilesJavajdk1.8.0_171bin>jps -l
47172 portal
6120 sun.tools.jps.Jps
C:Program FilesJavajdk1.8.0_171bin>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] ~]#
Här visas en lista över alla Java-processer som körs. Kolumn ett innehåller det lokala VM-ID:t och kolumn två visar applikationsnamnet. För att generera tråddumpen används jStack-programmet med flaggan –l, vilket resulterar i en detaljerad utskrift av dumpen. Outputen kan också sparas i en valfri textfil.
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 är ett grafiskt användargränssnittsverktyg för felsökning, övervakning och profilering av Java-applikationer. Verktyget ingår i JVM och kan startas från /bin-katalogen i Java-installationen. Det är intuitivt och användarvänligt. Jvisualvm erbjuder, bland andra funktioner, möjligheten att fånga tråddumpar för en given process.
För att granska tråddumpen för en specifik process, högerklicka på applikationen och välj ”Thread Dump” från kontextmenyn.
#3. jcmd
JCMD är ett kommandoradsverktyg som levereras med JDK och används för att skicka diagnostiska kommandon till JVM. Det fungerar enbart på den lokala maskinen där Java-applikationen körs. JCMD kan användas för att kontrollera Java Flight Recordings, diagnostisera och felsöka JVM- och Java-applikationer. Kommandot Thread.print kan användas för att erhålla en tråddump för en specifik process som anges av PID.
Här följer ett exempel på användning av jcmd:
jcmd 28036 Thread.print
C:Program FilesJavajdk1.8.0_171bin>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 FilesJavajdk1.8.0_171bin>#4. JMC
JMC, förkortning för Java Mission Control, är ett öppen källkodsbaserat GUI-verktyg som ingår i JDK för att samla in och analysera data från Java-applikationer. Verktyget startas från /bin-mappen i Java-installationen. Det används av Java-administratörer och utvecklare för att samla in detaljerad lågnivåinformation om JVM:s och applikationens beteende. Det möjliggör effektiv analys av data som samlas in av Java Flight Recorder.
När JMC startas visas en lista över de Java-processer som körs på den lokala datorn. Fjärranslutning är också möjlig. För en specifik process kan du högerklicka och välja ”Start Flight Recording”, och sedan kontrollera tråddumparna i fliken ”Trådar”.
#5. jconsole
jconsole är ett Java Management Extension-verktyg som används för hantering och övervakning. Det innehåller en uppsättning fördefinierade operationer på JMX-agenten som användaren kan utföra. Verktyget tillåter användaren att upptäcka och analysera stackspår för ett liveprogram. jconsole kan startas från /bin-mappen i Java-installationen.
Med hjälp av jconsole GUI-verktyget kan vi granska stackspårningen för varje tråd efter anslutning till en pågående Java-process. I fliken ”Trådar” visas namnen på alla aktiva trådar. För att identifiera dödlägen, klicka på ”Detect Deadlock” längst ner till höger i fönstret. Om ett dödläge påträffas visas det i en ny flik, annars indikeras att inga blockerade lås hittats.
#6. ThreadMxBean
ThreadMXBean är ett gränssnitt för hantering av trådsystem i Java Virtual Machine, och tillhör paketet java.lang.Management. Det används huvudsakligen för att identifiera trådar som fastnat i dödlägen och för att erhålla information om dem.
Genom att använda ThreadMxBean kan tråddumparna fångas programmatiskt. Metoden getThreadMXBean() i ManagementFactory används för att erhålla en instans av ThreadMXBean-gränssnittet. Detta returnerar antalet aktiva trådar, både demon- och icke-demontrådar. ManagementFactory är en fabriksklass för att erhålla hanterade bönor (managed beans) för 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 analys av tråddumpar
Analys av tråddumpar är ett värdefullt sätt att lokalisera problem i processer med flera trådar. Problem som dödlägen, låskonflikter och överdriven CPU-användning kan identifieras genom att studera de individuella trådarnas tillstånd.
Genom att analysera tråddumpen och korrigera eventuella problem i trådarnas status, kan applikationens maximala prestanda uppnås.
Om en process exempelvis konsumerar mycket CPU-kraft, kan det undersökas om det är en enskild tråd som står för merparten av användningen. Om en sådan tråd identifieras, omvandlas dess LWP-nummer till ett hexadecimalt värde. Därefter kan tråden identifieras i tråddumpen, genom att söka efter tråden vars nid (native thread ID) motsvarar det erhållna hexadecimala värdet. Med hjälp av stackspårningen för tråden kan den specifika problemorsaken lokaliseras. Process-ID för tråden kan erhållas med följande kommando:
ps -mo pid,lwp,stime,time,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
Låt oss granska följande tråddump. För att hämta tråddumpen för processen med ID 26680, används kommandot: 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
Låt oss utforska hur tråddumpar kan användas. Innehållet kan vara omfattande, men om det undersöks stegvis blir förståelsen enklare. Den första raden visar den tidpunkt då dumpen genererades och information om den använda JVM:
2020-06-27 09:01:29
Full tråddump Java HotSpot(TM) 64-bitars server VM (25.221-b11 blandat läge):
Listan över trådar visas sedan, med ReferenceHandler-tråden först.
Analys av blockerade trådar
Tråddumpningsloggarna kan hjälpa till att identifiera trådar med status ”BLOCKED” som kan orsaka att applikationen körs långsamt. Genom att lokalisera dessa ”BLOCKED” trådar, kan man identifiera de lås som trådarna försöker erhålla. Analys av stackspårningen för den tråd som håller låset kan leda till en lösning av problemet.
[[email protected] ~]# jstack -l 26680
.
.
.
.
" DB-Processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x0