Анализ частого GC (сбой распределения) и длительного времени GC

Java задняя часть JVM

последовательность

В этой статье в основном анализируется случай частого GC (сбой выделения), а время молодого GC слишком велико.

симптом

  • Процент пропускной способности gc постепенно снижался с обычных 99,96% до 98%, а самая низкая точка достигла 94%.
  • Время молодого gc постепенно увеличивается, постепенно поднимаясь от общих десяти миллисекунд, преодолевая 50, а затем преодолевая 100, 150, 200, 250
  • За период 8,5 дней произошло более 9000 GC, в том числе 4 полных GC со средней продолжительностью почти 8 секунд, большинство из которых были молодыми GC (allocation failure为主), среднее значение составляет более 270 миллисекунд, а максимальное значение составляет почти 7 секунд.
  • Средняя скорость создания объектов составляет 10,63 МБ/с, средняя скорость продвижения — 2 КБ/с, загрузка процессора нормальная, значительных всплесков нет.

JVM-параметры

-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=4 -XX:+UseAdaptiveSizePolicy -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=1073741824 -XX:NewSize=1073741824 -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps

jdk-версия

java -version
java version "1.8.0_66"
Java(TM) SE Runtime Environment (build 1.8.0_66-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.66-b17, mixed mode)

full gc

27.066: [Full GC (Metadata GC Threshold) [PSYoungGen: 19211K->0K(917504K)] [ParOldGen: 80K->18440K(1048576K)] 19291K->18440K(1966080K), [Metaspace: 20943K->20943K(1069056K)], 0.5005658 secs] [Times: user=0.24 sys=0.01, real=0.50 secs] 
100.675: [Full GC (Metadata GC Threshold) [PSYoungGen: 14699K->0K(917504K)] [ParOldGen: 18464K->23826K(1048576K)] 33164K->23826K(1966080K), [Metaspace: 34777K->34777K(1081344K)], 0.7937738 secs] [Times: user=0.37 sys=0.01, real=0.79 secs]
195.073: [Full GC (Metadata GC Threshold) [PSYoungGen: 24843K->0K(1022464K)] [ParOldGen: 30048K->44782K(1048576K)] 54892K->44782K(2071040K), [Metaspace: 58220K->58220K(1101824K)], 3.7936515 secs] [Times: user=1.86 sys=0.02, real=3.79 secs] 
242605.669: [Full GC (Ergonomics) [PSYoungGen: 67276K->0K(882688K)] [ParOldGen: 1042358K->117634K(1048576K)] 1109635K->117634K(1931264K), [Metaspace: 91365K->90958K(1132544K)], 22.1573804 secs] [Times: user=2.50 sys=3.51, real=22.16 secs]

Можно обнаружить, что произошли 4 полных gc, первые три были вызваны пороговым значением GC метаданных, и только последний был вызван эргономикой.

Full GC (Metadata GC Threshold)

Здесь используется Java8.В параметрах не указан размер и верхний предел метапространства.Проверьте это.

jstat -gcmetacapacity 7
   MCMN       MCMX        MC       CCSMN      CCSMX       CCSC     YGC   FGC    FGCT     GCT
       0.0  1136640.0    99456.0        0.0  1048576.0    12160.0 38009    16  275.801 14361.992
  • Игнорируйте следующий FGC, потому что проанализированный журнал — это только четверть его.
  • Здесь вы можете видеть, что MCMX (Максимальная емкость метапространства (КБ)) больше, чем G, а MC (Емкость метапространства (КБ)) составляет всего около 97 МБ, почему это вызывает полный GC (порог метаданных GC)

Связанные параметры

  • -XX:MetaspaceSize, начальный размер пространства (также начальный порог, то есть начальный верхний предел), достижение этого значения вызовет сборку мусора для выгрузки типа, а GC скорректирует значение: если большое количество of Если пространство большое, уменьшите значение соответствующим образом; если освободилось мало места, увеличьте значение соответствующим образом, если оно не превышает MaxMetaspaceSize.
  • -XX:MaxMetaspaceSize, максимальное пространство, по умолчанию не ограничено, в зависимости от емкости локального системного пространства.
  • -XX:MinMetaspaceFreeRatio, после GC, процент от минимальной емкости свободного места в метапространстве (即元数据在当前分配大小的最大占用大小), если коэффициент холостого хода меньше этого параметра (即超过了最大占用大小), то метапространство будет расширено.
  • -XX:MaxMetaspaceFreeRatio, после GC, процент от максимальной емкости свободного места в метапространстве (即元数据在当前分配大小的最小占用大小), если коэффициент холостого хода больше этого параметра (即小于最小占用大小), то метапространство будет уменьшено.

Поскольку настройки нет, по умолчанию на машине установлено:

java -XX:+PrintFlagsFinal | grep Meta
    uintx InitialBootClassLoaderMetaspaceSize       = 4194304                             {product}
    uintx MaxMetaspaceExpansion                     = 5451776                             {product}
    uintx MaxMetaspaceFreeRatio                     = 70                                  {product}
    uintx MaxMetaspaceSize                          = 18446744073709547520                    {product}
    uintx MetaspaceSize                             = 21807104                            {pd product}
    uintx MinMetaspaceExpansion                     = 339968                              {product}
    uintx MinMetaspaceFreeRatio                     = 40                                  {product}
     bool TraceMetadataHumongousAllocation          = false                               {product}
     bool UseLargePagesInMetaspace                  = false                               {product}

Можно видеть, что MinMetaspaceFreeRatio равно 40, MaxMetaspaceFreeRatio равно 70, MetaspaceSize равно 20M, а полный GC (порог метаданных GC) в основном делится на три

  • В первый раз [Metaspace: 20943K->20943K(1069056K)]
  • Второй раз [Metaspace: 34777K->34777K(1081344K)]
  • В третий раз [Metaspace: 58220K->58220K(1101824K)]

Видно, что порог метапространства постоянно подстраивается динамически, а что касается логики конкретной подстройки, то в официальном документе она вроде как не упоминается, так что пока не буду вникать. Пока значение Max не превышено, фатального эффекта нет, но для приложений с малой задержкой необходимо попытаться избежать трудоемкого gc, вызванного динамической подстройкой, которую можно решить путем расчета и установки начального порог в соответствии с оптимизацией.

Full GC (Ergonomics)

Здесь вы можете видеть, что причиной полного gc является эргономика, потому что UseAdaptiveSizePolicy включено, а полное gc вызвано собственной адаптивной настройкой jvm

GC (Allocation Failure)

Проанализировав полный сборщик мусора, давайте взглянем на молодой сборщик мусора и увидим, что 99% журнала вызваны сборкой мусора (ошибкой распределения). Ошибка распределения указывает на то, что молодое поколение (eden) претендует на место для нового объекта, но оставшегося подходящего места для молодого поколения (eden) недостаточно для минорного gc, вызванного требуемым размером.

-XX:+PrintTenuringDistribution

Desired survivor size 75497472 bytes, new threshold 2 (max 15)
- age   1:   68407384 bytes,   68407384 total
- age   2:   12494576 bytes,   80901960 total
- age   3:      79376 bytes,   80981336 total
- age   4:    2904256 bytes,   83885592 total
  • Желаемый размер оставшегося в живых указывает, что максимальное пространство, разрешенное в области оставшегося в живых, составляет 7 5497 472 байта.
  • Следующий список объектов представляет собой возрастное распределение текущих выживших объектов выжившего после этого gc, общий размер составляет 83885592 > 75497472, а размер age1 составляет 68407384 作用于下次gc). Объекты, которые превышают порог, будут переведены в старое поколение при следующей сборке мусора, если объект не будет выпущен.

возрастной список пуст

59.463: [GC (Allocation Failure) 
Desired survivor size 134217728 bytes, new threshold 7 (max 15)
[PSYoungGen: 786432K->14020K(917504K)] 804872K->32469K(1966080K), 0.1116049 secs] [Times: user=0.10 sys=0.01, real=0.20 secs]

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

Примеры выживших объектов после сборки мусора

jstat -gcutil -h10 7 10000 10000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  99.99  90.38  29.82  97.84  96.99    413  158.501     4   14.597  173.098
 11.60   0.00  76.00  29.83  97.84  96.99    414  158.511     4   14.597  173.109
 11.60   0.00  77.16  29.83  97.84  96.99    414  158.511     4   14.597  173.109
  0.00  13.67  60.04  29.83  97.84  96.99    415  158.578     4   14.597  173.176
  0.00  13.67  61.05  29.83  97.84  96.99    415  158.578     4   14.597  173.176
  • До ygc молодое поколение = eden + S1, после ygc молодое поколение = eden + S0
  • Из наблюдения видно, что пространство старого поколения не изменилось после ygc, а это означает, что это ygc, никакие объекты не продвигаются к старому поколению.
  • После gc уцелевший объект перемещается в другую уцелевшую область.
  • Так как выборка выполняется каждые 10 секунд, возникает задержка, то есть после gc сразу выделяется новый объект в eden-области, поэтому видимая здесь eden-область занята объектами.

real time > usr time + sys time

722914.974: [GC (Allocation Failure) 
Desired survivor size 109576192 bytes, new threshold 15 (max 15)
[PSYoungGen: 876522K->8608K(941568K)] 1526192K->658293K(1990144K), 0.0102709 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
722975.207: [GC (Allocation Failure) 
Desired survivor size 103284736 bytes, new threshold 15 (max 15)
[PSYoungGen: 843168K->39278K(941568K)] 1492853K->688988K(1990144K), 0.3607036 secs] [Times: user=0.17 sys=0.00, real=0.36 secs]

Существует более чем почти 300 gc реального времени, превышающего время usr + системное время.

  • реальный: относится ко времени WallClock, прошедшему от начала до конца операции
  • пользователь: относится к процессорному времени, потребляемому в пользовательском режиме;
  • sys: относится к процессорному времени, потребляемому состоянием ядра.

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

user + sys — фактическое время, затраченное ЦП.Обратите внимание, что это значение учитывает время на всех ЦП.Если процесс работает в многопоточной среде и многопоточное время накладывается, это значение будет превышать значение, записанное реальным т. е. user + sys >= real .

Здесь более 300 раз в реальном времени больше, чем время usr + системное время, что указывает на то, что могут быть две проблемы: одна связана с интенсивным вводом-выводом, а другая — с процессором (分配) недостаточно.

Механизм сбора мусора нового поколения

  • Попробуйте разместить новый объект в стеке. Если это не удается, попробуйте выделение TLAB. Если это не удается, подумайте, не следует ли напрямую обойти область eden и выделить место в старом поколении (-XX:PretenureSizeThreshold设置大对象直接进入年老代的阈值，当对象大小超过这个值时，将直接在年老代分配。), если нет, то наконец подумайте о подаче заявки на место в eden
  • Подать заявку на место в eden для создания нового объекта, в eden нет подходящего места, поэтому срабатывает минорный gc
  • второстепенный gc обрабатывает уцелевшие объекты в райской зоне и в выжившей зоне
    • Если возраст этих объектов достигает порогового значения, они напрямую переводятся в старое поколение.
    • Если скопированный объект слишком большой, он не будет скопирован в выживший, а сразу в старое поколение.
    • Если недостаточно места в области для оставшихся в живых/или недостаточно места во время процесса репликации, происходит переполнение оставшихся в живых, и непосредственно вводится старое поколение.
    • В противном случае, если в области для оставшихся в живых достаточно места, уцелевшие объекты копируются в область для оставшихся в живых.
  • В это время оставшиеся объекты в области Эдема и области выживших являются мусорными объектами, которые напрямую стираются и перерабатываются, а освободившееся пространство становится новым выделяемым пространством.
  • После минорного gc, если пространства eden достаточно, новый объект выделяет место в eden; если места eden по-прежнему недостаточно, новый объект выделяет место непосредственно в старом поколении

резюме

Из приведенного выше анализа видно, что молодое поколение кажется немного большим, а время ygc долгим; кроме того, пространство оставшихся в живых в основном пусто после каждого ygc, что означает, что новый объект генерируется быстро и жизненный цикл короткий, и изначально спроектированное пространство для выживания не пригодится. . Поэтому вы можете рассмотреть возможность уменьшения размера молодого поколения или попробовать изменить его на G1.

Есть несколько ключевых моментов о -XX:+PrintTenuringDistribution, которые нужно прояснить:

  • Какую область распределения объектов это печатает (survivor)
  • Печатать ли до gc или после gc (gc之后打印)
  • Когда новый объект прибывает к выжившему в первый раз, его возраст считается равным 0 или 1.

Возраст объекта – это количество пережитых им MinorGC. Когда объект размещается в первый раз, возраст равен 0. После первого MinorGC, если он не был восстановлен, возраст равен +1. Поскольку он в первый раз, чтобы испытать MinorGC, он входит в зону выжившего. Следовательно, возраст объекта, когда он впервые попадает в зону выживания, равен 1.

  • Динамическая настройка порога продвижения (новый порог)

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

doc

Категории