Давайте розглянемо, що таке дамп потоку та як проводити його аналіз.
Також ми обговоримо, яким чином це допомагає виявляти проблеми та які аналізатори можна застосовувати.
Що таке Потік?
Процес – це комп’ютерна програма, завантажена в оперативну пам’ять комп’ютера і запущена на виконання. Він може виконуватись як одним процесором, так і набором процесорів. У пам’яті процесу зберігається важлива інформація, наприклад, сховища змінних, дескриптори файлів, лічильник команд, регістри, сигнали та інше.
Процес може складатися з багатьох легких процесів, відомих як потоки. Це сприяє досягненню паралелізму, коли процес розбивається на декілька потоків, що покращує продуктивність. Усі потоки в рамках одного процесу використовують спільний простір пам’яті і залежать один від одного.
Дампи Потоків
Під час виконання процесу, ми можемо зафіксувати поточний стан виконання його потоків за допомогою дампів потоків. Дамп потоку – це знімок усіх потоків, активних у конкретний момент виконання програми. Він містить детальну інформацію про потік і його поточний стан.
Сучасні програми зазвичай використовують кілька потоків. Кожен потік потребує певних ресурсів і виконує певні дії, пов’язані з процесом. Це може підвищити ефективність програми, оскільки потоки можуть задіювати наявні ядра ЦП.
Проте існують певні компроміси. Наприклад, іноді декілька потоків можуть погано координуватися між собою, що призводить до виникнення взаємних блокувань. Тому, у разі виникнення проблем, ми можемо використовувати дампи потоків для дослідження стану потоків.
Дамп Потоку в Java
Дамп потоку JVM – це звіт про стан всіх потоків, які є частиною процесу в певний момент часу. Він містить відомості про стек потоку у вигляді трасування стека. Оскільки дані зберігаються у текстовому форматі, їх можна зберегти для подальшого аналізу. Аналіз дампів потоків може допомогти:
- Оптимізувати продуктивність JVM
- Оптимізувати продуктивність програми
- Діагностувати проблеми, такі як взаємні блокування, змагання за ресурси потоків та інше.
Генерація Дампів Потоків
Існує кілька способів генерувати дампи потоків. Нижче наведено деякі інструменти на основі JVM, які можна запустити з командного рядка/термінала (інструменти CLI) або з каталогу /bin (інструменти з графічним інтерфейсом) папки встановлення Java.
Розглянемо їх.
#1. jStack
Найпростіший спосіб створити дамп потоку – скористатися jStack. jStack входить до складу JVM і може запускатися з командного рядка. Для цього потрібен PID процесу, для якого потрібно створити дамп потоку. Щоб отримати PID, можна використовувати команду jps, як показано нижче.
jps -l
jps виводить список усіх ідентифікаторів процесів Java.
У Windows
C:Program FilesJavajdk1.8.0_171bin>jps -l 47172 portal 6120 sun.tools.jps.Jps C:Program FilesJavajdk1.8.0_171bin>
На 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] ~]#
Як бачимо, ми отримуємо перелік запущених процесів Java. Він містить ідентифікатор локальної віртуальної машини для запущеного процесу Java та назву програми у першому та другому стовпцях відповідно. Тепер, щоб створити дамп потоку, ми використовуємо програму jStack з прапорцем –l, який створює детальний вивід дампа. Вихідні дані можна також перенаправити у текстовий файл.
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 – це інструмент з графічним інтерфейсом, який допомагає виявляти, моніторити та профілювати програми Java. Він також входить до складу JVM і може бути запущений з каталогу /bin нашої установки Java. Він інтуїтивно зрозумілий і простий у використанні. Серед інших функцій, він також дозволяє робити дампи потоків для конкретного процесу.
Щоб переглянути дамп потоку для конкретного процесу, потрібно клацнути правою кнопкою миші на програмі та вибрати “Дамп потоку” в контекстному меню.
#3. jcmd
JCMD – це утиліта командного рядка, що постачається разом із JDK та використовується для надсилання запитів діагностичних команд до JVM.
Однак, він працює лише на локальному комп’ютері, де запущена програма Java. Його можна використовувати для управління записами польотів Java, діагностики та усунення несправностей програм JVM і Java. Можна використовувати команду Thread.print jcmd, щоб отримати список дампів потоків для певного процесу, ідентифікованого за PID.
Нижче наведено приклад використання 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, або Java Mission Control, – це графічний інтерфейс з відкритим кодом, який входить до складу JDK і використовується для збору та аналізу даних програми Java.
Його можна запустити з папки /bin нашої інсталяції Java. Адміністратори та розробники Java використовують цей інструмент для збору детальної низькорівневої інформації про поведінку JVM та програм. Він забезпечує детальний та ефективний аналіз даних, зібраних Java Flight Recorder.
Після запуску JMC, можна побачити список процесів Java, що виконуються на локальному комп’ютері. Можливе і віддалене підключення. Для конкретного процесу можна натиснути правою кнопкою миші та вибрати “Почати запис польоту”, а потім переглянути дампи потоків на вкладці “Потоки”.
#5. jconsole
jconsole – це інструмент Java Management Extension, що використовується для управління та моніторингу.
Він також має набір попередньо визначених операцій з агентом JMX, які користувач може виконувати. Це дозволяє користувачеві виявляти та аналізувати трасування стека запущених програм. Його можна запустити з папки /bin нашої інсталяції Java.
Використовуючи інструмент jconsole з графічним інтерфейсом, можна перевіряти трасування стека кожного потоку при підключенні до запущеного процесу Java. На вкладці “Потік” можна побачити назви всіх запущених потоків. Для виявлення взаємних блокувань можна натиснути кнопку “Виявити тупик” у нижньому правому куті вікна. Якщо взаємне блокування буде виявлено, воно відобразиться на новій вкладці, інакше з’явиться повідомлення “Взаємне блокування не виявлено”.
#6. ThreadMxBean
ThreadMXBean – це інтерфейс для управління системою потоків віртуальної машини Java, що належить до пакету java.lang.management. Він в основному застосовується для ідентифікації потоків, які потрапили в тупикову ситуацію, та отримання інформації про них.
Інтерфейс ThreadMxBean можна використовувати для програмного створення дампа потоку. Метод getThreadMXBean() з ManagementFactory використовується для отримання екземпляра інтерфейсу ThreadMXBean. Він повертає кількість активних потоків, як демонів, так і не-демонів. ManagementFactory – це фабричний клас для отримання керованих компонентів для платформи Java.
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 ();
}
Ручний Аналіз Дампів Потоків
Аналіз дампів потоків може бути дуже корисним для виявлення проблем у багатопоточних процесах. Такі проблеми, як взаємні блокування, змагання за блокування та надмірне використання ЦП потоками, можна вирішити, аналізуючи стани окремих потоків.
Максимальну пропускну здатність програми можна досягти, виправивши стан кожного потоку після аналізу дампа потоку.
Наприклад, якщо процес використовує забагато ресурсів ЦП, можна дізнатися, який саме потік їх найбільше споживає. Якщо такий потік виявлено, його номер LWP необхідно перетворити на шістнадцяткове число. Далі, в дампі потоку, ми можемо знайти потік з nid, який дорівнює отриманому шістнадцятковому числу. Використовуючи трасування стека потоку, можна точно визначити проблему. Давайте визначимо ідентифікатор процесу потоку за допомогою наступної команди.
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
Розглянемо приклад фрагмента дампа потоку нижче. Щоб отримати дамп потоку для процесу 26680, використовуйте jstack -l 26680.
[[email protected] ~]# jstack -l 26680 2020-06-27 09:01:29 <strong>Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.221-b11 mixed mode):</strong> "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 . . . . . . . "<strong>Reference Handler</strong>" #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
Тепер давайте розглянемо, що ми можемо досліджувати за допомогою дампів потоків. Якщо ми подивимося на дамп потоку, то побачимо багато даних, що може здатися занадто складним. Однак, якщо аналізувати крок за кроком, то все стає досить зрозумілим. Розглянемо перший рядок:
2020-06-27 09:01:29
Повний дамп потоку Java HotSpot(TM) 64-Bit Server VM (25.221-b11 змішаний режим):
Вище показано час створення дампа та інформація про використану JVM. Далі, в кінці, ми можемо побачити перелік потоків, першим серед яких є наш потік ReferenceHandler.
Аналіз Заблокованих Потоків
Аналізуючи наведені нижче журнали дампа потоку, можна помітити, що він виявляє потоки зі статусом BLOCKED, що знижує продуктивність програми. Отже, якщо нам вдасться виявити потоки зі статусом BLOCKED, можна спробувати визначити блокування, які ці потоки намагаються отримати. Аналіз трасування стека з потоку, що наразі утримує блокування, може допомогти у розв’язанні проблеми.
[[email protected] ~]# jstack -l 26680 . . . . " DB-Processor-13" daemon prio=5 tid=0x003edf9