За годы работы у нас сформировался определенный опыт диагностики и решения проблем, связанные с производительностью наших Java-приложений. В этой статье я опишу причины торможения, с которыми приходилось столкнуться, и возможные пути их исправления. Также опишу основные настройки, которые мы делаем, и ресурсы сервера, которые использует приложение.

Речь пойдет о бизнес-приложениях с одним сервером Java-приложения и одним сервером базы данных PostgreSQL, в каждом из которых одновременно работают от 500 до 2000 сотрудников компании. Приложения разработаны на базе открытой и бесплатной платформы lsFusion (пример приложения), но большинство описанных проблем и настроек не являются специфическими именно для нее.

Архитектура

В нашем случае сервер приложения представляет собой простую службу, которая запускает один java-процесс, обрабатывающий подключения по RMI-протоколу. Он общается как с каждым десктоп-клиентом, установленным у конкретных пользователей через Web Start, так и с веб-сервером Apache Tomcat, которые реализует веб-интерфейс. С другой стороны, сервер приложения обращается к PostgreSQL для непосредственной работы с данными.

Как правило, мы устанавливаем сервер приложений и веб-сервер на одну виртуальную машину, а PostgreSQL - на другую. Общаются они друг с другом через сетевые подключения. В то же время, в случае относительно небольших баз данных, все службы устанавливаются на одну виртуальную машину.

Ресурсы

Основные ресурсы, которые потребляет сервер приложений - это CPU и память. Обращения к диску в нашем случае практически не идет, поэтому для сервера приложений можно спокойно выделять маленькие и медленные диски.

Сервер приложений lsFusion (как и большинство других java-приложений) использует CPU для двух целей : обработка запросов клиентов и сборка мусора. 

Специфика платформы lsFusion заключается в том, что сервер приложений является своего рода “прослойкой”, которая не хранит в себе пользовательских данных, а фактически только выполняет SQL-запросы к серверу БД, и передает их результат клиенту. Параллелизм в этом процессе практически не используется, поэтому один клиент в большинстве случаев использует один поток. Таким образом, количество используемых CPU для пользователей прямо пропорциональна количеству пользователей в системе.

В приложении на платформе lsFusion логика системы задается декларативно при помощи встроенного языка. В ходе работы на ее основе постоянно генерируются SQL-запросы при помощи достаточно сложных алгоритмов, чье выполнение составляет значительную часть загрузки CPU. Этот процесс мы называем “компиляцией запросов”. Важно понимать, что в случае очень сложной логики, генерация SQL запроса может занимать до нескольких секунд, что в свою очередь может приводить к задержкам для пользователей. Чтобы уменьшить нагрузку на процессор и ускорить процесс, “скомпилированные” SQL-запросы сохраняются в LRU-кэш, который является общим для всех пользователей. Таким образом одно и то же действие у разных пользователей может выполняться разное время. Данные из кэша удаляются по истечению определенного интервала времени при отсутствии к ним обращения. Этот интервал динамически изменяется в зависимости от загрузки памяти сервера приложений.

Сборка мусора

Одним из основных нововведений, появившихся в Java по сравнению с C++, было автоматическое управление памятью. Разработчику не нужно самостоятельно удалять объекты, а они сами очищаются, когда на них заканчиваются ссылки, специальным процессом, который называется сборщиком мусора. Такой подход значительно упрощает разработку и отладку, уменьшает количество ошибок, однако в то же время увеличивает потребление памяти.

Java-приложение, в отличие от PostgreSQL, как правило, работает как один процесс (если приложение само не создает новых) с большим количеством потоков. Самую большую часть  используемой памяти этим процессом занимает так называемая куча, в которой находятся все пользовательские объекты. Ее размер задается в параметрах запуска java-процесса и не может изменяться в ходе работы. Параметр Xms задает начальный размер кучи на запуске, а Xmx - максимальный размер. Мы, как правило, задаем их одинаковыми, так как никаких других служб на этих виртуальных машинах нет, и можно отдать серверу приложений сразу всю доступную память.

В любой момент времени память в куче занята тремя категориями объектов.

  1. Постоянные объекты. Они создаются на старте приложения и необходимы для работы платформы. Их размер зависит только от сложности логики приложения. Соответственно, чем больше размер кучи, выделенной для сервера приложений, тем таких объектов меньше в процентном соотношении.

  2. Кэши. Основную часть кэшей занимает кэш, в которым хранятся сгенерированные запросы. Его размер постоянно изменяется в зависимости от действий пользователей и интервала очистки. Туда попадают новые запросы, а старые по мере выпадания из интервала кэша автоматически собираются сборщиком мусора. Так как свойств в приложении могут быть десятки тысяч, то различных вариантов запросов могут быть сотни тысяч, и даже миллионы. По этой причине кэш занимает много памяти, и часто подвергается ротации.

  3. Временные объекты. Они создаются в ходе обработки пользовательских запросов и должны существовать непродолжительное время. В их число входят, например, данные, которые пользователь видит в определенный момент на форме, пролистывая таблицу.

Специфика работы Java-приложений заключается в том, что нехватка памяти чаще всего приводит не к завершению его работы, а к торможению. По мере того как память начинает заканчиваться, любой алгоритм сборки мусора начинает работать более активно, значительно нагружая CPU и останавливая работу пользовательских потоков. По этой причине, когда начинаются жалобы сразу всех пользователей на тормоза, в первую очередь мы смотрим на логи сборщика мусора. Для включения такого логирования в командную строку запуска приложения (где задаются и Xmx с Xms) добавляется следующая строка :

-Xlog:gc:file=logs/memory.log:tags,uptime,time,level:filecount=10,filesize=50m
-Xlog:gc*,gc+ergo+cset=info,gc+ref=info,gc+heap=info,gc+age=info,gc+phases=info:file=logs/gc.log:tags,uptime,time,level:filecount=10,filesize=50m

Для приложения на платформе lsFusion ее нужно добавить в параметр FUSION_OPTS файла /etc/lsfusion5-server/lsfusion.conf. Вместо logs/memory.log и logs/gc.log можно выбрать любой другой путь, в том числе и абсолютный. Первая часть строки включает логирование основных событий сборки мусора в файл memory.log, а вторая - более детальное логирование в gc.log, необходимое для глубокого анализа работы алгоритма сборки мусора. 

На практике мы используем два алгоритма сборки мусора : G1 и ZGC. По умолчанию, начиная с Java 11 используется сборщик мусора G1. ZGC рекомендуется использовать, только начиная с Java 17.

G1

Одной из важных особенностей данного алгоритма является, так называемый процесс Stop The World (STW). В этот момент все пользовательские процессы фактически приостанавливаются на определенное время для выполнения манипуляций с памятью.

Если немного упростить, то у этого сборщика мусора есть два режима работы : Normal и Mixed. В первом уничтожаются только “временные” объекты, которые были созданы совсем недавно и быстро стали не нужны (а в Java таких генерируется большое количество). В ходе этого процесса выполняется STW на небольшой промежуток времени. По умолчанию, он таргетируется на 200 мс, но в редких случаях может увеличиваться. В нормальном режиме лог работы сборщика мусора (в memory.log) будет выглядеть так :

Лог в режиме Normal

[2023-06-13T10:58:23.468+0300][132718,843s][info][gc] GC(15072) Pause Young (Normal) (G1 Evacuation Pause) 69342M->60419M(92160M) 164,364ms

[2023-06-13T10:58:27.551+0300][132722,926s][info][gc] GC(15073) Pause Young (Normal) (G1 Evacuation Pause) 69507M->60822M(92160M) 173,723ms

[2023-06-13T10:58:30.992+0300][132726,367s][info][gc] GC(15074) Pause Young (Normal) (G1 Evacuation Pause) 68918M->60846M(92160M) 140,823ms

[2023-06-13T10:58:35.382+0300][132730,757s][info][gc] GC(15075) Pause Young (Normal) (G1 Evacuation Pause) 69934M->61308M(92160M) 168,218ms

[2023-06-13T10:58:39.385+0300][132734,761s][info][gc] GC(15076) Pause Young (Normal) (G1 Evacuation Pause) 69788M->61625M(92160M) 183,205ms

[2023-06-13T10:58:43.183+0300][132738,559s][info][gc] GC(15077) Pause Young (Normal) (G1 Evacuation Pause) 68921M->61993M(92160M) 185,701ms

[2023-06-13T10:58:46.529+0300][132741,905s][info][gc] GC(15078) Pause Young (Normal) (G1 Evacuation Pause) 69417M->62546M(92160M) 191,775ms

[2023-06-13T10:58:48.827+0300][132744,202s][info][gc] GC(15079) Pause Young (Normal) (G1 Evacuation Pause) 69298M->62842M(92160M) 151,425ms

[2023-06-13T10:58:51.711+0300][132747,086s][info][gc] GC(15080) Pause Young (Normal) (G1 Evacuation Pause) 71162M->63417M(92160M) 172,871ms

[2023-06-13T10:58:54.858+0300][132750,233s][info][gc] GC(15081) Pause Young (Normal) (GCLocker Initiated GC) 70873M->63658M(92160M) 148,662ms

[2023-06-13T10:58:58.970+0300][132754,345s][info][gc] GC(15082) Pause Young (Normal) (G1 Evacuation Pause) 72970M->64051M(92160M) 158,405ms

[2023-06-13T10:59:02.736+0300][132758,111s][info][gc] GC(15083) Pause Young (Normal) (G1 Evacuation Pause) 71987M->64382M(92160M) 163,136ms

[2023-06-13T10:59:06.620+0300][132761,995s][info][gc] GC(15084) Pause Young (Normal) (G1 Evacuation Pause) 72990M->64630M(92160M) 167,712ms

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

Как только использованная память достигает определенного порога параллельно запускается подготовительный процесс Concurrent Mark Cycle для сборки уже и “старых” объектов. К этим объекта относятся как объекты, выпавшие из кэшей, так и временные объекты, которые по какой-то причине просуществовали долгое время.

Лог во время Concurrent Mark Cycle

[2023-06-13T10:59:09.442+0300][132764,817s][info][gc] GC(15085) Pause Young (Normal) (G1 Evacuation Pause) 73398M->64869M(92160M) 162,195ms

[2023-06-13T10:59:12.620+0300][132767,996s][info][gc] GC(15086) Pause Young (Normal) (GCLocker Initiated GC) 74053M->65239M(92160M) 171,033ms

[2023-06-13T10:59:16.562+0300][132771,937s][info][gc] GC(15087) Pause Young (Concurrent Start) (G1 Evacuation Pause) 73975M->65629M(92160M) 176,270ms

[2023-06-13T10:59:16.563+0300][132771,938s][info][gc] GC(15088) Concurrent Mark Cycle

[2023-06-13T10:59:19.438+0300][132774,814s][info][gc] GC(15089) Pause Young (Normal) (G1 Evacuation Pause) 72509M->66000M(92160M) 169,908ms

[2023-06-13T10:59:22.597+0300][132777,973s][info][gc] GC(15090) Pause Young (Normal) (G1 Evacuation Pause) 72240M->66164M(92160M) 142,407ms

[2023-06-13T10:59:28.069+0300][132783,444s][info][gc] GC(15091) Pause Young (Normal) (G1 Evacuation Pause) 75092M->66648M(92160M) 162,733ms

[2023-06-13T10:59:30.652+0300][132786,027s][info][gc] GC(15088) Pause Remark 71389M->70685M(92160M) 429,297ms

[2023-06-13T10:59:31.827+0300][132787,203s][info][gc] GC(15092) Pause Young (Normal) (G1 Evacuation Pause) 73272M->65931M(92160M) 209,858ms

[2023-06-13T10:59:35.621+0300][132790,996s][info][gc] GC(15093) Pause Young (Normal) (G1 Evacuation Pause) 74507M->66298M(92160M) 155,798ms

[2023-06-13T10:59:39.701+0300][132795,076s][info][gc] GC(15094) Pause Young (Normal) (G1 Evacuation Pause) 74714M->66537M(92160M) 157,649ms

[2023-06-13T10:59:43.672+0300][132799,047s][info][gc] GC(15095) Pause Young (Normal) (G1 Evacuation Pause) 75785M->66845M(92160M) 171,834ms

[2023-06-13T10:59:44.924+0300][132800,299s][info][gc] GC(15088) Pause Cleanup 69732M->69732M(92160M) 3,838ms

[2023-06-13T10:59:44.953+0300][132800,328s][info][gc] GC(15088) Concurrent Mark Cycle 28390,315ms

После его завершения будет запущена сборка мусора по всем объектам (Mixed) :

Лог в режиме Mixed

[2023-06-13T10:59:47.104+0300][132802,480s][info][gc] GC(15096) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 75261M->66993M(92160M) 154,723ms

[2023-06-13T10:59:48.266+0300][132803,641s][info][gc] GC(15097) Pause Young (Mixed) (G1 Evacuation Pause) 70545M->64039M(92160M) 134,788ms

[2023-06-13T10:59:50.164+0300][132805,540s][info][gc] GC(15098) Pause Young (Mixed) (G1 Evacuation Pause) 68103M->62145M(92160M) 216,037ms

[2023-06-13T10:59:52.386+0300][132807,761s][info][gc] GC(15099) Pause Young (Mixed) (G1 Evacuation Pause) 66177M->60924M(92160M) 292,175ms

[2023-06-13T10:59:54.121+0300][132809,496s][info][gc] GC(15100) Pause Young (Mixed) (G1 Evacuation Pause) 64956M->60118M(92160M) 329,477ms

[2023-06-13T10:59:55.846+0300][132811,221s][info][gc] GC(15101) Pause Young (Mixed) (G1 Evacuation Pause) 64150M->59568M(92160M) 399,318ms

[2023-06-13T10:59:58.029+0300][132813,404s][info][gc] GC(15102) Pause Young (Mixed) (G1 Evacuation Pause) 63600M->59262M(92160M) 414,342ms

[2023-06-13T11:00:00.539+0300][132815,915s][info][gc] GC(15103) Pause Young (Mixed) (G1 Evacuation Pause) 63294M->59115M(92160M) 488,603ms

[2023-06-13T11:00:02.762+0300][132818,137s][info][gc] GC(15104) Pause Young (Mixed) (G1 Evacuation Pause) 63147M->58769M(92160M) 508,020ms

[2023-06-13T11:00:07.423+0300][132822,798s][info][gc] GC(15105) Pause Young (Normal) (G1 Evacuation Pause) 68721M->59659M(92160M) 177,594ms

[2023-06-13T11:00:09.505+0300][132824,880s][info][gc] GC(15106) Pause Young (Normal) (G1 Evacuation Pause) 64875M->59638M(92160M) 139,130ms

В данном примере возникают не очень продолжительные паузы всех процессов (максимум 508мс), тем не менее они могут быть заметны пользователям, так как возникают последовательно за короткий интервал. Проблема алгоритма G1 заключается в том, что по мере роста размера кучи (увеличения Xmx) паузы во время Mixed сборки увеличиваются значительно быстрее. Это приводит к тому, что при 120ГБ выделенной памяти на практике сервер может останавливаться на 2-4 секунды, что уже очень некомфортно для пользователей. Частично это можно решить за счет увеличения параметра G1RSetRegionEntries (добавив в параметры запуска строку -XX:G1RSetRegionEntries=4096). Однако, это не полностью устраняет проблему, и фактически использовать больше 120ГБ с G1 для lsFusion проблематично (хотя в других java-приложениях может быть и больше, так как там по другому может использоваться память).

В нормальном режиме работы G1 очистка памяти должна происходить не медленнее, чем создание новых объектов. По мере увеличения потребления памяти, начинают чаще происходить Mixed сборки мусора, что увеличивает скорость очистки памяти, но в то же время увеличивая нагрузку на CPU. В случае, если все-таки память переполнится, например, во время Concurrent Markup Cycle, то происходит самое “страшное” : запускается Full GC. В этот момент все приложение целиком останавливается, и G1 начинает процесс полной сборки, чтобы очистить все, что может. Выглядит в логах это вот так :

Лог в момент Full GC

[2023-05-31T12:26:48.567+0300][51692,765s][info][gc] GC(5950) Pause Young (Normal) (G1 Preventive Collection) 101885M->100407M(102400M) 128,952ms

[2023-05-31T12:26:49.288+0300][51693,486s][info][gc] GC(5951) Pause Young (Normal) (G1 Preventive Collection) 101911M->100438M(102400M) 125,058ms

[2023-05-31T12:26:50.077+0300][51694,275s][info][gc] GC(5952) Pause Young (Normal) (G1 Preventive Collection) 101942M->100507M(102400M) 129,082ms

[2023-05-31T12:26:50.870+0300][51695,068s][info][gc] GC(5953) Pause Young (Normal) (G1 Preventive Collection) 101947M->100551M(102400M) 137,166ms

[2023-05-31T12:26:51.668+0300][51695,866s][info][gc] GC(5954) To-space exhausted

[2023-05-31T12:26:51.668+0300][51695,866s][info][gc] GC(5954) Pause Young (Normal) (G1 Preventive Collection) 101927M->102400M(102400M) 205,167ms

[2023-05-31T12:27:16.976+0300][51721,174s][info][gc] GC(5955) Pause Full (G1 Compaction Pause) 102400M->40140M(102400M) 25306,711ms

[2023-05-31T12:27:17.361+0300][51721,559s][info][gc] GC(5872) Concurrent Mark Cycle 186733,618ms

[2023-05-31T12:27:19.603+0300][51723,801s][info][gc] GC(5956) Pause Young (Normal) (G1 Evacuation Pause) 45260M->40789M(102400M) 212,895ms

В итоге все пользователи зависают на 25 секунд, но память при этом очищается с 100ГБ до 40ГБ.

Скорость сборки мусора также зависит от количества потоков, которые ей занимаются. Если для сборки во время STW (в частности при Full GC) задействуется сразу достаточное количество потоков ( по умолчанию, ⅝ всех логических ядер, и увеличение вряд ли поможет), то в обычном режиме используется четверть всех ядер. Увеличить их количество можно при помощи опции ConcGCThreads (поставить в строке запуска -XX:ConcGCThreads=<кол-во потоков>). Однако, слишком большое значение может приводить к тому, что ядер не будет хватать для пользовательских процессов. Поэтому с изменением этого параметра надо быть аккуратным.

При установке размера кучи с использованием G1 следует учитывать, что сам алгоритм использует достаточно большие структуры для хранения внутренней информации. Поэтому реальный объем потребляемой памяти может на 20-30% превышать выделенный размер кучи. Соответственно, выставлять параметр Xmx надо с учетом этого. Например, если выделить для кучи 100ГБ, то процесс может использовать 130ГБ. Если в операционной системе не будет хватать памяти процессу, то либо сработает oom_killer, убив все приложение, или пойдет использование swap.

ZGC

Для относительно небольших приложений стандартного сборщика мусора G1, как правило, достаточно. Когда количество одновременно работающих пользователей начинает превышать одну тысячу, то для того, чтобы избежать длительных пауз во время STW, мы используем ZGC. Чтобы его включить надо в параметры запуска добавить строку -XX:+UseZGC.

Следует отметить, что при больших размерах кучи часто бывает нужно поднимать параметр max_map_count. Это можно обнаружить в логах memory.log. При старте сервера в нем будет следующее предупреждение :

Предупреждение

[warning][gc] 

***** WARNING! INCORRECT SYSTEM CONFIGURATION DETECTED! *****

The system limit on number of memory mappings per process might be too low for the given

max Java heap size (102400M). Please adjust /proc/sys/vm/max_map_count to allow for at

least 184320 mappings (current limit is 65530). Continuing execution with the current

limit could lead to a premature OutOfMemoryError being thrown, due to failure to map memory.

Если этого не сделать, то сервер запустится, но через какое-то время работы просто внезапно упадет.

Преимущество алгоритма ZGC в том, что у него очень низкие глобальные паузы STW (несколько миллисекунд). Однако, из-за этого скорость сборки мусора у него ниже по сравнению с G1 (за все надо платить), что требует большего размера кучи. В то же время, ZGC не потребляет так много дополнительной памяти, как G1. Таким образом, если для G1 было выделено 120ГБ памяти, и он справлялся, то даже 150ГБ для ZGC может быть недостаточно. Необходимый размер мы обычно вычисляем опытным путем, но плюс в том, что ZGC может эффективно работать на очень больших объемах памяти. Учитывая, что на современных серверах памяти сейчас много, то можно выделить с запасом (мы выделяли пока максимум 300ГБ).

Когда ZGC не успевает очищать память быстрее, чем она используется, блокируются до следующего процесса очистки не все приложение, а лишь те процессы, которые создают новые объекты. В логах memory.log это выглядит следующим образом :

Лог ZGC

[2023-06-13T11:12:59.656+0300][41920,946s][info][gc] GC(473) Garbage Collection (Allocation Rate) 176690M(66%)->138672M(52%)

[2023-06-13T11:13:22.915+0300][41944,205s][info][gc] GC(474) Garbage Collection (Allocation Rate) 171332M(64%)->142632M(54%)

[2023-06-13T11:13:51.224+0300][41972,514s][info][gc] GC(475) Garbage Collection (Allocation Rate) 196496M(74%)->134658M(51%)

[2023-06-13T11:14:17.064+0300][41998,355s][info][gc] GC(476) Garbage Collection (Allocation Rate) 176030M(66%)->136424M(51%)

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-86818-Consignment.consignment-pausable-daemon-1) 118,959ms

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-78999-Disparity.disparities-pausable-daemon-4) 403,743ms

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-86302-Purchase.userOrder-pausable-daemon-1) 404,228ms

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-83403-Purchase.userOrder-pausable-daemon-2) 119,936ms

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-21120-Invoice.orderInvoiceDashboard-pausable-daemon-23) 8,367ms

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-86539-Purchase.userInvoice-pausable-daemon-1) 404,173ms

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-86465-Purchase.userOrder-pausable-daemon-1) 401,052ms

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-66068-Purchase.invoices-pausable-daemon-2) 398,211ms

[2023-06-13T11:14:52.235+0300][42033,526s][info][gc] Allocation Stall (pool-85728-Purchase.userInvoice-pausable-daemon-1) 395,880ms

В данном примере паузы незначительные, но в случае большой перегрузки памяти они могут составлять несколько секунд. Таким образом, с алгоритмом ZGC в отличие от G1 (с STW) пользователи “зависают” неравномерно, и у кого-то все может работать хорошо, а у кого-то будут тормоза. Также в ZGC отсутствует аварийный процесс полной очистки, поэтому в случае критических ситуаций выход в нормальный режим работы у него занимает значительно дольше, чем у G1.

Кэши

В ходе работы загрузка памяти непостоянна, и могут быть моменты, когда резко увеличивается генерация новых объектов, что приводит к тому, что сборка мусора перестает успевать. Когда такое происходит, платформа lsFusion пытается автоматически уменьшать размеры кэшей запросов (как самые большие), чтобы больше памяти оставалось под новые временные объекты. Для этой цели платформа слушает уведомления об окончании сборки мусора, и, если после ее завершения занятая память становится больше какого-то порога, то уменьшается интервал хранения LRU-кэшей запросов. 

Если, наоборот, занятая память становится меньше какого-то порога, то интервал увеличивается. Информация об этом процессе записывается в файл logs/lru.log

Лог LRU кэшей

14 июн. 2023 07:44:26,034  INFO LRULogger - COLLECTED, USED : 67409117696, LASTCOLLECTED : 68450582016

14 июн. 2023 07:44:27,907  INFO LRULogger - COLLECTED, USED : 66986689024, LASTCOLLECTED : 67409117696

14 июн. 2023 07:44:38,907  INFO LRULogger - ADJUST COLLECTED : 66986689024 UPAVERAGE : 67645734912, DOWNAVERAGE : 48318382080

14 июн. 2023 07:45:01,907  INFO LRULogger - COLLECTED, USED : 80522551808, LASTCOLLECTED : 66986689024

14 июн. 2023 07:45:02,907  INFO LRULogger - COLLECTED, USED : 77964502016, LASTCOLLECTED : 80522551808

14 июн. 2023 07:45:03,907  INFO LRULogger - COLLECTED, USED : 75632051200, LASTCOLLECTED : 77964502016

14 июн. 2023 07:45:05,907  INFO LRULogger - COLLECTED, USED : 73490678784, LASTCOLLECTED : 75632051200

14 июн. 2023 07:45:06,907  INFO LRULogger - COLLECTED, USED : 71532752384, LASTCOLLECTED : 73490678784

14 июн. 2023 07:45:08,126  INFO LRULogger - COLLECTED, USED : 69835786240, LASTCOLLECTED : 71532752384

14 июн. 2023 07:45:09,908  INFO LRULogger - COLLECTED, USED : 68563074560, LASTCOLLECTED : 69835786240

14 июн. 2023 07:45:11,331  INFO LRULogger - COLLECTED, USED : 67959500800, LASTCOLLECTED : 68563074560

14 июн. 2023 07:45:21,908  INFO LRULogger - ADJUST COLLECTED : 67959500800 UPAVERAGE : 67645734912, DOWNAVERAGE : 48318382080

14 июн. 2023 07:45:21,908  INFO LRULogger - DEC MULTI 1.645215055596301

14 июн. 2023 07:45:43,907  INFO LRULogger - COLLECTED, USED : 81505929216, LASTCOLLECTED : 67959500800

14 июн. 2023 07:45:44,907  INFO LRULogger - COLLECTED, USED : 78765725184, LASTCOLLECTED : 81505929216

14 июн. 2023 07:45:45,907  INFO LRULogger - COLLECTED, USED : 76320339968, LASTCOLLECTED : 78765725184

14 июн. 2023 07:45:47,177  INFO LRULogger - COLLECTED, USED : 74154607616, LASTCOLLECTED : 76320339968

14 июн. 2023 07:45:48,907  INFO LRULogger - COLLECTED, USED : 72082626048, LASTCOLLECTED : 74154607616

14 июн. 2023 07:45:50,243  INFO LRULogger - COLLECTED, USED : 70413041664, LASTCOLLECTED : 72082626048

14 июн. 2023 07:45:51,908  INFO LRULogger - COLLECTED, USED : 69021050880, LASTCOLLECTED : 70413041664

14 июн. 2023 07:45:53,907  INFO LRULogger - COLLECTED, USED : 68127248392, LASTCOLLECTED : 69021050880

14 июн. 2023 07:46:04,907  INFO LRULogger - ADJUST COLLECTED : 68127248392 UPAVERAGE : 67645734912, DOWNAVERAGE : 48318382080

14 июн. 2023 07:46:04,907  INFO LRULogger - DEC MULTI 1.371012546330251

14 июн. 2023 07:46:21,907  INFO LRULogger - COLLECTED, USED : 76099157504, LASTCOLLECTED : 68127248392

14 июн. 2023 07:46:22,907  INFO LRULogger - COLLECTED, USED : 73147974656, LASTCOLLECTED : 76099157504

14 июн. 2023 07:46:24,907  INFO LRULogger - COLLECTED, USED : 70566243840, LASTCOLLECTED : 73147974656

Строка DEC MULTI 1.371012546330251 показывает, что интервал хранения логов был снижен до 1.37 часа, как только использованная память после сборки (68127248392 байт) стала выше порога (67645734912 байт). Пороговый интервал использования памяти и скорость увеличения/снижения интервала задаются в настройках платформы.

Большое потребление памяти

Одним из главных рисков во время работы приложения является ситуация, когда определенный пользователь делает действие, которое начинает генерировать большое количество памяти. Например, это может быть выгрузка во внешний формат большого массива данных, или внесение изменений, которые могут приводить к высокой сложности алгоритма построения запроса. 

Платформа lsFusion умеет подсчитывать сколько новой памяти использует каждый поток за определенный интервал и постоянно записывает эту информацию в файл logs/allocatedbytes.log :

Лог генерации новой памяти по потокам
Лог генерации новой памяти по потокам

Для защиты от переполнения памяти в платформе есть определенные пороги, которые стараются предотвратить такую ситуацию. Например, есть порог по памяти, при превышении которого, результаты уже выполненного запроса не будут передаваться на сервер приложений, а пользователю будет выдано сообщение с ошибкой (TOO LARGE QUERY ROWS). Также платформа умеет автоматически уничтожать потоки, которые генерируют слишком много памяти за определенный интервал. 

Открытые файлы

Еще одной проблемой, с которой часто приходится сталкиваться на сервере приложений, является то, что во многих ОС на базе Linux, по умолчанию, выставлен достаточно низкий лимит на количество открытых файлов. Это сделано для того, чтобы один процесс не мог нарушить работы всей системы. В нашем же случае, вся виртуальная машина фактически работает для одного процесса, поэтому этот лимит имеет смысл поднимать.

По умолчанию, во многих ОС порог для одного процесса составляет всего 4096 файлов. При этом каждое сетевое подключение также попадает в "открытые файлы". Каждый пользователь (а их может быть больше 2000) или входящий/исходящий HTTP-запрос могут создавать новые соединения. В случае превышения порога, во время создания соединения или открытия файла потокам начнет приходить ошибка "Слишком много открытых файлов" ("Too many open files"). 

Для решения описанной проблемы лучше всего поднять пороги непосредственно для службы, которая запускает java приложение. В нашем случае мы в файле /usr/lib/systemd/system/lsfusion5-server.service добавляем следующий блок :

[Service]
LimitNOFILE=16384
LimitNOFILESoft=16384

Слишком большие пороги также не имеет смысла выставлять, так как если открытых файлов становится больше 16К, то явно что-то идет не так, и лучше выяснить и исправить первопричину проблемы.

Swap

Если выделить серверу приложений слишком большой размер кучи, то дальше возможны два варианта, когда операционной системе перестанет хватать памяти для java-приложения. Либо ОС завершит этот процесс при помощи oom_killer как главного и единственного претендента на смерть. Либо, если включен swap, то память начнет сбрасываться в него. И это тоже очень плохо. 

Дело в том, что во время любой сборки мусора идет реорганизация памяти. В частности, она идет и во время действий при STW, когда останавливаются все пользовательские потоки. Если в этот момент окажется, что нужный участок памяти находится в свопе, то во время его загрузки из свопа приложение будет висеть для всех. Кроме того, java никак не учитывает использование свопа и не отдаст уже выделенную память. То есть в своп уйдет какой-то другой кусок памяти, который потом также повиснет при следующей реорганизации памяти, и процесс торможения будет повторяться. Поэтому нужно всячески стараться избегать использования свопа на сервере приложений. Проще всего в таком случае просто понижать Xmx.

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

Также в swap операционная система может скидывать неиспользуемую память просто в ходе работы. Это регулируется системным параметром vm.swappiness и измеряется в процентах. Чтобы это максимально предотвратить, обычно мы его выставляем в /etc/sysctl.conf равным 1 или 0 :

vm.swappiness = 1

Резюме

Главный параметр, от которого зависит работа Java-приложения - это максимальный размер кучи (Xmx). Подбирать его нужно аккуратно опытным путем, так как слишком большое значение приведет к торможению из-за попадания памяти в своп. Слишком маленькое значение не будет утилизировать всю память сервера, а также будет приводить к более частым сборкам мусора и увеличению загрузки CPU. Чем больше CPU на сервере, тем быстрее за счет параллелизма будет идти сборка мусора, и тем меньше нужно памяти. Чем больше памяти на сервере, тем реже нужно будет собирать мусор, и тем меньше будет загрузка CPU.

Сборщик мусора G1 достаточно эффективен, но у него длинные паузы всего сервера приложений. По этой причине его можно использовать на серверах с общей памятью до 150ГБ, а далее лучше переключаться на ZGC (есть еще Shenandoah, но мы его пока нигде не пробовали). Рекомендуется настраивать логирование работы сборщика мусора, и смотреть в эти логи в первую очередь, если сразу все пользователи жалуются на медленную работу программы, или наблюдается очень высокая загрузка CPU.

Комментарии (3)


  1. pythoned195
    19.06.2023 15:09
    +2

    вместо парсинга логов может поставить jmx экспортер и закинуть его таргетом в графану ?


    1. CrushBy Автор
      19.06.2023 15:09

      Так можно и к Zabbix легко плагин прикрутить. Просто Zabbix обычно администрируют люди у заказчиков, и с ними надо согласовывать (что мы и делаем часто). Но логи все равно пишем, если нужен более детальный разбор логов сборки мусора (из gc.log).


  1. Throwable
    19.06.2023 15:09

    По поводу лимита файловых дескрипторов: практически во всех дистрибутивах он установлен в 1024.

    В JVM процессах ещё есть такая неприятная вещь, как non-heap memory, которая выходит за рамки лимита по Xmx и собственно вообще ничем не лимитируется. Его любят использовать всякие вещи, IO подсистемы и т.д. В итоге возможна ситуация, когда процесс убивается ОС, хотя в куче полно места, и OOM с дампом не сгенерированны. Особенно актуально, когда выставлены лимиты cgroups на контейнер.

    Ещё неплохая практика выставлять Xms равным Xmx, таким образом жёстко резервируя память для java процесса.