Tuning de aplicação Java Web rodando em Jetty

Programação Java
#1

Caros,

Gostaria de compartilhar minhas dúvidas e quem saber obter opiniões sobre o meu dilema com quem já passou por isso.

Herdei uma aplicação web com as seguintes características:

  • Java 6 / Spring IoC e Web Flow / Hibernate / Banco Oracle RAC / Jetty 6.1.14

É uma aplicação crítica (24x7), que tem muita demanda de utilização, tanto na quantidade de acessos, quanto no peso dos processos que executa.

Hoje esta aplicação está rodando em 4 servidores físicos (2 CPUs quad core com 32 Gb RAM). Cada servidor tem 6 (seis) instâncias de Jetty rodando a aplicação.

Em média temos cerca de 50 conexões (requests) simultâneas em cada servidor. Ou seja, um volume considerável a atender. Logo, criação de destruição de objetos bem intenso.

As instâncias do mesmo servidor compartilham sessão, basicamente, pelo memcached. Então só preciso de balanceamento “stick session” para manter o usuário no mesmo servidor, podendo variar a instância do Jetty que o atende.

Acontece que, como herdei isso, muitas das parametrizações de tuning estão lá há tempos e sem uma documentação explicando as razões.

Vi que isso foi feito quando o havia só 2 servidores e cada um tinha apenas 8Gb RAM. Hoje o cenário é outro a não foi refeito o tuning.

As configurações passadas para a JVM são:

-Xms=1024m -Xmx=1024m -XX:MaxPermSize=256m -server -XX:+UseConcMarkSweepGC -XX:+CMSPermGenSweepingEnabled -XX:+CMSClassUnloadingEnabled -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000

Ou seja, cada JVM aloca 1 giga RAM para a sua heap.

Não fiz testes de carga/stress ainda, mesmo porque os servidores estão em produção, mas acho que posso otimizar isso.

Talvez aumentando a memória da HEAP e diminuindo o número de instâncias de Jettys em cada servidor (de 6 para 4 ou 3).

Aumentando a memória para 2Gb pode chegar a ser um problema para o garbage Collector? Talvez ele tomar mais tempo e recursos do servidor para varrer e limpar objetos sem uso?

Alguma consideração?

#2

Referências:

http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html

http://www.oracle.com/technetwork/java/hotspotfaq-138619.html

#3

Oi Daniel!

Voce vai ter problemas sim com o GC se tiver um heap muito grande. Para o tipo de aplicacao que voce descreveu, o CMS é o melhor caso mesmo, pois minimiza o tempo de parada para coleta. Mas mesmo assim ainda há um período necessário de parada (stop the world) que sua aplicação fica travada. Esse tempo é maior conforme o tamanho da memória.

Difícil é estimar quantos GB você pode jogar em cada JVM. Eu acho 32GB muito, acho que você sofreria com muito tempo de parada. Mas talvez dê para deixar mais de 2GB por aplicação. Precisa subir, monitorar e ver o resultado; rode o -verbose:gc e -XX:+PrintGCDetails para observar os tempos de coleta.

Das opções, faça testes também paralelizando a geração nova (pelas suas opções, você roda GC paralelizaveis apenas nas regioes tenured e permgen). Para habilitar a coleta paralela na geração nova, use -XX:+UseParNewGC. Talvez seja uma boa usar o -XX:+UseTLAB. Bom essas opções todas de parellização vão usar melhor os 8 cores da sua máquina, mas precisa ver na prática se não fica pior já que não há apenas uma única VM rodando na máquina.

E a não ser que você tenha um bom motivo pra usar o GC e unload de classes no PermGen, eu desabilitaria isso (e aumentaria o MaxPermSize pra uns 500m). Geralmente o pessoal usa coleta no PermGen para suportar hotdeploy da aplicação; se for esse o caso, não faça. HotDeploys tem problemas sérios de memory leaks mesmo com essas opções habilitadas, e já que você tem um ambiente balanceado com várias instâncias, me parece que você não precisa de hotdeploy para evitar indisponibilidade. Mas se o motivo não for hotdeploy, aí ok.

Por fim, se você for corajoso mesmo, podia testar o novo G1 presente nos últimos updates da JVM 6 da Sun (beta) e vai estar pronto no JDK 7. É o no GC da Sun desenvolvido exatamente para essa sua situação: você tem muita memória mas quer minimizar os tempos de parada. Usando G1 você conseguiria teoricamente subir uma VM só com os 32 GBs e isso não geraria tempos de parada altos. A grande sacada desse GC é nunca coletar a memória toda de uma vez, mas sempre por blocos pequenos. Para brincar com ele no Java 6 ainda, use -XX:+UnlockExperimentalVMOptions e -XX:+UseG1GC. Se testá-lo aí, manda as impressões :slight_smile:

E escrevi um pouco sobre GC para o livro de Arquitetura que estamos lançando aqui na Caelum. Inclusive há um preview desse capítulo aberto para download: http://www.arquiteturajava.com.br

Abraços
Sérgio

#4

Sérgio, muito bom.

A principio vou coletar estatísticas do modo como está hoje, e depois mudar os parâmetros, pegar stats de novo e comparar.

Depois vou tentar setar o Eden (new generation)como sugeriu, já que não está ainda. Não usamos Hot Deploy nunca. O que é uma boa.

Nosso RHEL é 64 bits, não teria problema, mas acho que 2Gb de heap já é suficiente nesse momento. Mas um outro problema depois vai ser saber se 3 ou 4 instâncias de Jetty terão o mesmo throughtput das 6 atuais, o que considero demais e talvez mal otimizado.

Ainda assim consigo usar um dos servers de teste como essa G1 e ver o que dá. Vou aos poucos para me assegurar dos resultados. E vou postando aqui.

Muito obrigado e parabéns pelo alto conhecimento.

Daniel Destro

#5

Legal, aguardo os resultados então!

Viu, mas não fica com preconceito com relação a ter várias instâncias, talvez não haja necessidade de diminuir. É realmente algo bastante usado por aí. Já vi um projeto grande na área de comércio eletrônico que tinha hardware parecido com esse (8 cores, 32 GB RAM) e rodava 8 instâncias do Jetty. Tinha um throughput bem alto e boa performance.

#6

Deixei os mesmos parâmetros e vi que o GC roda direto, a cada 2 ou 3 segundos em média, mas o tempo de execução é ínfimo.

[GC [ParNew: 110843K->4118K(118016K), 0.0102440 secs] 615483K->508855K(1035520K), 0.0105290 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
[GC [ParNew: 109078K->3158K(118016K), 0.0073700 secs] 613815K->508124K(1035520K), 0.0075610 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
[GC [ParNew: 108228K->4378K(118016K), 0.0103470 secs] 613195K->509817K(1035520K), 0.0105690 secs] [Times: user=0.04 sys=0.01, real=0.01 secs]
[GC [ParNew: 109338K->3851K(118016K), 0.0078400 secs] 614777K->509450K(1035520K), 0.0080830 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

#7

Em uma das instâncias passei a configurar a memória da New Generation (-Xmn256m). Acredito que antes, por padrão, era 128 mb.

Percebi que a JVM usa quase toda Eden, pois nosso software usa muitos objetos de tempo de vida curto. Isso evita jogá-los pra Old Generation. O GC limpa a New Generation de + de 200 mega para menos de 20 mega.

Mas percebi que o tempo médio do GC subiu:

[GC [ParNew: 227061K->19262K(235968K), 0.0235670 secs] 687158K->481441K(1022400K), 0.0237770 secs] [Times: user=0.09 sys=0.01, real=0.02 secs]
[GC [ParNew: 229054K->15395K(235968K), 0.0200430 secs] 691233K->480019K(1022400K), 0.0202380 secs] [Times: user=0.08 sys=0.01, real=0.02 secs]
[GC [ParNew: 225187K->10807K(235968K), 0.0259010 secs] 689811K->481232K(1022400K), 0.0261230 secs] [Times: user=0.09 sys=0.02, real=0.03 secs]

#8

SENSACIONAL!
Livro: Arquitetura e Design de Software - http://www.arquiteturajava.com.br/
Capítulo: Gerenciar memória não é simples - http://www.arquiteturajava.com.br/livro/gerenciamento-de-memoria-e-garbage-collector.pdf

#9

O grande tradeoff de GC é entre tempo de parada de eficiência das coletas. Quanto mais memória, diminui a frequência de execução e aumenta o tempo de parada. Precisa achar um número aí no meio que tenha um tempo de parada bom pra você, com uma frequência aceitável. Talvez habilitar o -XX:+UseParNewGC deixe as coletas na YoungGen mais rápidas nesses casos com a geração em tamanho maior.

Mas Daniel, esse seu log todo só mostra os minor GCs, e como você mesmo falou, sua aplicação cria muitos objetos rapidamente descartáveis. Então sua OldGen vai demorar bastante pra lotar. Mas quando lotar, vai rodar um FullGC bem tenso se o heap for grande demais. É esse FullGC que costuma ser o pior, ele tem um tempo de parada bem alto comparado aos minor GC.

#10

Pensando mais um pouco: esses logs que você mandou são bem interessantes. Mostram realmente a imensa quantidade de objetos de vida curta que sua aplicação tem (perfeito pro GC geracional).

Parece até que o uso de memória após os minor GC é meio que constante, o que seria ótimo pois sua OldGen não vai lotar. Se você aumentar bem sua YoungGen, apesar dos tempos de parada serem um pouco maiores, a frequência de execucação cai bastante e eles tendem a ser extremamente eficientes. Precisa é achar o balanço.

Chutando um pouco na aplicação alheia, acho que se você conseguir uma YoungGen com 1 GB (-XX:NewSize=1G) cujos tempos de parada não passem de 500 a 300 ms, acho que terá um excelente cenário.

#11

Exatamente isso. Joguei agora para 512 mega o new generation. E olha isso:

[GC [ParNew: 457795K->28286K(471872K), 0.0576990 secs] 897624K->479369K(996160K), 0.0578550 secs] [Times: user=0.19 sys=0.04, real=0.06 secs]
[GC [1 CMS-initial-mark: 451083K(524288K)] 588774K(996160K), 0.0824670 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]
[GC [ParNew: 447742K->33853K(471872K), 0.0291160 secs] 898825K->484936K(996160K), 0.0293020 secs] [Times: user=0.12 sys=0.00, real=0.03 secs]
[CMS-concurrent-mark: 0.638/1.146 secs] [Times: user=3.54 sys=0.07, real=1.14 secs]
[CMS-concurrent-preclean: 0.033/0.037 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
[CMS-concurrent-abortable-preclean: 0.399/1.106 secs] [Times: user=2.74 sys=0.08, real=1.10 secs]
[GC[YG occupancy: 244797 K (471872 K)][Rescan (parallel) , 0.0445820 secs][weak refs processing, 0.1587140 secs][class unloading, 0.0158030 secs][scrub symbol & string tables, 0.0220800 secs] [1 CMS-remark: 451083K(524288K)] 695881K(996160K), 0.2448160 secs] [Times: user=0.45 sys=0.00, real=0.24 secs]
[CMS-concurrent-sweep: 0.343/0.345 secs] [Times: user=0.35 sys=0.00, real=0.35 secs]
[CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[GC [ParNew: 453309K->25378K(471872K), 0.0639420 secs] 898797K->481880K(996160K), 0.0641670 secs] [Times: user=0.21 sys=0.02, real=0.06 secs]
[GC [ParNew: 444834K->25985K(471872K), 0.0410570 secs] 901336K->487154K(996160K), 0.0412690 secs] [Times: user=0.19 sys=0.02, real=0.04 secs]

Detalhe que neste momento, pelos logs do Apache, estamos com 1/3 a 1/4 da carga de 1 hora atrás.

Agora o GC roda menos frequentemente, embora mais demorado.

Acho que se eu der 1 giga pra Eden, ele consome tudo.

#12

Alterando agora para -Xms1536m -Xmx1536 -Xmn1024m o comportamento ficou bem diferente:

[CMS-concurrent-sweep: 0.346/0.391 secs] [Times: user=0.46 sys=0.01, real=0.39 secs]
[CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [1 CMS-initial-mark: 445881K(524288K)] 744361K(1468032K), 0.1513860 secs] [Times: user=0.15 sys=0.00, real=0.15 secs]
[CMS-concurrent-mark: 0.670/0.670 secs] [Times: user=1.33 sys=0.00, real=0.67 secs]
[CMS-concurrent-preclean: 0.026/0.027 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.486/5.023 secs] [Times: user=2.63 sys=0.03, real=5.03 secs]
[GC[YG occupancy: 338263 K (943744 K)][Rescan (parallel) , 0.1738760 secs][weak refs processing, 0.1343480 secs][class unloading, 0.0169160 secs][scrub symbol & string tables, 0.0232950 secs] [1 CMS-remark: 445881K(524288K)] 784145K(1468032K), 0.3523170 secs] [Times: user=0.40 sys=0.00, real=0.36 secs]
[CMS-concurrent-sweep: 0.340/0.340 secs] [Times: user=0.34 sys=0.00, real=0.34 secs]
[CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [1 CMS-initial-mark: 445880K(524288K)] 801573K(1468032K), 0.1853720 secs] [Times: user=0.19 sys=0.00, real=0.18 secs]
[CMS-concurrent-mark: 0.683/0.738 secs] [Times: user=1.56 sys=0.02, real=0.74 secs]
[CMS-concurrent-preclean: 0.026/0.028 secs] [Times: user=0.05 sys=0.00, real=0.03 secs]
CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.291/5.015 secs] [Times: user=2.23 sys=0.02, real=5.01 secs]
[GC[YG occupancy: 409999 K (943744 K)][Rescan (parallel) , 0.2288580 secs][weak refs processing, 0.1309110 secs][class unloading, 0.0171990 secs][scrub symbol & string tables, 0.0223650 secs] [1 CMS-remark: 445880K(524288K)] 855880K(1468032K), 0.4033250 secs] [Times: user=0.46 sys=0.02, real=0.41 secs]

Acredito que, dentro destas experimentações, até 256 mega de New Generation seja a melhor opção. Mesmo porque, acho que a JVM esteja bem ajustada já.

#13

Uau, 5 seg de parada nesse último foi tenso!

Nos primeiros teste parecia que você tinha 1 GB de heap total com 256 pra Young. Ou seja, uma relação 3/1 entre Old e Young. Esse último teste já deu uma relação 1/2, bem diferente.

E se aumentar o OldGen também? 2 GB o heap total com 500m de Young?

Talvez fosse legal brincar com essas proporções. Já tive bons resultados em aplicações com muitos objetos de vida curta colocando 1/1 ou 2/1.

#14

Você viu que ele chegou a abortar o processo por "timeout".

Como você sugeriu: -Xms2048m -Xmx2048 -Xmn512m. Parece que ele trabalha mesmo mais otimizado assim. O GC roda menos frequentemente, mas leva menos de 100ms pra executar. Embora agora eu só tenho 1/4 do tráfego que tinha 2 hrs antes.

[GC [ParNew: 456865K->41910K(471872K), 0.0760260 secs] 854016K->449566K(2044736K), 0.0761690 secs] [Times: user=0.25 sys=0.02, real=0.07 secs]
[GC [ParNew: 461366K->39962K(471872K), 0.0625840 secs] 869022K->456859K(2044736K), 0.0627220 secs] [Times: user=0.24 sys=0.03, real=0.07 secs]
[GC [ParNew: 459418K->49780K(471872K), 0.0690310 secs] 876315K->477207K(2044736K), 0.0691800 secs] [Times: user=0.26 sys=0.04, real=0.07 secs]
[GC [ParNew: 469236K->40500K(471872K), 0.0752160 secs] 896663K->479561K(2044736K), 0.0754210 secs] [Times: user=0.29 sys=0.04, real=0.07 secs]
[GC [ParNew: 459956K->31868K(471872K), 0.0587600 secs] 899017K->482146K(2044736K), 0.0589470 secs] [Times: user=0.18 sys=0.04, real=0.06 secs]
[GC [1 CMS-initial-mark: 450277K(1572864K)] 707999K(2044736K), 0.1643530 secs] [Times: user=0.16 sys=0.00, real=0.17 secs]
[GC [ParNew: 451324K->33106K(471872K), 0.0311740 secs] 901602K->483384K(2044736K), 0.0313400 secs] [Times: user=0.14 sys=0.00, real=0.03 secs]
[CMS-concurrent-mark: 0.660/1.360 secs] [Times: user=4.45 sys=0.11, real=1.36 secs]
[CMS-concurrent-preclean: 0.035/0.038 secs] [Times: user=0.07 sys=0.00, real=0.04 secs]
[CMS-concurrent-abortable-preclean: 0.372/0.933 secs] [Times: user=2.23 sys=0.04, real=0.93 secs]
[GC[YG occupancy: 244688 K (471872 K)][Rescan (parallel) , 0.0482690 secs][weak refs processing, 0.1467430 secs][class unloading, 0.0158190 secs][scrub symbol & string tables, 0.0229630 secs] [1 CMS-remark: 450277K(1572864K)] 694965K(2044736K), 0.2375100 secs] [Times: user=0.47 sys=0.01, real=0.24 secs]
[CMS-concurrent-sweep: 0.354/0.418 secs] [Times: user=0.97 sys=0.01, real=0.42 secs]
[CMS-concurrent-reset: 0.014/0.014 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[GC [ParNew: 452562K->23364K(471872K), 0.0539370 secs] 897721K->479344K(2044736K), 0.0541390 secs] [Times: user=0.25 sys=0.02, real=0.05 secs]
[GC [ParNew: 442820K->21573K(471872K), 0.0391630 secs] 898800K->483601K(2044736K), 0.0393670 secs] [Times: user=0.13 sys=0.03, real=0.04 secs]

#15