Как вы наверняка уже знаете, скоро в Питере пройдёт очередная конференция Joker. Я собираюсь сделать на ней доклад о том, как расследовать поведение JVM, кажущееся поначалу таинственным и загадочным. Этот пост — тизер, предназначенный для того, чтобы дать вам возможность понять, чего ждать от доклада.
Предположим, что к вам вдруг приходит информация о проблеме: при сборке мусора отображаются причины «Last Ditch Collection» и «No GC», и поиск в интернете не даёт ничего вразумительного. К счастью, HotSpot практически полностью собирается из OpenJDK, и потому, как минимум в теории, мы можем найти ответы на все интересующие нас вопросы прямо в исходниках. Чем мы и займёмся!
Last Ditch Collection
Вооружившись исходным кодом OpenJDK, поищем интересующую нас строку:
$ grep -irn "Last Ditch Collection" .
./src/share/vm/gc_interface/gcCause.cpp:94: return "Last ditch collection";
Зайдём в файл и обнаружим там отсылку к _last_ditch_collection — элементу enum, содержащего все возможные причины сборки мусора. Сразу же подсмотрим и нужную константу для «No GC», ей окажется _no_gc. Продолжим грепать:
$ grep -rn "GCCause::_last_ditch_collection" .
...
./src/share/vm/gc_implementation/shared/vmGCOperations.cpp:286: heap->collect_as_vm_thread(GCCause::_last_ditch_collection);
...
Похоже, что это оно! Почитав метод, в котором находится вызов, и в особенности — его комментарии, мы довольно быстро понимаем, что происходит.
По всей видимости, когда HotSpot не может выделить место для чего-то, что должно находиться в metaspace (например, для класса), сперва запускается сборка мусора с причиной GCCause::_metadata_GC_threshold. Если это не помогает, то производится попытка расширить metaspace. Если и это не помогает, то запускается полная сборка мусора с причиной GCCause::_last_ditch_collection. Во время этой сборки подчищаются soft references. Если даже это не помогает, то тогда место действительно кончилось, и пора кидать OOM.
Звучит правдоподобно, но стоит научиться стабильно это воспроизводить. Если верить написанному выше, то при активном замусоривании metaspace мы должны увидеть как минимум одну сборку с причиной «Last ditch collection»:
ClassPool pool = ClassPool.getDefault();
for(long l = 0; l < Long.MAX_VALUE; l++) {
pool.makeClass("com.example.Kitty" + l).toClass();
}
Если это запустить с параметрами по умолчанию, то ждать придётся довольно долго. Но мы можем уменьшить размер metaspace и получить результат быстрее:
$ java -cp build/libs/labs-8-all.jar -XX:+PrintGCDetails -XX:MaxMetaspaceSize=10m ru.gvsmirnov.perv.labs.gc.NoGcTrigger
...
[Full GC (Last ditch collection) [...] 14470K->14425K(32768K), [Metaspace: 8971K->8971K(1056768K)], 0.0481030 secs]
...
Exception in thread "main" javassist.CannotCompileException: by java.lang.OutOfMemoryError: Metaspace
at javassist.ClassPool.toClass(ClassPool.java:1099)
...
В большинстве случаев мы увидим более, чем одну сборку с причиной «last ditch collection». Это вполне ожидаемо, поскольку иначе бы от них не было толку, и вряд ли бы эту фичу вообще реализовали.
Кстати, здесь мы смотрели на исходники Java 9, но логика last ditch collection не менялась очень давно, так что тут беспокоиться не о чем.
Ещё одна забавная вещь, которую стоит упомянуть: нам, в общем-то, и не нужно было писать кода, активно гадящего в metaspace. Да и вообще какого-либо кода: ведь JVM и сама горазда позагружать классы. Если мы просто запустим java -XX:+PrintGCDetails -XX:MaxMetaspaceSize=2m X, то получим несколько раз last ditch collection, а затем и OOM. Виртуальная машина даже не успеет понять, что класса X не существует.
No GC
Перейдём к «No GC». Капитан подсказывает нам, что разработчики HotSpot вряд ли бы назвали так нормальную причину сборки мусора. Да и вообще, единственный случай, в котором мы, по логике, должны такое увидеть — это если мы успеем запустить jstat раньше, чем произойдёт хоть одна сборка мусора:
$ jstat -gccause -t `jps | grep NoGc | cut -d' ' -f1` 100
Timestamp S0 S1 E O P YGC YGCT FGC FGCT GCT LGCC GCC
0.7 0.00 0.00 4.00 0.00 40.34 0 0.000 0 0.000 0.000 No GC No GC
0.8 0.00 0.00 6.00 0.00 45.82 0 0.000 0 0.000 0.000 No GC No GC
0.9 0.00 0.00 6.00 0.00 51.44 0 0.000 0 0.000 0.000 No GC No GC
Или если он сделает проверку, когда сборщик мусора не активен:
Timestamp S0 S1 E O P YGC YGCT FGC FGCT GCT LGCC GCC
2.8 0.00 0.00 0.00 0.78 31.00 5 0.080 5 1.051 1.131 Allocation Failure No GC
Так что, если это было обнаружено в другой ситуации, то это, должно быть, баг. А поскольку когда мы разбирали last ditch collection, таких странностей не наблюдалось, то есть шанс того, что он уже исправлен. Проявим немного оптимизма и поищем все подходящие коммиты:
$ hg grep --all '::_no_gc'
...
src/share/vm/gc_implementation/shared/vmGCOperations.cpp:2097:+: assert(((_gc_cause != GCCause::_no_gc) &&
...
Ага! Похоже, что проблему действительно пофиксили в коммите номер 2097, ещё в феврале 2013 года. Заглянув в файл hotspot_version, мы обнаруживаем, что последняя HotSpot, в которой должна наблюдаться проблема — это 21.0-b01. У меня под рукой была Java 6 с версией HotSpot 20.45-b01:
$ java -version
java version "1.6.0_45"
Java(TM) SE Runtime Environment (build 1.6.0_45-b06)
Java HotSpot(TM) 64-Bit Server VM (build 20.45-b01, mixed mode)
При запуске нашего примера с котиками, немедленно получается следующий результат:
Timestamp S0 S1 E O P YGC YGCT FGC FGCT GCT LGCC GCC
2.7 0.00 0.00 0.00 0.78 100.00 5 0.080 5 1.051 1.131 unknown GCCause Allocation Failure
2.8 0.00 0.00 0.00 0.78 100.00 5 0.080 5 1.051 1.131 unknown GCCause Allocation Failure
Это довольно близко, но не совсем то, что мы искали. Однако, при более детальном изучении патча становится очевидным, что нужно просто использовать другой сборщик мусора. Добавление -XX:+UseG1GC даст нам нужный результат:
Timestamp S0 S1 E O P YGC YGCT FGC FGCT GCT LGCC GCC
1.6 ? ? ? ? 96.78 ? ? ? ? ? G1 Evacuation Pause No GC
1.7 ? ? ? ? 100.00 ? ? ? ? ? No GC Permanent Generation Full
1.8 ? ? ? ? 100.00 ? ? ? ? ? No GC Permanent Generation Full
1.9 ? ? ? ? 100.00 ? ? ? ? ? No GC Permanent Generation Full
2.0 ? ? ? ? 100.00 ? ? ? ? ? No GC Permanent Generation Full
Успех! Кстати, тот человек, который первым ответит, почему тут какие-то знаки вопроса, и что именно должно навести нас на использование G1, получит приглашение на Joker Unconference ;)
Послесловие
Итак, только что, на основании одного-единственного твита и используя базовые утилиты командной строки, мы ответили на не гуглящийся вопрос, нашли стародавний баг в HotSpot, смогли благодаря этому оценить сверху версию JVM, и даже узнали, какой использовался сборщик мусора.
Мораль проста: HotSpot — не какая-то загадочная шайтан-машина. В мире вообще нет ничего загадочного, оно есть лишь у нас в головах.
P.S. Если у вас есть интересный пример из этой оперы, то не стесняйтесь присылать его. Вполне возможно, что я разберу его в докладе, или даже просто так :)
P.P.S. На конференцию приедет несколько приглашённых спикеров, не знающих русского языка. они будут рады, если будет больше докладов на английском. Я добавил опрос, чтобы понять, как к такому может отнестись основная часть слушателей.
Автор: gvsmirnov
