Что может вызвать большое расхождение между второстепенным временем GC и общим временем паузы?
У нас есть приложение, чувствительное к задержке, и мы испытываем некоторые паузы, связанные с GC, которые мы не полностью понимаем. Иногда у нас есть небольшой сборщик мусора, который приводит к тому, что время паузы приложения намного больше, чем указанное время сборщика мусора. Вот пример фрагмента журнала:
485377.257: [GC 485378.857: [ParNew: 105845K-> 621K (118016K), 0,0028070 с] 136492K-> 31374K (1035520K), 0,0028720 с ] [Times: user=0.01 sys=0.00, real=1.61 s]
Общее время, в течение которого потоки приложения были остановлены: 1,6032830 секунд.
Общее время паузы здесь на порядки больше, чем указанное время GC. Это единичные и случайные события: непосредственно предшествующие и последующие незначительные события GC не показывают такого большого расхождения.
Процесс выполняется на выделенной машине с большим количеством свободной памяти, 8 ядрами, работающей под управлением Red Hat Enterprise Linux ES Release 4 Update 8 с ядром 2.6.9-89.0.1EL-smp. Мы наблюдали это с (32-битными) версиями JVM 1.6.0_13 и 1.6.0_18.
Мы работаем с этими флагами:
-server -ea -Xms512m -Xmx512m -XX: + UseConcMarkSweepGC -XX: NewSize = 128m -XX: MaxNewSize = 128m -XX: + PrintGCDetails -XX: + PrintGCTimeStamps -XX: + PrintGCApplicationStoppedTace -XUX-X: X:
Кто-нибудь может предложить какое-то объяснение относительно того, что здесь может происходить, и / или какие-то пути для дальнейшего расследования?
3 ответа
Ты уверен, что не обмениваешься? Как правило, видя:
Время: пользователь =0,01 сис =0,00, реальное =1,61 с
(из вашего следа)
предполагает, что что-то произошло в процессе, который не загружает процессор, но требует времени настенных часов... и это обычно подкачка или другой ввод / вывод. немного иостата может помочь пролить свет...
Используете ли вы много встроенной памяти вне кучи Java? (возможно, через DirectByteBuffer, nio и т. д.), которые могут быть использованы в вашем выражении "много свободной памяти" (к вашему удивлению). top или vmstat также могут показать это.
"Время до безопасной точки" является большой причиной для такого рода вещей. К сожалению, GC регистрирует только время с момента начала работы (после того, как ВСЕ поток приложения был приостановлен в безопасной точке), до того момента, когда он завершится (после чего потоки будут освобождены из своих безопасных точек). -XX:+PrintGCApplicationStoppedTime (гораздо более правильно) сообщает время, от которого первый поток сказал перейти к безопасной точке, до времени, когда последний поток был выпущен для повторного запуска.
К сожалению, часто бывает так, что одному потоку требуется много времени, чтобы прийти в безопасную точку, и когда это происходит, все другие приятные и вежливые потоки, которые пошли в безопасную точку и остановились там, когда ему сказали, будут ждать, пока не наступит бродяга. Примерами таких вещей являются длительные операции во время выполнения. Например, массив клонирования объектов в большинстве виртуальных машин виртуальной машины Java не имеет возможностей внутренней безопасной точки (представьте себе, что клонировать массив объемом 1 ГБ нужно, чтобы в середине потребовалась пауза GC). Оптимизированные подсчитанные циклы также могут работать очень долго без внутренних контрольных точек.
[У Зинга есть встроенный профилировщик времени для безопасной точки, частично для того, чтобы отслеживать и устранять подобные вещи].
Вы говорите, что "много свободной памяти", но ваш размер кучи ограничен 512 МБ. Возможно, вам не хватает памяти чаще / раньше, чем вы думаете.