Я пытаюсь оценить, как долго потоки в java-приложении блокируются паузами сборки мусора «остановить мир», используя параметр JVM -XX:+PrintGCApplicationStoppedTime.
Я анализирую файл gc.log и добавляю сообщаемое время остановки к временной метке сборщика мусора (-XX:+PrintGCDateStamps), чтобы получить временные отметки «начало и конец» для событий сборщика мусора.
Потоки приложения измеряют время, необходимое для отправки 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 мс с момента «освобождения» потоков приложения из безопасной точки до момента, когда сборщик мусора вычислил время «остановить мир».
Верна ли эта интерпретация?
Код в методе 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