G1 сборщик мусора длинная пауза не знаю

Question

Я пытаюсь настроить мое приложение на отзывчивость, максимально допустимая пауза GC составляет 40 мс. Не удалось понять, почему эта пауза заняла около 900 мс. Применение - приложение с низкой задержкой, предназначенное для обслуживания высокого QPS.

GC PARAMS: -Xmx5G -XX: + UseG1GC -XX: MaxGCPauseMillis = 40

Журналы:

2014-10-02T16:31:08.508+0530: 2072.186: [GC pause (young) 
Desired survivor size 148373504 bytes, new threshold 15 (max 15) 
- age 1: 10600184 bytes, 10600184 total 
- age 2:  67024 bytes, 10667208 total 
- age 3:  44560 bytes, 10711768 total 
- age 4:  3520 bytes, 10715288 total 
- age 5:  4080 bytes, 10719368 total 
- age 6:  4464 bytes, 10723832 total 
- age 7:  2568 bytes, 10726400 total 
- age 8:  4872 bytes, 10731272 total 
- age 9:  3216 bytes, 10734488 total 
- age 10:  2400 bytes, 10736888 total 
- age 11:  2024 bytes, 10738912 total 
- age 12:  3144 bytes, 10742056 total 
- age 13:  8584 bytes, 10750640 total 
- age 14:  2672 bytes, 10753312 total 
- age 15:  696 bytes, 10754008 total 
, 0.0384210 secs] 
    [Parallel Time: 15.2 ms, GC Workers: 15] 
     [GC Worker Start (ms): Min: 2072186.5, Avg: 2072186.5, Max: 2072186.6, Diff: 0.1] 
     [Ext Root Scanning (ms): Min: 1.0, Avg: 1.0, Max: 1.1, Diff: 0.1, Sum: 15.2] 
     [Update RS (ms): Min: 0.3, Avg: 0.4, Max: 0.4, Diff: 0.1, Sum: 5.7] 
     [Processed Buffers: Min: 1, Avg: 3.3, Max: 5, Diff: 4, Sum: 49] 
     [Scan RS (ms): Min: 0.5, Avg: 0.5, Max: 0.6, Diff: 0.1, Sum: 7.8] 
     [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] 
     [Object Copy (ms): Min: 12.8, Avg: 12.9, Max: 13.0, Diff: 0.2, Sum: 193.0] 
     [Termination (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.7] 
     [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.4] 
     [GC Worker Total (ms): Min: 14.9, Avg: 15.0, Max: 15.1, Diff: 0.2, Sum: 225.1] 
     [GC Worker End (ms): Min: 2072201.5, Avg: 2072201.5, Max: 2072201.6, Diff: 0.1] 
    [Code Root Fixup: 0.2 ms] 
    [Code Root Migration: 0.6 ms] 
    [Clear CT: 0.8 ms] 
    [Other: 21.6 ms] 
     [Choose CSet: 0.0 ms] 
     [Ref Proc: 14.2 ms] 
     [Ref Enq: 0.6 ms] 
     [Free CSet: 6.6 ms] 
    [Eden: 2244.0M(2244.0M)->0.0B(2571.0M) Survivors: 19.0M->10.0M Heap: 2443.7M(5120.0M)->191.4M(5120.0M)] 
[Times: user=0.26 sys=0.00, real=0.90 secs] 
2014-10-02T16:31:09.406+0530: 2073.085: Total time for which application threads were stopped: 0.8992240 seconds 

Java -версии:
Java версия "1.7.0_60"
Java (TM) SE Runtime Environment (сборка 1.7.0_60-b19)
Java HotSpot (TM) 64-разрядный сервер VM (сборка 24.60-B09, смешанный режим)

Пожалуйста, помогите мне т o понять, что вызвало такую ​​долгую паузу? И как это предотвратить?

Answer 1

Из того, что я могу сказать, процесс был заблокирован во время gc, а это означало, что он должен был ждать ресурсов.

Эта строка говорит вам время выполнения:

[Times: user=0.26 sys=0.00, real=0.90 secs] 

С

• user означает чистое время центрального процессора.
• sys значение время ядра.
• real значение реальный мир время.

Время messured на Java дс ниже 40мс, видите эту строку:

, 0.0384210 secs] 

Такой блок может произойти, когда:

• Выполнение тяжелых операций ввода-вывода (например, сеть , Диски)
• Другой процесс в системе вызывает большую нагрузку на один из необходимых ресурсов ces

В вашем случае я бы подумал, что, должно быть, было что-то еще, едящее процессорное время, но это трудно сказать.

Дополнение

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