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

Эта поучительная история повествует о том, как важно развивать навыки гугления, и о том, как я боролся с ежечасным полным 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 />

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

Выводы

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

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


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