RKDEEP

Производительность java приложений

Kirill Rybkin2021-07-10

Опишем структурированный подход к выявлению узких мест в производительности, рассмотрим основные моменты на которые следует обратить внимание. Пост возник после презентации jClarity на Devoxx UK видео

Структурированный подход к решению проблем производительности

Когда случаются провалы производительности, нет необходимости изменять параметры JVM без точного понимания, к чему приведут ваши действия. Не стоит добавлять просто магические ключи JVM. Следуя структурированному подходу можно избегать неверных гипотез о причинах проблем с производительностью. Подход визуализирован на схеме ниже. PDM diagram

Kernel dominant, user dominant or no dominator?

На схеме выделено три секции. На первом шаге необходимо определить какую работу выполняет процессор. Для этого используем консольную утилиту Linux vmstat. Запускаем vmstat с параметром 5, что выполнит вывод в консоль каждые 5 сек.

$ vmstat 5
procs -----------memory----------   ---swap-- -----io---- -system-- ------cpu-----
 r  b  swpd    free  buff   cache     si  so     bi  bo    in   cs  us sy id wa st
 5  0     0 3261272 96056 1042868      0   0   1579 519    20 3626  45  9 34 13  0
 0  0     0 3261264 96064 1042832      0   0      0   2    19  423   6  2 91  2  0
 0  0     0 3261264 96064 1042832      0   0      0   0    19  429   6  2 92  0  0
 0  0     0 3261140 96064 1042832      0   0      0   0    19  311   4  1 95  0  0

Если CPU находится в режиме ядра более 10%

Когда вывод vmstat показывает преобладание режима ядра, возможна одна из нескольких причин:

  • Переключение контекста: два или более приложения борятся за время CPU
  • Диск I/O: инструментарий для проверки vmstat и iostat
  • Виртуализация: KVM CLI (virsh), Docker CLI, Kubernetes CLI
  • Сеть I/O: инструментарий netstat и Wireshark

Как посмотреть переключение контекста приложения и потока?

С помощью утилиты jps или ps узнаем pid процесса мониторинга напр. так: 

kirill@kirill-pc:~/next-blog$ jps -lmv
5712 org.jetbrains.idea.maven.server.RemoteMavenServer -Djava.awt.headless=true -Didea.version==2018.1.8 -Xmx768m -Didea.maven.embedder.version=3.3.9 -Dfile.encoding=UTF-8

Смотрим общую статистику по процессу 

kirill@kirill-pc:~/next-blog$ pidstat -w  -p 5712
Linux 5.8.0-50-generic (kirill-pc)     12.08.21     _x86_64_    (24 CPU)

22:07:02      UID       PID   cswch/s nvcswch/s  Command
22:07:02     1000      5712      0,00      0,00  java

или по каждому потоку

kirill@kirill-pc:~/next-blog$ pidstat -w -t -p 5712
Linux 5.8.0-50-generic (kirill-pc)     12.08.21     _x86_64_    (24 CPU)

22:08:55      UID      TGID       TID   cswch/s nvcswch/s  Command
22:08:55     1000      5712         -      0,00      0,00  java
22:08:55     1000         -      5712      0,00      0,00  |__java
22:08:55     1000         -      5714      0,23      0,01  |__java
22:08:55     1000         -      5717      0,00      0,00  |__java
22:08:55     1000         -      5718      0,00      0,00  |__java
22:08:55     1000         -      5719      0,00      0,00  |__java
22:08:55     1000         -      5720      0,00      0,00  |__java
22:08:55     1000         -      5721      0,00      0,00  |__java
22:08:55     1000         -      5722      0,00      0,00  |__java
22:08:55     1000         -      5723      0,00      0,00  |__java
22:08:55     1000         -      5724      0,00      0,00  |__java
22:08:55     1000         -      5725      0,00      0,00  |__java
22:08:55     1000         -      5726      0,00      0,00  |__java
22:08:55     1000         -      5727      0,00      0,00  |__java
22:08:55     1000         -      5728      0,00      0,00  |__java
22:08:55     1000         -      5729      0,00      0,00  |__java
22:08:55     1000         -      5730      0,00      0,00  |__java
22:08:55     1000         -      5731      0,00      0,00  |__java
22:08:55     1000         -      5732      0,00      0,00  |__java
...

TID (идентификатор потока) поможет найти поток в дампе потоков с помощью jstat.

Использование диска I/O

Утилита показывает статистику по нагрузке на систему ввода вывода:

kirill@kirill-pc:~/next-blog$ iostat
Linux 5.8.0-50-generic (kirill-pc)     12.08.21     _x86_64_    (24 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           4,03    0,03    0,73    0,06    0,00   95,14

Device             tps    kB_read/s    kB_wrtn/s    kB_dscd/s    kB_read    kB_wrtn    kB_dscd
sda               2,14       152,45         1,80         0,00     528996       6256          0
sdb              45,53       892,21       797,40         0,00    3096026    2767013          0

Сеть I/O: инструментарий netstat

# netstat -nap

покажет какой процесс какие порты открыл, если надо проверить, скажем, какой процесс занял порт, который требуется вашему приложению.

CPU пользовательского режима приближается к 100%

Когда вывод vmstat показывает преобладание использования CPU в режиме пользователя, это причина посмотреть на JVM и на GC детально. Первое что необходимо сделать это включить GC логгинг. Для java от 1.4 до 1.8, должны добавить следующие аргументы JVM:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<file-path>

Для Java 9 и выше:

-Xlog:gc*:file=<file-path>

Есть несколько бесплатных инструментов для графического представления GC логов. Рассмотрим вывод GCViewver:

GCVIEWVER output
На скрине Gcviewver видно, что идет выделение короткоживущих объектов. Очистка молодого поколения в среднем занимает 0,01 сек. В Java 8 и более ранних версиях сборщики мусора JVM по умолчанию являются параллельными сборщиками. Они выполняют полную "остановку мира" для сборок (как молодой, так и полной) и оптимизированы для достижения максимальной пропускной способности. После остановки всех потоков приложения многопоточные сборщики мусора используют все доступные ядра процессора, чтобы выполнить сборку мусора как можно быстрее. После того, как остановлены все потоки приложения (или пользователя), HotSpot просматривает молодое поколение и определяет все объекты, которые не являются мусором.

Что необходимо учитывать:

  • Полный GC блокирует приложение;
  • Когда наблюдается полный GC без освобождения памяти, возможна утечка памяти;
  • Приложение при нормальной работе должно показывать график формы "пилы" потребления кучи;

Как определить утечку памяти?

Запустим приложение с заложенной утечкой памяти код:

public class MemoryLeak {

    public static final long timeToWait = 10;
    public static final double NUMBER_OF_OBJECTS_TO_CREATE = 1000;

    public static void main(String[] args) {
        System.out.println("Start app ");
        Map m = new HashMap();
        while (true) {
            for (int i = 0; i < NUMBER_OF_OBJECTS_TO_CREATE; i++) {
                if (!m.containsKey(i)) {
                    m.put(new MapKey(i), new MapValue());
                }
            }

            System.out.println("Created leaking objects");

            // Wait for the given amount of time
            try {
                Thread.sleep(timeToWait);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

public class MapKey {
    Integer id;

    MapKey(Integer id) {
        this.id = id;
    }

    @Override
    public int hashCode() {
        return id.hashCode();
    }
}

В классе MapKey не переопределен метод equals() и не происходит замещения элемента в Map<> новым объектом MapValue. Смотрим на работу сборщика мусора, чтобы удостовериться что память не очищается после Full GC.

GCVIEWVER output

Узнаем id процесса.

kirill@kirill-pc:~/Downloads$ jps
26816 Jps
23524 Launcher
7718 Main
23527 MemoryLeak

С помощью утилиты jmap смотрим количество созданных объектов и занимаемый размер.

kirill@kirill-pc:~/Downloads$ jmap -histo:live 23527

 num     #instances         #bytes  class name
----------------------------------------------
   1:       7947149      445040344  java.util.HashMap$TreeNode
   2:       7947150      127154400  MapKey
   3:       7947150      127154400  MapValue
   4:       6930062      110880992  java.lang.Integer
   5:            14       67110176  [Ljava.util.HashMap$Node;

Видим преобладание TreeNode, MapKey, MapValue

Процессор в ожидании

Если процессор не показывает преобладания в режиме ядра или пользовательском, но пользователи наблюдают проблему производительности, то скорее всего потоки ожидают внешней системы или блокированы.

Материалы

  1. "Java: оптимизация программ" Бенджамин Эванс, Джеймс Гоф и Kpuc Ньюланд.
  2. "PDM" (https://github.com/rajendrapenumalli/PerformanceEngineeringNotes/wiki/Performance-Diagnostic-Methodology)