Высокая частота сохраняемых фаз CMS, даже если у Old/Young gen достаточно места

Я заранее признаю, что эта проблема очень похожа на: большое количество cms-mark/ mark -mark-pauses-даже-хотя-старый-gen-is-not-half-full и inured-collection-start-for-for- нет очевидных причин. Я пишу, потому что: 1. Эти темы старше 1 года, и 2. Я надеюсь узнать, как найти коренные причины возникновения такого поведения.

У нас есть сервер приложений Java 24/7 OAS / OC4J (это не наша вина!), Работающий на RHEL5/Redhat 5.11, Java 6. Это было стабильным в отношении памяти в течение многих лет, пока недавно мы не начали наблюдать высокую загрузку ЦП из-за частые космические циклы CMS. Это происходит даже тогда, когда есть больше, чем достаточно места как в молодых, так и в постоянных помещениях. Мое прочтение на эту тему предполагает, что постоянный цикл CMS обычно начинается, когда постоянное пространство (Old gen) занимает примерно 92% емкости. Но мы видим, что это постоянно происходит с 30% -ной производительностью даже меньше. А также, я должен упомянуть, когда общая куча кажется меньше, чем значение по умолчанию 45% для общего использования кучи, иначе InitiatingHeapOccupancyPercent,

Мы все еще рассматриваем последние изменения кода и попробовали несколько вещей, но эти проблемы сохраняются. Таким образом, пока мы не можем воспроизвести вне рабочих серверов, хотя усилия в среде dev/qa продолжаются.

Я думаю, что у меня есть три основных вопроса здесь:

  1. Что может вызывать частую (преждевременную?) Начальную фазу цикла CMS. И как мы можем это проверить или расследовать? Например, проверить различные сегменты текущего выделения памяти (eden, Survivor, Old-Gen) для огромных объектов или тому подобное?
  2. Я читал об использовании -XX:+UseCMSInitiatingOccupancyOnly а также -XX:CMSInitiatingOccupancyFraction=NN (например, в статьях, упомянутых выше). Что может быть разумным (== безопасным) значением для NN, и каковы риски переопределения эргономики CMS по умолчанию таким образом?
  3. Любые другие вещи, которые мы должны рассмотреть или исследовать?

Вот некоторые подробности о нашей проблеме:

  • Итак, пока мы не можем воспроизвести это вне производства. Таким образом, отладка или настройка не вариант
  • Мы используем ночное задание cron, чтобы заставить Full GC смягчать фрагментацию с помощью jmap -histo: live pid
  • Аргументы нашей командной строки JVM относительно памяти приведены ниже:

-XX:+PrintGCDetails-XX:+PrintGCDateStamps-XX:+PrintTenuringDistribution-XX:-TraceClassUnloading-XX:+UseConcMarkSweepGC-XX:+CMSClassUnloadingEnabled-XX:+HeapDumpOnOutOfMemoryError-XX:+ExplicitGCInvokesConcurrent-XX:+UseCMSCompactAtFullCollection-Xms10g-Xmx10g-Xmn3g-XX:SurvivorRatio=6-XX:PermSize=256m-XX:MaxPermSize=256m-XX:TargetSurvivorRatio=80-XX:ParallelGCThreads=8

Примечание: мы недавно попытались поднять молодое поколение до 3,5 г как несколько отчаянный эксперимент. (На производстве!) Никаких заметных различий не наблюдается

  • Выход из jmap -heap, Замечания: From Space кажется, всегда занят на 100%. Это нормально или что-то указывает? 


    using parallel threads in the new generation.
    using thread-local object allocation.
    Concurrent Mark-Sweep GC



Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 10737418240 (10240.0MB)
   NewSize          = 3758096384 (3584.0MB)
   MaxNewSize       = 3758096384 (3584.0MB)
   OldSize          = 5439488 (5.1875MB)
   NewRatio         = 2
   SurvivorRatio    = 6
   PermSize         = 268435456 (256.0MB)
   MaxPermSize      = 268435456 (256.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 3288334336 (3136.0MB)
   used     = 1048575408 (999.9994354248047MB)
   free     = 2239758928 (2136.0005645751953MB)
   31.88773709900525% used
Eden Space:
   capacity = 2818572288 (2688.0MB)
   used     = 578813360 (551.9994354248047MB)
   free     = 2239758928 (2136.0005645751953MB)
   20.535693282172794% used
From Space:
   capacity = 469762048 (448.0MB)
   used     = 469762048 (448.0MB)
   free     = 0 (0.0MB)
   100.0% used
To Space:
   capacity = 469762048 (448.0MB)
   used     = 0 (0.0MB)
   free     = 469762048 (448.0MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 6979321856 (6656.0MB)
   used     = 1592989856 (1519.1935119628906MB)
   free     = 5386332000 (5136.806488037109MB)
   22.82442175425016% used
Perm Generation:
   capacity = 268435456 (256.0MB)
   used     = 249858712 (238.2838363647461MB)
   free     = 18576744 (17.716163635253906MB)
   93.07962357997894% used

  •  Выходные данные собственного анализатора GC Log, показывающие частые начальные циклы оценки (IM)/ примечания (RM) и низкую занятость молодых / арендованных. Вы можете видеть, что занятость Young gen медленно растет до 98,30%, вскоре после чего мы ожидаем ParNew (PN) Young GC: 

               |            |  PN: |YHeapB4|YHeapAf|YHeapDt|
               |            |------|-------|-------|-------|
               |            |PF,CF,|       |       |       |
               |            |  SY: |OHeapB4|OHeapAf|OHeapDt|
               |            |------|-------|-------|-------|
    Date       |Time        |IM,RM:|Y Occ% |OHeap  |O Occ% |Duration|THeapB4|THeapAf|THeapDt|Promoted|% Garbage|Interval| Alloc |AllocRate(MB/s)|PromoRate(MB/s)
    ------------------------------------------------------------------------------------------------------------------------------------------------------------
    2016-12-05|14:16:59.455|  RM  |  15.11|1620287|  23.77|     0.18
    2016-12-05|14:17:03.057|  IM  |  16.16|1615358|  23.70|     0.66
    2016-12-05|14:17:13.444|  RM  |  17.70|1615358|  23.70|     0.23
    2016-12-05|14:17:17.227|  IM  |  18.82|1513691|  22.21|     0.70
    2016-12-05|14:17:27.887|  RM  |  28.54|1513691|  22.21|     0.33
    2016-12-05|14:17:30.390|  IM  |  29.45|1513667|  22.21|     1.02
    2016-12-05|14:17:41.326|  RM  |  32.90|1513667|  22.21|     0.66
    2016-12-05|14:17:44.290|  IM  |  34.86|1513666|  22.21|     1.23
    ...[deleted for brevity]...
    2016-12-05|14:37:28.024|  IM  |  95.88|1377444|  20.21|     2.93
    2016-12-05|14:37:40.601|  RM  |  95.89|1377444|  20.21|     2.15
    2016-12-05|14:37:46.032|  IM  |  95.89|1377443|  20.21|     2.83
    2016-12-05|14:37:58.557|  RM  |  98.30|1377443|  20.21|     2.21
    2016-12-05|14:38:03.988|  IM  |  98.30|1377307|  20.21|     2.90
    2016-12-05|14:38:15.638|  PN  |3211264| 458752|2752512|     0.77|4588571|1942900|2645671|  106841|    96.12
    2016-12-05|14:38:18.193|  RM  |  18.04|1484148|  21.78|     0.24
    2016-12-05|14:38:21.813|  IM  |  18.04|1480802|  21.73|     0.75
    2016-12-05|14:38:31.822|  RM  |  19.05|1480802|  21.73|     0.34
    ...[and so on]...
  • Фактический вывод журнала GC, начиная с первой начальной метки (IM) в 14:17:03.057 сверху вывод. Точно так же, как указано выше, но я показываю GN ParNew Young для полноты: 


    2016-12-05T14:17:03.057-0800: [GC [1 CMS-initial-mark: 1615358K(6815744K)] 2134211K(10027008K), 0.6538170 secs] [Times: user=0.65 sys=0.00, real=0.66 secs]
    2016-12-05T14:17:06.178-0800: [CMS-concurrent-mark: 2.463/2.467 secs] [Times: user=5.04 sys=0.01, real=2.46 secs]
    2016-12-05T14:17:06.251-0800: [CMS-concurrent-preclean: 0.072/0.073 secs] [Times: user=0.07 sys=0.00, real=0.08 secs]
     CMS: abort preclean due to time 2016-12-05T14:17:13.442-0800: [CMS-concurrent-abortable-preclean: 7.189/7.192 secs] [Times: user=7.46 sys=0.02, real=7.19 secs] 
    2016-12-05T14:17:13.444-0800: [GC[YG occupancy: 568459 K (3211264 K)][Rescan (parallel) , 0.1020240 secs][weak refs processing, 0.0312140 secs][class unloading, 0.0396040 secs][scrub symbol & string tables, 0.0368990 secs] [1 CMS-remark: 1615358K(6815744K)] 2183818K(10027008K), 0.2344980 secs] [Times: user=0.89 sys=0.00, real=0.23 secs]
    2016-12-05T14:17:15.212-0800: [CMS-concurrent-sweep: 1.533/1.533 secs] [Times: user=1.54 sys=0.00, real=1.54 secs]
    2016-12-05T14:17:15.225-0800: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
    2016-12-05T14:17:17.227-0800: [GC [1 CMS-initial-mark: 1513691K(6815744K)] 2118034K(10027008K), 0.7036950 secs] [Times: user=0.71 sys=0.00, real=0.70 secs]
    2016-12-05T14:17:20.548-0800: [CMS-concurrent-mark: 2.613/2.617 secs] [Times: user=5.62 sys=0.03, real=2.62 secs]
    2016-12-05T14:17:20.667-0800: [CMS-concurrent-preclean: 0.113/0.119 secs] [Times: user=0.23 sys=0.00, real=0.12 secs]
     CMS: abort preclean due to time 2016-12-05T14:17:27.886-0800: [CMS-concurrent-abortable-preclean: 7.217/7.219 secs] [Times: user=8.54 sys=0.07, real=7.22 secs] 
    2016-12-05T14:17:27.887-0800: [GC[YG occupancy: 916526 K (3211264 K)][Rescan (parallel) , 0.2159770 secs][weak refs processing, 0.0000180 secs][class unloading, 0.0460640 secs][scrub symbol & string tables, 0.0404060 secs] [1 CMS-remark: 1513691K(6815744K)] 2430218K(10027008K), 0.3276590 secs] [Times: user=1.59 sys=0.02, real=0.33 secs]
    2016-12-05T14:17:29.611-0800: [CMS-concurrent-sweep: 1.396/1.396 secs] [Times: user=1.40 sys=0.00, real=1.39 secs]
    ...[And So On]...
    2016-12-05T14:38:03.988-0800: [GC [1 CMS-initial-mark: 1377307K(6815744K)] 4534072K(10027008K), 2.9013180 secs] [Times: user=2.90 sys=0.00, real=2.90 secs]
    2016-12-05T14:38:09.403-0800: [CMS-concurrent-mark: 2.507/2.514 secs] [Times: user=5.03 sys=0.03, real=2.51 secs]
    2016-12-05T14:38:09.462-0800: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
    2016-12-05T14:38:15.638-0800: [GC [ParNew
    Desired survivor size 375809632 bytes, new threshold 4 (max 15)
    - age   1:  115976192 bytes,  115976192 total
    - age   2:  104282224 bytes,  220258416 total
    - age   3:   85871464 bytes,  306129880 total
    - age   4:   98122648 bytes,  404252528 total
    : 3211264K->458752K(3211264K), 0.7731320 secs] 4588571K->1942900K(10027008K), 0.7732860 secs] [Times: user=3.15 sys=0.00, real=0.77 secs]
     CMS: abort preclean due to time 2016-12-05T14:38:18.192-0800: [CMS-concurrent-abortable-preclean: 7.842/8.730 secs] [Times: user=12.50 sys=0.07, real=8.73 secs]
    2016-12-05T14:38:18.193-0800: [GC[YG occupancy: 579220 K (3211264 K)][Rescan (parallel) , 0.1208810 secs][weak refs processing, 0.0008320 secs][class unloading, 0.0483220 secs][scrub symbol & string tables, 0.0414970 secs] [1 CMS-remark: 1484148K(6815744K)] 2063368K(10027008K), 0.2376050 secs] [Times: user=1.07 sys=0.00, real=0.24 secs]
    2016-12-05T14:38:19.798-0800: [CMS-concurrent-sweep: 1.366/1.366 secs] [Times: user=1.40 sys=0.00, real=1.37 secs]
    2016-12-05T14:38:19.811-0800: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
    2016-12-05T14:38:21.813-0800: [GC [1 CMS-initial-mark: 1480802K(6815744K)] 2060239K(10027008K), 0.7487000 secs] [Times: user=0.75 sys=0.00, real=0.75 secs]

Исходя из замечательных наблюдений и предложений Алексея, мы попытаемся увеличить производство в Перми (и я сообщу). Но в качестве предварительной проверки его предположения я провел исследование использования perm gen для всех контейнерных JVM на одном из наших хостов, и это кажется очень правдоподобным. В приведенном ниже фрагменте PID=2979 (при пропускной способности 92% perm) демонстрирует постоянное поведение при сборе CMS.



    [oracle@ikm-oasb-3 bin]$ for p in `opmnctl status | grep OC4JG | awk '{print $5}'`; do echo -n "PID=$p "; jmap -heap $p | grep -A4 'Perm Gen' | egrep '%'; done 2> /dev/null
    PID=8456    89.31778371334076% used
    PID=8455    89.03931379318237% used
    PID=8454    91.1630779504776% used
    PID=8453    89.17466700077057% used
    PID=8452    87.69496977329254% used
    PID=2979    92.2750473022461% used
    PID=1884    90.25585949420929% used
    PID=785    76.16643011569977% used
    PID=607    89.06879723072052% used
Источник

1 ответ

Решение

Цикл очистки старого пространства CMS запускается, когда либо старое пространство достигает порога занятости, либо постоянное пространство достигает порога.

До Java 8 постоянное пространство является частью кучи мусора и входит в объем алгоритма CMS.

В вашем случае Пермь на 93%

Perm Generation:
   capacity = 268435456 (256.0MB)
   used     = 249858712 (238.2838363647461MB)
   free     = 18576744 (17.716163635253906MB)
   93.07962357997894% used

Эта статья описывает аналогичный случай.

Если вы посоветуете увеличить пространство для перми или вы можете настроить отдельный порог занятости для перми, используя –XX: CMSInitiatingPermOccupancyFraction=95 вариант.

Дополнительные параметры настройки GC.

Источник
Другие вопросы по тегам