Java зависает на несколько секунд, но в журнале gc не найдена пауза gc
У меня есть Java-приложение, работающее в Linux (CentOS 7) с использованием g1 gc, и оно регулярно зависает на несколько секунд, выглядит так же, как gc pauses, но я не могу найти такие длинные паузы в gc log.
Чтобы убедиться, что 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 с Total time, для которого были остановлены потоки приложения):
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(прозрачные огромные страницы) и подкачка памяти также были отключены.
И я нашел одну вещь, которую не могу понять:
Рядом с паузой всегда есть старт одновременной метки, и там, где происходит старт одновременной метки, также есть пауза.
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
2 ответа
Наконец, я обнаружил, что это вызвано ошибкой jdk по поводу одновременной маркировки для больших ссылочных массивов:
Большие эталонные массивы вызывают очень длительное время синхронизации
И мое решение состоит в том, чтобы изменить большой массив ссылок на разделенные двухмерные массивы
Хотя GC является одним из источников пауз в виртуальных машинах, безопасные точки (остановить мирские паузы) могут быть инициированы другими операциями, такими как очистка кэша кода, смещенная блокировка, определенные операции отладки и т. Д. Вот список операций безопасной точки. Чтобы устранить эти безопасные точки, используйте следующие параметры:
Safepoints:
-XX:+UnlockDiagnosticVMOptions
-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1
-XX:+SafepointTimeout
-XX:SafepointTimeoutDelay=500
-XX:+LogVMOutput
-XX:LogFile=/var/log/jvm/vm.log
GC:
-verbose:gc
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-Xloggc:/var/log/jvm/garbage.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=100M