Эта поучительная история повествует о том, как важно развивать навыки гугления, и о том, как я боролся с ежечасным полным Garbage collection.
После того, как мы мигрировали в продакшене один из компонентов системы (единственный, работающий на Tomcat) на новую версию томката, неожиданно саппорт запаниковал, увидев в логах полуторасекундные запуски GC.
Вообще, в нашем проекте (FX trading platform в инвестиционном банке) любой запуск GC больше 50 миллисекунд (ms) вызывает беспокойство саппорта, мониторящего, кроме всего прочего, логи GC, а GC больше 100 ms вызывают истерику. Поэтому, увидев в логах 1.45 секунд, они просто запаниковали. Мне повезло быть на «второй линии обороны» в тот день, и я начал разбираться, в чем же дело.
Для начала, полез в логи. И увидел:
Ключевое здесь — указание на то, что это System — т.е. полная сборка мусора активирована вызовом
Первым делом, по старой памяти, был проверен DGC (ссылка на антимонгольском, кратко — сборщик мусора, активируемый при использовании в приложении RMI). Когда-то именно он был причиной полных сборок каждый час на многих наших системах, по той простой причине, что мы используем RMI для JMX. Поэтому в один прекрасный день, много лет назад, мы на всех системах добавили в параметры запуска JVM следующее:
Источники сих настроек: [1], [2]. Все, что они призваны изменить — сказать DGC, что он может запускаться раз в
Проверив старт-скрипт томката, я увидел, что там есть маленькая ошибка, и вместо
Однако, исправив это недоразумение, я был очень удивлен, когда после перезапуска томкатов мы снова увидели все те же ежечасные
Оригинальный метод:
Измененный метод:
Как видите, все, что мы здесь делаем — узнаем, кто же все-таки нас вызвал, путем вывода в
Подменяем
Тот самый DGC! Но как? Мы же выставили фактически бесконечный интервал между запусками DGC? Вот тут мне пришлось напрячь все мои скиллы гугления. И так я искал, и этак — ничего не мог найти. Проверил, не перезаписывает ли кто мои установки для DGC — оказалось, что к моменту запуска GC все системные свойства имеют такие же значения, как я и выставил. Сюрприз…
![image](https://habrastorage.org/r/w780q1/getpro/habr/post_images/def/f8b/b4b/deff8bb4bc7cf554ab29d2e95e8a8d13.jpg)
На этом месте мое подозрение пало на томкат. И вот, счастливая комбинация слов в запросе к гуглу дала-таки мне одну-единственную ссылку, которая заставила меня произнести то, что печатать здесь мне очень стыдно, и мои английские коллеги (помогавшие мне, по мере сил, в расследовании, путем задавания наводящих вопросов типа «А гуглить пробовал?») очень неодобрительно на меня посмотрели… Потом посмотрели на то, что написано по ссылке — и повторили мои ругательства.
Итак, вот она, ссылка, которая, в свою очередь, ведет на багзиллу томката: тынц. Вкратце, эти гениальные ребята из апача через рефлексию перезаписывают значение интервала, с которым должен вызываться DGC, прямо в классе
Вот код из томкатовского класса
Там же, на SO, я нашел и workaround:
Именно это я и сделал. Как вы можете видеть из кода выше, флаг
А выводов, в общем-то, немного:
Краткое описание проблемы
После того, как мы мигрировали в продакшене один из компонентов системы (единственный, работающий на 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()
. Думаю, будет лишним говорить, что у нас в коде это не используется.Лирическое отступление
Если быть совсем честным, то это не правда — мы используем вызов
System.gc()
, со вполне благой целью. Дело в том, что в процессе старта система пре-кеширует огромное количество «static data» — информации о пользователях, валютах и т.п., и процесс этот генерирует довольно много мусора. Поэтому после того, как мы закончили все приготовления, и непосредственно перед тем, как мы отрапортуем, что система запустилась, мы вызываем System.gc()
, чтобы заодно избавиться от лишней фрагментации памяти. Кроме того, мы делаем то же самое каждую ночь в 17:00 по Нью-Йоркскому времени, когда заканчивается торговый день, и вся наша система уходит в оффлайн на 5 минут (maintenance mode), с целью убрать накопившийся за день мусор и дефрагментировать память. В рабочее время, мы стараемся избегать old-gen collection, так как даже ParNew-сборки, занимающие 20-40 ms, создают порой непозволительные задержки.Первым делом, по старой памяти, был проверен 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 все системные свойства имеют такие же значения, как я и выставил. Сюрприз…
![image](https://habrastorage.org/getpro/habr/post_images/def/f8b/b4b/deff8bb4bc7cf554ab29d2e95e8a8d13.jpg)
...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
просто отключает этот блок кода, ответственный за странное поведение. И — о, чудо! — это помогло! Ежечасные сборки мусора исчезли в небытие, саппорт счастлив, я пошел пить чай.Выводы
А выводов, в общем-то, немного:
- Самое главное — учитесь правильно формулировать запросы к гуглу! Я попробовал с десяток разных комбинаций, пока наконец-то не наткнулся на совершенно банальный запрос
tomcat hourly full GC
, который и выдал мне искомую ссылку. - Не надо подразумевать, что сторонний, пусть даже очень известый софт, не имеет багов — очень даже имеет! И это ужу не первый раз, когда мы нарываемся на баги. В прошлый раз это был баг в Hotspot CMS, который очень сильно портил нам время на сборку мусора. Решился апгрейдом на новую JVM.
- Ну и, конечно, рефлексия — зло, особенно если вы — разработчик контейнера или библиотеки, и лезете
грязными рукамирефлексией в системные классы.
Спасибо за внимание, надеюсь, кому-то мой опыт окажется полезен.