Разгрузка класса CMS заняла много времени - PullRequest
Новая
       41

Разгрузка класса CMS заняла много времени

1 голос
/ 22 марта 2019

При большой нагрузке была замечена большая пауза GC (400 мс) для нашего приложения.В ходе исследования выясняется, что пауза происходит на фазах CMS Final Remark и class unloading, что занимает намного больше времени, чем на других фазах (10x-100X): 

    (CMS Final Remark) 
        [YG occupancy: 142247 K (294912 K)]
2019-03-13T07:38:30.656-0700: 24252.576: 
        [Rescan (parallel) , 0.0216770 secs]
2019-03-13T07:38:30.677-0700: 24252.598: 
        [weak refs processing, 0.0028353 secs]      
2019-03-13T07:38:30.680-0700: 24252.601: 
        [class unloading, 0.3232543 secs]       
2019-03-13T07:38:31.004-0700: 24252.924: 
        [scrub symbol table, 0.0371301 secs]
2019-03-13T07:38:31.041-0700: 24252.961: 
        [scrub string table, 0.0126352 secs]
        [1 CMS-remark: 2062947K(4792320K)] 2205195K(5087232K), 0.3986822 secs]
[Times: user=0.63 sys=0.01, real=0.40 secs]

Total time for which application threads were stopped: 0.4156259 seconds, 
Stopping threads took: 0.0014133 seconds

Эта пауза всегда происходит в первую секундуВ тесте производительности продолжительность паузы варьируется от 300 мс до 400 + мс.

К сожалению, у меня нет доступа к серверу (он находится на обслуживании), и у меня есть только журналы для нескольких тестовых прогонов.Но когда сервер станет доступен, я хочу быть готовым к дальнейшему расследованию, но я не знаю, что вызывает такое поведение.

Моя первая мысль была о страницах Linux Huge, но мы их не используем.

Через некоторое время в журналах я обнаружил следующее: 

Heap after GC invocations=7969 (full 511):
 par new generation   total 294912K, used 23686K [0x0000000687800000, 0x000000069b800000, 0x000000069b800000)
  eden space 262144K,   0% used [0x0000000687800000, 0x0000000687800000, 0x0000000697800000)
  from space 32768K,  72% used [0x0000000699800000, 0x000000069af219b8, 0x000000069b800000)
  to   space 32768K,   0% used [0x0000000697800000, 0x0000000697800000, 0x0000000699800000)
 concurrent mark-sweep generation total 4792320K, used 2062947K [0x000000069b800000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 282286K, capacity 297017K, committed 309256K, reserved 1320960K
  class space    used 33038K, capacity 36852K, committed 38872K, reserved 1048576K
}


Heap after GC invocations=7970 (full 511):
 par new generation   total 294912K, used 27099K [0x0000000687800000, 0x000000069b800000, 0x000000069b800000)
  eden space 262144K,   0% used [0x0000000687800000, 0x0000000687800000, 0x0000000697800000)
  from space 32768K,  82% used [0x0000000697800000, 0x0000000699276df0, 0x0000000699800000)
  to   space 32768K,   0% used [0x0000000699800000, 0x0000000699800000, 0x000000069b800000)
 concurrent mark-sweep generation total 4792320K, used 2066069K [0x000000069b800000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 282303K, capacity 297017K, committed 309256K, reserved 1320960K
  class space    used 33038K, capacity 36852K, committed 38872K, reserved 1048576K
}

Исследование GC-паузы происходит между вызовами GC 7969 и 7970. И количество используемого пространства в метапространстве почти одинаково(на самом деле он увеличился)

Итак, похоже, что на самом деле это не некоторые классы срывов, которые больше не используются (так как пространство не было очищено), и это не безопасная проблема, связанная с достижением точки - поскольку блокировка потоков заняла небольшое время(0.0014133).

Как расследовать такой случай и какая диагностическая информация требуется для надлежащей готовности.

Технические подробности

Centos5 + JDK8 + CMSGC с аргументами: 

-XX:+CMSClassUnloadingEnabled 
-XX:CMSIncrementalDutyCycleMin=10 
-XX:+CMSIncrementalPacing 
-XX:CMSInitiatingOccupancyFraction=50 
-XX:+CMSParallelRemarkEnabled 
-XX:+DisableExplicitGC 
-XX:InitialHeapSize=5242880000 
-XX:MaxHeapSize=5242880000 
-XX:MaxNewSize=335544320 
-XX:MaxTenuringThreshold=6 
-XX:NewSize=335544320 
-XX:OldPLABSize=16
-XX:+UseCompressedClassPointers 
-XX:+UseCompressedOops 
-XX:+UseConcMarkSweepGC 
-XX:+UseParNewGC
...