Ахаха, HotSpot, что ты делаешь, прекрати!

Original author: Gleb Smirnov
  • Translation
  • Tutorial


Как вы наверняка уже знаете, скоро в Питере пройдёт очередная конференция 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 ;) SerCe уже дал правильный ответ.

Послесловие

Итак, только что, на основании одного-единственного твита и используя базовые утилиты командной строки, мы ответили на не гуглящийся вопрос, нашли стародавний баг в HotSpot, смогли благодаря этому оценить сверху версию JVM, и даже узнали, какой использовался сборщик мусора.

Мораль проста: HotSpot — не какая-то загадочная шайтан-машина. В мире вообще нет ничего загадочного, оно есть лишь у нас в головах.

P.S. Если у вас есть интересный пример из этой оперы, то не стесняйтесь присылать его. Вполне возможно, что я разберу его в докладе, или даже просто так :)

P.P.S. На конференцию приедет несколько приглашённых спикеров, не знающих русского языка. они будут рады, если будет больше докладов на английском. Я добавил опрос, чтобы понять, как к такому может отнестись основная часть слушателей.

Only registered users can participate in poll. Log in, please.

Готовы ли вы прослушать этот доклад на английском, а не на русском?

  • 57.3%Да, готов. Пусть иностранные коллеги тоже послушают.129
  • 42.7%Нет, не готов.96
AdBlock has stolen the banner, but banners are not teeth — they will be back

More
Ads

Comments 9

    +1
    На G1 намекает хотя-бы файл, затронутый патчем:
    b/src/share/vm/gc_implementation/g1/vm_operations_g1.hpp


    Вопросики, это баг:
    The jstat does not support G1 in the JDK6u21
      0
      Почти! :)
      Но ведь патчем затронуты и vmCMSOperations.hpp и vmPSOperations.cpp, а не только vm_operations_g1.hpp. Почему один даёт "unknown GCCause", а другой — "No GC"?
        +2
        Конкретно в G1 никак не проставлялся gc_cause, fix, что повлияло на VM_G1IncCollectionPause, соответственно jstat работал некорректно.
          +1
          Точно. Инвайт ваш :)
      –2
      A вот я не готов читать на английском. Я в отпуске.
        0
        Ты не был понят широкими массами. Да и мной тоже :)
          +2
          В этом ответе я 1. Похвастался, что тоже читаю доклад. 2. Похвастался, что буду в отпуске. 3. Похвастался, что когда я не в отпуске, то много читаю докладов на анлийском.

          Кошмар, а не коммент. Я-б сам минусанул.
            0
            Можешь этот минусануть взамен!
              0
              не, суррогаты не употребляем.

      Only users with full accounts can post comments. Log in, please.