#java #garbage-collection #jvm #jvm-arguments #jvm-hotspot
#java #сбор мусора #jvm #jvm-аргументы #jvm-точка доступа
Вопрос:
Я обнаружил на сервере длинные безопасные точки (> 10 секунд!) в jvm safepoint.log:
6534.953: no vm operation [ 353 0 4 ] [ 0 0 14179 0 0 ] 0
7241.410: RevokeBias [ 357 0 1 ] [ 0 0 14621 0 0 ] 0
8501.278: BulkRevokeBias [ 356 0 6 ] [ 0 0 13440 0 2 ] 0
9667.681: no vm operation [ 349 0 8 ] [ 0 0 15236 0 0 ] 0
12094.170: G1IncCollectionPause [ 350 0 4 ] [ 0 0 15144 1 24 ] 0
13383.412: no vm operation [ 348 0 4 ] [ 0 0 15783 0 0 ] 0
13444.109: RevokeBias [ 349 0 2 ] [ 0 0 16084 0 0 ] 0
На моем ноутбуке, с которым я играл -XX:SafepointTimeoutDelay = 2
и это работает хорошо, печатая плохие потоки:
# SafepointSynchronize::begin: Timeout detected:
...
# SafepointSynchronize::begin: (End of list)
<writer thread='11267'/>
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
567.766: BulkRevokeBias [ 78 1 2 ] [ 0 6 6 0 0 ] 0
Итак, я добавил опции на сервер:
-XX: SafepointTimeout -XX:SafepointTimeoutDelay=1000
чтобы увидеть, какие потоки вызывают проблему, но я не вижу никаких отпечатков, в то время как я все еще вижу длительное время безопасной точки.
Почему это не применяется на сервере?
Вот фактическая конфигурация сервера (взята из safepoint.log):
Java HotSpot(TM) 64-Bit Server VM (25.202-b08) for linux-amd64 JRE (1.8.0_202-b08), built on Dec 15 2018 12:40:22 by amp;quot;java_reamp;quot; with gcc 7.3.0
...
-XX: PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=10
-XX: UnlockDiagnosticVMOptions
-XX: LogVMOutput
-XX:LogFile=/opt/pprb/card-pro/pci-pprb-eip57/logs/safepoint.log
-XX: SafepointTimeout
-XX:SafepointTimeoutDelay=1000
...
Комментарии:
1. Ты перезапустил виртуальную машину, верно?
2. Может быть, попробуйте добавить -XX: PrintGCApplicationStoppedTime, чтобы посмотреть, получите ли вы больше информации?
3. Крис, да, перезапущен.
4. У нас уже есть
-XX: PrintGCApplicationStoppedTime
. В журналах GC я вижу те же проблемы:2019-03-25T12:42:57.678 0300: 6777.056: Total time for which application threads were stopped: 18.0049752 seconds, Stopping threads took: 18.0036770 seconds
5. Создайте собственный поток, который запускается, например, каждые 100 мс, и проверьте, не прерывается ли он также длительными паузами. В любом случае всегда следите за использованием памяти ОС, использованием ввода-вывода и т.д.
Ответ №1:
В safepoint «Общее время, за которое были остановлены потоки приложения: 18.0049752 секунды, остановка потоков заняла: 18.0036770 секунд», возможно, вызвано ожиданием блокировки потока, а может и нет. Когда SafepointTimeoutDelay= 1000, если более одного потока ожидают 1 секунду, будет вызван метод SafepointSynchronize::print_safepoint_timeout в safepoint.cpp для печати определенных потоков используется Safepointstate. Но когда весь поток перейдет в безопасную точку и по другой причине задержится на 18 секунд, метод не будет вызван, и для него не будет журналов.
Мы можем установить safepoint = trace в jdk9 , чтобы знать все состояние потока в журнале gc.