История одного garbage collection’а

Краткое описание проблемы

После того, как мы мигрировали в продакшене один из компонентов системы (единственный, работающий на Tomcat) на новую версию томката, неожиданно саппорт запаниковал, увидев в логах полуторасекундные запуски GC.

Вообще, в нашем проекте (FX trading platform в инвестиционном банке) любой запуск GC больше 50 миллисекунд (ms) вызывает беспокойство саппорта, мониторящего, кроме всего прочего, логи GC, а GC больше 100 ms вызывают истерику. Поэтому, увидев в логах 1.45 секунд, они просто запаниковали. Мне повезло быть на «второй линии обороны» в тот день, и я начал разбираться, в чем же дело.

Ход расследования

Для начала, полез в логи. И увидел:
[Full GC (System) 25.575: [CMS: 20700K->22393K(655360K) <...>

Ключевое здесь — указание на то, что это System — т.е. полная сборка мусора активирована вызовом System.gc(). Думаю, будет лишним говорить, что у нас в коде это не используется.

Первым делом, по старой памяти, был проверен DGC (ссылка на антимонгольском, кратко — сборщик мусора, активируемый при использовании в приложении RMI). Когда-то именно он был причиной полных сборок каждый час на многих наших системах, по той простой причине, что мы используем RMI для JMX. Поэтому в один прекрасный день, много лет назад, мы на всех системах добавили в параметры запуска JVM следующее:

-Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE -Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE 

Источники сих настроек: [1], [2]. Все, что они призваны изменить — сказать DGC, что он может запускаться раз в 0x7FFFFFFFFFFFFFFE миллисекунд (примерно раз в 292471208 лет).

Проверив старт-скрипт томката, я увидел, что там есть маленькая ошибка, и вместо 0x7FFFFFFFFFFFFFFE используется 0x7FFFFFFFFFFFFFFF. Граничное это значение вызывает IllegalArgumentException (код из sun.misc.GC класса):

if (this.latency == 9223372036854775807L) {     throw new IllegalStateException("Request already cancelled"); } 

We need to go deeper!

Однако, исправив это недоразумение, я был очень удивлен, когда после перезапуска томкатов мы снова увидели все те же ежечасные Full GC (System)! Пришлось напрячь соображалку. Чтобы узнать, кто же виноват в вызове System.gc(), я быстренько написал свою реализацию класса java.lang.Runtime, скопировав стандартный класс и изменив у него метод gc() (который вызывается при вызове System.gc()).
Оригинальный метод:

public native void gc(); 

Измененный метод:

public void gc() {     Thread.dumpStack(); } 

Как видите, все, что мы здесь делаем — узнаем, кто же все-таки нас вызвал, путем вывода в stdout стектрейса, т.к. все, что делает метод Thread.dumpStack() — создает исключение и выводит его стектрейс:

    /**      * Prints a stack trace of the current thread to the standard error stream.      * This method is used only for debugging.      *      * @see     Throwable#printStackTrace()      */     public static void dumpStack() {         new Exception("Stack trace").printStackTrace();     } 

Подменяем java.lang.Runtime класс в нашей джава-машине с помощью -Xbootclasspath/p:/tmp/runtime, запускаем… И что же мы видим?

java.lang.Exception: Stack trace         at java.lang.Thread.dumpStack(Thread.java:1249)         at java.lang.Runtime.gc(Runtime.java:689)         at java.lang.System.gc(System.java:926)         at sun.misc.GC$Daemon.run(GC.java:92) 

Тот самый DGC! Но как? Мы же выставили фактически бесконечный интервал между запусками DGC? Вот тут мне пришлось напрячь все мои скиллы гугления. И так я искал, и этак — ничего не мог найти. Проверил, не перезаписывает ли кто мои установки для DGC — оказалось, что к моменту запуска GC все системные свойства имеют такие же значения, как я и выставил. Сюрприз…

…Deeper!

На этом месте мое подозрение пало на томкат. И вот, счастливая комбинация слов в запросе к гуглу дала-таки мне одну-единственную ссылку, которая заставила меня произнести то, что печатать здесь мне очень стыдно, и мои английские коллеги (помогавшие мне, по мере сил, в расследовании, путем задавания наводящих вопросов типа «А гуглить пробовал?») очень неодобрительно на меня посмотрели… Потом посмотрели на то, что написано по ссылке — и повторили мои ругательства.
Итак, вот она, ссылка, которая, в свою очередь, ведет на багзиллу томката: тынц. Вкратце, эти гениальные ребята из апача через рефлексию перезаписывают значение интервала, с которым должен вызываться DGC, прямо в классе sun.rmi.GC, и несмотря на то, что мы выставили свои -Dsun.rmi.dgc.* свойства, они все равно не имеют никакого эффекта! Ибо мы используем томкат 6.0.35, а баг этот был исправлен в следующей версии, 6.0.36.

Вот код из томкатовского класса JreMemoryLeakPreventionListener, который собственно ответственен за это поведение:

/*  * Several components end up calling:  * sun.misc.GC.requestLatency(long)  *   * Those libraries / components known to trigger memory leaks  * due to eventual calls to requestLatency(long) are:  * - javax.management.remote.rmi.RMIConnectorServer.start()  */ if (gcDaemonProtection) {     try {         Class<?> clazz = Class.forName("sun.misc.GC");         Method method = clazz.getDeclaredMethod("requestLatency", new Class[] {long.class});         method.invoke(null, Long.valueOf(3600000));     } catch (...) {         ...     } } 

Там же, на SO, я нашел и workaround:

set <Listener className="org.apache.catalina.core.JreMemoryLeakPreventionListener" gcDaemonProtection="false"/>

Именно это я и сделал. Как вы можете видеть из кода выше, флаг gcDaemonProtection просто отключает этот блок кода, ответственный за странное поведение. И — о, чудо! — это помогло! Ежечасные сборки мусора исчезли в небытие, саппорт счастлив, я пошел пить чай.

Выводы

А выводов, в общем-то, немного:

1. Самое главное — учитесь правильно формулировать запросы к гуглу! Я попробовал с десяток разных комбинаций, пока наконец-то не наткнулся на совершенно банальный запрос tomcat hourly full GC, который и выдал мне искомую ссылку.
2. Не надо подразумевать, что сторонний, пусть даже очень известый софт, не имеет багов — очень даже имеет! И это ужу не первый раз, когда мы нарываемся на баги. В прошлый раз это был баг в Hotspot CMS, который очень сильно портил нам время на сборку мусора. Решился апгрейдом на новую JVM.
3. Ну и, конечно, рефлексия — зло, особенно если вы — разработчик контейнера или библиотеки, и лезете грязными руками рефлексией в системные классы.

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

PS спасибо за инвайт, о Великое НЛО!