почему vmop (Java GC Options) увеличивается при увеличении трафика - PullRequest
Новая
       11

почему vmop (Java GC Options) увеличивается при увеличении трафика

0 голосов
/ 28 апреля 2019

У меня есть онлайн-сервис с Java.Если qps составляет около 2000, задержка нормальная, но если qps увеличивается до 3000, задержка намного выше.

Есть ли какой-нибудь совет относительно улучшения, особенно относительно времени STW?

Логика кода проста (как служба доступа):

  1. Декодирование Tcp-запроса и Protobuf(около 200 КБ на запрос)
  2. Разделение запроса и повторная упаковка protobuf
  3. Маршрутизация к обратному сервису и асинхронное ожидание ответа
  4. Обработка ответа от обратного сервиса, перенос с другим protobufи отвечая клиенту.

JINFO: 

-Djava.net.preferIPv4Stack=true -Xmx6g -Xms6g -Xmn4g 
-Djava.ext.dirs=./lib:/data/home/soft/jdk1.8.0_65/jre/lib/ext 
-Dlog4j.configuration=./conf/log4j.properties -Dio.netty.noPreferDirect=false 
-XX:MaxDirectMemorySize=4g -XX:+UseConcMarkSweepGC -XX:ParallelCMSThreads=8 
-XX:+CMSScavengeBeforeRemark 
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 
-XX:OnOutOfMemoryError=./bin/stop.sh -XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=. -XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCDetails 
-Xloggc:logs/gc.log -XX:+CMSParallelRemarkEnabled 
-XX:ParallelGCThreads=32

Я обнаружил, что более высокий STW вызван vmop.И НИКАКОЙ ПОЛНОЙ GC не произошло во время тестирования. 

998.860: GenCollectForAllocation          [     253          2              2    ]      [     0     0     0     0     6    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
999.578: GenCollectForAllocation          [     253          2              2    ]      [     0     0     0     0    16    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
1000.273: GenCollectForAllocation          [     253          3              3    ]      [     0     0     0     0    11    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
1000.970: GenCollectForAllocation          [     253          2              2    ]      [     0     0     0     0     8    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
1001.666: GenCollectForAllocation          [     253          2              2    ]      [     0     0     0     0     7    ]  0
  • Когда qps составляет около 2000, vmop обычно ниже 10 мс.Total time for which application threads were stopped меньше 0,010 секунд.
  • Qps составляет около 3000, vmop выше 10 мс,

Мой вопрос:

  1. Есть лиЛюбой совет по улучшению производительности, особенно о времени STW (vmop)?
  2. Что вызывает высокий vmop?Достигнув безопасных точек или скопировав память?

Дополнительные тестовые данные: Обратный сервис сохраняет qps = 3000, и я запускаю один / два Java-сервис для сравнения и получаю разрыв в производительности.Задержка обратного обслуживания составляет около 6,8 мс.Журналы GC одного Java-процесса (с qps = 3000 для каждого процесса): 

2019-05-16T14:54:56.742+0800: 67083.398: Total time for which application threads were stopped: 0.0104372 seconds, Stopping threads took: 0.0001939 seconds
2019-05-16T14:54:57.788+0800: 67084.444: [GC (Allocation Failure) 2019-05-16T14:54:57.788+0800: 67084.444: [ParNew: 5054250K->22742K(5662336K), 0.0109608 secs] 5776050K->744839K(7759488K), 0.0111268 secs] [Times: user=0.33 sys=0.01, real=0.02 secs] 
2019-05-16T14:54:57.799+0800: 67084.455: Total time for which application threads were stopped: 0.0122376 seconds, Stopping threads took: 0.0001943 seconds
2019-05-16T14:54:58.848+0800: 67085.504: [GC (Allocation Failure) 2019-05-16T14:54:58.848+0800: 67085.504: [ParNew: 5055958K->26545K(5662336K), 0.0108330 secs] 5778055K->748938K(7759488K), 0.0109914 secs] [Times: user=0.34 sys=0.00, real=0.02 secs] 
2019-05-16T14:54:58.859+0800: 67085.515: Total time for which application threads were stopped: 0.0121166 seconds, Stopping threads took: 0.0002086 seconds
2019-05-16T14:54:59.905+0800: 67086.561: [GC (Allocation Failure) 2019-05-16T14:54:59.905+0800: 67086.561: [ParNew: 5059761K->25093K(5662336K), 0.0115089 secs] 5782154K->747784K(7759488K), 0.0116708 secs] [Times: user=0.36 sys=0.00, real=0.01 secs] 
2019-05-16T14:54:59.917+0800: 67086.573: Total time for which application threads were stopped: 0.0127589 seconds, Stopping threads took: 0.0001810 seconds
2019-05-16T14:55:00.957+0800: 67087.613: [GC (Allocation Failure) 2019-05-16T14:55:00.957+0800: 67087.613: [ParNew: 5058309K->27559K(5662336K), 0.0043041 secs] 5781000K->750551K(7759488K), 0.0044697 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 
2019-05-16T14:55:00.962+0800: 67087.618: Total time for which application threads were stopped: 0.0055974 seconds, Stopping threads took: 0.0001974 seconds
2019-05-16T14:55:02.004+0800: 67088.660: [GC (Allocation Failure) 2019-05-16T14:55:02.004+0800: 67088.660: [ParNew: 5060775K->18771K(5662336K), 0.0032344 secs] 5783767K->742062K(7759488K), 0.0033973 secs] [Times: user=0.08 sys=0.00, real=0.00 secs]

Журналы GC двух Java-процессов (с qps = 1500 для каждого процесса): 

2019-05-16T14:49:19.774+0800: 66746.430: Total time for which application threads were stopped: 0.0075090 seconds, Stopping threads took: 0.0001816 seconds
2019-05-16T14:49:21.879+0800: 66748.535: [GC (Allocation Failure) 2019-05-16T14:49:21.879+0800: 66748.535: [ParNew: 5047304K->15661K(5662336K), 0.0070949 secs] 5601138K->569792K(7759488K), 0.0072536 secs] [Times: user=0.19 sys=0.00, real=0.00 secs] 
2019-05-16T14:49:21.886+0800: 66748.542: Total time for which application threads were stopped: 0.0084102 seconds, Stopping threads took: 0.0001858 seconds
2019-05-16T14:49:23.977+0800: 66750.633: [GC (Allocation Failure) 2019-05-16T14:49:23.977+0800: 66750.633: [ParNew: 5048877K->10672K(5662336K), 0.0033657 secs] 5603008K->565100K(7759488K), 0.0035116 secs] [Times: user=0.08 sys=0.00, real=0.01 secs] 
2019-05-16T14:49:23.981+0800: 66750.637: Total time for which application threads were stopped: 0.0045580 seconds, Stopping threads took: 0.0001763 seconds
2019-05-16T14:49:26.090+0800: 66752.746: [GC (Allocation Failure) 2019-05-16T14:49:26.090+0800: 66752.746: [ParNew2019-05-16T14:49:23.981+0800: 66750.637: Total time for which application threads were stopped: 0.0045580 seconds, Stopping threads took: 0.0001763 seconds
2019-05-16T14:49:26.090+0800: 66752.746: [GC (Allocation Failure) 2019-05-16T14:49:26.090+0800: 66752.746: [ParNew: 5043888K->9061K(5662336K), 0.0036848 secs] 5598316K->563786K(7759488K), 0.0038302 secs] [Times: user=0.08 sys=0.00, real=0.00 secs]

1 Ответ

0 голосов
/ 29 апреля 2019

У вас есть причинно-следственная связь, это не , вызванное vmop. Vmop - это безопасная точка, запрошенная сборщиком мусора, под которой он может выполнять свои задачи остановки мира.

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

...