Статьи

Какой поток Java потребляет мой процессор?

Апрель 17, 2019
Что вы делаете, когда ваше Java-приложение потребляет 100% ресурсов процессора? Оказывается, вы можете легко найти проблемные темы, используя встроенные инструменты UNIX и JDK. Профилировщики или агенты не требуются.

Для тестирования мы будем использовать эту простую программу:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
public class Main {
    public static void main(String[] args) {
        new Thread(new Idle(), 'Idle').start();
        new Thread(new Busy(), 'Busy').start();
    }
}
 
class Idle implements Runnable {
 
    @Override
    public void run() {
        try {
            TimeUnit.HOURS.sleep(1);
        } catch (InterruptedException e) {
        }
    }
}
 
class Busy implements Runnable {
    @Override
    public void run() {
        while(true) {
            'Foo'.matches('F.*');
        }
    }
}

Как видите, запускается два потока. Idle не потребляется никакой процессор (помните, что спящие потоки потребляют память, но не процессор), в то время как Busy съедает все ядро, поскольку анализ и выполнение регулярных выражений является удивительно сложным процессом. Давайте запустим эту программу и забудем об этом. Как мы можем быстро выяснить, что Busy является проблемной частью нашего программного обеспечения? Прежде всего мы используем top, чтобы узнать идентификатор процесса ( PID ) java процесса, который потребляет большую часть процессора. Это довольно просто:

1
$ top -n1 | grep -m1 java

Это отобразит первую строку top вывода, содержащего предложение « java »:

1
22614 tomek     20   0 1360m 734m  31m S    6 24.3   7:36.59 java

Первый столбец — это PID, давайте его извлечем. К сожалению, оказалось, что top использует управляющие коды ANSI для цветов — невидимых символов, которые ломают такие инструменты, как grep и cut . К счастью, я нашел Perl-скрипт для удаления этих символов и, наконец, смог извлечь PID процесса java исчерпав мой процессор:

1
$ top -n1 | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' '

cut -f1 -d' ' просто берет первое значение из разделенных пробелами столбцов:

1
22614

Теперь, когда у нас есть проблемный PID JVM, мы можем использовать top -H чтобы найти проблемные потоки Linux. Опция -H выводит список всех потоков в отличие от процессов , столбец PID теперь представляет внутренний идентификатор потока Linux:

1
2
$ top -n1 -H | grep -m1 java
$ top -n1 -H | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' '

Выходные данные удивительно похожи, но первое значение теперь является идентификатором потока:

1
2
25938 tomek     20   0 1360m 748m  31m S    2 24.8   0:15.15 java
25938

Таким образом, у нас есть идентификатор процесса нашей занятой JVM и идентификатор потока Linux (скорее всего, из этого процесса), потребляющий наш процессор. Самое интересное : если вы посмотрите на вывод jstack (доступный в JDK), рядом с именем каждого потока будет напечатан какой-то загадочный идентификатор:

1
2
3
'Busy' prio=10 tid=0x7f3bf800 nid=0x6552 runnable [0x7f25c000]
    java.lang.Thread.State: RUNNABLE
        at java.util.regex.Pattern$Node.study(Pattern.java:3010)

Все верно, параметр nid=0x645a совпадает с идентификатором потока, напечатанным с помощью top -H . Конечно, чтобы не сделать это слишком простым, top использует десятичную запись, а jstack печатает в шестнадцатеричном виде. Опять есть простое решение, printf ‘% x’ :

1
2
$ printf '%x' 25938
6552

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

1
2
3
4
#!/bin/bash
PID=$(top -n1 | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' ')
NID=$(printf '%x' $(top -n1 -H | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' '))
jstack $PID | grep -A500 $NID | grep -m1 '^$' -B 500

PID содержит идентификатор java а NID — идентификатор потока, скорее всего, из этой JVM. Последняя строка просто сбрасывает трассировку стека JVM данного PID и отфильтровывает (используя grep ) поток, имеющий соответствующий nid . Угадайте, что это работает:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
$ ./profile.sh
'Busy' prio=10 tid=0x7f3bf800 nid=0x6552 runnable [0x7f25c000]
    java.lang.Thread.State: RUNNABLE
        at java.util.regex.Pattern$Node.study(Pattern.java:3010)
        at java.util.regex.Pattern$Curly.study(Pattern.java:3854)
        at java.util.regex.Pattern$CharProperty.study(Pattern.java:3355)
        at java.util.regex.Pattern$Start.<init>(Pattern.java:3044)
        at java.util.regex.Pattern.compile(Pattern.java:1480)
        at java.util.regex.Pattern.<init>(Pattern.java:1133)
        at java.util.regex.Pattern.compile(Pattern.java:823)
        at java.util.regex.Pattern.matches(Pattern.java:928)
        at java.lang.String.matches(String.java:2090)
        at com.blogspot.nurkiewicz.Busy.run(Main.java:27)
        at java.lang.Thread.run(Thread.java:662)

Многократный запуск скрипта (или с помощью watch , см. Ниже) захватывает поток Busy в разных местах, но почти всегда внутри парсера регулярного выражения — что является нашей проблемной частью!

Несколько потоков

Если в вашем приложении есть несколько потоков, watch -n1 ./profile.sh процессором, вы можете использовать watch -n1 ./profile.sh чтобы запускать сценарий каждую секунду и получать полу-дампы стека в реальном времени, скорее всего, из разных потоков. Тестирование с помощью следующей программы:

1
2
3
new Thread(new Idle(), 'Idle').start();
new Thread(new Busy(), 'Busy-1').start();
new Thread(new Busy(), 'Busy-2').start();

вы увидите трассировку стека потоков Busy-1 или Busy-2 (в разных местах внутри класса Pattern ), но не в режиме Idle .

Ссылка: Какой поток Java потребляет мой процессор? от нашего партнера JCG Томаша Нуркевича в блоге о Java и соседстве .

39
Share: