четверг, 21 ноября 2019 г.

Настройка и мониторинг производительности Java приложений

Состав кучи

Java Heap разделена на 3 основные части:
  • Область Yang
    • Eden
      Все объекты изначально попадают в эту область.
      Когда Eden полностью заполняется, срабатывает Minor GC только над областью Yang
      Minor GC всегда происходит с остановкой основного цикла программы (Stop-the-word), но за счет небольшого размера области, сборка происходит быстро.


    • Survivor (выжившие)
      Если на объект имеются ссылки, то он перемещается из Eden в S0 Survivor
      При этом счетчик числа GC у объекта инкрементируется.
      Объекты без ссылок, удаляются из Eden.
      • S0 (From) Когда Eden снова заполняется полностью, снова срабатывает Minor GC
        Теперь он затрагивает области Eden и Survivor

        - Объекты без ссылок удаляются из Eden и Survivor
        - Используемые объекты из S0 и Eden перемещаются в S1 и инкрементируется счетчик
      • S1 (To) После второго Minor GC куча выглядит так:

  • Область Old или Tenured (Штатный)
    После InitialTenuringThreshold операций Minor GC (по умолчанию = 7 ) объект перестает считаться Yang и переносится из области Survivor в постоянную область Old (Tenured)

    - Объем Old области больше, чем Yang (обычно в NewRatio раз = 2) и наполняется медленней
    - Full GC по Old области редки, но достаточно продолжительны
    - Цель настройки объектов программы и GC - минимизировать число Full GC


  • Область Permanent
    Область Permanent фиксирован по размеру и почти не растет во время работы.
    Внутри ее содержится данные о метаданных и классах.

Параметры настройки

Названия основных параметров:

Просмотреть список всех параметров:
java -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal -version
Если параметр объявлен с "=" , то это значение по умолчанию.
Если с ":=" , то параметр был переопределен.

Полное описание всех параметров на сайте oracle.

Значения, выставляемые по умолчанию:
* Для серверного ПК:
- Parallel (Throutput) collector
- Xms (начальный размер Heap) = 1/64 доступной памяти
- Xmx (максимальный размер Heap) = 1/4 памяти
* Для прочих устройств:
- Serial gc
- Xm* параметры такиеже

Вариант оптимизации: устанавливать Xms = Xmx, чтобы ускорить работу программы, за счет уменьшения числа изменений объема памяти

Виды сборщиков мусора

Serial

-XX:+UseSerialGC
Используется в клиентских java машинах.
Обе области: yang и old работают в 1 поток
Вариант оптимизации - это множество независимых программ работающих параллельно на 1 машине.
В этом случае однопоточный gc создан меньше нагрузки, чем множество многопоточных.

Parallel

-XX:+UseParallelGC
Yang GC работает в параллельном режиме
Olg GC по прежнему однопоточный
Число потоков задается параметром "-XX:ParallelGCThreads" - по умолчанию = числу ядер процессора. Если на машине запущенно множество программ, то число параллельных потоков можно снизить.
Подходит для серверных приложений, где важен объем обрабатываемых данных, а не скорость отклика, т.к. очистка происходит с остановкой основной программы.

Parallel Old

-XX:+UseParallelOldGC
Такой же как "Parallel", но Old GC выполняется параллельно, что еще добавляет пропускной способности.

Над Old областью также происходит дефрагментация данных, что упрощает поиск свободных мест для будущих объектов:

Над Yang областью не надо проводить дефргаментацию, т.к. она заполняется перемещением между S0 и S1.

Concurrent Mark-Sweep

-XX:+UseConcMarkSweepGC
Используется, когда важно время отклика с минимальным временем на gc, а не объем обработанной информации.
CMS gc не копирует и не дефрагментирует память. Происходит пометка (mark) неиспользуемой памяти и последующая очистка (sweep).
Отсутствие копирования и дефрагментации уменьшает время простоя на очистку, но увеличивает фрагментацию.
Что в совокупности увеличивает потребление CPU и Озу на 20% в сравнении с копирующими коллекторами.

G1

-XX:+UseG1GC
Этот коллектор используется по умолчанию в серверных приложениях.

По принципу работы G1 схож с CMS, но имеет ряд преимуществ:
* Выполняется конкурентно как CMS gc
* Память дефрагментируется без остановки основного цикла программы
* Фиксированный (предсказуемый) размер паузы gc
* Пропускная способность остается достаточно высокой
* Не требует дополнительных 20% озу, как CMS gc (но все равно нужны 10% = G1ReservePercent)

Достигается это за счет того, что вся память делится на 2048 регионов (-XX:G1HeapRegionSize) от 1 до 32 МБ (в зависимости от размера кучи).
Выжившие объекты копируются из своего региона в свободный (дефрагментация), этот процесс дискретный и может быть остановлен в любой момент (фиксированная пауза)


Желатльно чтобы размер объекта был от 50-100% размера региона. Если объект больше региона, то он будет хранится в смежных регионах, что может вызывать задержки при обработке.

Параметры коллектора, на которые стоит обратить внимание:

-XX:MaxGCPauseMillis=200
Ставьте этот параметр = 90% от необходимого времени отклика

-XX:ConcGCThreads
кол-во процессов параллельной обработки регионов

-XX:InitiatingHeapOccupancyPercent=45
заполненность heap, после которой начинается gc

-XX:G1ReservePercent=10
резерв памяти, для защиты от переполнения

Полный список параметров и их описание на сайте oracle

GC в Hive

В сборке Hadoop от Hortonworks используется G1 gc для Hive
Сменить GC можно, только с перезапуском сервиса.
В виду сложности этой операции, проведем тесты с параметрыми G1, которые можно менять прямо во время выполнения запроса.

Databricks провела тесты сравнения нескольких коллекторов и их параметров.
По результату исследования был сделан вывод:
* Лучший коллектор для hadoop - G1
* Уменьшить % заполняемости heap (InitiatingHeapOccupancyPercent), чтобы gc происходил раньше, что должно уменьшить число долгих full gc
* Увеличить число параллельных потоков gc (ConcGCThreads) - это увеличит нагрузку на CPU, но ускорит GC

Протестируем параметры gc на запросе с distinct, чтобы был создан большой хэш массив и сортировок со слиянием.

1. Запуск с параметрами по умолчанию:
select sum(amount) amount, count(distinct `check_id`) as clnt_count, COUNT(*) as cnt 
from checks h
join material m on m.material = h.material
where calday between '20180601' and '20180631'
AND m.base_uom = 'ST'
;

Task Execution Summary
------------------------------------------------------------------------------------------------------------------
  VERTICES  TOTAL_TASKS  FAILED_ATTEMPTS  KILLED_TASKS   DURATION(ms)  CPU_TIME(ms)  GC_TIME(ms)  INPUT_RECORDS  OUTPUT_RECORDS
------------------------------------------------------------------------------------------------------------------
     Map 1          120                1             0      129018.00     9,566,290      364,407    316,971,979      32,483,111
     Map 3            1                0             0        3244.00         7,890          223        508,786         432,428
 Reducer 2            1                0             0      154769.00       154,740        3,998     32,483,111               0
------------------------------------------------------------------------------------------------------------------
Время GC = 364 407 мс.
Полный список параметров GC во время работы:
ps -eo pid,user,pcpu,cmd --sort -pcpu | grep application_1564490628193_26776 | head
31478 lenta_e+  287 /usr/jdk64/jdk1.8.0_112/bin/java -Xmx3276m -Djava.net.preferIPv4Stack=true -Dhdp.version=2.6.5.0-292 
-XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseG1GC -XX:+ResizeTLAB -server -XX:NewRatio=8 
-Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=/...

java -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal -version | grep InitiatingHeapOccupancyPercent
uintx InitiatingHeapOccupancyPercent            = 45                                  {product}

java -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal -version | grep ConcGCThreads
uintx ConcGCThreads                             = 0                                   {product}

2. Изменим параметры G1: увеличим число потоков (ConcGCThreads) и установим % памяти на котором будет срабатывать GC на 35 (InitiatingHeapOccupancyPercent)
set hive.tez.java.opts=-server -Djava.net.preferIPv4Stack=true -XX:NewRatio=8 -XX:+UseNUMA 
-XX:+UseG1GC -XX:InitiatingHeapOccupancyPercent=35 -XX:ConcGCThreads=20 
-XX:+ResizeTLAB -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintCommandLineFlags;
Повторим тотже запрос:
Task Execution Summary
------------------------------------------------------------------------------------------------------------------
  VERTICES  TOTAL_TASKS  FAILED_ATTEMPTS  KILLED_TASKS   DURATION(ms)  CPU_TIME(ms)  GC_TIME(ms)  INPUT_RECORDS  OUTPUT_RECORDS
------------------------------------------------------------------------------------------------------------------
     Map 1          120                6             0      145231.00     9,737,630      382,224    316,971,979      32,483,161
     Map 3            1                0             0        9747.00        16,540          167        508,786         432,428
 Reducer 2            1                0             0      229923.00       256,220        7,052     32,483,161               0
------------------------------------------------------------------------------------------------------------------
Время GC = 382 224 мс. Не смотря на рекомендации, время GC увеличилось.
Для себя сделал вывод - нет смысла трогать параметры GC в большинстве случаев, если нет явных проблем при сборке мусора.

Комманды для мониторинга Java из консоли

PrintCommandLineFlags

Основные параметры Java: MaxHeapSize, GC
java -XX:+PrintCommandLineFlags -version
-XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=32210157568 -XX:+PrintCommandLineFlags -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
java version "1.8.0_112"
Java(TM) SE Runtime Environment (build 1.8.0_112-b15)
Java HotSpot(TM) 64-Bit Server VM (build 25.112-b15, mixed mode)

Verbose: gc

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc

[GC (Allocation Failure)  279616K->146232K(1013632K), 0.3318607 secs]
[GC (Allocation Failure)  425848K->295442K(1013632K), 0.4266943 secs]
[Full GC (System.gc())  434341K->368279K(1013632K), 0.5420611 secs]
[GC (Allocation Failure)  647895K->368280K(1013632K), 0.0075449 secs]
Выводить в консоль подробную информацию о работе GC
* GC - minor gc над yang областью
* Full GC - поный gc над Old областью
[Тип GC heap_до -> после (общий размер heap), время_gc]

Дополнительные параметры verbose:gc
* PrintGCTimeStamps - время в секундах с момента старта программы
* PrintGCDetails - дополнительная информация о затратах CPU
* PrintGCApplicationsStoppedTime - время работы GC с остановкой программы
* PrintGCApplicationsConcurrentTime - время на конкурентную работу GC

HeapDumpOnOutOfMemoryError

Создать дамп heap в случае OOM, для последующего анализа причины:
$ java -XX:+HeapDumpOnOutOfMemoryError -mn256m -mx512m ConsumeHeap
java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid2262.hprof ...
Heap dump file created [531535128 bytes in 14.691 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
        at ConsumeHeap$BigObject.(ConsumeHeap.java:22)
        at ConsumeHeap.main(ConsumeHeap.java:32)
Дамп по умолчанию создается в working дирректории VM, если нужна кастомное расположение, то нужно указать параметр "-XX:HeapDumpPath"
Список объектов в топе можно проанализировать с помощью VisualVM

JCMD

Консольное приложение для отправки комманд к работающему java приложению.
* Запуск без параметров - получить список java приложений: pid, команда запуска
$ jcmd
19122 org.apache.hadoop.fs.FsShell ...
2562 sun.tools.jcmd.JCmd
17364 org.apache.hadoop.util.RunJar ....
Запуск с команда:
jcmd process_id/main_class команда
командаОписание
helpСписок этих параметров
JFR.startСтартовать запись Java Flight Recorder
jcmd 8416 JFR.start
8416:
Started recording 1. No limit (duration/maxsize/maxage) in use.

Use JFR.dump recording=1 filename=FILEPATH to copy recording data to file

Options: (options must be specified using the key or key=value syntax)
        name : [optional] Name that can be used to identify recording, e.g. "My Recording" (STRING, no default value)
        defaultrecording : [optional] Starts the default recording, can only be combined with settings. (BOOLEAN, false)
        dumponexit : [optional] Dump running recording when JVM shuts down (BOOLEAN, no default value)
        settings : [optional] Settings file(s), e.g. profile or default. See JRE_HOME/lib/jfr (STRING SET, no default value)
        delay : [optional] Delay recording start with (s)econds, (m)inutes), (h)ours), or (d)ays, e.g. 5h. (NANOTIME, 0)
        duration : [optional] Duration of recording in (s)econds, (m)inutes, (h)ours, or (d)ays, e.g. 300s. (NANOTIME, 0)
        filename : [optional] Resulting recording filename, e.g. "C:UsersuserMy Recording.jfr" (STRING, no default value)
        compress : [optional] GZip-compress the resulting recording file (BOOLEAN, false)
        maxage : [optional] Maximum time to keep recorded data (on disk) in (s)econds, (m)inutes, (h)ours, or (d)ays, e.g. 60m, or 0 for no limit (NANOTIME, 0)
JFR.stop Остановить запись Java Flight Recorder
jcmd 8416 JFR.stop
8416:
Must provide either name or recording.
JFR.dump Сохранить запись Java Flight Recorder
jcmd 8416 JFR.dump recording=1 filename=C:/work/jmeter.jfr
8416:
Dumped recording 1, 492,2 kB written to:

C:\work\jmeter.jfr
JFR.checkПроверка - включен ли Java Flight Recorder?
jcmd 8416 JFR.check
8416:
Java Flight Recorder not enabled.

Use VM.unlock_commercial_features to enable.
VM.native_memory
VM.check_commercial_featuresПроверка включенности коммерческих возможностей
VM.unlock_commercial_features Включить комерческие возможности VM
jcmd 8416 VM.unlock_commercial_features
8416:
Commercial Features now unlocked.
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
Thread.printПолучить stacktrace всех потоков. Удобно, если приложение зависло с блокировкой, для определения проблемного места.
GC.class_stats
GC.class_histogram
jcmd 5988 GC.class_histogram | less
5988:
 num     #instances         #bytes  class name
----------------------------------------------
   1:         34214        6976016  [C
   2:          7152         826984  java.lang.Class
   3:         34041         816984  java.lang.String
GC.heap_dumpСделать дамп heap для анализа в VisualVM
GC.run_finalization
GC.runВыполнить GC
VM.uptimeВремя работы приложения
VM.flags
VM.system_properties
VM.command_line
VM.versionВерсия java

JSTAT

Консольная утилита для мониторинга GC
$ jcmd
12419 org.apache.hadoop.fs.FsShell ....
17364 org.apache.hadoop.util.RunJar ....
13353 sun.tools.jcmd.JCmd
#узнаем ID процесса нужной JVM

$ jstat -gcutil 17364 1000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  43.75  32.45  16.94  98.49  96.01     61    1.772     4    0.385    2.157
  0.00  43.75  32.45  16.94  98.49  96.01     61    1.772     4    0.385    2.157
  0.00  43.75  32.45  16.94  98.49  96.01     61    1.772     4    0.385    2.157
  0.00  43.75  32.45  16.94  98.49  96.01     61    1.772     4    0.385    2.157
  0.00  43.75  32.45  16.94  98.49  96.01     61    1.772     4    0.385    2.157
  0.00  43.75  32.45  16.94  98.49  96.01     61    1.772     4    0.385    2.157
  0.00  43.75  32.45  16.94  98.49  96.01     61    1.772     4    0.385    2.157
1000 - это период обновления монитора

YGC - число срабатываний Yang GC
YGCT - время работы Yang GC
FGC - число срабатываний Full GC
FGCT - время работы Full GC
GCT - общее время GC
S0, S1, E (eden), O (Full) - % утилизации областей Heap

VisualVM

Удобное бесплатное приложение от Oracle для анализа Java приложений.
VisualVM расширяется за счет plugins. Основные, которыми рекомендую пользоваться:


Overview - общие параметры jvm


Visual GC - online визуализация и история работы GC в разрезе областей heap


Sampler - информация о нагрузке на CPU и объеме объектов.
Замеры происходят с некоторой периодичностью раз в несколько мс, что обеспечивает минимальную нагрузку на приложение, но дает не 100% правильную картину.
Распределение времени CPU по методам приложения:


Топ объектов по памяти, без привязки к методам:


Но тут же можно снять heap dump и узнать реальную картину распредления памяти по методам и объектам:


Если это оконное java приложение, то сэмплировать можно выбранную часть окна:



Профилирование
Профилировщик явно трассирует работу программы, что дает наиболее верный резальтат в сравнении с сэмплированием.
Для того, чтобы начать трассировать программу, нужно запустить ее с особенными параметрами:
java -Xmx512m -agentpath:path_to_visualvm/profiler/lib/deployed/jdk16/windows-amd64/profilerinterface.dll=path_to_visualvm\profiler\lib,5140 -jar app.jar
После чего к запущенному приложению можно подключиться для анализа из visualvm.
При запуске можно указать фильтр на определенный класс приложения.
В отличие от сэплирования, при трассировке, объем объектов можно анализировать в разрезе методов:


Так же можно анализировать исходящие JDBC запросы:


Распределение времени CPU:



Flight Recorder

Коммерческий продукт JVM. Позволяет включать и сохранять трассировку с работающей программы, к которой нет прямого доступа через visyalvm или нет возможности поменять параметры запуска для профилирования.
Снятую тарссировку можно после проанализировать через Mission Control.
Описание способа включения Flight Recorder описано в разделе JCMD

Mission Control

Приложение для анализа трассировок записанных Flight Recorder (.jfr)
Общая информация о системных показателях: CPU, Memory:


Топ объектов в heap (можно получить и разрез по методам):


Распределение времени по объектам:


Но, похоже, статистики по JDBC нет.

Мониторинг OS

Мониторинг CPU, ОЗУ
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
 0  0 929068 149581824 1098396 140196416    0    0    77   234    0    0 22  2 76  0  0
 3  0 929052 149588400 1098400 140197936    2    0  1052   454 4157 7887  3  0 97  0  0
 0  0 929052 149595328 1098400 140197200    0    0   973    63 3535 7412  2  0 98  0  0
* Procs
r: число процессов ожидающих выполнение
b: число спящих процессов
* Memory
swpd: зарезервировано виртуальной памяти
free: свободной памяти
buff: памяти для буферов
cache: памяти под кэш
* Swap
si: памяти загруженной в озу с диска / сек
so: памяти выгруженной на диск / сек
* IO
bi: число считанных блоков / сек
bo: число записанных блоков / сек
* System
in: плановая смена контекста на новый поток
cs: внеплановая смена контекста, когда потом с большим приоритетом вытесняет низкоприоритетный
* % общего времени CPU
us: время за работой программ
sy: время работы ОС. Большой % тут означает большое число блокировок при доступе к ресурсам.
id: Время Idle
wa: время ожидания IO
st: Время виртуализации

Top CPU процессов
включая строку запуска процесса
ps -eo pid,user,pcpu,cmd --sort -pcpu
  PID USER     %CPU CMD
 9834 hive      188 /usr/jdk64/jdk1.8.0_112/bin/java ...
 7173 ams      46.9 /usr/jdk64/jdk1.8.0_112/bin/java ...
10438 yarn     17.9 /usr/jdk64/jdk1.8.0_112/bin/java ...
Потоки процесса
Получить список потоков, отсортированных по потреблению CPU:
ps -eLf --sort -pcpu | less
UID        PID  PPID   LWP  C NLWP STIME TTY          TIME CMD
hive     15690     1 15690  0  326 Nov18 ?        00:00:00 /usr/jdk64/jdk1.8.0_112/bin/java ...
hive     15690     1 15692  0  326 Nov18 ?        00:01:00 /usr/jdk64/jdk1.8.0_112/bin/java ...
В 4 столбце "LWP" находится ID потока.
Если сделать theatdump процесса через jstack, то можно найти проблемный поток, который грузит CPU.
Для этого LWP нужно преобразовать из десятичной системы в шестнадцатеритную и найти поток с этим nid (0x3d4a == 15690)
jstack [ option ] pid

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x00000250e4979000 nid=0x3d4a waiting on condition  [0x000000b82a9ff000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.ref.Reference.waitForReferencePendingList(java.base@10.0.1/Native Method)
    at java.lang.ref.Reference.processPendingReferences(java.base@10.0.1/Reference.java:174)
    at java.lang.ref.Reference.access$000(java.base@10.0.1/Reference.java:44)
    at java.lang.ref.Reference$ReferenceHandler.run(java.base@10.0.1/Reference.java:138)
   Locked ownable synchronizers:
    - None

Nethogs - Топ процессов по использованию сети


IOTOP - Топ процессов по использованию IO


Оптимизация работы с памятью в программах

Слабые ссылки
Слабые ссылки могут очищаться GC, даже если на них есть другие ссылки в программе.
Удобно использовать для кэша - даже если объект пропадет из памяти, его всегда можно восстановить.

* SoftReference - объект будет удален, если JVM очень нужна память и на объект только слабые ссылки
* WeakReference - объект будет удален, если на объект только слабые ссылки
* PhantomReference - могут быть удалены в любой момент
SoftReference<Object> cache = SoftReference<Object>(obj);
Object o = cache.get();
if (o != null) {
    //o
}

Finalizer
Finalizer - проблема для GC и создает дополнительную нагрузку.
Не гарантируется:
* Когда Finalizer будет вызван
* Будет ли Finalizer вообще вызван
* Порядок вызова Finalizer

Примитивы
* Используйте литералы, вместо создания строк
* Используйте глобальную видимость объектов, чтобы их переиспользовать
* Примитивы работают быстрей, чем объектные аналоги
* Условия проверки быстрей, генерации и отлова исключений
* Большое кол-во synchronization блокировок замедляет программу
* Используйте копирование памяти кусками (arraycopy), вместо построчного

Комментариев нет:

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