Статьи

Регистрация остановок в мире в JVM

Февраль 22, 2019

Металлический сейф Различные события могут заставить JVM приостановить все потоки приложения. Такие паузы называются паузами Stop-The-World (STW). Наиболее распространенной причиной запуска паузы STW является сборка мусора ( пример в github ), но различные действия JIT ( пример ), отзыв смещенной блокировки ( пример ), определенные операции JVMTI и многие другие также требуют остановки приложения.

Точки, в которых потоки приложения могут быть безопасно остановлены, называются неожиданными безопасными точками. Этот термин также часто используется для обозначения всех пауз STW.

Журналы GC более или менее распространены. Тем не менее, это не захватывает информацию о всех безопасных точках. Чтобы получить все это, используйте эти параметры JVM:

1
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

Если вас интересует наименование, явно ссылающееся на GC, не пугайтесь — включение этих параметров регистрирует все безопасные точки, а не только паузы сбора мусора. Если вы запустите следующий пример ( источник в github) с указанными выше флагами

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
public class FullGc {
  private static final Collection<Object> leak = new ArrayList<>();
  private static volatile Object sink;
 
  public static void main(String[] args) {
    while (true) {
      try {
        leak.add(new byte[1024 * 1024]);
        sink = new byte[1024 * 1024];
      } catch (OutOfMemoryError e) {
        leak.clear();
      }
    }
  }
}

вы должны увидеть записи, подобные следующим в вашем стандартном выводе:

1
2
3
4
Application time: 0.3440086 seconds
Total time for which application threads were stopped: 0.0620105 seconds
Application time: 0.2100691 seconds
Total time for which application threads were stopped: 0.0890223 seconds

Читать это легко (особенно по сравнению с журналами GC) — из вышесказанного вы можете видеть, что приложению удалось выполнить полезную работу за первые 344 миллисекунды, приостановить все потоки на 62 миллисекунды, после чего потребовалось 210 мс полезной работы и еще одна пауза 89 мс.

Вы можете использовать эти флаги в сочетании с флагами GC, например, при повторном запуске той же программы с добавлением -XX: + PrintGCDetails вывод будет выглядеть примерно так:

1
2
[Full GC (Ergonomics) [PSYoungGen: 1375253K->0K(1387008K)] [ParOldGen: 2796146K->2049K(1784832K)] 4171400K->2049K(3171840K), [Metaspace: 3134K->3134K(1056768K)], 0.0571841 secs] [Times: user=0.02 sys=0.04, real=0.06 secs]
Total time for which application threads were stopped: 0.0572646 seconds, Stopping threads took: 0.0000088 seconds

Исходя из вышесказанного, мы видим, что потоки приложения были вынуждены останавливаться на 57 мс для выполнения сборки мусора. Из которых 8 микросекунд были потрачены на ожидание прибытия всех потоков приложения в безопасную точку. Но если мы возьмем другой пример ( источник в github ) и запустим его с теми же параметрами, мы можем увидеть следующий вывод:

1
2
Total time for which application threads were stopped: 0.0001273 seconds, Stopping threads took: 0.0000196 seconds
Total time for which application threads were stopped: 0.0000648 seconds, Stopping threads took: 0.0000174 seconds

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

1
-XX:+PrintSafepointStatistics  -XX:PrintSafepointStatisticsCount=1

Включение их делает журнал JVM дополнительной информацией к стандартному выводу, выглядя примерно так:

1
2
5.141: RevokeBias                       [      13          0              2    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0000782 seconds, Stopping threads took: 0.0000269 seconds

Информация о контрольных точках отображается в следующей последовательности:

  • Отметка времени в миллисекундах с момента запуска JVM (5.141 в приведенном выше примере)
  • Имя операции, которая вызвала паузу ( RevokeBias ).
    • Если вы видите «no vm operation», это означает, что это так называемая «гарантированная безопасная точка». По умолчанию JVM вызывает безопасную точку каждую секунду для обработки всех операций в очереди, которые не являются срочными. Флаг GuaranteedSafepointInterval может использоваться, чтобы изменить это поведение (установите его в 0, чтобы отключить его вообще)
  • Количество потоков, которые были остановлены в безопасной точке (13)
  • Количество потоков, запущенных в начале безопасной точки (0)
  • Количество потоков, которые были заблокированы, когда операция vm начала свое выполнение (2)
  • Время для разных этапов прибытия в безопасную точку и выполнения операции (все нули)

Итак, теперь мы видим, что использование смещенных блокировок может привести к большому количеству пауз STW, даже если они занимают десятки микросекунд. В эти массово параллельные дни нередко отключать их сразу.

В общем, вы действительно можете избавить себя от неприятностей, постоянно записывая эти данные. Для этого укажите следующие параметры JVM:

1
-XX:+LogVMOutput -XX:LogFile=vm.log

И все выходные данные JVM будут сохранены в файле vm.log. Однако интерпретация и действия на основе этих журналов — это очень широкая тема, выходящая за рамки данной статьи, но я могу написать об этом одну или две публикации в будущем, поэтому, если вам интересно, следите за обновлениями — либо через нашу подписку на Twitter, либо через RSS-канал .

Если вам нужно больше читать прямо сейчас, есть отличная запись в блоге Нитсана Вакарта : и, конечно же, исходный код OpenJDK .

Ссылка: Запись паузы «остановить мир» в JVM от нашего партнера по JCG Глеба Смирнова в блоге Plumbr Blog .
35
Share: