Статья будет полезна для тех, кто поддерживает приложения на Java, так как большая ее часть посвящена анализу работы G1 GC, знакомству с соответствующими инструментами и особенностями тюнинга GC, в частности для очень больших heap`ов. А также тем, кто пытается разобраться, на что способен Hazelcast, и для чего его можно применить.

Так исторически сложилось, что на проекте уже использовался Hazelcast, и мы решили попробовать переиспользовать его под новую задачу. Она заключалась в хранении объектов в БД с одним специфичным требованием – данные нельзя записывать на диск, что сильно сужало доступные варианты. Безусловно, мы понимали, что надежность такого хранилища будет низкой, но выбора не было. И, хотя, у нас были мысли развернуть для этого Redis или VoltDB, мы решили опробовать Hazelcast, так как в его возможности, помимо прочего, так же входит in-memory хранилище.

Что из этого получилось – читайте под катом.

Для кого и зачем

Эта статья посвящена тому, как мы сконфигурировали Hazelcast под свои нужды, на какие подводные камни наткнулись, как тюнили сборщик мусора и какие выводы о работе с Hazelcast сделали. По HZ не очень много материалов, и эта статья будет описывать, что он не умеет, а что – умеет. Рассматривать мы будем только OSS-версию. И все эксперименты будем проводить только с контейнером из репозитория – версии 5.3.1, так как это то, что у нас уже используется, и заменить образ возможности нет.

Статья состоит из трех частей:

  1. знакомство с распределенной map`ой в HZ и возможностями по ее настройке и настройке самого кластера;

  2. разбор инструментов, которые будем использовать в дальнейшем для анализа происходящего;

  3. попыток добиться стабильного и долговременного хранения наших данных в кластере.

Основная цель: хранить в RAM строки разнообразного размера, от килобайта до сотен мегабайт. Делать это будем с использованием распределенной map`ы Hazelcast`а.

К кластеру HZ предъявляются требования:

  • при падении n нод из 2n+1 кластера данные должны сохранять доступность и не потеряться, авария не должна повлиять на остальные ноды кластера, он не должен сложиться, как домино;

  • хранение большого количества данных – в кластере будут хранить десятки гигабайт (и хранить долго);

  • кластер должен справляться с загрузкой больших объектов в 10 МБ и больше;

  • нода кластера не должна падать по ООМ, при достижении лимита по памяти, должен срабатывать механизм выселения.

Hazelcast и распределенная map`а

Коротко о том, где мы будем разворачиваться. Мы создадим кластер для тестов в кубере из трех нод из официального чарта:

image:
  tag: "5.3.1"
cluster:
  memberCount: 3
resources:
  requests:
    memory: 10Gi
    cpu: 8
  limits:
    memory: 10Gi
    cpu: 8

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

Теперь познакомимся поближе с тем, как работает HZ, что такое map`а в его понимании, и какие возможности по ее конфигурированию у нас есть. Ориентироваться будем на документацию.

Распределенная map`а – это key-values хранилище, разбитое на партиции, равномерно распределенное по нодам кластера и расположенное исключительно в RAM. У каждой партиции может быть один или несколько бэкапов. Основные партиции и бэкапы распределены так, что копии одной партиции не находятся на одной ноде кластера. Ниже представлена визуализация этой схемы:

Пример распределения данных в хранилище из документации. Черным - основные партиции, синим - реплики
Пример распределения данных в хранилище из документации. Черным - основные партиции, синим - реплики

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

Важной для нас фишкой является возможность ограничить максимальный размер хранилища, задав максимальное количество объектов в map`е. Вариантов реализации много, и подробнее о них можно почитать в документации. Если кратко, мы можем ограничить размер хранилища в целом или размер партиции, а также путем задания максимального количества памяти heap`а, которые она может занимать. Если при добавлении очередного объекта в map`у превышается заданный лимит, будет выполнено выселение. Ниже показан его алгоритм:

Схема алгоритма выселения из документации
Схема алгоритма выселения из документации

Если места не хватает (условие на 3 шаге), выбирается наилучший кандидат на выселение среди случайно выбранных ключей (шаги c 4 по 8), и делается это несколько раз, пока не освободится достаточно места под новый объект (это на диаграмме алгоритма из документации не отображено, но мы об этом поговорим позже). На 7 шаге на выбор доступны по дефолту политики вымещения LRU, LFU или RANDOM. Также можно написать свой компаратор. Но это, скорее, задача для разработчика, поэтому рассматривать его не будем. То есть алгоритм вероятностный, и выселяться будет не наиболее подходящий объект в map`е, а наиболее подходящий в случайной выборке.

Возвращаясь к настройкам map`ы, для объекта в map`е можно определить время жизни time-to-live-seconds или max-idle-seconds. Стоит обратить внимание, что выселение по времени жизни не будет работать, если не включить per-entry-stats-enabled, иначе в метаданных записи не будет информации о времени ее последнего изменения или обращения к ней.

Планирование емкости кластера

Теперь, когда стало понятнее, с чем мы имеем дело, познакомимся с рекомендациями по планированию емкости кластера, которые дает документация.

Пойдем по пунктам, которые имеют значения для наших целей, прикидывая значения под размер тестового кластера.

  • Объем данных в памяти – на данном этапе не понятно, какой overhead по памяти даст сам Hazelcast. Рекомендации предлагают оставить 40% памяти под работу Hazelcast и только 60% под данные, что выглядит очень расточительно – почти половина ресурса кластера уходит в никуда. Пока будем считать, что данных у нас будет 8 ГБ на ноду кластера.

  • Количество бэкапов – исходя из требования нам нужен 1 бэкап, чтобы кластер мог успешно пережить падение одного из серверов.

  • Синхронный или асинхронный бэкап – для наших задач важна консистентность данных, поэтому синхронный.

  • Партиционирование – по умолчанию партиций 271. Попробуем рассчитать, сколько данных будет в одной партиции – у нас 8 ГБ на ноду, три ноды и один бэкап. Итого:
    8 ГБ * 3 / 2 = 12 ГБ
    12 ГБ / 271 ~ 45 МБ

  • В документации рекомендуется придерживаться размера партиций от 50 МБ до 100 МБ, так что будем считать, что уменьшать количество партиций нет смысла.

Эти и другие параметры можно задать отдельно для каждой создаваемой map`ы, указав их в секции map конфига ноды, в чарте кубера у нас это будет .hazelcast.yaml.hazelcast.map.test-map.

Общесистемные параметры

Познакомимся с общесистемными параметрами и отметим, что может понадобиться:

  • hazelcast.graceful.shutdown.max.wait – максимальный период ожидания завершения работы кластера для выполнения graceful shutdown. Этот параметр нужно будет определить эмпирически: наполнить кластер данными, выключить одну ноду и засечь, сколько времени партиции мигрируют между нодами;

  • hazelcast.map.eviction.batch.size – максимальное количество ключей map`ы, которые будут выселены в одном цикле вымещения при изменении в map`е;

  • hazelcast.map.eviction.sample.count – количество ключей map`ы, из которых будет выполнено выселение согласно заданной политике;

  • hazelcast.partition.count – количество партиций map`ы или другого распределенного хранилища;

  • hazelcast.partition.max.parallel.migrations – максимальное количество партиций, которые могут одновременно мигрировать на одной ноде кластера. Для нас важно то, что этот параметр влияет на overhead по памяти в случае аварии, когда начинается перераспределение партиций. Чем больше параллельных миграций - тем больше overhead. По умолчанию их 10;

  • hazelcast.partition.migration.stale.read.disabled – позволяет выполнять чтение из находящихся в стадии миграции партиций. Если чтение разрешено, есть риск прочитать неактуальные данные. Но может быть полезен в случае, если миграция партиций выполняется слишком долго, так как в этой время map`а фактически становится недоступной. По умолчанию отключено;

  • hazelcast.max.no.heartbeat.seconds – таймаут ожидания hearbeatа, через который нода кластера будет считаться упавшей, по умолчанию – 60 секунд;

  • hazelcast.shutdownhook.policy – политика выключения ноды кластера. Есть два варианта: TERMINATE and GRACEFUL. Варианты говорят сами за себя. Gracefull позволяет данным мигрировать на другие ноды перед остановкой;

  • hazelcast.shutdownhook.enabled – включает или отключает возможность завершить работу кластера gracefully;

  • hazelcast.jmx – включает экспорт JMX-метрик.

Также в документации есть рекомендации по настройке JVM. Там рекомендуют использовать G1 GC (в контейнере hazelcast/hazelcast:5.3.1, используется Java 11, поэтому он и так используется по дефолту), и не тюнить GC, если только в этом нет необходимости.

Откровенно бесполезные рекомендации оставить все по дефолту, можно было бы и не указывать это. Мы сразу их нарушим и выставим Xmx и Xms, чтобы задать фиксированные размер heap в абсолютных значениях, а не в виде 80% от общей памяти, как это было изначально. Это будет нагляднее, чем проценты, да и размер heap`а и так придется менять, чтобы подобрать оптимальный.

Настройки кластера

Исходя из всего выше сказанного, зададим настройки кластера и map`ы.

Рядом с каждым из параметров в виде комментария указано обоснование выбора
hazelcast:
  # Включаем Hazelcast
  enabled: true
  # Добавляем флаги JVM, которые будет переданы через ENV переменную JAVA_OPTS. В эту же строку мы будем в дальнейшем добавлять новые флаги в процессе тюнинга GC и системные параметры Hazelcast. Пока у нас установлен максимальный и минимальный размер heap`а
  javaOpts: "-Xmx9g -Xms9g"
  yaml:
    hazelcast:
      # задаем имя кластера
      cluster-name: test
      map:
        # Задаем параметры для map`ы
        test-map:
          # Сбор статистики о каждом вхождении map`ы. Увеличивает хранения метаданных на запись примерно на 40 байт, то есть до ~90 байт - https://docs.hazelcast.com/hazelcast/5.3/data-structures/reading-map-metrics
          # Но без этой статистики не будет работать выселение по TTL
          per-entry-stats-enabled: true
          # Количество реплик map`ы
          backup-count: 1
          # Формат в котором данные хранятся, мы храним строки, поэтому бинарный формат будет к месту
          in-memory-format: BINARY
          # Включает статистику map`ы, это позволит мониторить размер map`ы, количество операций и прочее
          statistics-enabled: true
          # Настраиваем политику выселения
          eviction:
            # Удалять самый старый по времени обращения объект при достижении лимита памяти
            eviction-policy: LRU
            # Ограничиваем размер heap`а, который может занимать map`а на одной ноде
            max-size-policy: USED_HEAP_SIZE
            # Максимальный размер в мегабайтах, начнем наши эксперименты с 8 ГБ
            size: 8192
          # Зададим время жизни в 0, то есть отключим на время экспериментов
          time-to-live-seconds: 0
        # Задаем настройки map по умолчанию
        default:
          time-to-live-seconds: 0
          in-memory-format: BINARY
          eviction:
            eviction-policy: LRU
            max-size-policy: USED_HEAP_SIZE
            size: 1
      # Конфигурация системных настроек кластера, сюда также походу статьи будем добавлять параметры
      properties:
        hazelcast.shutdownhook.policy: GRACEFUL
        hazelcast.shutdownhook.enabled: true
        hazelcast.graceful.shutdown.max.wait: 600
        hazelcast.jmx: true
      # настройки защиты от split-brain, в статье они не затрагиваются
      # https://docs.hazelcast.com/imdg/4.2/network-partitioning/split-brain-protection
      split-brain-protection:
        splitBrainProtectionRuleWithFourMembers:
          enabled: true
          minimum-cluster-size: 2

Какие инструменты будем использовать

Чтобы не действовать вслепую, нам понадобятся инструменты для отслеживания происходящего в Hazelcast`е и в самой JVM. Использование Hazelcast Management Center сразу отметаем, потому что при размере кластера больше 3-х нод для его использования требуется лицензия.

Начнем с того, что включим экспортер метрик HZ и JMX. Образ Hazelcast позволяет добавить в java agent prometheus экспортер. С этими метриками можно заменить Hazelcast Management center на Grafana и Prometheus. В чарте эти метрики включаются параметром:

metrics:
  enabled: true

Также чуть выше мы включили statistics-enabled и per-entry-stats-enabled.

Выбор дашбордов

К сожалению, хорошего дашборда для мониторинга состояния кластера мы не нашли, поэтому взяли то, что нашли в Интернете, объединили, немного дополнили и получили такой дашборд. Он позволяет отслеживать размер heap`а, потребление нативной памяти, работу алгоритма выселения и размер партиций map`ы на ноде. За всем этим придется следить во время тестирования кластера. Еще нужно будет следить за состоянием JVM, для этого мы использовали обычный дашборд JVM, например этот. Но его пришлось немного подкорректировать под наши лейблы.

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

Логи GC и SJK

Метрики JMX не покроют все наши потребности анализа работы JVM. В JMX не видно, что происходит при сборке мусора в деталях, не виден mixed GC, не видно и деталей потребления нативной памяти. Поэтому добавим в флаги JVM включение логов GC и отслеживание нативной памяти:

hazelcast:
  javaOpts: "-XX:NativeMemoryTracking=detail -Xlog:gc*:stderr:time,level,tags"

В логах GC мы хотим видеть, когда вызывается mixed GC, как идет процесс пометки живых объектов в old gen, сколько времени занимают паузы full GC, и сколько сегментов памяти удалось очистить. Если в статье появляются логи, как ниже – это логи GC:

[info][gc,start       ] GC(1411) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[info][gc,task        ] GC(1411) Using 8 workers of 8 for evacuation
[info][gc             ] GC(1411) To-space exhausted
[info][gc,phases      ] GC(1411)   Pre Evacuate Collection Set: 0.1ms
[info][gc,phases      ] GC(1411)   Evacuate Collection Set: 0.9ms
[info][gc,phases      ] GC(1411)   Post Evacuate Collection Set: 0.2ms
[info][gc,phases      ] GC(1411)   Other: 0.2ms
[info][gc,heap        ] GC(1411) Eden regions: 1->0(14)
[info][gc,heap        ] GC(1411) Survivor regions: 0->0(2)
[info][gc,heap        ] GC(1411) Old regions: 274->275
[info][gc,heap        ] GC(1411) Humongous regions: 13->13
[info][gc,metaspace   ] GC(1411) Metaspace: 57373K(60368K)->57373K(60368K) NonClass: 50801K(52560K)->50801K(52560K) Class: 6571K(7808K)->6571K(7808K)
[info][gc             ] GC(1411) Pause Young (Concurrent Start) (G1 Humongous Allocation) 8650M->8650M(9216M) 1.589ms
[info][gc,cpu         ] GC(1411) User=0.00s Sys=0.00s Real=0.00s

Так как мы используем официальный образ с JRE, то у нас нет jcmd, jstat, jfr и прочих утилит. Для простоты мы использовали sjk, который покрыл все наши запросы в рамках этих работ. Чтобы утилита могла работать, надо в чарте отключить RO ограничение на файловой системе:

securityContext:
  # readOnlyRootFilesystem is a flag to enable readOnlyRootFilesystem for the Hazelcast security context
  readOnlyRootFilesystem: false

После чего просто копируем jar`ник в контейнер или прямо на ноду с ним. Подключаться к процессу можно будет по pid.

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

  • чтобы посмотреть значение флагов JVM

java -jar /data/external/sjk.jar vminfo -p ${PID} --flags
  • чтобы посмотреть распределение нативной памяти

java -jar /data/external/sjk.jar jcmd -p ${PID} -c VM.native_memory

Флаг NativeMemoryTracking, который установили ранее, позволит получить с помощью этой командой следующий вывод:

Native Memory Tracking
Native Memory Tracking:
Total: reserved=52771384KB, committed=52453848KB
-                 Java Heap (reserved=50331648KB, committed=50331648KB)
                            (mmap: reserved=50331648KB, committed=50331648KB) 
-                     Class (reserved=61637KB, committed=59845KB)
                            (classes #10788)
                            (  instance classes #10201, array classes #587)
                            (malloc=2245KB #31979) 
                            (mmap: reserved=59392KB, committed=57600KB) 
                            (  Metadata:   )
                            (    reserved=59392KB, committed=57600KB)
                            (    used=56469KB)
                            (    free=1131KB)
                            (    waste=0KB =0.00%)
-                    Thread (reserved=114481KB, committed=13265KB)
                            (thread #111)
                            (stack: reserved=113961KB, committed=12745KB)
                            (malloc=392KB #668) 
                            (arena=128KB #220)
-                      Code (reserved=250264KB, committed=35736KB)
                            (malloc=2576KB #10859) 
                            (mmap: reserved=247688KB, committed=33160KB) 
-                        GC (reserved=1977885KB, committed=1977885KB)
                            (malloc=76749KB #26061) 
                            (mmap: reserved=1901136KB, committed=1901136KB) 
-                  Compiler (reserved=7618KB, committed=7618KB)
                            (malloc=716KB #911) 
                            (arena=6902KB #12)
-                  Internal (reserved=1047KB, committed=1047KB)
                            (malloc=1015KB #2247) 
                            (mmap: reserved=32KB, committed=32KB) 
-                     Other (reserved=2435KB, committed=2435KB)
                            (malloc=2435KB #49) 
-                    Symbol (reserved=12386KB, committed=12386KB)
                            (malloc=9310KB #108513) 
                            (arena=3077KB #1)
-    Native Memory Tracking (reserved=3449KB, committed=3449KB)
                            (malloc=426KB #6030) 
                            (tracking overhead=3022KB)
-               Arena Chunk (reserved=7967KB, committed=7967KB)
                            (malloc=7967KB) 
-                   Logging (reserved=5KB, committed=5KB)
                            (malloc=5KB #193) 
-                 Arguments (reserved=22KB, committed=22KB)
                            (malloc=22KB #537) 
-                    Module (reserved=207KB, committed=207KB)
                            (malloc=207KB #1878) 
-              Synchronizer (reserved=326KB, committed=326KB)
                            (malloc=326KB #2751) 
-                 Safepoint (reserved=8KB, committed=8KB)
                            (mmap: reserved=8KB, committed=8KB) 

Управление кластером и доступ к хранилищу из командной строки

В качестве cli для выполнения ручных операций мы будем использовать hz-cli. Она есть в контейнере с самим сервером, либо ее можно поставить на отдельный сервер или запустить в отдельном контейнере. Последние два варианта предпочтительнее. hz-cli будет использовать те же JVM флаги, что и основное приложение, подтягивая их из переменной окружения JAVA_OPTS. Поэтому, если там будут флаги вроде Xms, мы рискуем уронить контейнер целиком с ООМ.

Подключаться к кластеру будем командой:

hz-cli --targets test@hazelcast:5701 console
hz-cli --help
Usage: hz-cli [-hvV] [-f=<config>] [-t=[<cluster-name>@]<hostname>:<port>[,
              <hostname>:<port>]] [COMMAND]
Utility to perform operations on a Hazelcast cluster.
By default it uses the file config/hazelcast-client.xml to configure the client
connection.
 
Global options are:
 
  -t, --targets=[<cluster-name>@]<hostname>:<port>[,<hostname>:<port>]
                          The cluster name and addresses to use if you want to
                            connect to a cluster other than the one configured in
                            the configuration file. At least one address is
                            required. The cluster name is optional.
  -h, --help              Show this help message and exit.
  -V, --version           Print version information and exit.
  -f, --config=<config>   Optional path to a client config XML/YAML file. The
                            default is to use config/hazelcast-client.xml.
  -v, --verbosity         Show logs from Jet client and full stack trace of errors
Commands:
  help             Displays help information about the specified command
  cancel           Cancels a running job
  cluster          Shows current cluster state and information about members
  console          Starts the console application for trying out in-memory data
                     structures of Hazelcast. It is not recommended for use in
                     production.
  delete-snapshot  Deletes a named snapshot
  list-jobs        Lists running jobs on the cluster
  list-snapshots   Lists exported snapshots on the cluster
  restart          Restarts a running job
  resume           Resumes a suspended job
  save-snapshot    Exports a named snapshot from a job and optionally cancels it
  sql              Starts the SQL shell [BETA]
  submit           Submits a job to the cluster
  suspend          Suspends a running job

Мы будем использовать hz-cli для базовых действий:

  • смотреть значение ключа

  • смотреть размер map`ы

  • чистить map`у

На мой взгляд, возможность этой cli очень ограничены, поэтому помимо нее я часто использую Python-клиент. Через него, например, можно посмотреть статистику по каждому ключу, узнать, в какую партицию попал ключ, на какую ноду и так далее. Пример использования ниже:

>>> import hazelcast
>>> config = hazelcast.config.Config()
>>> config.client_name = "load-test"
>>> config.cluster_members = ["hazelcast:5701"]
>>> config.cluster_name = "test"
>>> client = hazelcast.HazelcastClient(config)
>>> map = client.get_map("test-map")
>>> key_info = map.get_entry_view("2")
>>> result = key_info.result()
>>> result.creation_time
1708718561000
>>> result.cost
4184

Еще одна важная утилита - hz-cluster-admin. Мы ее использовать не будем, но о ней нужно знать. Она позволяет управлять кластером в целом, например, перевести его в состояние NO_MIGRATION можно командой:

# Проверить состояние кластера
hz-cluster-admin -a ${CLUSTER_ADDR} -p 30701 -o get-state
# Сменить состояние на no_migration
hz-cluster-admin -a ${CLUSTER_ADDR} -p 30701 -o change-state -s no_migration
hz-cluster-admin --help
Utility to query and change the state of a Hazelcast cluster.
It uses the Hazelcast REST API, which must be enabled in the cluster's
configuration.  To enable REST API, please do one of the following:
- Change member config using JAVA API: config.getNetworkConfig().getRestApiConfig().setEnabled(true);
- Change XML/YAML configuration property: hazelcast.network.rest-api.enabled to true
- Add system property: -Dhz.network.rest-api.enabled=true
- Add environment variable property: HZ_NETWORK_RESTAPI_ENABLED=true
 A command may fail with a message like
'REST endpoint group is not enabled - CP'.
In that case you must change the cluster's configuration to enable
the CP endpoint group.
To enable CP endpoint group, please do one of the following:
- Change member config using JAVA API: config.getNetworkConfig().getRestApiConfig().enableGroups(RestEndpointGroup.CP);
./hz-cluster-admin: line 17: enabled: command not found
- Change XML/YAML configuration property: hazelcast.network.rest-api.endpoint-group CP with  set to true
- Add system property: -Dhz.network.rest-api.endpoint-groups.cp.enabled=true
- Add environment variable property: HZ_NETWORK_RESTAPI_ENDPOINTGROUPS.CP.ENABLED=true

Parameters:
  -o, --operation    : Specifies the operation to perform, one of 'get-state', 'change-state',
                       'shutdown', 'force-start', 'partial-start', 'get-cluster-version',
                       'change-cluster-version'.
  -s, --state        : Changes the cluster state. Valid states: 'active', 'frozen', 'passive', 'no_migration'.
  -a, --address      : IP address to connect to. The default is 127.0.0.1.
  -p, --port         : TCP port to connect to. The default is 5701.
  -c, --clustername : The name of the cluster. The default is 'dev'.
  -P, --password     : The password of the cluster. The default is 'dev-pass'.
  -v, --version      : The cluster version to change to. To be used with '-o change-cluster-version'.
  -d, --debug        : Show verbose output from curl

HTTPS-related (relevant only when TLS is enabled on the Hazelcast cluster):
      --https        : Use the HTTPS protocol for REST calls.
      --cacert       : Path to the trusted PEM-encoded certificate, used to verify member certificates.
      --cert         : Path to the PEM-encoded client certificate. Needed for client certificate authentication.
      --key          : Path to the PEM-encoded client private key. Needed for client certificate authentication.
      --insecure     : Disable member certificate verification.

Инструменты для тестирования

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

  • load-test.py – наполняет map`у ключами по порядку с n до n+c, где

    n, c – целые положительные числа,
    n – количество объектов в map`е на момент старта скрипта,
    c – количество ключей, которые будут добавлены.
    Размер строки будем задавать в зависимости от потребностей.

  • check-eviction.py – проверяет, какие ключи были вымещены. В вывод будет выдано немного данных о содержимом map`ы и затем построчно количество выселенных ключей. В load-test.py мы задавали ключи последовательными числами, этот же скрипт делит числовой отрезок на батчи согласно размеру, который можно задать через флаг. И в выводе печатает количество выселенных ключей в каждом батче. Потом этот массив чисел можно занести, к примеру, в excel-таблицу и построить график или использовать matplotlib, или любой другой инструмент визуализации на выбор.

Код скриптов:

load-test.py

#! /usr/bin/env python3
# -*- coding: utf-8 -*-
import argparse
import os
from datetime import timedelta
import time
import hazelcast
import math
from hazelcast.future import combine_futures

def progress_bar(current, total, message, bar_length=20):
    fraction = current / total

    arrow = int(fraction * bar_length - 1) * '-' + '>'
    padding = int(bar_length - len(arrow)) * ' '

    ending = '\n' if current == total else '\r'
    string_to_print = f'{message}: [{arrow}{padding}] {int(fraction*100)}%'
    print(string_to_print, " " * ( os.get_terminal_size().columns - len(string_to_print.encode(encoding = 'UTF-8', errors = 'strict')) ), end=ending)
    
parser = argparse.ArgumentParser(prog='load-test', description='Небольшой бенчмарк для hazelcast')
parser.add_argument('-b','--batch', required=False, dest='batch', default=10000, type=int, action='store',
    help='Размер групп, в которых объекты отправляются (влияет только на отображение прогресса)')
parser.add_argument('-s','--size', required=False, dest='size', type=int, default=1, action='store',
    help='Размер объекта для сохранения в килобайтах')
parser.add_argument('-c','--count', required=True, dest='count', type=int, action='store',
    help='Количество элементов для добавления')
parser.add_argument('-m','--member', required=True, dest='members', type=str, action='append',
    help='Ноды кластера, к которым будет выполняться подключение')
parser.add_argument('--smart', required=False, dest='smart', action='store_true', default=False,
    help='smart-routing будет включен')
parser.add_argument('--cluster', required=False, dest='cluster', action='store', default='dev',
    help='Имя кластера, к которому выполняется подключение')
parser.add_argument('--map', required=False, dest='map', action='store', default='test-map',
    help='Имя мапы, которая будет наполнена')
args = parser.parse_args()
    
batch = args.batch
put_items = args.count
size = args.size
members = args.members
smart = args.smart
cluster = args.cluster
map = args.map


print("Запуcк")
config = hazelcast.config.Config()
config.client_name = "load-test"
config.cluster_members = members
config.smart_routing = len(members) > 1 or smart
config.cluster_name = cluster
client = hazelcast.HazelcastClient(config)

map = client.get_map(map)
keys = map.key_set().result()
keys = [int(numeric_string) for numeric_string in keys]
keys.sort()

last_old_key = keys[-1] if len(keys) > 0 else 0
first_new_key = last_old_key + 1
last_new_key = last_old_key + put_items
print(f"Заполняются ключи с {first_new_key} по {last_new_key}")
string_val = "x" * 1024 * size
results = []
start_time = time.time()
for i in range(first_new_key, last_new_key + 1):
    res = map.put(f"{i}", string_val)
    results.append(res)
    if i % batch == 0:
        combine_futures(results).result()
        new_time = time.time()
        
        time_left = ( new_time - start_time ) * ( last_new_key - i ) / batch
        progress_bar(i - first_new_key, put_items, f"{timedelta(seconds=math.ceil(time_left))} осталось")
        
        start_time = new_time
        results = []
    

progress_bar(put_items - 1, put_items, "Почти готово")
combine_futures(results).result()
progress_bar(put_items, put_items, "Готово")
client.shutdown()

check-eviction.py

#! /usr/bin/env python3
# -*- coding: utf-8 -*--
import argparse
import hazelcast

parser = argparse.ArgumentParser(prog='check-eviction', description='Проверка выселенных элементов после бенчмарка')
parser.add_argument('-m','--member', required=True, dest='members', type=str, action='append',
    help='Ноды кластера, к которым будет выполняться подключение')
parser.add_argument('--smart', required=False, dest='smart', action='store_true', default=False,
    help='smart-routing будет включен'
parser.add_argument('-b','--batch', required=False, dest='batch', default=1000, type=int, action='store',
    help='Размер групп, на которые будут разбиты ключи для подсчета выселенных элементов')
parser.add_argument('--cluster', required=False, dest='cluster', action='store', default='dev',
    help='Имя кластера, к которому выполняется подключение')
parser.add_argument('--map', required=False, dest='map', action='store', default='test-map',
    help='Имя мапы, которая будет наполнена')
args = parser.parse_args()

members = args.members
cluster = args.cluster
map = args.map
batch = args.batch

config = hazelcast.config.Config()
config.client_name = "load-test"
config.cluster_members = members
config.smart_routing = smart
config.cluster_name = cluster
client = hazelcast.HazelcastClient(config)

map = client.get_map(map)
keys = map.key_set().result()
keys = [int(numeric_string) for numeric_string in keys]
keys.sort()
keys_len = len(keys)
print("Первый ключ: ", keys[0])
print("Последний ключ: ", keys[-1])
print("Размер: ", keys_len)
print("Батч: ", batch)
p = keys[0]
keys = keys[1 : keys_len]
splits = []
skipped_batch_value = batch
for i in keys:
    if ( p + 1 ) != i:
        for s in range(p + 1, i):
            d, _ = divmod(s, batch)
            d += 1
            if len(splits) < d:
                splits += [skipped_batch_value] * (d - len(splits))
                splits[d - 1] = 0
            splits[d - 1] += 1
        
        skipped_batch_value = 0 
    p = i

print("Выселено: ", sum(splits))
for i in splits:
    print(i)

client.shutdown()

Начинаем эксперименты

Поставим перед собой цели, что мы будем проверять.

  1. Проверим, что расчетное количество объектов успешно помещается в map`у и там хранится. Данные не превышают по размеру лимит.

  2. Проверим доступность кластера. При падении n нод кластера он продолжает работу, старые данные из кластера не теряются, могут быть прочитаны и могут быть добавлены новые.

  3. Проверим, что размер объектов может быть любой. При добавлении большого объекта в map`у, заполненную под завязку маленькими, адекватно срабатывает выселение.

  4. Проверим, что выселение объектов не затрагивает новые объекты.

Далее пойдем по этим четырем сценариям.

Сценарий 1. Проверяем вместимость

Для начала посчитаем в теории, сколько у нас поместится файлов. Сделаем это по формуле:

ОбъектовПоместится = ОЗУНаОднойНоде * КолвоНод / ( ( 1 + КолвоБэкапов ) * РазмерОбъекта )

Пускай размер объектов будет 5 МБ, в таком случае мы можем рассчитывать на 2676 объектов.

Сгенерируем соответствующие объекты, выполнив

./load-test.py -c 2676 -m hazelcast.test:5701 --smart --size=5120 --batch=50 --cluster test --map test-map

И сразу же падаем по heap space OOM. Графики в данном случае не очень информативны – хип действительно закончился, но это было и так понятно:

Дашборд JVM 1
Дашборд JVM 1

Смотрим логи полного GC, который выполнялся перед падением, и видим:

[info][gc             ] GC(1206) Pause Full (G1 Humongous Allocation) 9185M->9173M(9216M) 43.699ms
[info][gc,cpu         ] GC(1206) User=0.14s Sys=0.00s Real=0.04s
[info][gc,task        ] GC(1207) Using 8 workers of 8 for full compaction
[info][gc,start       ] GC(1207) Pause Full (G1 Humongous Allocation)
[info][gc,phases,start] GC(1207) Phase 1: Mark live objects
[info][gc,stringtable ] GC(1207) Cleaned string and symbol table, strings: 23848 processed, 0 removed, symbols: 153109 processed, 0 removed
[info][gc,phases      ] GC(1207) Phase 1: Mark live objects 8.835ms
[info][gc,phases,start] GC(1207) Phase 2: Prepare for compaction
[info][gc,phases      ] GC(1207) Phase 2: Prepare for compaction 2.767ms
[info][gc,phases,start] GC(1207) Phase 3: Adjust pointers
[info][gc,phases      ] GC(1207) Phase 3: Adjust pointers 8.374ms
[info][gc,phases,start] GC(1207) Phase 4: Compact heap
[info][gc,phases      ] GC(1207) Phase 4: Compact heap 1.170ms
[info][gc,heap        ] GC(1207) Eden regions: 0->0(115)
[info][gc,heap        ] GC(1207) Survivor regions: 0->0(15)
[info][gc,heap        ] GC(1207) Old regions: 9->9
[info][gc,heap        ] GC(1207) Humongous regions: 2286->2286
[info][gc,metaspace   ] GC(1207) Metaspace: 54575K(57552K)->54575K(57552K) NonClass: 48244K(50000K)->48244K(50000K) Class: 6330K(7552K)->6330K(7552K)

Нас интересуют три ключевые фразы: Humongous Allocation, Old regions: 9, Humongous regions: 2286. На что мы наткнулись – G1 GC делит память на регионы. Если объект занимает больше половины региона, он считается огромным и попадает сразу в old gen. Но главное для нас – это то, сколько занимают такие объекты. А занимают они целое число регионов. Посмотрим на текущий размер региона в флагах JVM (здесь и далее для этого используется SJK, команда показана выше).

size_t G1HeapRegionSize = 4194304 {product} {ergonomic}

То есть 4 МБ, а значит наш ~5 МБ объект занимает два региона – 8 МБ. Сверимся с показаниями логов GC. 9173 МБ heap`а поделим на 2286 Humongous regions, получим примерно 4 МБ. Метрики ниже нам показывают, что на ноде всего было ~1000 объектов (включая бэкапы):

Дашборд Hazelcast Map Overview 1
Дашборд Hazelcast Map Overview 1

Учитывая, что метрики мы, вероятно, получили не перед самым падением, то все сходится с показаниями лога GC – два региона на объект.

Что делать? Менять размер региона. Он может быть от 1 до 32 МБ. Для нас есть два пути:

  • уменьшить размер региона, скажем, до 1 МБ, чтобы дефрагментация была не так ощутима. То есть объект больше 512 КБ станет «автоматически» больше на размер от 0 до 1 МБ. Но это слишком сильно ограничивает размер объекта. В процентном соотношении overhead на дефрагментацию более-менее сойдет на нет, только если объект будет размером в сотню МБ. Звучит страшно.

  • увеличить размер региона, но в таком случае мы ограничены максимумом Java в 32 МБ, то есть любой объект больше 16 МБ будет занимать от 0 до 32 МБ лишних. Звучит получше, в этом случае мы хотя бы получаем верхний предел комфортного хранения объектов, а не красную зону прямо по размеру наших объектов.

При выборе из двух зол есть еще один большой нюанс – рекомендации Java. И она рекомендует разделать регионы так, чтобы их было не более 2048. В нашем тестовом кластере с размером региона в 32 МБ будет всего 288 регионов, что в принципе подходит под требование. Но и для нашей целевой схемы это более чем подходит. В ней будет ~50 ГБ heap, то есть 25 МБ минимальный рекомендованный для нас размер. Отлично, значит будет 32 МБ.

Остается вопрос, как так получилось, что у нас стоит ограничение на размер map`ы, но мы все равно получили ООМ. Ответ на графиках:

Дашборд Hazelcast Map Overview 2
Дашборд Hazelcast Map Overview 2
Дашборд Hazelcast Map Overview 3
Дашборд Hazelcast Map Overview 3

Я заполнил map`у тысячей объектов по 5 МБ, и Hazelcast считает, что это всего 3,33 ГБ. Heap же при этом показывает реальную цифру, близкую к 5,5 ГБ. А выселение HZ инициирует только если его подсчет размера достигнет лимита, что происходит на уровне JVM он не учитывает.

Возможно здесь лучше справилась бы политика выселения FREE_HEAP_SIZE, а не USED_HEAP_SIZE? Проверим, создам вторую map`у, у обоих политика вымещения FREE_HEAP_SIZE, для примера, пускай свободной в mapе будет ~3 ГБ.

map:
  test-map:
    per-entry-stats-enabled: true
    time-to-live-seconds: 0
    backup-count: 1
    in-memory-format: BINARY
    statistics-enabled: true
    eviction:
      eviction-policy: LRU
      max-size-policy: FREE_HEAP_SIZE
      size: 3000
  test-map-2:
    per-entry-stats-enabled: true
    time-to-live-seconds: 0
    backup-count: 1
    in-memory-format: BINARY
    statistics-enabled: true
    eviction:
      eviction-policy: LRU
      max-size-policy: FREE_HEAP_SIZE
      size: 3000

Я наполнил одну map`у тысячей объектов, состояние памяти стало таким:

Дашборд Hazelcast Map Overview 4
Дашборд Hazelcast Map Overview 4

Обращаем внимание на количество элементов в нашей map`е. Начинаем заполнять вторую, и вот что видим:

Дашборд Hazelcast Map Overview 5
Дашборд Hazelcast Map Overview 5

Смотрим внимательно, меняется ли размер первой map`ы – нет. Выселение происходит только в рамках той map`ы, которую мы заполняем, а значит одна из них просто задавит другую, и ничего с этим сделать не получится. Поэтому мы останемся на USED_HEAP_SIZE.

Оставим на полях большую галочку номер I, вернемся к этому моменту в выводах. А пока зафиксируем первый параметр, который мы добавим к Java –
-XX:G1HeapRegionSize=32m

Закрепляем успех с вымещением из map`ы

На этот раз точно так же наполняем все под завязку, и еще добавляем сверху, чтобы спровоцировать вымещение. Смотрим, что получилось:

Дашборд Hazelcast Map Overview 7
Дашборд Hazelcast Map Overview 7

А получился у нас 2471 объект и под завязку заполненная map`а, вымещение успешно сработало. Количество объектов, можно сказать, совпало с ожидаемыми 2676, особенно с учетом небольшого overheadа на хранение статистики, который дает параметр per-entry-stats-enabled.

Что ж, все прошло удачно. Смотрим, что происходило с памятью пода – и тут настораживает сразу несколько вещей. Пойдем по порядку.

Предварительная аллокация

Дашборд Hazelcast Map Overview 8
Дашборд Hazelcast Map Overview 8

Глядя на график выше, видим, что физическая память уменьшалась с ростом heap`а, хотя мы установили флаг Xms, который должен определить размер heap`а, который Java будет использовать сразу при старте. По графику ниже мы видим, что committed размер не менялся, он всегда был 9 ГБ, как и ожидалось, а вот used потихоньку увеличивался.

Дашборд JVM 2
Дашборд JVM 2

Похоже Java не аллоцирует у ОС всю память, которую коммитит. Нас это не устраивает по двум причинам:

  1. так сложнее понять, сколько памяти и подо что уходит. На примере того же heap`а на графике выше – commited память была 9 ГБ все время с начала старта, поэтому этот график нам ничего не скажет о реальном использовании. Used тоже ничего не покажет, пустая память – не означает возвращенная ОС. И куда делся целый гигабайт памяти, который мы видим на графике использования физической памяти пода? Там однозначно есть что-то кроме heap`а, но что и сколько? Поможет навести порядок и во всем этом разобраться флаг AlwaysPreTouch – с ним Java сразу будет аллоцировать память, которую коммитит.

  2. мы хотим освободить себя от сюрпризов внезапных падений, когда Java начнет задействовать память, которую закоммитила ранее. Мы на это пару раз попадались, и не только в рамках этих тестов. Такие падения особенно неприятны тем, что с точки зрения JVM она использует положенную ей память, но сюда вмешается oom-киллер кубера и убьет под. Из-за этого произойдет очень неприятная ситуация – не будет вызван full GC, и даже если у нас было что почистить в памяти, мы этого не сделаем. Как побочный эффект – мы не получим в логах информации о том, какой раздел памяти начал расти и уперся в лимит, а это не всегда heap.

И это второй флаг, который мы добавляем к себе в коллекцию - -XX:+AlwaysPreTouch

Куда делась память

Добавим новый флаг, заполним map`у заново и вернемся к разбору того, на что все-таки ушли 300 МБ сверх 9 ГБ закоммиченной памяти.

Это, конечно, очевидно, что память любого процесса, это не только память heap`а, это еще и стек, и код самой программы, и статические переменные. Но что конкретно происходит в Java? В качестве ответа могу предложить ознакомиться с этой статьей, которую считаю оптимальной по доходчивости и наполнению. Главное, что мы из нее вынесем – у каких пулов памяти мы сможем контролировать лимит. Только у четырех следующих пулов :

  1. Heap – через флаг Xmx

  2. Metaspace – через флаг MaxMetaspaceSize

  3. Три пула памяти, составляющих Code Cache – через флаг ReservedCodeCacheSize

  4. Суммарный размер буферных пулов Direct MemoryMaxDirectMemorySize

Посмотрим, что у нас есть в дефолтном JVM дашборде:

Дашборд JVM 3
Дашборд JVM 3

Non heap должен включать в себя metaspace, и этот график показывает нам всего 90 МБ, а ниже metaspace всего лишь 56 МБ. Похоже, что в метриках JMX экспортера мы полной картины не увидим. Вооружаемся SJK и смотрим, какие флаги сейчас выставлены в JVM по умолчанию, до которых мы еще не добрались:

size_t MaxMetaspaceSize = 18446744073709547520 {product} {default}
size_t CompressedClassSpaceSize = 1073741824 {product} {default}
bool UseCompressedClassPointers = true {lp64_product} {ergonomic}
intx VMThreadStackSize = 1024 {pd product} {default}
uintx ReservedCodeCacheSize = 251658240 {pd product} {ergonomic}
uintx StringTableSize = 65536 {product} {default}
uint64_t MaxDirectMemorySize = 0 {product} {default}

А вот что происходит в нативной памяти. Я оставил комментарии к каждому интересующему нас пулу прямо в отчете:

Total: reserved=11324673KB, committed=9972605KB
# С хипом ничего интересного не происходит, у нас уже настроены его размеры с помощью xmx и xms флагов
-                 Java Heap (reserved=9437184KB, committed=9437184KB)
                            (mmap: reserved=9437184KB, committed=9437184KB)
# Это пул мы видели на графиках JVM
-                     Class (reserved=1102068KB, committed=59972KB)
                            (classes #10614)
                            (  instance classes #10029, array classes #585)
                            (malloc=2292KB #29159) 
                            (mmap: reserved=1099776KB, committed=57680KB) 
# Metaspace регулируется флагом MaxMetaspaceSize, и сейчас он выставлен в тысячи петабайт, то есть размер практически не ограничен. Используется всего 48 МБ и, судя по графикам, практически не меняется во время работы приложения, но для ровного счета и небольшого запаса под большой кластер выставим этот флаг в 128 МБ
                            (  Metadata:   )
                            (    reserved=51200KB, committed=50000KB)
                            (    used=48401KB)
                            (    free=1599KB)
                            (    waste=0KB =0.00%)
# Размер Class space регулируется флагом CompressedClassSpaceSize и входит в MaxMetaspaceSize. И хотя по умолчанию под него зарезервирован 1 ГБ, этот пул выключен по умолчанию, если хип больше 32 ГБ. У нас хип будет большим, поэтому ограничение этого пула мы просто пропустим
                            (  Class space:)
                            (    reserved=1048576KB, committed=7680KB)
                            (    used=6474KB)
                            (    free=1206KB)
                            (    waste=0KB =0.00%)
# Размер памяти, уходящий под потоки, мы, судя по всему, не сможем лимитировать напрямую. У нас есть флаг VMThreadStackSize (он же Xss), которым мы ограничиваем размер стека потока. По умолчанию этот лимит равен 1 МБ, и делать его меньше кажется экономией на спичках в нашем случае
-                    Thread (reserved=96953KB, committed=9057KB)
                            (thread #94)
                            (stack: reserved=96507KB, committed=8611KB)
                            (malloc=337KB #566) 
                            (arena=108KB #186)
# Размер пула code регулируется флагом ReservedCodeCacheSize, который по умолчанию 240 МБ. Возьмем этот пул на карандаш, к нему еще вернемся
-                      Code (reserved=249533KB, committed=27457KB)
                            (malloc=1845KB #8725) 
                            (mmap: reserved=247688KB, committed=25612KB)
# Пул памяти сборщика мусора для меня стал сюрпризом, хотя это вполне логично, где-то должна храниться информация о регионах, циклах сборки мусора и прочем. Но о нем я даже не задумывался, потому что не ожидал, что он займет 400 МБ из 9 ГБ heap`а. Этот пул никак не ограничить, поэтому нам придется делать небольшой запас и подбирать его под большой кластер
-                        GC (reserved=403673KB, committed=403673KB)
                            (malloc=20621KB #8907) 
                            (mmap: reserved=383052KB, committed=383052KB)
-                  Compiler (reserved=6756KB, committed=6756KB)
                            (malloc=553KB #814) 
                            (arena=6203KB #12)
-                  Internal (reserved=1049KB, committed=1049KB)
                            (malloc=1017KB #2036) 
                            (mmap: reserved=32KB, committed=32KB)
-                     Other (reserved=1857KB, committed=1857KB)
                            (malloc=1857KB #47)
# Этот пул так же нельзя ограничить напрямую, только лимитировать размер хеш-таблицы, который в нем хранится через флаг StringTableSize. Этот пул используется для экономии места на одинаковых строках, и сохранение в него строк выполняется вызовом метода String.intern() из кода. Я не лез в HZ, чтобы проверить, используется ли он. Но, судя по тому, что мы загружаем тестом одинаковые строки и видим, как они кладутся в хип - нет. Так что этот пул не грозит разрастись. Поэтому оставим этот параметр по умолчанию 
-                    Symbol (reserved=12366KB, committed=12366KB)
                            (malloc=9257KB #107301) 
                            (arena=3109KB #1)
# Эта память используется при включении флага NativeMemoryTracking, который мы используем для получения отчетов о потреблении нативной памяти. Отслеживание нативной памяти мы отключим, как закончим тестирование, поэтому проигнорируем этот пул
-    Native Memory Tracking (reserved=3000KB, committed=3000KB)
                            (malloc=364KB #5147) 
                            (tracking overhead=2636KB)
-               Arena Chunk (reserved=9692KB, committed=9692KB)
                            (malloc=9692KB)
-                   Logging (reserved=6KB, committed=6KB)
                            (malloc=6KB #262)
-                 Arguments (reserved=21KB, committed=21KB)
                            (malloc=21KB #534)
-                    Module (reserved=202KB, committed=202KB)
                            (malloc=202KB #1859)
-              Synchronizer (reserved=305KB, committed=305KB)
                            (malloc=305KB #2571)
-                 Safepoint (reserved=8KB, committed=8KB)
                            (mmap: reserved=8KB, committed=8KB)

Что касается пула Code Cache – на дашборде JVM его видно в метрике jvm_memory_pool_bytes_used{pool=~"CodeHeap.*"}. На самом деле он состоит из трех разделов – два по 117 МБ и один – 5,5 МБ:

Дашборд JVM 4
Дашборд JVM 4

За все время нагрузки они росли, что видно на графике ниже:

Дашборд JVM 5
Дашборд JVM 5

Но незначительно. Поэтому мы оставим 240 МБ. Кажется, этого хватит с лихвой, и об этом пуле можно будет больше не вспоминать.

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

Похоже мы разобрались с памятью. Напоследок посмотрим, сходятся ли наши находки с графиком Non Heap:

Дашборд Hazelcast Map Overview 9
Дашборд Hazelcast Map Overview 9

Он практически не двигался за все время нагрузки и был примерно 520 МБ. Просуммировав всю commited память пулов из статистики выше, кроме heap`а, получаем 510 МБ, что попадает практически в точку. Итак, добавляем в коллекцию –XX:MaxMetaspaceSize=128m и -XX:ReservedCodeCacheSize=240m. И в голове держим, что нам еще нужно сделать запас под GC. Сейчас у нас ушло под него 400 МБ, то есть ~4,5%.

Direct buffer memory

У нас еще остался пул – Direct Memory, я вынес его отдельно, потому что он особенный. Это память, которая аллоцируется, напрямую используя malloc. Размер этого пула не виден в отчете по использованию нативной памяти. По умолчанию ограничения на его размер нет.

Попробуем определить, используется ли в HZ такое в принципе, будем искать MXBean`ы связанные с буферным пулом с помощью SJK:

java -jar /data/external/sjk.jar mx -p {PID} -mg -b '**:*,type=BufferPool' -all

И видим результат:java.nio:name=mapped,type=BufferPool и java.nio:name=direct,type=BufferPool

Некая библиотека nio используется Direct Buffer. Она, как я понял, задействуется при работе с IO, в том числе с сетью, так что нагрузка на нее должна иметь значение. Попробуем определить, как много она использует, и выведем полную информацию об этом MXBean`е:

java -jar /data/external/sjk.jar mxdump -p ${PID} -q 'java.nio:name=direct,type=BufferPool'

Вывод мы получаем в json формате:

{
  "name": "java.nio:name=direct,type=BufferPool",
  "modelerType": "sun.management.ManagementFactoryHelper$1",
  "TotalCapacity": 1824973,
  "MemoryUsed": 1824973,
  "Count": 38,
  "Name": "direct",
  "ObjectName": "java.nio:type=BufferPool,name=direct"
}

Нас интересует два атрибута: TotalCapacity и MemoryUsed, они оба в байтах. В простое у нас используется всего 1,7 МБ. Метрика с этого пула собирается prometheus-агентом, поэтому мы можем понаблюдать за его размером в динамике. Метрики называются jvm_buffer_pool_used_bytes и jvm_buffer_pool_capacity_bytes. Панели для этого пула в дефолтном дашборде не было, поэтому ее добавим, запустим нагрузку и помониторим:

Дашборд JVM 6
Дашборд JVM 6

По графику видно, что пул немного вырос, но незначительно. Я пробовал загружать большие объекты, попробовал отключать ноды кластера, чтобы вызвать миграцию партиций, но превысить планку в 2 МБ не удалось. Поэтому ограничим этот буфер в 128 МБ. Этого должно хватить с запасом.

И это четвертый флаг, который мы получили -XX:MaxDirectMemorySize=128m

Промежуточные итоги по памяти

Итак, посчитаем, что у нас получилось:

Java process memory = Xmx + MaxMetaspaceSize + ReservedCodeCacheSize + MaxDirectMemorySize + GC + небольшой запас = 9 ГБ + 128 МБ + 240 МБ + 128 МБ + 460 МБ + небольшой запас = 9,93 ГБ + 71 МБ

То есть мы успешно влезли в 10 ГБ памяти контейнера. Запас можно было бы взять чуть побольше, 71 МБ, наверное, маловато. Но для тестов не будем заморачиваться и оставим как есть.

Перезапустим HZ с новыми флагами, снова заполним его объектами и посмотрим на нативную память еще раз, сверимся с нашими расчетами:
Native Memory Tracking:
Total: reserved=10399831KB, committed=9973079KB
-                 Java Heap (reserved=9437184KB, committed=9437184KB)
                            (mmap: reserved=9437184KB, committed=9437184KB) 
-                     Class (reserved=176392KB, committed=60248KB)
                            (classes #10649)
                            (  instance classes #10064, array classes #585)
                            (malloc=2312KB #29738) 
                            (mmap: reserved=174080KB, committed=57936KB) 
                            (  Metadata:   )
                            (    reserved=51200KB, committed=50256KB)
                            (    used=48641KB)
                            (    free=1615KB)
                            (    waste=0KB =0.00%)
                            (  Class space:)
                            (    reserved=122880KB, committed=7680KB)
                            (    used=6496KB)
                            (    free=1184KB)
                            (    waste=0KB =0.00%)
-                    Thread (reserved=99016KB, committed=9260KB)
                            (thread #96)
                            (stack: reserved=98561KB, committed=8805KB)
                            (malloc=345KB #578) 
                            (arena=111KB #190)
-                      Code (reserved=249646KB, committed=28794KB)
                            (malloc=1958KB #9054) 
                            (mmap: reserved=247688KB, committed=26836KB) 
-                        GC (reserved=403704KB, committed=403704KB)
                            (malloc=20652KB #9223) 
                            (mmap: reserved=383052KB, committed=383052KB) 
-                  Compiler (reserved=11946KB, committed=11946KB)
                            (malloc=570KB #869) 
                            (arena=11376KB #20)
-                  Internal (reserved=796KB, committed=796KB)
                            (malloc=764KB #2100) 
                            (mmap: reserved=32KB, committed=32KB) 
-                     Other (reserved=1862KB, committed=1862KB)
                            (malloc=1862KB #49) 
-                    Symbol (reserved=12387KB, committed=12387KB)
                            (malloc=9278KB #107544) 
                            (arena=3109KB #1)
-    Native Memory Tracking (reserved=3041KB, committed=3041KB)
                            (malloc=378KB #5352) 
                            (tracking overhead=2663KB)
-               Arena Chunk (reserved=3315KB, committed=3315KB)
                            (malloc=3315KB) 
-                   Logging (reserved=6KB, committed=6KB)
                            (malloc=6KB #262) 
-                 Arguments (reserved=21KB, committed=21KB)
                            (malloc=21KB #534) 
-                    Module (reserved=202KB, committed=202KB)
                            (malloc=202KB #1861) 
-              Synchronizer (reserved=306KB, committed=306KB)
                            (malloc=306KB #2578) 
-                 Safepoint (reserved=8KB, committed=8KB)
                            (mmap: reserved=8KB, committed=8KB)

В разделе total у нас больше нет превышение reserved памяти, и объем памяти примерно совпадает с нашими расчетами – ~9,92 ГБ. Будем считать эту часть успешно настроенной, и первый сценарий тестирования пройденным.

Сценарий 2: проверка доступности кластера

Проверим, как кластер переживает аварии

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

ОбъектовПоместится = ОЗУНаОднойНоде * ( КолвоНод - КолвоБэкапов )/ ( ( 1 + КолвоБэкапов ) * РазмерОбъекта )

Получается мы можем рассчитывать на 1784 объекта по 5 МБ. Наполняем кластер этими объектами, проверим, все ли загрузилось нормально:

hazelcast[default] > ns test-map
namespace: test-map
hazelcast[test-map] > m.size
Size = 1784

Теперь роняем одну ноду и смотрим, не потерялись ли записи:

hazelcast[test-map] > m.size
Size = 1784

Отлично, все на месте. Поднимем под обратно. Посмотрим на поведение памяти в этот момент:

Дашборд JVM 7
Дашборд JVM 7

Никаких внезапных пиков, так что можно считать, что все прошло успешно.

Дадим поду завершить работу штатно

Снова заполним хранилище и дадим ноде завершить работу штатно, перевезя свои партиции на другие ноды. И сразу же получаем java.lang.OutOfMemoryError: Java heap space. Перед падением результат full GC выглядит так:

[info][gc,start       ] GC(1412) Pause Full (G1 Humongous Allocation)
[info][gc,phases,start] GC(1412) Phase 1: Mark live objects
[info][gc,stringtable ] GC(1412) Cleaned string and symbol table, strings: 24820 processed, 0 removed, symbols: 156887 processed, 0 removed
[info][gc,phases      ] GC(1412) Phase 1: Mark live objects 10.056ms
[info][gc,phases,start] GC(1412) Phase 2: Prepare for compaction
[info][gc,phases      ] GC(1412) Phase 2: Prepare for compaction 4.329ms
[info][gc,phases,start] GC(1412) Phase 3: Adjust pointers
[info][gc,phases      ] GC(1412) Phase 3: Adjust pointers 10.251ms
[info][gc,phases,start] GC(1412) Phase 4: Compact heap
[info][gc,phases      ] GC(1412) Phase 4: Compact heap 5.964ms
[info][gc,heap        ] GC(1412) Eden regions: 0->0(14)
[info][gc,heap        ] GC(1412) Survivor regions: 0->0(2)
[info][gc,heap        ] GC(1412) Old regions: 275->274
[info][gc,heap        ] GC(1412) Humongous regions: 13->13
[info][gc,metaspace   ] GC(1412) Metaspace: 57373K(60368K)->57373K(60368K) NonClass: 50801K(52560K)->50801K(52560K) Class: 6571K(7808K)->6571K(7808K)
[info][gc             ] GC(1412) Pause Full (G1 Humongous Allocation) 8650M->8650M(9216M) 49.188ms
[info][gc,cpu         ] GC(1412) User=0.16s Sys=0.01s Real=0.05s

Судя по всему, аллокация огромного объекта во время миграции партиций потребовала слишком много места, которого у пода не было. И это не нехватка места в map`е, потому что я оставил запас, к тому же в таком случае просто сработало бы вымещение. Этот тот самый overhead на миграцию, о котором мы говорили в начале этой статьи. На этом этапе у нас есть следующие варианты действий:

  1. Отказаться от миграций партиций при завершении работы пода вовсе, поменяв параметр hazelcast.shutdownhook.policy. В таком случае под будет сразу выключаться, а оставшиеся живые реплики начнут между собой разбираться, как восстановить данные. В общем достаточно неплохой вариант. Но смущает, что в теории значительной разницы нет, включен ли gracefull shutdown или нет. Потому что вне зависимости от того, как под завершил работу, между оставшимися двумя репликами партиции перераспределяются в том же объеме. И, на мой взгляд, надеяться, что без gracefull shutdown все будет в порядке, может быть опрометчиво. Поэтому от этого варианта отказываемся.

  2. Можно уменьшить hazelcast.partition.max.parallel.migrations, количество партиций, которые одновременно мигрируют. Но в таком случае мы замедляем время выключения пода. Учитывая, что на время миграции партиции становятся read only (настраивается параметром hazelcast.partition.migration.stale.read.disabled), это может быть проблемой в случае аварии. Поэтому от этого мы тоже отказываемся.

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

    Но у этого есть обратная сторона – в случае аварии, чтобы восстановить работу кластера, нужно будет вручную переводить его в статус ACTIVE, дать данным перемигрировать на упавшие ноды, и вернуть в NO_MIGRATION. Хотя эти не слишком сложные действия можно автоматизировать, все же это относительно ненадежно. У нас есть временное окно с момента аварии до момента устранения ее последствий, когда партиции кластера не имеют бэкапов, и если что-то пойдет не так, откажут оставшиеся ноды, данные будут утеряны. По этой причине пока отложим это решение в сторону на случай, если не получится добиться корректной работы другими путями.

  4. И последний вариант – это держать в heap`е небольшой запас памяти под миграцию. С этого вариант и начнем, так как он самый простой. Если будем видеть, что overhead слишком большой, выберем вариант 3.

Дальше путем проб и ошибок выявляем оптимальный запас в 1,5 ГБ heap`а. В map`е 7,5 ГБ мы можем хранить 2304 объектов по 5 МБ. При повторном тесте все прошло успешно, что видно по графикам памяти во время теста:

Дашборд JVM 8
Дашборд JVM 8

Миграция прошла быстро, судя по графику heap`а, работал full GC, но ноды устояли. Забегая вперед скажу, что, хотя на маленьком кластере пришлось зарезервировать 1/5 heap`а, на большом кластере мы зарезервировали всего лишь 1/10, что вполне приемлемо. Поэтому остановимся на этом варианте и будем считать этот сценарий тестирования пройденным. Здесь новых флагов или параметров у нас не появилось.

Сценарий 3: проверка работы алгоритма выселения

Далее приступаем к проверке алгоритма выселения. Сначала наполним map`у под завязку маленькими объектами по 10 КБ. Вот что у нас получилось:

Дашборд Hazelcast Map Overview 10
Дашборд Hazelcast Map Overview 10

Запомним heap cost в байтах и количество выселений на ноду. После загрузки одного объекта в 100 МБ получили такое:

Дашборд Hazelcast Map Overview 11
Дашборд Hazelcast Map Overview 11

Видим, что объект попал в партиции на первой и второй ноде, и теперь map`а на первой ноде стала на 104 847 363 байт больше, то есть практически ровно (100 МБ - 10 КБ), то есть был вымещен один объект, что сходится с графиком Eviction count. А на второй ноде график вымещения не показывает это, потому что в него попадают только вымещения из основной партиции, но не из реплик.

Что ж, в документации мы видели параметр hazelcast.map.eviction.batch.size, он решит наши проблемы и позволит определить количество объектов, которые будут выселены из map`ы при добавлении нового. По-хорошему это соотношение должно быть таким – размер наибольшего объекта / размер наименьшего. Но не все так просто, и мы дойдем до этого чуть позже, а пока выставим этот параметр равным 100 – для нас это примерное соотношение между средним объектом и наибольшим возможным.

Добавим этот параметр, почистим map`у и повторим, но на этот раз после наполнения map`ы файлами по 10 КБ я загружу один большой объект и следом 1000 маленьких, чуть ниже станет понятно зачем:

Дашборд Hazelcast Map Overview 12
Дашборд Hazelcast Map Overview 12

На графике выше начальная точка – размер map`ы на ноде перед загрузкой большого объекта. Потом видим скачок – это загрузка большого объекта, и, наконец, спад – это загрузка маленьких. При этом по среднему размеру объекта видно, что спад произошел не из-за удаления большого объекта при выселении, а из-за того, что даже маленькие объекты триггерили 100 выселений до тех пор, пока размер хранилища не пришел в норму. То есть, если мы получим аномально большой объект и превысим лимит mapы, то потребление памяти map`ой со временем стабилизируется само.

Это еще одна галочка на полях, номер III, к ней мы тоже вернемся.

Что ж, с этим больше ничего не сделать, флаг
-Dhazelcast.map.eviction.batch.size=100 добавляем в javaOpts и считаем эту часть успешно законченной.

Сценарий 4: выселение объектов

Это снова тест алгоритма вымещения. Хочу проверить, будут ли у Hazelcast проблемы с выбором кандидата для удаления из ограниченного количества объектов. Для чистоты эксперимента hazelcast.map.eviction.batch.size вернем 1, а для наглядности будем проверять на трех миллионах, чтобы выборка была значительно меньше количества ключей в map`е. Размер объекта, который будем грузить, примерно получится 4 КБ.

После наполнения буду тестировать вторым скриптом, который есть в спойлере в разделе об используемых инструментах, используя команду:

./check-eviction.py -m hazelcast:5701 --batch=10000 --cluster test --map test-map

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

Пример неуспешного выселения
Пример неуспешного выселения
Пример успешного выселения
Пример успешного выселения

На графике сверхуhazelcast.map.eviction.sample.count = 15, на графике снизу hazelcast.map.eviction.sample.count = 10000. Показателем для нас является соотношение количества выселенных объектов к номеру последнего выселенного ключа – это точность работы алгоритма. Для первого графика это всего лишь 13%, для второго – 83%. В общем ожидаемо, что размер выборки значительно улучшает работу алгоритма, выселение намного точнее выбирает самые старые объекты.

Но не все так просто, вернем hazelcast.map.eviction.batch.size = 100 и проверим, как эти два флага работают вместе:

Пример деградации точности алгоритма выселения
Пример деградации точности алгоритма выселения

Алгоритм стал намного менее точным, всего лишь 46%. Хотя в теории ничего не изменилось, даже если некоторые объекты почему-то потребовали нескольких выселений. Посмотрим на исходный код функции evict. Она просто просто несколько раз вызвала selectEvictableEntry.

Мое предположение – это связано с тем, что элементы вытесняются только из тех партиций, которые расположены на ноде, на которую попадает новый объект. Элементы по партициям распределяются примерно равномерно, в том числе и по возрасту, а значит, вытесняя 100 объектов, мы удаляем не самые старые объекты с 1-го по 100-тый, а с 1-го и далее n-ый в плоть до n * 100, где n – количество нод в кластере. А значит ситуация будет хуже с увеличением количества нод и увеличением hazelcast.map.eviction.batch.size. И никакого влияния оказать на это нельзя.

Но это не единственная проблема при комбинировании этих двух параметров.

Из-за того, что на каждое выселение из hazelcast.map.eviction.batch.size вызывается алгоритм, перебирающий hazelcast.map.eviction.sample.count объектов, мы получаем сложность алгоритма равную hazelcast.map.eviction.batch.size * hazelcast.map.eviction.sample.count. Ниже представлен график pps в map`е с 10 млн. объектов,hazelcast.map.eviction.batch.size = 10000 и hazelcast.map.eviction.sample.count = 10000, для сравнения второй график выселения тех же объектов, но с обоими параметрами по 1:

Дашборд Hazelcast Map Overview 13
Дашборд Hazelcast Map Overview 13
Дашборд Hazelcast Map Overview 14
Дашборд Hazelcast Map Overview 14

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

То есть у нас есть три показателя:

  1. точность алгоритма выселения

  2. способность алгоритма выселения вымещать достаточно ключей под очередной объект

  3. быстродействие

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

По итогу мы остановились на таких значениях:
-Dhazelcast.map.eviction.sample.count=1000
-Dhazelcast.map.eviction.batch.size=10

Особенности большого кластера

Когда мы развернулись на большом кластере и прогнали все те же тесты, мы наткнулись на некоторые особенности, пришедшие с значительным увеличением heap'а.

Первое, что мы заметили, это большие stop the world паузы по время Full GC, ниже логи с большого кластера.

[info][gc,task       ] GC(571) Using 20 workers of 20 for full compaction
[info][gc,start      ] GC(571) Pause Full (G1 Evacuation Pause)
[info][gc,phases,start] GC(571) Phase 1: Mark live objects
[info][gc,stringtable ] GC(571) Cleaned string and symbol table, strings: 25098 processed, 178 removed, symbols: 156563 processed, 24 removed
[info][gc,phases      ] GC(571) Phase 1: Mark live objects 44.623ms
[info][gc,phases,start] GC(571) Phase 2: Prepare for compaction
[info][gc,phases      ] GC(571) Phase 2: Prepare for compaction 22.625ms
[info][gc,phases,start] GC(571) Phase 3: Adjust pointers
[info][gc,phases      ] GC(571) Phase 3: Adjust pointers 19.819ms
[info][gc,phases,start] GC(571) Phase 4: Compact heap
[info][gc,phases      ] GC(571) Phase 4: Compact heap 2277.859ms
[info][gc,heap        ] GC(571) Eden regions: 0->0(64)
[info][gc,heap        ] GC(571) Survivor regions: 0->0(8)
[info][gc,heap        ] GC(571) Old regions: 1618->1472
[info][gc,heap        ] GC(571) Humongous regions: 14->14
[info][gc,metaspace   ] GC(571) Metaspace: 57383K(59136K)->57141K(59136K)
[info][gc             ] GC(571) Pause Full (G1 Evacuation Pause) 52221M->46018M(52224M) 2380.418ms
[info][gc,cpu         ] GC(571) User=18.10s Sys=0.00s Real=2.38s

И в этих логах сразу бросаются в глаза четыре момента:

  1. дольше всего выполняется сжатие – 2,3 секунды

  2. GC очистил память от 6 ГБ мертвых объектов

  3. вся память – это Old Regions

  4. Не выполнилось ни одного mixed GC

Вернувшись к тестовому стенду, мы начали нагружать его и внимательно следить за работой GC:

Дашборд JVM 9
Дашборд JVM 9

Прежде всего видим, что пропорции между Eden и Old Gen меняются в процессе работы кластера. Сначала он занимает большую часть heap'а, но по мере того, как Old Gen увеличивается, под Young Gen практически ничего не остается – всего лишь 192 МБ. При этом, глядя на частоту работы GC, нельзя сказать, что после уменьшения Eden Space почти в 10 раз, участился minor GC по Young Gen.

И тут ситуация двоякая:

  • с одной стороны, нам не нужен большой Eden Space – большинство объектов в памяти у нас долгоживущие, а значит практически все будет попадать в Old Gen рано или поздно. Мертвых объектов, чтобы освободить от них память, в этом пуле практически не будет, потому что большие объекты, удаленные по TTL или вымещенные по размеру, уже будут в Old Gen. А это значит, что каждый проход minor GC будет копировать объекты между пулами Young Gen, пока они не состарятся и не попадут в Old Gen. К тому же если Old Gen будет слишком мал, чтобы хранить наши долгоживущие объекты, мы будем получать ошибки “To‑space exhausted”, что будет провоцировать full GC и перераспределение памяти между поколениями. Как в примере ниже, где я установил изначальный и максимальный размер молодого поколения в 4 ГБ:

    Дашборд JVM 10
    Дашборд JVM 10

    Как только Old Gen достиг своего предела в 5 ГБ, minor GC начал выдавать ошибки “To‑space exhausted”, после чего вызывал full GC в попытке ужать heap или удалить мертвые объекты. Но у него ничего не получалось, поэтому Old Gen расширялся. И это происходило до тех пор, пока его размер не стабилизировался из-за лимита на размер самой map`ы.

  • с другой стороны, слишком маленький Young Gen будет часто провоцировать minor GC. Hazelcast все-таки создает объекты во время своей работы, и не хотелось бы из-за частых minor GC тащить эти объекты в Old Gen, где они очень быстро, по сравнению с данными map`ы, станут мусором.

Исходя из этого мы определили, что оптимальный для нас размер Young Gen примерно 4% от размера кластера. В таком случае размера Old Gen хватит для хранения наших данных. Зафиксировать его размер можно двумя флагами: NewSize и MaxNewSize.

Ограничения времени работы GC

Вернемся немного назад к графику Old Gen на нашем тестовом стенде. Глядя на происходящее, мы видим, что в какой-то момент память в нем так же была очищена – метрика used поползла вниз. Изучим этот момент поближе.

В логах в этот момент наблюдаем следующее
[info][gc             ] GC(116) Concurrent Cycle
[info][gc,marking     ] GC(116) Concurrent Clear Claimed Marks
[info][gc,marking     ] GC(116) Concurrent Clear Claimed Marks 0.179ms
[info][gc,marking     ] GC(116) Concurrent Scan Root Regions
[info][gc,marking     ] GC(116) Concurrent Scan Root Regions 0.629ms
[info][gc,marking     ] GC(116) Concurrent Mark (276.088s)
[info][gc,marking     ] GC(116) Concurrent Mark From Roots
[info][gc,task        ] GC(116) Using 2 workers of 2 for marking
[info][gc,marking     ] GC(116) Concurrent Mark From Roots 22.784ms
[info][gc,marking     ] GC(116) Concurrent Preclean
[info][gc,marking     ] GC(116) Concurrent Preclean 0.153ms
[info][gc,marking     ] GC(116) Concurrent Mark (276.088s, 276.111s) 22.997ms
[info][gc,start       ] GC(116) Pause Remark
[info][gc,stringtable ] GC(116) Cleaned string and symbol table, strings: 23623 processed, 0 removed, symbols: 152205 processed, 0 removed
[info][gc,mmu         ] GC(116) MMU target violated: 6.0ms (5.0ms/6.0ms)
[info][gc             ] GC(116) Pause Remark 8381M->8381M(9216M) 12.190ms
[info][gc,cpu         ] GC(116) User=0.08s Sys=0.00s Real=0.01s
[info][gc,marking     ] GC(116) Concurrent Rebuild Remembered Sets
[info][gc,marking     ] GC(116) Concurrent Rebuild Remembered Sets 18.942ms
[info][gc,start       ] GC(116) Pause Cleanup
[info][gc             ] GC(116) Pause Cleanup 8381M->8381M(9216M) 0.304ms
[info][gc,cpu         ] GC(116) User=0.00s Sys=0.00s Real=0.00s
[info][gc,marking     ] GC(116) Concurrent Cleanup for Next Mark
[info][gc,marking     ] GC(116) Concurrent Cleanup for Next Mark 15.447ms
[info][gc             ] GC(116) Concurrent Cycle 71.705ms
[info][gc,start       ] GC(117) Pause Young (Prepare Mixed) (G1 Evacuation Pause)
[info][gc,task        ] GC(117) Using 8 workers of 8 for evacuation
[info][gc,mmu         ] GC(117) MMU target violated: 6.0ms (5.0ms/6.0ms)
[info][gc             ] GC(117) To-space exhausted
[info][gc,phases      ] GC(117)   Pre Evacuate Collection Set: 0.0ms
[info][gc,phases      ] GC(117)   Evacuate Collection Set: 8.3ms
[info][gc,phases      ] GC(117)   Post Evacuate Collection Set: 4.1ms
[info][gc,phases      ] GC(117)   Other: 0.4ms
[info][gc,heap        ] GC(117) Eden regions: 12->0(12)
[info][gc,heap        ] GC(117) Survivor regions: 2->2(2)
[info][gc,heap        ] GC(117) Old regions: 270->286
[info][gc,heap        ] GC(117) Humongous regions: 0->0
[info][gc,metaspace   ] GC(117) Metaspace: 53006K(55888K)->53006K(55888K) NonClass: 46757K(48464K)->46757K(48464K) Class: 6249K(7424K)->6249K(7424K)
[info][gc             ] GC(117) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 8756M->8901M(9216M) 12.836ms
[info][gc,cpu         ] GC(117) User=0.08s Sys=0.00s Real=0.01s
[info][gc,task        ] GC(118) Using 8 workers of 8 for full compaction
[info][gc,start       ] GC(118) Pause Full (G1 Evacuation Pause)
[info][gc,phases,start] GC(118) Phase 1: Mark live objects
[info][gc,stringtable ] GC(118) Cleaned string and symbol table, strings: 23623 processed, 0 removed, symbols: 152205 processed, 0 removed
[info][gc,phases      ] GC(118) Phase 1: Mark live objects 9.563ms
[info][gc,phases,start] GC(118) Phase 2: Prepare for compaction
[info][gc,phases      ] GC(118) Phase 2: Prepare for compaction 3.953ms
[info][gc,phases,start] GC(118) Phase 3: Adjust pointers
[info][gc,phases      ] GC(118) Phase 3: Adjust pointers 8.071ms
[info][gc,phases,start] GC(118) Phase 4: Compact heap
[info][gc,phases      ] GC(118) Phase 4: Compact heap 629.886ms
[info][gc,heap        ] GC(118) Eden regions: 0->0(14)
[info][gc,heap        ] GC(118) Survivor regions: 2->0(2)
[info][gc,heap        ] GC(118) Old regions: 286->251
[info][gc,heap        ] GC(118) Humongous regions: 0->0
[info][gc,metaspace   ] GC(118) Metaspace: 53006K(55888K)->53006K(55888K) NonClass: 46757K(48464K)->46757K(48464K) Class: 6249K(7424K)->6249K(7424K)
[info][gc             ] GC(118) Pause Full (G1 Evacuation Pause) 8901M->7717M(9216M) 661.134ms
[info][gc,cpu         ] GC(118) User=2.57s Sys=0.00s Real=0.66s

Отработал цикл пометки живых объектов в Old Gen, затем началась mixed сборка мусора. Но мы видим, что сборка мусора пишет “MMU target violated”. Судя по всему, она упирается в лимиты MaxGCPauseMillis и GCPauseIntervalMillis.

Первый флаг ставит лимит на время выполнения GC, второй определяет временной интервал между GC, из-за чего и получаем ошибку MMU (Minimum Mutator Utilization) – процент доступности процессора для работы приложения за последний отрезок времени GCPauseIntervalMillis. Чтобы понизить ограничение на время работы GC увеличим этот лимит. По умолчанию он 5 мс, мы сделаем 1000 мс. Значение выбрано исходят из того, что его порядок совпадает с временем полной сборки мусора. Раз она успевает выполниться, то и для смешанной сборки должно подойти.

Флаг GCPauseIntervalMillis построим, чтобы сохранить соотношение, и сделаем его 1200 мс. Для нас большее значение имеет своевременная работа GC, чем скорость обслуживания запросов, поэтому на ограничении паузы GC мы не стали экономить.

Настройка количества воркеров для пометки

Еще одним проблемным местом может стать количество воркеров, которые используются для цикла пометки. Их количество регулируется флагом ConcGCThreads, который по умолчанию выставляется равным 1/4 от общего количества потоков GC, заданных флагом ParallelGCThreads. В нашем случае это 2 и 8 соответственно. В логах время цикла пометки достигает нескольких сотен миллисекунд, и это на тестовом кластере. На большом мы получали около одной секунды. Поэтому значение этого флага мы увеличили до 5, что позволило сократить среднее время пометки до 400 мс.

Настройка работы mixed GC

От MMU избавились, но в логе выше видно, что после цикла пометки сработал mixed GC и сразу же получил “To‑space exhausted”, запустив full GC. При этом, mixed GC не посчитал возможным очистить ни один регион в Old Gen. В то же время, full GC сократил их количество на 35. И тут у меня два предположения:

  • либо Java решила, что количество места, которое может освободить GC, слишком не значительно, потому мертвые объекты можно не чистить mixed GC, и за их удаление взялся только full GC;

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

С аналогичной ситуацией мы столкнулись на большом кластере, но там mixed GC вообще никогда не запускается, работает только minor и full GC.

Для регулировки поведение mixed GC есть два флага:

  • G1HeapWastePercent – определяет порог срабатывания смешанной сборки мусора в виде процента от размера heap. Если сборка сможет освободить больше памяти, чем этот процент, то она запуститься. Если нет, то для прошедшего цикла пометки живых объектов смешанная сборка больше не запустится, и, пока не выполнится новый цикл, будет работать только full GC и minor GC;

  • G1MixedGCLiveThresholdPercent – определяет пороговое количество живых объектов в регионе, чтобы он не был выбран для смешанной сборки мусора. К сожалению, в openjdk 11.0.20, который используется в образе, этого флага нет.

Получается единственным спасением является G1HeapWastePercent. По умолчанию он равен 5%, то есть 450 МБ на тестовом кластере и 2,5 ГБ на большом. Это значительный объем места, который смешанная очистка просто игнорирует. В случае, когда наш кластер заполнен под завязку, этот порог может просто не преодолеваться. Поэтому значение этого флага надо уменьшать. Если установить его меньше 2, чтобы mixed GC вызывался как можно чаще, full GC будет использовать не все доступные воркеры, а 1 или 4, для 0 и 1 процента соответственно. Поэтому мы выставили флаг равным 2, так как при использовании только одного потока для полной сборки пауза увеличилась с 1-2 секунд до 12.

Как итог наших манипуляций, теперь в логе у нас появилась такая сборка мусора:

[info][gc,start      ] GC(120) Pause Young (Mixed) (G1 Evacuation Pause)
[info][gc,task       ] GC(120) Using 8 workers of 8 for evacuation
[info][gc,phases     ] GC(120)   Pre Evacuate Collection Set: 0.0ms
[info][gc,phases     ] GC(120)   Evacuate Collection Set: 10.9ms
[info][gc,phases     ] GC(120)   Post Evacuate Collection Set: 0.5ms
[info][gc,phases     ] GC(120)   Other: 0.2ms
[info][gc,heap       ] GC(120) Eden regions: 9->0(9)
[info][gc,heap       ] GC(120) Survivor regions: 2->2(2)
[info][gc,heap       ] GC(120) Old regions: 258->261
[info][gc,heap       ] GC(120) Humongous regions: 0->0
[info][gc,metaspace  ] GC(120) Metaspace: 53902K(56732K)->53902K(56732K) NonClass: 47558K(49232K)->47558K(49232K) Class: 6343K(7500K)->6343K(7500K)
[info][gc            ] GC(120) Pause Young (Mixed) (G1 Evacuation Pause) 8605M->8408M(9216M) 11.760ms
[info][gc,cpu        ] GC(120) User=0.06s Sys=0.00s Real=0.01s

Ей удалось освободить 200 МБ, а раньше она просто пропускалась. При постоянной большой нагрузке в несколько тысяч pps, после нескольких таких сборок мы все равно натыкаемся на full GC:

[info][gc,task       ] GC(128) Using 8 workers of 8 for full compaction
[info][gc,start      ] GC(128) Pause Full (G1 Evacuation Pause)
[info][gc,phases,start] GC(128) Phase 1: Mark live objects
[info][gc,stringtable ] GC(128) Cleaned string and symbol table, strings: 25765 processed, 2098 removed, symbols: 152183 processed, 0 removed
[info][gc,phases      ] GC(128) Phase 1: Mark live objects 61.601ms
[info][gc,phases,start] GC(128) Phase 2: Prepare for compaction
[info][gc,phases      ] GC(128) Phase 2: Prepare for compaction 31.082ms
[info][gc,phases,start] GC(128) Phase 3: Adjust pointers
[info][gc,phases      ] GC(128) Phase 3: Adjust pointers 28.033ms
[info][gc,phases,start] GC(128) Phase 4: Compact heap
[info][gc,phases      ] GC(128) Phase 4: Compact heap 1769.070ms
[info][gc,heap        ] GC(128) Eden regions: 0->0(11)
[info][gc,heap        ] GC(128) Survivor regions: 0->0(2)
[info][gc,heap        ] GC(128) Old regions: 288->249
[info][gc,heap        ] GC(128) Humongous regions: 0->0
[info][gc,metaspace   ] GC(128) Metaspace: 53917K(56732K)->53561K(56732K) NonClass: 47573K(49232K)->47306K(49232K) Class: 6343K(7500K)->6254K(7500K)
[info][gc             ] GC(128) Pause Full (G1 Evacuation Pause) 9215M->7695M(9216M) 1941.362ms
[info][gc,cpu         ] GC(128) User=1.94s Sys=0.00s Real=1.94s

Похоже все равно остается много регионов, которые не подцепляет mixed GC, но мы как минимум успешно оттянули момент его запуска.

Вернемся к графику Old Gen. Сейчас нас интересует момент, когда GC начал очистку этого поколения. Цикл пометки живых объектов, а значит и работа mixed GC, начался только тогда, когда в heap`е осталась примерно половина свободного места. Момент, когда начинает работу цикл пометки можно определить флагом InitiatingHeapOccupancyPercent, по умолчанию он 45%. То есть, когда Old Gen разрастется до 45% от своего максимума, Java начнет применять mixed GC вместо minor, чтобы очищать heap. Так как Old Gen у нас очень большой, есть смысл запускать его пораньше, чтобы облегчить ему работу, пока heap не разросся. Поэтому мы установили его значение в 25%.

Запас свободного heap`а

Еще один флаг, влияющий на сборку мусора – G1ReservePercent. Этот флаг в документации рекомендуется использовать в случае, когда часто встречается “To‑space exhausted”. В документации мало информации о том, как он работает, но, судя по названию, должен подталкивать GC к сохранению некоторого процента heap`а свободным. По умолчанию он равен 10. Мы увеличим до 25, при котором «зарезервированное место» превышает тот запас, который мы делали под переезд партиций ранее.

Задержка в отправке heartbeat`ов

Еще одну большую проблему мы увидели, когда давали нагрузку на забитый под завязку большой кластер. В какой-то момент он падал, начиная с одной из нод, а в логах GC наблюдались сообщения Humongous Allocation, хотя в хранилище большие объекты мы не загружали. Предшествовали этим сообщениям следующие логи самого Hazelcast:

[hz.nervous_tesla.cached.thread-9] [c.h.i.c.i.ClusterHeartbeatManager]: [10.233.90.105]:5701 [dev] [5.3.1] Suspecting Member [10.233.117.91]:5701 - 8fed7bd7-ca74-41ef-88ed-84229d21c6ed because it has not sent any heartbeats since 2024-03-01 10:04:44.960. Now: 2024-03-01 10:05:53.507, heartbeat timeout: 60000 ms, suspicion level: 1.00
[hz.nervous_tesla.cached.thread-9] [c.h.i.c.i.MembershipManager]: [10.233.90.105]:5701 [dev] [5.3.1] Removing Member [10.233.117.91]:5701 - 8fed7bd7-ca74-41ef-88ed-84229d21c6ed
[hz.nervous_tesla.client.thread-3] [c.h.m.i.LocalMapStatsProvider]: [10.233.90.105]:5701 [dev] [5.3.1] partitionId: 110, replica: 1 has no owner!
[hz.nervous_tesla.cached.thread-9] [c.h.i.p.InternalPartitionService]: [10.233.90.105]:5701 [dev] [5.3.1] Remaining migration tasks: 1. (repartitionTime=Thu Jan 01 00:00:00 GMT 1970, plannedMigrations=0, completedMigrations=0, remainingMigrations=0, totalCompletedMigrations=0)
[hz.nervous_tesla.IO.thread-in-1] [c.h.i.s.t.TcpServerConnection]: [10.233.90.105]:5701 [dev] [5.3.1] Initialized new cluster connection between /10.233.90.105:43211 and /10.233.117.91:5701

Нода кластера потеряла соединение с другой, после чего потерянная нода была удалена из кластера, и началась миграция партиции. Через какое-то время нода возвращается в кластер. При этом, если посмотреть на логи других нод, можно увидеть, что heartbeat`ы на некоторые ноды приходят просроченные:

[hz.nervous_tesla.priority-generic-operation.thread-0] [c.h.i.c.i.ClusterHeartbeatManager]: [10.233.90.105]:5701 [dev] [5.3.1] Ignoring heartbeat from Member [10.233.94.116]:5701 - 9c73de67-2e0e-4e76-ae81-1bdfc2222938 since it is expired (now: 2024-03-01 10:06:49.694, timestamp: 2024-03-01 10:06:06.828)

Заглянув в логи отключившихся нод, мы увидели там длительные паузы полных сборок мусора. Из-за этих постоянных пауз, судя по всему, нода не может поддерживать отправку heartbeat`ов. Поэтому мы увеличили таймаут hazelcast.max.no.heartbeat.seconds до 120 секунд.

Финальный список флагов, которые мы меняли

Итого, после всех изысканий у нас добавились флаги:
-XX:NewSize=360m, -XX:MaxNewSize=360m, -XX:MaxGCPauseMillis=1000,
-XX:GCPauseIntervalMillis=1200, -XX:ConcGCThreads=3,
-XX:G1HeapWastePercent=0, -XX:G1ReservePercent=25,
-XX:InitiatingHeapOccupancyPercent=25,
-Dhazelcast.max.no.heartbeat.seconds=120

Заключение

В итоге все наши флаги выглядят так:

hazelcast:
  javaOpts: "-Xmx9g -Xms9g -XX:G1HeapRegionSize=32m -XX:+AlwaysPreTouch -XX:MaxMetaspaceSize=128m -XX:MaxDirectMemorySize=128m -XX:NewSize=360m -XX:MaxNewSize=360m -XX:MaxGCPauseMillis=1000 -XX:GCPauseIntervalMillis=1200 -XX:ConcGCThreads=5 -XX:G1HeapWastePercent=0 -XX:InitiatingHeapOccupancyPercent=25 -XX:G1ReservePercent=25 -Dhazelcast.map.eviction.sample.count=1000 -Dhazelcast.map.eviction.batch.size=10"

Чтобы сделать выводы об успешности наших работ, резюмирую, чего мы добились:

  • научились рассчитывать вместимость хранилища и прогнозировать время хранения объектов;

  • выявили проблему фрагментации памяти humongous объектами и связанную с ней ошибку оценки размера объекта в памяти и минимизировали вероятность ее проявления;

  • добились от JVM предсказуемости в потреблении памяти и корректного завершения работы ноды кластера в случае ее недостатка;

  • добились от кластера высокой доступности и сохранности данных при падении части нод;

  • смогли выйти за пределы рекомендуемых 60% данных от общего объема RAM, достигнув 85% (это на большом кластере, на тестовом – 75%);

  • развернули кластер с 50 ГБ heap`а, против 16 ГБ, рекомендуемых в документации;

  • добились от алгоритма вымещения относительной точности работы;

  • выявили проблему переполнения хранилища при большом разбросе размеров объектов и минимизировали риски, связанные с ее возникновением;

  • добились от GC более эффективной работы при работе с большим heap`ом.

Чего не добились:

  • отказоустойчивости – при аварии map`а становится не доступной для чтения или записи из-за переезда партиций. И хотя нашлось два способа это обойти, они слишком рискованные, и мы не стали к ним прибегать;

  • не смогли добиться хранения объектов любых размеров;

  • не смогли добиться стабильной работы кластера. Падение нод можно отсрочить, минимизировать риск, но не гарантировано исключить.

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

  • I – Загрузка больших объектов размером больше половины сегмента гарантированно приведет к падению.

    Можно брать запас heap`а под фрагментацию, чтобы отсрочить проблему, но рано или поздно его все равно окажется недостаточно. Даже если HZ запатчат, и он будет считать размер огромных объектов честно, сам G1 GC все равно не предназначен для такой задачи. 2048 регионов heap`а, рекомендованных документацией для G1 GC, по 32 МБ – это всего лишь 64 ГБ на сервер. Чтобы хранить действительно много данных, масштабироваться вертикально – не подойдет. Но даже если у нас достаточно серверов, чтобы вместить общий объем за счет партиционирования, проблема фрагментации останется все равно.

    Мы сможем хранить больше объектов, но не большие объекты. Храня такие объекты, мы подвергаем риску весь кластер, ведь если упадет одна нода, проблемные объекты начнут переезжать на другие ноды и уронят и их. Единственное лечение – это вводить ограничения на уровне бизнес-логики приложения, которое этим хранилищем пользуется. В ходе изучения вопроса я натыкался на рекомендации использовать CMS GC, якобы он лучше справляется с большим хипом. Но если смотреть по верхам – его не рекомендуют, поскольку считают устаревшим. В то же время он разделяет память на сегменты, что спасло бы от риска уронить кластер. Было бы интересно опробовать и другие GC, но в рамках используемого образа мы ограничены только этими двумя. К тому же остальные проблемы сменой GC не разрешились бы.

  • II – То, что у JVM нет возможности ограничить все пулы памяти и нет возможности их мониторить, тоже является большой проблемой.

    Это означает, лимиты придется выявлять эмпирическим путем, ловя спонтанные падения контейнера по OOM, без возможности отследить проблемный пул памяти, и вслепую увеличивать под них запас RAM. Другого варианта нет.

  • III – Даже если объекты небольшого размера, но при этом не соответствующие друг другу по объему, есть вероятность, что кластер не сможет их переварить.

    Например, хранилище заполнено объектами в 1 МБ, и мы начали заполнять map`у большими объектами в 16 МБ, то будет достаточно всего 100 таких объектов, чтобы исчерпать наш запас хипа в 1,5 ГБ, который мы оставили под работу самого Hazelcast. Как и в случае с humongous объектами, сначала это произойдет на одной ноде, а потом каскадом лягут остальные. 

  • IV – Закладывать большие размеры выборки и количество вымещений опасно, потому что алгоритмы вымещения и выборки линейные и роняют ниже плинтуса pps.

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


Итого, в данной конфигурации, используя JVM 11 и G1 GC, добиться целей не получилось.

Следующим этапом следовало бы рассмотреть возможность обновить JVM до 17 версии, которая заявлена как поддерживаемая Hazelcast, и опробовать ZGC или другие сборщики мусора. Но у нас такой возможности нет, и свои изыскания мы на этом закончили. Поэтому было бы интересно узнать об опыте других команд по развертыванию Hazelcast и о его использовании с альтернативными сборщиками мусора.

Источники

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