Является ли время "остановки мира", сообщаемое с PrintGCApplicationStoppedTime, действительно точным?

Question

Я пытаюсь оценить, как долго потоки в java-приложении блокируются паузами «остановка мира» для сборки мусора, используя опцию -XX: + PrintGCApplicationStoppedTime JVM.

Я анализирую файл gc.log и добавляю сообщенное время остановки в метку времени GC (-XX: + PrintGCDateStamps), чтобы получить метки времени «запуска и остановки» для событий GC.

Потоки приложения измеряют время, необходимое для отправки HTTP-запроса и получения ответа, и регистрируют отметку времени, когда запрос отправляется, и продолжительность запроса.

Когда я сравниваю метки времени события GC с метками времени приложения (DATA), я получаю странные результаты:

Type|   Start time|Start time diff|     End time|End time diff|  Duration
DATA|1330360259830|            230|1330360260139|            7|       309
DATA|1330360259849|            211|1330360260138|            8|       289
DATA|1330360259960|            100|1330360260135|           11|       175
DATA|1330360259979|             81|1330360260135|           11|       156
DATA|1330360259980|             80|1330360260135|           11|       155
DATA|1330360259989|             71|1330360260135|           11|       146
DATA|1330360260019|             41|1330360260135|           11|       116
DATA|1330360260029|             31|1330360260135|           11|       106
  GC|1330360260060|              0|1330360260146|            0|        86

«Нечетная» часть, приведенная выше, состоит в том, что большинство записей «DATA» заканчиваются за 11 мс до окончания события GC. Моя интерпретация заключается в том, что с момента, когда потоки приложения были «освобождены» из безопасной точки, прошло около 11 мс, пока GC не рассчитал время «остановки мира».
Правильно ли это истолковано?

Код в методе SafepointSynchronize::end() в hotspot/src/share/vm/runtime/safepoint.cpp из openjdk, похоже, пробуждает приостановленные потоки Java перед вычислением времени остановки.
Это означает, что сообщаемое время остановки ненадежно , поток, который вычисляет время остановки, может быть приостановлен между пробуждением потоков Java и вычислением времени, верно?
(Я не программист на C ++, поэтому я мог неправильно истолковать код.)

Приложение было запущено с Oracle JDK 1.6.0_20 на сервере Solaris 10 5/08 x86.

Командная строка:

java -Xss128k -Xms1024m -Xmx1024m -XX:MaxPermSize=28m -Xloggc:logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -XX:+PrintHeapAtGC -classpath [...] net.grinder.engine.process.WorkerProcessEntryPoint

Answer 1

эти флаги имеют неправильные имена, и вы правы, что они ненадежны.Отчет об ошибке, который вы ищете, это этот , и он был исправлен в hs17, который впервые попал в производство в 6u21 (согласно этому списку исправлений ), поэтому вы на 1 версию устарели.

Также обратите внимание, что вы все равно используете данные неправильно.Флаг остановленного времени сопровождается флагом PrintGCApplicationConcurrentTime, и эти два флага печатают время, проведенное в безопасной точке, вы можете использовать PrintSafepointStatistics для получения информации о том, для чего предназначены безопасные точки.

Этот ответ на похожую тему.