Увеличение Малого GC Время паузы

Question

У нас возникла странная проблема, связанная с незначительным GC. Одно из наших приложений, которое находится в производстве с 18-месячного началось с того, Исторически наши незначительные паузы GC составляли около 30-50 мсек, однако теперь они составляют от 110 мс до 400 мс. Не было никаких изменений в конфигурациях кучи, но было внесено большое количество изменений кода.

Приложение представляет собой веб-службу Rest, работающую на tomcat, размещенную в облаке с 8 виртуальными машинами cpu и 24 GB RAM и разговаривая с cassandra , Мы попытались воссоздать проблему для отладки ее в более низкой среде, запустив тест производительности, но не смог этого сделать. Существует один сервис отдыха, который вызывается с одинаковой рабочей нагрузкой с 98% времени, однако 2% рабочей нагрузки бит разный. Мы не можем загрузить эти 2% вызовов из-за проблем с данными.

Когда мы запускаем нагрузку, мы видим, что почти такое же количество кучи восстанавливается или продвигается, как в обычном сценарии (загрузка выполняется в 8-10 раз при запуске теста нагрузки), но незначительные паузы gc равны < 50 мс всегда , (Мы не выполнить ту же нагрузку на производство VM как сво операции чтения)

С тест производительности запросов (высокая нагрузка):

2015-09-15T10:16:51.617+0000: 300001.062: [GC (Allocation Failure) [PSYoungGen: 1922537K->174564K(1922560K)] 2146305K->432640K(4019712K), 0.0604696 secs] [Times: user=0.44 sys=0.00, real=0.06 secs] 
2015-09-15T10:16:54.033+0000: 300003.478: [GC (Allocation Failure) [PSYoungGen: 1922383K->174567K(1922560K)] 2180459K->469257K(4019712K), 0.0493751 secs] [Times: user=0.28 sys=0.00, real=0.05 secs] 
2015-09-15T10:16:56.468+0000: 300005.912: [GC (Allocation Failure) [PSYoungGen: 1922535K->174570K(1922560K)] 2217225K->504099K(4019712K), 0.0437478 secs] [Times: user=0.27 sys=0.00, real=0.05 secs] 
2015-09-15T10:16:58.696+0000: 300008.140: [GC (Allocation Failure) [PSYoungGen: 1922538K->174576K(1922560K)] 2252067K->541818K(4019712K), 0.0407501 secs] [Times: user=0.25 sys=0.00, real=0.04 secs] 
2015-09-15T10:17:00.887+0000: 300010.331: [GC (Allocation Failure) [PSYoungGen: 1922544K->174573K(1922560K)] 2289786K->577682K(4019712K), 0.0468752 secs] [Times: user=0.32 sys=0.00, real=0.05 secs] 
2015-09-15T10:17:03.142+0000: 300012.586: [GC (Allocation Failure) [PSYoungGen: 1922541K->174581K(1922560K)] 2325650K->617970K(4019712K), 0.0424797 secs] [Times: user=0.26 sys=0.00, real=0.04 secs] 
2015-09-15T10:17:05.394+0000: 300014.838: [GC (Allocation Failure) [PSYoungGen: 1922549K->174587K(1922560K)] 2365938K->659487K(4019712K), 0.0425134 secs] [Times: user=0.27 sys=0.00, real=0.04 secs] 
2015-09-15T10:17:07.661+0000: 300017.106: [GC (Allocation Failure) [PSYoungGen: 1922555K->174566K(1922560K)] 2407455K->694256K(4019712K), 0.0389039 secs] [Times: user=0.24 sys=0.00, real=0.04 secs] 
2015-09-15T10:17:09.951+0000: 300019.395: [GC (Allocation Failure) [PSYoungGen: 1922534K->174577K(1922560K)] 2442224K->726822K(4019712K), 0.0385114 secs] [Times: user=0.29 sys=0.00, real=0.03 secs] 
2015-09-15T10:17:12.302+0000: 300021.746: [GC (Allocation Failure) [PSYoungGen: 1922545K->174591K(1922560K)] 2474790K->762111K(4019712K), 0.0400951 secs] [Times: user=0.28 sys=0.00, real=0.04 secs] 

Но в значительно меньшей нагрузке производства для одной и той же виртуальной машины Java на том же машина, незначительные GC паузы достаточно высоки:

015-09-15T05:36:27.428+0000: 283176.872: [GC (Allocation Failure) [PSYoungGen: 1844205K->125665K(1922560K)] 1991878K->273338K(4019712K), 0.1087286 secs] [Times: user=0.61 sys=0.00, real=0.11 secs] 
2015-09-15T05:39:05.945+0000: 283335.390: [GC (Allocation Failure) [PSYoungGen: 1873633K->157526K(1922560K)] 2021306K->305200K(4019712K), 0.1099762 secs] [Times: user=0.58 sys=0.00, real=0.11 secs] 
2015-09-15T05:41:43.686+0000: 283493.131: [GC (Allocation Failure) [PSYoungGen: 1905494K->174576K(1922560K)] 2053168K->337666K(4019712K), 0.1249486 secs] [Times: user=0.70 sys=0.00, real=0.13 secs] 
2015-09-15T05:45:06.059+0000: 283695.503: [GC (Allocation Failure) [PSYoungGen: 1922544K->174560K(1922560K)] 2085634K->371522K(4019712K), 0.1434632 secs] [Times: user=0.95 sys=0.00, real=0.15 secs] 
2015-09-15T05:48:08.511+0000: 283877.955: [GC (Allocation Failure) [PSYoungGen: 1922528K->174576K(1922560K)] 2119490K->404319K(4019712K), 0.1145014 secs] [Times: user=0.76 sys=0.00, real=0.11 secs] 
2015-09-15T05:50:49.150+0000: 284038.594: [GC (Allocation Failure) [PSYoungGen: 1922544K->174571K(1922560K)] 2152287K->436331K(4019712K), 0.1178926 secs] [Times: user=0.68 sys=0.00, real=0.12 secs] 
2015-09-15T05:54:18.962+0000: 284248.407: [GC (Allocation Failure) [PSYoungGen: 1922539K->174560K(1922560K)] 2184299K->467992K(4019712K), 0.0975615 secs] [Times: user=0.63 sys=0.00, real=0.10 secs] 
2015-09-15T05:57:45.177+0000: 284454.621: [GC (Allocation Failure) [PSYoungGen: 1922240K->174577K(1922560K)] 2215672K->501369K(4019712K), 0.1108669 secs] [Times: user=0.75 sys=0.00, real=0.11 secs] 
2015-09-15T06:00:55.609+0000: 284645.053: [GC (Allocation Failure) [PSYoungGen: 1922545K->174584K(1922560K)] 2249337K->534084K(4019712K), 0.0970370 secs] [Times: user=0.65 sys=0.00, real=0.10 secs] 
2015-09-15T06:03:32.692+0000: 284802.137: [GC (Allocation Failure) [PSYoungGen: 1922552K->174582K(1922560K)] 2282052K->569585K(4019712K), 0.1109909 secs] [Times: user=0.80 sys=0.00, real=0.11 secs] 
2015-09-15T06:06:14.975+0000: 284964.420: [GC (Allocation Failure) [PSYoungGen: 1922550K->174586K(1922560K)] 2317553K->599629K(4019712K), 0.0967938 secs] [Times: user=0.41 sys=0.00, real=0.10 secs] 

Теперь, если минорный время GC паузы состоит из карты сканирования, Stack сканирование, сканирование старого поколения и копирования времени, что все должно быть вроде похожи, если не идентичны в описанном выше сценарии , почему GC приостанавливает время? Или я пропустил что-то очень основное здесь?

JVM Version Info: 
java version "1.8.0_20" 
Java(TM) SE Runtime Environment (build 1.8.0_20-b26) 
Java HotSpot(TM) 64-Bit Server VM (build 25.20-b23, mixed mode) 

ворох параметров:

-XX:+DisableExplicitGC 
-XX:GCLogFileSize=10485760 
-XX:+HeapDumpOnOutOfMemoryError 
-XX:InitialHeapSize=4G 
-XX:MaxHeapSize=4G 
-Xmn2G 
-XX:NumberOfGCLogFiles=25 
-XX:+PrintGC -XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps 
-XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution 
-XX:SurvivorRatio=10 -XX:-UseAdaptiveSizePolicy 
-XX:+UseCompressedOops -XX:+UseGCLogFileRotation 
-XX:+UseParallelGC -XX:+UseParallelOldGC 

Answer 1

Вы используете параллельный коллектор, который имеет throughput as its primary goal. Поэтому неудивительно, что он может сделать разные компромиссы для достижения своих целей пропускной способности при различных нагрузках.

Если хочет, чтобы попытаться сохранить паузы низко вы должны указать pause time goal.

Это явно прописано в официальной документации:

по умолчанию, нет Максимального времени паузы цели.

Поэтому я нахожу удивительным, что вы пробовали все эти параметры GC, но даже не пытались использовать те, которые были представлены в первых параграфах.

Если вы были cargo-culting параметры из другого места, я настоятельно рекомендую вам не делать этого, не обращаясь сначала к документации, чтобы понять их цель.

---

Edit: присмотревшись на вариантах, которые вы используете, вы прижав соотношение survitor и отключив адаптивную политику размера, который предотвращает GC от настройки нового гена для удовлетворения целей паузы времени.

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

Вместе это приводит к разным временам паузы.

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