Technè

Ainda que isto não devesse acontecer, é relativamente comum observar problemas de desempenho indesejáveis quando um sistema vai para o ambiente de produção. Uma das causas para tal situação está relacionada a sincronização excessiva, sejá por má codificação ou configuração. A situação é ainda mais grave porque estes se manifestam apenas quando o sistema está sob uma carga intensa, tornando-os quase que indectáveis se não forem executados testes de carga devidamente escritos durante o desenvolvimento.

O processo de identificação do problema pode ser simplificado, uma vez que exista uma infraestrutura de monitoramento implementada no sistema comparado ao cenário onde o único indício é a queda de throughput. Entretanto, independente do suporte mencionado, pode-se empregar o mesmo método para identificar a porção de código que está ocasionando o problema.

Projeto de exemplo

De forma a melhorar a didática deste post, está disponível para download um projeto de exemplo que permite uma experimentação prática com um problema conhecido do Hibernate que se manifesta quando um SequenceHiLoGenerator é configurado com o parâmetro allocationSize definido como “1″ e o sistema está sob carga.

O projeto foi estruturado em torno do problema descrito acima que faz com que o Hibernate aguarde a geração de um sequence dentro de um bloco sincronizado para cada instância de entidade que tem que ser salva. Isto pode ser potencialmente nocivo se existem muitas requisições concorrentes ou se o banco de dados começa a demorar um pouco mais a responder as requisições.

Testando o exemplo

O primeiro passo para executar o exemplo é iniciar o HSQLDB – a opção pelo HSQLDB foi motivada pelo fato dele apresentar um mecanismo de geração de Sequence e por não necessitar de nenhum processo complexo de instalação – a partir do arquivo hsqldb.launch. O próximo passo é executar o insertOneThread.launch e deixar que ele execute por algum tempo. Execute então o JConsole através do jconsole.bat e conecte ao aplicativo br.org.cesar.contentionsample.main.Main. Selecione a opção MBeans, expanda o pacote br.org.cesar.contentionsample.monitoring, pacote este em que você deverá encontrar o InsertMBean. Abaixo do InsertMBean você encontrará um item chamado Attributes que quando selecionado exibirá uma janela similar a abaixo:

Amostra de exemplo para o Insert com uma Thread

Estes são os resultados para uma execução em minha máquina, tome nota dos valores obtidos a partir da execução em sua máquina para comparar com os próximos testes.

Encerre o insertOneThread.launch em execução e inicie o insertTenThreads.launch, repita os passos descritos acima para a coleta dos tempos de execução. Seguem abaixo, da mesma forma, os resultados encontrados quando o teste foi executado em minha máquina:

Amostra de exemplo para o Insert com 10 Threads

Encerre desta vez o insertTenThreads.launch e execute o insertFiftyThreads.launch. Note que os resultados estão aumentando em uma proporção razoável. Novamente estou disponibilizando meus resultados:

Amostra de exemplo para o Insert com 50 Threads

A idéia por trás do aumento de threads era simular o aumento de carga visto em um ambiente de produção. Isto é relativamente simples em um teste sintético como este mas pode ser, dependendo do cenário, mais complexo e envolver o aumento de testes em uma suíte de testes do JMeter ou do Grinder.

É interessante destacar que nos testes o insertTimeMax (isto é, o tempo máximo necessário para uma inserção na base de dados) subiu de inexpressivos 501ms com uma única thread para o valor de 8829ms. O mesmo sintoma pode ser visto nas coletas das médias de execução que foi de 28ms para 1123ms. Todos estes resultados convergem para um cenário de contenção de Threads uma vez que nosso tempo de resposta foi altamente impactado em decorrência do aumento de concorrência em nosso código.
O próximo passo é identificar o código responsável pelo aumento.

Detectando o código responsável pelo problema

A detecção do problema envolve identificar que porção de código as threads estão tentando executar e qual mutex que está impedindo que elas executem.

Uma das possibilidades para identicar o problema é usar o JDB. O único requisito para usar o JDB é ter a JVM em modo debug (ex.: -Xdebug -Xrunjdwp:transport=dt_socket,server=y,address=8888).

Reinicie o insertFiftyThreads.launch através da opção do Eclipse “Run As->Run Configurations” e dessa vez adicione o texto a seguir em “VM Arguments”:

Inicie o jdb.bat e execute o comando suspend (isto interromperá todas as Threads, requisito para a extração de um thread dump usando este método) e então execute o comando where all. O comando where all irá imprimir a localização de cada thread em execução.
Uma rápida olhada no thread dump irá revelar que uma grande porção das threads neste problema de exemplo estão no mesmo trecho que está a Thread 7 como pode ser observado no screenshot abaixo:

Thread bloqueada

Na situação oposta, temos a thread que detém o mutex e está gerando o identificado. Esta thread terá o seguinte stacktrace:

Thread gerando o identificador

E uma vez que no nosso exemplo nós tínhamos uma única entidade e consequentemente uma única instância do SequenceHiLoGenerator, nós veremos uma única thread no trecho de código mencionado acima.

Contudo estas constratações não são suficientes para concluirmos que temos threads bloqueadas em decorrência de um mutex, é preciso comparar o resultado com o obtido pelo comando threadlocks. Execute o comando threadlocks all e agrupe os dados do thread dump e do thread locks em uma planilha. Segue abaixo um exemplo do resultado da execução do comando threadlocks:

Thread locks

No exemplo a Thread 11 (destacada em vermelho) está aguardando o mutex para gerar o identificador enquanto que a Thread 10 (destacada em amarelo) adquiriu o mutex e já está gerando o identificador (como pode ser observado no screenshot da thread gerando o identificador).
É possível perceber que todas as threads estão aguardando o mutex do tipo org.hibernate.id.SequenceHiLoGenerator estão paradas no método org.hibernate.id.SequenceHiLoGenerator.generate (SequenceHiLoGenerator.java:74). O motivo é que este mutex é resultado da palavra reservada synchronized no método exposto a seguir:

Sendo assim, o desempenho abaixo do esperado é relacionado ao valor “1″ que foi atribuído ao parâmetro allocationSize e faz com que o trecho de código dentro do primeiro if seja executado para cada operação de save em uma entidade. Este por sua vez necessita consultar o próximo valor de sequence ao SGBD para cada requisição – processo este que só pode ser executado por uma thread por vez.

Configurando corretamente e reexecutando os testes

Encerre o insertFiftyThreads.launch, defina um valor coerente para o allocationSize (se não especificado, o allocationSize assume o valor padrão de 50, entretanto em cenários de carga muito alta pode haver benefícios em se usar valores maiores). Reexecute o insertFiftyThreads, colete novamente os dados do MBean e certifique-se que o problema de contenção foi solucionado. Nos meus testes eu identifiquei uma média de 146ms, um máximo de 4766ms e um mínimo de 0ms com o valor padrão para o allocationSize, ou seja, 50.