Уточнение вывода ГХ

Question

Я запускаю Java-приложение со следующими настройками:
-XX: + CMSParallelRemarkEnabled
-XX: + UseConcMarkSweepGC
-XX: + UseParNewGC
-XX: + PrintGCApplicationStoppedTime
-XX: + PrintGCApplicationConcurrentTime
-XX: + PrintGCDetails
-XX: + PrintGCTimeStamps
-XX: + PrintGCDateStamps
-XX: + PrintHeapAtGC
-XX: + PrintTenuringDistribution

Я не уверен, как интерпретировать соответствующие журналы gc (ниже). В частности:

• Куча после вызовов GC = 31 (полный 3) : это означает, что было 31 второстепенных GC и 3 полных GC?

• Что вызывает несколько последовательных строк Общее время, в течение которого потоки приложения были остановлены и Время приложения ? Можно ли получить метки времени, связанные с каждой из этих строк?

GC logs:

Total time for which application threads were stopped: 0.0046910 seconds  
Application time: 0.7946670 seconds  
Total time for which application threads were stopped: 0.0002900 seconds  
Application time: 1.0153640 seconds  
Total time for which application threads were stopped: 0.0002780 seconds  
Application time: 1.0161890 seconds  
Total time for which application threads were stopped: 0.0002760 seconds  
Application time: 1.0145990 seconds  
Total time for which application threads were stopped: 0.0002950 seconds  
Application time: 0.9999800 seconds  
Total time for which application threads were stopped: 0.0002770 seconds  
Application time: 1.0151640 seconds
Total time for which application threads were stopped: 0.0002730 seconds
Application time: 0.9996590 seconds  
Total time for which application threads were stopped: 0.0002880 seconds  
Application time: 0.9624290 seconds  

{Heap before GC invocations=30 (full 3):  
 par new generation   total 131008K, used 130944K [0x00000000eac00000, 0x00000000f2c00000, 0x00000000f2c00000)  
  eden space 130944K, 100% used [0x00000000eac00000, 0x00000000f2be0000, 0x00000000f2be0000)  
  from space 64K,   0% used [0x00000000f2bf0000, 0x00000000f2bf0000, 0x00000000f2c00000)  
  to   space 64K,   0% used [0x00000000f2be0000, 0x00000000f2be0000, 0x00000000f2bf0000)  
 concurrent mark-sweep generation total 131072K, used 48348K [0x00000000f2c00000, 0x00000000fac00000, 0x00000000fac00000)  
 concurrent-mark-sweep perm gen total 30000K, used 19518K [0x00000000fac00000, 0x00000000fc94c000, 0x0000000100000000)  

2010-05-11T09:30:13.888+0100: 384.955: [GC 384.955: [ParNew  
Desired survivor size 32768 bytes, new threshold 0 (max 0)  
: 130944K->0K(131008K), 0.0052470 secs] 179292K->48549K(262080K), 0.0053030 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]  

Heap after GC invocations=31 (full 3):  
 par new generation   total 131008K, used 0K [0x00000000eac00000, 0x00000000f2c00000, 0x00000000f2c00000)  
  eden space 130944K,   0% used [0x00000000eac00000, 0x00000000eac00000,   0x00000000f2be0000)
  from space 64K,   0% used [0x00000000f2be0000, 0x00000000f2be0000, 0x00000000f2bf0000)  
  to   space 64K,   0% used [0x00000000f2bf0000, 0x00000000f2bf0000, 0x00000000f2c00000)  
 concurrent mark-sweep generation total 131072K, used 48549K [0x00000000f2c00000, 0x00000000fac00000, 0x00000000fac00000)  
 concurrent-mark-sweep perm gen total 30000K, used 19518K [0x00000000fac00000, 0x00000000fc94c000, 0x0000000100000000)  
}

Total time for which application threads were stopped: 0.0056410 seconds  
Application time: 0.0475220 seconds  
Total time for which application threads were stopped: 0.0001800 seconds  
Application time: 1.0174830 seconds  
Total time for which application threads were stopped: 0.0003820 seconds  
Application time: 1.0126350 seconds  
Total time for which application threads were stopped: 0.0002750 seconds  
Application time: 1.0155910 seconds
Total time for which application threads were stopped: 0.0002680 seconds
Application time: 1.0155580 seconds  
Total time for which application threads were stopped: 0.0002880 seconds  
Application time: 1.0155480 seconds  
Total time for which application threads were stopped: 0.0002970 seconds  
Application time: 0.9896810 seconds  

Answer 1

эти строки без отметок времени не являются событиями gc, они записывают, когда происходят безопасные точки и как долго они длились. До 6у21 они несколько ненадежны.

Answer 2

У вас будут метки времени, соответствующие каждой записи.

Пример из журнала моего сервера показывает

124951.831: [GC 1915727K->1295438K(1994752K), 0.1964641 secs]
Total time for which application threads were stopped: 0.1983187 seconds
125015.262: [GC 1909838K->1302111K(1994752K), 0.2037094 secs]
Total time for which application threads were stopped: 0.2055489 seconds

124951.831 и 125015.262 в этом случае - количество секунд , прошедших с момента запуска JVM.

124951.831 соответствует 34 часам, 42 минутам и 31 секунде работы JVM.

125015.262 соответствует 34 часам, 43 минутам, 35 ​​секундам работы JVM.

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

Разница важна (125015 - 124951) показывает, что минорный ГК сработал через 64 ​​секунды (в моем случае).

Эти строки меток времени отсутствуют в вашем журнале?

Answer 3

Да, это количество малых и крупных коллекций вместе взятых. Было 28 второстепенных ГК и 3 главных ГК.

Незначительные коллекции вызывают те строки, которые вы цитируете. Если нет отметок времени, я не думаю, что вы можете заставить их изменить модификацию JVM. Тем не менее, я понимаю, что «Время приложения» - это время, в течение которого приложение запускалось с момента последней незначительной коллекции (пауза), так что это может дать вам то, что вы хотите. Я полагаю, что это по крайней мере дельта времени с момента последнего выхода.