Análise e melhoria de um teste com GC

Motivado pela liberação do teste de threads, quiz fazer um pequeno teste, que ajude a analisar o funcionamento do Garbage Collector e como algumas alterações podem melhorar o desempenho.

Quando se fala em teste, existe muita discussão sobre a validade dos resultados.

Então já digo que este é um teste caseiro, para ter sua opinião, faça o teste em seu ambiente.

1) Teste

O teste de threads (NumThreads.java, projeto completo), lança todas

as

threads enumeradas no parametro, em que cada thread faz uma série de

processamento matemático, cada thread pode repetir o processamento em

uma quantidade determinada.

o fluxo de criaçao, coloca em um array, depois faz o start de cada

thread, depois faz um join para esperar o processamento de todas as

threads.

O start de cada thread não começa imediatamente, existe um barreira

(CyclicBarrier) que aguarda o contador de todas as threads que foram

iniciadas para que todas possam de fato entrar em operação juntas.

Em uma configuração default da JVM não consegui inicar com mais de 2700

threads, 2000 operações matemáticas por thread, ocorriam erros da JVM

(OOME, ThreadDeath,

Stackoverflow, etc.)

A minha máquina é um laptop toshiba, Core2 Duo T2400 1.83 GHz com 3 GB

de RAM.

2) Monitoramento

O monitoramento foi feito usando o vmstat, jvisualvm, jmap

No caso do <a

href=”http://code.google.com/p/claudius-alphaworks/source/browse/trunk/shell_bin/vmstat_date.sh”>vmstat,

coloquei a data como prefixo.

3) Resultado (1a bateria)

O teste foi iniciado com os seguintes parametros, que geralmente é o

comum, onde configura-se apenas o tamanho máximo do heap.

Depoi veremos o que se pode melhorar neste teste.

$ time java -Xmx2g -classpath build/WEB-INF/classes/:src/conf/:src/java/ br.com.claudius.threads.NumThreads 2700 5000 60

O tempo total, deve ser descontado 60s que usei como pausa antes das

threads começarem de fato (3o parametro)

real 3m11.948s
user 2m14.612s
sys 1m40.354s

O tempo total foi de 2min11s ou 131s

O que chama a atenção na configuração default é o tamanho do Stack de

320 kb, bem grande.

$ jinfo -flag ThreadStackSize 18610
-XX:ThreadStackSize=320

A configuração do heap (apenas a parte importante)

$ jmap -heap 18610
Server compiler detected.
JVM version is 16.0-b13

using thread-local object allocation.
Parallel GC with 2 thread(s)

Heap Configuration:
 MinHeapFreeRatio = 40
 MaxHeapFreeRatio = 70
 MaxHeapSize = 2147483648 (2048.0MB)
 NewSize = 4194304 (4.0MB)
 MaxNewSize = 4294901760 (4095.9375MB)
 OldSize = 4194304 (4.0MB)
 NewRatio = 2
 SurvivorRatio = 8
 PermSize = 16777216 (16.0MB)
 MaxPermSize = 67108864 (64.0MB)

Um pedaço do vmstat durante a execução

2010-04-02 20:47:16 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
2010-04-02 20:47:16 r b swpd free buff cache si so bi bo in cs us sy id wa
...
2010-04-02 20:48:44 51 0 0 283440 81520 1825480 0 0 0 0 1131 934 61 36 3 0
2010-04-02 20:48:48 50 0 0 286032 81528 1811856 0 0 0 11 1230 1291 64 30 5 0
2010-04-02 20:48:52 109 0 0 259780 81528 1811324 0 0 0 5 1133 1579 58 36 5 0

Percebe-se que a “run queue” (coluna r) possui um alto número

de

tarefas aguardando um tempinho da CPU para processar alguma instrução.

Vejam um screenshot do visualgc ao fim do teste

O VisualGC é um plugin do VisualVM. Na versão atual do Java, o visualvm faz parte do download do java, mas é chamado de jvisualvm. Durante o teste ocorreram 115 ações do GC na área YOUNG que duraram 3.306 ms, enquanto a área OLD com seus 1,3 GB ociosos.  ## 4) Análise O objetivo do teste é a JVM e não a aplicação, então nem vamos olhar na aplicação. Sempre em uma análise do GC, é importante diminuir o impacto do tempo do GC na aplicação. Sempre que puder diminuir o tempo total do GC ajuda o throughput da aplicação. Em uma análise óbvia, percebe-se que a área OLD está ociosa, enquanto existe atividade intensa na área YOUNG, então seria natural aumentar a área YOUNG para um tamanho grande. Aqui que costuma ocorrer um erro comum também, onde aumentar uma área é proporcional ao tempo de GC, pelo tamanho maior a ser varrido. Por esta applicação ser orientada a CPU (muitas threads), processamento matemático, sem sincronização, sem rede, sem banco de dados, então é uma análise orientada para menor consumo de CPU e otimização do funcionamento do Garbage Collector.   ## 5) Resultado (2a bateria) Será feito uma otimização na invocação do comando java

$ time java -server -XX:+AlwaysTenure -XX:+UseConcMarkSweepGC -Xss64k -Xms2g -Xmx2g -classpath build/WEB-INF/classes/:src/conf/:src/java/ br.com.claudius.threads.NumThreads 2700 2000 10

Parametros adicionais:

Parametro	Explicação
-server	Usa otimizações específicas para o modo de aplicações servidoras.
-XX:+AlwaysTenure	Não usa espaços Survivors da área YOUNG, a promoção vai direto da YOUNG para OLD.
-XX:+UseConcMarkSweepGC	Usa o algoritmo concorrente na área OLD e Paralelo na área YOUNG (-XX:+UseParNewGC)
-Xss64k	Reserva 64 kb para o tamanho do stack de thread.
-Xms2g	Aloca inicialmente o tamanho do heap para 2 GB

real 1m5.618s
user 0m51.967s
sys 0m38.598s

Percebe-se a melhoria no tempo de 66s. Descontar 10s deste tempo final, pois na aplicação tem uma pausa de 10s antes de começar o teste. O visualgc mostra uma melhoria significativa, onde ocorreram 86 ações do GC com duração da atividade de  GC em 836 ms.  Ao efetuar a mesma medição com o jstat, percebe-se uma melhoria marginal no tempo total do GC, mas com boa diminuição na quantidade de GC.

$ jstat -gcutil 1451 3s
 S0 S1 E O P YGC YGCT FGC FGCT GCT
 0,00 0,00 54,22 0,08 11,30 71 0,799 0 0,000 0,799
 0,00 0,00 81,01 0,08 11,30 75 0,808 0 0,000 0,808

Ao diminuir o tamanho do stack para 48k (o mínimo aceito pela JVM), o tempo do GC melhorou bem. Com -Xss48k

$ jstat -gcutil 4265 3s
 S0 S1 E O P YGC YGCT FGC FGCT GCT
 0,00 0,00 44,52 0,08 11,30 75 0,670 0 0,000 0,670
 0,00 0,00 97,33 0,08 11,30 79 0,685 0 0,000 0,685

O comportamente da CPU mostrado pelo vmstat, mostra um uso bem mais modesto da CPU, veja a coluna r (run queue)

2010-04-05 00:40:14 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
2010-04-05 00:40:14 r b swpd free buff cache si so bi bo in cs us sy id wa
...
2010-04-05 00:40:53 24 0 0 1386056 249416 953668 0 0 0 0 1190 631 52 32 16 0
2010-04-05 00:40:56 7 0 0 1390532 249424 953660 0 0 0 4 1199 645 59 32 10 0
2010-04-05 00:40:59 18 0 0 1395652 249424 953500 0 0 0 0 1196 609 54 34 12 0

Nota 2: o VisualGC é um plugin do VisualVM (Tools -> Plugins -> Available Plugins) ## 5) Conclusão No 2o teste foi percebido uma melhoria significativa no tempo total e com menos impacto na utilização da CPU. Não foi feito um super mega tunning para este exemplo, mas mostrar que com uma boa análise, alguns testes, é possível observar o comportamento da aplicação e aplicar as otimizações no lugar certo. Tente executar um teste e análise em seu ambiente. ## 6) FAQ ? ### 6.1) Você usou o G1 ? Usei o algorítimo G1 mas o resultado foi inferior ao concorrente, mas o pior neste caso foi que a ferramenta jstat não consegue exibir os resultados das áreas de memória.

Warning: Unresolved Symbol: sun.gc.generation.0.space.1.capacity substituted NaN
Warning: Unresolved Symbol: sun.gc.generation.0.space.1.used substituted NaN
...
Warning: Unresolved Symbol: sun.gc.collector.0.time substituted NaN
Warning: Unresolved Symbol: sun.gc.collector.1.time substituted NaN
 S0 S1 E O P YGC YGCT FGC FGCT GCT
 � � � � 30,33 � � � � �

  ### 6.2) Porque aumentar o stack size da aplicação de teste para monitorar ? Parece que as ferramentas gráficas jconsole e visualvm exigem um stack de tamanho maior para monitorar, caso contrário ocorre um erro

*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message transform method call failed at ../../../src/share/instrument/JPLISAgent.c line: 806
Segmentation fault

isso é assunto para outro blog ### 6.3) Porque não aumentar o tamanho da área YOUNG (-XX:+NewSize) Ao aumentar o tamanho da área YOUNG diminuiu a quantidade de GC, mas o tempo total do GC aumentou e isso trouxe uma performance inferior ao teste final. Nem sempre aumentar o tamanho da YOUNG beneficia a aplicação. Cada caso tem de ser analisado diferente.