У меня есть java-приложение, работающее в Linux (CentOS 7) с использованием g1 gc, и оно регулярно зависает на несколько секунд, это выглядит так же, как паузы gc, но я не могу найти такие длинные паузы в журнале gc.
Чтобы убедиться, что java-приложение зависает, я запустил фоновый поток, который ничего не дозирует, кроме как распечатывает журнал каждые 500 мс. И журнал оказался приостановленным на несколько секунд. Вот журнал, и он был приостановлен с [14:31:02,834] до [14:31:05,677].
WARN [2018-07-16 14:30:57,831][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:30:58,331][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:30:58,832][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:30:59,332][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:30:59,832][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:00,333][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:00,833][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:01,333][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:01,834][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:02,334][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:02,834][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:05,677][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:06,177][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:06,678][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:07,178][clock]py.datanode.DataNodeAppEngine(196):tick...
И в то же время журнал gc (grep с общим временем, в течение которого потоки приложения были остановлены):
2018-07-16T14:30:58.327+0800: 2679.423: Total time for which application threads were stopped: 0.3750533 seconds, Stopping threads took: 0.0003430 seconds
2018-07-16T14:31:05.176+0800: 2686.272: Total time for which application threads were stopped: 0.5037637 seconds, Stopping threads took: 0.0004556 seconds
2018-07-16T14:31:06.978+0800: 2688.074: Total time for which application threads were stopped: 0.0060367 seconds, Stopping threads took: 0.0003190 seconds
Кроме того, в этом java-процессе также есть несколько потоков, выполняющих собственные коды, они написаны на C и не подвержены влиянию jvm. Эти потоки работали хорошо, я совершенно уверен в этом, потому что один из этих потоков является потоком сердцебиения, а время ожидания сердцебиения составляет 800 мс, но во время паузы тайм-аут сердцебиения не был обнаружен.
Я также следил за использованием процессора, и процессор с 12 ядрами простаивал до 80%.
Использование памяти также не слишком велико, THP (прозрачные огромные страницы) и память подкачки также были отключены.
И я нашел одну вещь, которую я не могу понять:
Рядом с паузой всегда находится concurrent-mark-start, и везде, где происходит concurrent-mark-start, также есть пауза.
2018-07-16T14:30:58.489+0800: 2679.586: [GC concurrent-mark-start]
Я знаю, что одновременная фаза меток не вызовет STW, но я не могу поверить, что это просто совпадение, потому что я воспроизводил это много раз, и это всегда так.
А вот загрузка ЦП и использование памяти во время одной из пауз от YourKit:
Благодаря предложению @jspcal я получил SafepointStatistics:
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
2566.430: G1IncCollectionPause [ 745 0 0 ] [ 0 0 2705 3 474 ] 0
G1IncCollectionPause потребовалось почти 3 секунды, чтобы добраться до безопасной точки, в то время как время вращения и время блокировки равны 0.
