Как теги JVMTI могут повлиять на паузы GC

В этом посте анализируется, почему и как агенты Plumbr в некоторых случаях увеличивали продолжительность GC-пауз. Устранение основной проблемы выявило интересную информацию о том, как метки JVMTI обрабатываются во время пауз GC.

Обнаружение проблемы

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

2015-01-30T17:19:08.965-0200: 182.816: [Full GC (Ergonomics) 
[PSYoungGen: 524800K->0K(611840K)] 
[ParOldGen: 1102620K->1103028K(1398272K)] 1627420K->1103028K(2010112K), 
[Metaspace: 2797K->2797K(1056768K)], 0.9563188 secs] 
[Times: user=7.32 sys=0.01, real=0.96 secs]

И вот один с приложенным агентом Plumbr:

2015-02-02T17:40:35.872-0200: 333.166: [Full GC (Ergonomics) 
[PSYoungGen: 524800K->0K(611840K)] 
[ParOldGen: 1194734K->1197253K(1398272K)] 1719534K->1197253K(2010112K), 
[Metaspace: 17710K->17710K(1064960K)], 1.9900624 secs] 
[Times: user=7.94 sys=0.01, real=1.99 secs]

Аномалия скрыта в прошедшем времени. В режиме реального времени , фактическое время, которое прошло. Если вы посмотрите на секундомер в вашей руке, реальное время будет равно этому числу. Время  пользователя  (плюс системное время) — это общее время ЦП, которое было использовано во время измерения. Это может быть больше, чем в реальном времени, если на нескольких ядрах есть несколько потоков. Таким образом, для Parallel GC реальное время должно быть примерно равно (пользовательское время / количество потоков). На моей машине это соотношение должно быть близко к 7, и это действительно было так без агента Plumbr. Но с Plumbr это соотношение значительно упало. Определенно не в порядке!

Начальное расследование

Учитывая такие доказательства, следующие наиболее вероятные гипотезы:

1. Plumbr заставляет JVM выполнять тяжелую однопоточную операцию после каждого GC
2. Plumbr заставляет JVM использовать меньше потоков для сборки мусора

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

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

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

1. Приложение должно просочиться в память, чтобы Plumbr обнаружил
2. Приложение должно часто останавливаться для сбора мусора
3. … и как последний момент — приложение должно иметь большой живой набор, а это означает, что число объектов, переживших Full GC, должно быть большим.

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

С помощью этого простого поиска нам удалось определить проблему с помощью одного действия, которое выполняет агент Plumbr. Проблема исчезла с отключенной маркировкой JVMTI. Во время нашего  анализа пути к корню gc и цепочке ссылок мы  помечаем  каждый объект в куче. Судя по всему, времена GC были каким-то образом затронуты сгенерированными нами тегами.

Нахождение основной причины

Тем не менее, было неясно, почему паузы GC были продлены. Мусор быстро собирается, и предполагается, что большинство помеченных объектов имеют право на сборку мусора. Однако было обнаружено, что при большом живом наборе (что является одним из симптомов утечки памяти) сохраняется много помеченных объектов.

Но эй, даже если все объекты в живом наборе помечены, это не должно линейно влиять на время GC. После завершения GC мы получаем уведомления обо всех наших отмеченных объектах, которые были собраны, но живой набор не входит в число этих объектов. Это заставляет задуматься о том, повторяет ли HotSpot по какой-то странной причине все помеченные объекты после каждого GC.

Чтобы проверить претензию, можно взглянуть на исходный код горячей точки. После некоторого поиска мы в итоге пришли к  JvmtiTagMap :: do_weak_oops ,  который действительно перебирает  все теги  и выполняет ряд не очень дешевых операций для всех из них. Что еще хуже, эта операция выполняется последовательно и не распараллеливается. И последний кусочек головоломки был решен после нахождения цепочки вызовов, вызывающих этот метод после каждой сборки мусора.  (Почему это сделано так, как это делается, и что это имеет отношение к слабым ссылкам, выходит за рамки этой статьи)

+  if(isGenerated(*tag_ptr)) {
+    *tag_ptr = 0;
+  }