что может вызвать большое расхождение между малым временем GC и общим временем паузы?

Question

У нас есть приложение, чувствительное к задержке, и мы испытываем некоторые паузы, связанные с ГХ, которые мы не полностью понимаем. Иногда у нас есть небольшой сборщик мусора, который приводит к тому, что время паузы приложения намного больше, чем указанное время сборщика мусора. Вот пример фрагмента журнала:

485377.257: [GC 485378.857: [ParNew: 105845K-> 621K (118016K), 0,0028070 с] 136492K-> 31374K (1035520K), 0,0028720 с] [Times: user = 0,01 sys = 0,00, реальный = 1,61 с]
Общее время, в течение которого потоки приложений были остановлены: 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: новый размер = 128 м *

Кто-нибудь может предложить какое-то объяснение относительно того, что здесь может происходить, и / или какие-то пути для дальнейшего расследования?

Answer 1

Ты уверен, что не обмениваешься? Обычно видя:

Время: пользователь = 0,01 сис = 0,00, реальное = 1,61 с

(по вашему следу)

предполагает, что что-то произошло в процессе, который не требует использования процессора, но требует времени на настенных часах ... и это обычно своп или другой ввод / вывод. немного иостата может помочь пролить свет ...

Используете ли вы много встроенной памяти вне кучи Java? (возможно, через DirectByteBuffer, nio и т. д.), которые могут съесть ваше утверждение «много свободной памяти» (к вашему удивлению). top или vmstat также могут показывать это.

Answer 2

«Время до безопасной точки» является большой причиной для такого рода вещей. К сожалению, GC регистрирует только время с момента начала работы (после того, как ВСЕ поток приложения был приостановлен в безопасной точке), до момента завершения (после которого потоки будут освобождены из своих безопасных точек). -XX: + PrintGCApplicationStoppedTime (гораздо более правильно) сообщает время, от которого первый поток сказал перейти к безопасной точке, до времени, когда последний поток был выпущен для повторного запуска.

К сожалению, довольно часто можно увидеть, что один поток занимает много времени, чтобы добраться до безопасной точки, и когда это происходит, все другие приятные и вежливые потоки, которые перешли в безопасную точку и остановились там, когда им сказали, будут ждать, пока не выйдет Приходит. Примерами таких вещей являются длительные операции во время выполнения. Например. В большинстве JVM клонирование массива объектов выполняется без внутренних возможностей безопасных точек (представьте себе, что клонирование массива 1 ГБ происходит, и в середине необходимо сделать паузу в GC). Оптимизированные подсчитанные циклы также могут работать очень долго без внутренних безопасных точек.

[У Zing есть встроенный профилировщик времени для безопасной точки, частично для отслеживания и устранения подобных вещей].

Answer 3

Вы говорите, что "много свободной памяти", но размер вашей кучи ограничен 512 МБ. Возможно, вам не хватает памяти чаще / раньше, чем вы думаете.