Заглядываем за кулисы Java-приложения с помощью pidstat и jstack

В данной статье мы посмотрим лишь на две утилиты pidtstat и jstack. Их всего две, но они многое могут рассказать о работе многопоточного Java-приложения. Например, найти, какой поток оказался в состоянии deadlock, или какой поток загружает CPU на 100%.

Для начала нам надо узнать PID нашей Java-программы. Это можно сделать либо с помощью стандартной утилиты ps или с помощью утилиты из JDK jps.

# jps -lmv
1591 MultiCastReceiver lo

Как видим, PID программы — 1591. Теперь можно заглянуть внутрь этой Java-программы. Для этого надо запустить pidstat с опцией -t:

# pidstat -t -p 1591
Linux 4.18.0-193.6.3.el8_2.x86_64 (xxxx)    07/06/2020      _x86_64_        (3 CPU)

08:14:58 PM   UID      TGID       TID    %usr %system  %guest   %wait    %CPU   CPU  Command
08:14:58 PM     0      1591         -    3.49    2.51    0.00    0.00    6.00     1  java
08:14:58 PM     0         -      1591    0.00    0.00    0.00    0.00    0.00     1  |__java
08:14:58 PM     0         -      1592    3.25    2.56    0.00    0.75    5.81     0  |__java
08:14:58 PM     0         -      1593    0.00    0.00    0.00    0.00    0.00     0  |__GC Thread#0
08:14:58 PM     0         -      1594    0.00    0.00    0.00    0.00    0.00     1  |__G1 Main Marker
08:14:58 PM     0         -      1595    0.00    0.00    0.00    0.00    0.00     0  |__G1 Conc#0
08:14:58 PM     0         -      1596    0.00    0.00    0.00    0.00    0.00     1  |__G1 Refine#0
08:14:58 PM     0         -      1597    0.00    0.00    0.00    0.04    0.00     1  |__G1 Young RemSet
08:14:58 PM     0         -      1598    0.00    0.00    0.00    0.03    0.00     1  |__VM Thread
08:14:58 PM     0         -      1599    0.00    0.00    0.00    0.00    0.00     0  |__Reference Handl
08:14:58 PM     0         -      1600    0.00    0.00    0.00    0.00    0.00     0  |__Finalizer
08:14:58 PM     0         -      1601    0.00    0.00    0.00    0.00    0.00     1  |__Signal Dispatch
08:14:58 PM     0         -      1602    0.10    0.01    0.00    0.01    0.11     1  |__C2 CompilerThre
08:14:58 PM     0         -      1603    0.03    0.00    0.00    0.00    0.03     1  |__C1 CompilerThre
08:14:58 PM     0         -      1604    0.00    0.00    0.00    0.00    0.00     1  |__Sweeper thread
08:14:58 PM     0         -      1605    0.00    0.00    0.00    0.00    0.00     0  |__Service Thread
08:14:58 PM     0         -      1606    0.01    0.01    0.00    0.29    0.02     2  |__VM Periodic Tas
08:14:58 PM     0         -      1607    0.00    0.00    0.00    0.00    0.00     2  |__Common-Cleaner
08:14:58 PM     0         -      1608    0.01    0.00    0.00    0.01    0.01     0  |__Thread-0

В колонке TID выводится идентификатор потока, а в колонке Command — его название. Как видно из иллюстрации, при запуске Java-программы, у которой есть два потока,

08:14:58 PM 0 - 1592 3.25 2.56 0.00 0.75 5.81 0 |__java
08:14:58 PM 0 - 1608 0.01 0.00 0.00 0.01 0.01 0 |__Thread-0

дополнительно запускается еще 15 (пятнадцать!) сервисных потоков, которые принадлежат JVM: потоки сборщика мусора, потоки JIT-компилятора и проч.

Вывод pidstat позволяет узнать, сколько ресурсов отъедает каждый поток. Если ваша программа — многопоточная, то через pidstat можно увидеть, например, какой поток загружает CPU на 100%.

Та же команда pidstat с опцией -w покажет количество переключений контекста в каждом потоке:

# pidstat -wt -p 1591
Linux 4.18.0-193.6.3.el8_2.x86_64 (xxxx)    07/06/2020      _x86_64_        (3 CPU)

08:35:47 PM   UID      TGID       TID   cswch/s nvcswch/s  Command
08:35:47 PM     0      1591         -      0.01      0.00  java
08:35:47 PM     0         -      1591      0.01      0.00  |__java
08:35:47 PM     0         -      1592   1398.73      0.45  |__java
08:35:47 PM     0         -      1593      0.02      0.00  |__GC Thread#0
08:35:47 PM     0         -      1594      0.00      0.00  |__G1 Main Marker
08:35:47 PM     0         -      1595      0.00      0.00  |__G1 Conc#0
08:35:47 PM     0         -      1596      0.00      0.00  |__G1 Refine#0
08:35:47 PM     0         -      1597      2.57      0.00  |__G1 Young RemSet
08:35:47 PM     0         -      1598      0.81      0.00  |__VM Thread
08:35:47 PM     0         -      1599      0.00      0.00  |__Reference Handl
08:35:47 PM     0         -      1600      0.00      0.00  |__Finalizer
08:35:47 PM     0         -      1601      0.00      0.00  |__Signal Dispatch
08:35:47 PM     0         -      1602      0.24      0.01  |__C2 CompilerThre
08:35:47 PM     0         -      1603      0.21      0.00  |__C1 CompilerThre
08:35:47 PM     0         -      1604      0.07      0.00  |__Sweeper thread
08:35:47 PM     0         -      1605      0.01      0.00  |__Service Thread
08:35:47 PM     0         -      1606     13.96      0.00  |__VM Periodic Tas
08:35:47 PM     0         -      1607      0.01      0.00  |__Common-Cleaner
08:35:47 PM     0         -      1608      0.78      0.00  |__Thread-0
08:35:47 PM     0         -      1852      0.01      0.00  |__Attach Listener

У программы — два потока. Один — главный (TID: 1592), который запускает второй поток (Thread-0, TID: 1608). И видно, что львиная доля переключений контекста приходится на главный поток:

08:35:47 PM     0         -      1592   1398.73      0.45  |__java

Теперь сделаем дамп потоков с помощью jstack:

# sudo jstack 1591
2020-07-06 20:19:16
Full thread dump Java HotSpot(TM) 64-Bit Server VM (13.0.2+8 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x00007f9e140028c0, length=11, elements={
0x00007f9e5c018000, 0x00007f9e5c0ce800, 0x00007f9e5c0d0800, 0x00007f9e5c0d9800,
0x00007f9e5c0db800, 0x00007f9e5c0dd800, 0x00007f9e5c0df000, 0x00007f9e5c10f800,
0x00007f9e5c113800, 0x00007f9e5c128800, 0x00007f9e14001000
}

"main" #1 prio=5 os_prio=0 cpu=114880.62ms elapsed=475.30s tid=0x00007f9e5c018000 nid=0x638 runnable  [0x00007f9e629c0000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainDatagramSocketImpl.receive0(java.base@13.0.2/Native Method)
        - locked <0x00000000c9b949b0> (a java.net.PlainDatagramSocketImpl)
        at java.net.AbstractPlainDatagramSocketImpl.receive(java.base@13.0.2/AbstractPlainDatagramSocketImpl.java:182)
        - locked <0x00000000c9b949b0> (a java.net.PlainDatagramSocketImpl)
        at java.net.DatagramSocket.receive(java.base@13.0.2/DatagramSocket.java:815)
        - locked <0x00000000c9b96968> (a java.net.DatagramPacket)
        - locked <0x00000000c9b74268> (a java.net.MulticastSocket)
        at MultiCastReceiver.main(MultiCastReceiver.java:49)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.25ms elapsed=475.12s tid=0x00007f9e5c0ce800 nid=0x63f waiting on condition  [0x00007f9e40a8a000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.ref.Reference.waitForReferencePendingList(java.base@13.0.2/Native Method)
        at java.lang.ref.Reference.processPendingReferences(java.base@13.0.2/Reference.java:241)
        at java.lang.ref.Reference$ReferenceHandler.run(java.base@13.0.2/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.42ms elapsed=475.12s tid=0x00007f9e5c0d0800 nid=0x640 in Object.wait()  [0x00007f9e40989000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(java.base@13.0.2/Native Method)
        - waiting on <0x00000000c9b02790> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(java.base@13.0.2/ReferenceQueue.java:155)
        - locked <0x00000000c9b02790> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(java.base@13.0.2/ReferenceQueue.java:176)
        at java.lang.ref.Finalizer$FinalizerThread.run(java.base@13.0.2/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.47ms elapsed=475.04s tid=0x00007f9e5c0d9800 nid=0x641 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=755.20ms elapsed=475.04s tid=0x00007f9e5c0db800 nid=0x642 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #6 daemon prio=9 os_prio=0 cpu=219.06ms elapsed=475.04s tid=0x00007f9e5c0dd800 nid=0x643 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #7 daemon prio=9 os_prio=0 cpu=2.00ms elapsed=475.04s tid=0x00007f9e5c0df000 nid=0x644 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #8 daemon prio=9 os_prio=0 cpu=0.26ms elapsed=474.93s tid=0x00007f9e5c10f800 nid=0x645 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #9 daemon prio=8 os_prio=0 cpu=1.58ms elapsed=474.84s tid=0x00007f9e5c113800 nid=0x647 in Object.wait()  [0x00007f9e31efc000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(java.base@13.0.2/Native Method)
        - waiting on <0x00000000c9b45418> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(java.base@13.0.2/ReferenceQueue.java:155)
        - locked <0x00000000c9b45418> (a java.lang.ref.ReferenceQueue$Lock)
        at jdk.internal.ref.CleanerImpl.run(java.base@13.0.2/CleanerImpl.java:148)
        at java.lang.Thread.run(java.base@13.0.2/Thread.java:830)
        at jdk.internal.misc.InnocuousThread.run(java.base@13.0.2/InnocuousThread.java:134)

"Thread-0" #10 prio=5 os_prio=0 cpu=149.66ms elapsed=474.64s tid=0x00007f9e5c128800 nid=0x648 waiting on condition  [0x00007f9e31dfb000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(java.base@13.0.2/Native Method)
        at MultiCastReceiver.run(MultiCastReceiver.java:66)
        at java.lang.Thread.run(java.base@13.0.2/Thread.java:830)

"Attach Listener" #11 daemon prio=9 os_prio=0 cpu=1.76ms elapsed=113.42s tid=0x00007f9e14001000 nid=0x73c waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=0 cpu=83.01ms elapsed=475.13s tid=0x00007f9e5c0cb800 nid=0x63e runnable

"GC Thread#0" os_prio=0 cpu=2.62ms elapsed=475.29s tid=0x00007f9e5c057800 nid=0x639 runnable

"G1 Main Marker" os_prio=0 cpu=0.11ms elapsed=475.29s tid=0x00007f9e5c061000 nid=0x63a runnable

"G1 Conc#0" os_prio=0 cpu=0.10ms elapsed=475.29s tid=0x00007f9e5c062800 nid=0x63b runnable

"G1 Refine#0" os_prio=0 cpu=0.15ms elapsed=475.28s tid=0x00007f9e5c09f000 nid=0x63c runnable

"G1 Young RemSet Sampling" os_prio=0 cpu=39.78ms elapsed=475.28s tid=0x00007f9e5c0a0800 nid=0x63d runnable
"VM Periodic Task Thread" os_prio=0 cpu=255.14ms elapsed=474.92s tid=0x00007f9e5c111800 nid=0x646 waiting on condition

JNI global refs: 16, weak refs: 0

Итак, main поток занят тем, что постоянно исполняет строку:

at java.net.PlainDatagramSocketImpl.receive0(java.base@13.0.2/Native Method)

Это объясняется тем, что данная программа занимается приемом сообщений из сокета по протоколу UDP. А такое большое количество переключений контекста объясняется тем, что поток часто ждет, когда наполнится буфер данных, прежде чем продолжит их обрабатывать.

В дампе идентификатор потока указан в шестистнадцатеричной системе. Например, поток «G1 Refine#0» имеет идентификатор nid=0x63b. Если перевести этот идентификатор в десятичную форму:

# echo $((0x63b))

получится:

А это в точности соответствует:

08:14:58 PM 0 - 1596 0.00 0.00 0.00 0.00 0.00 1 |__G1 Refine#0

Итоги

В данной статье я показал, как с помощью утилит pidstat и jstack можно заглянуть во внутрь многопоточного Java-приложения и узнать, как ведет себя каждый поток этого приложения.

Полезные Linux-команды — еще несколько команд для оценки производительности системы.
Утилиты для копания во внутренностях JVM позволяют со всех сторон рассмотреть производительность Java-приложения.

Добавить комментарий Отменить ответ

Введите свой комментарий...

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

E-mail (Адрес никогда не будет опубликован)

Имя

Сайт

Для комментария используется ваша учётная запись WordPress.com. ( Выход / Изменить )

Для комментария используется ваша учётная запись Twitter. ( Выход / Изменить )

Для комментария используется ваша учётная запись Facebook. ( Выход / Изменить )

Отмена

Connecting to %s

Algo & DMA: технологии биржевой торговли

Биржевые технологии, алгоритмическая торговля, Java и программирование

Заглядываем за кулисы Java-приложения с помощью pidstat и jstack

Итоги

Добавить комментарий Отменить ответ

Итоги

Поделиться ссылкой:

Понравилось это:

Похожее

Добавить комментарий Отменить ответ