Eu tenho um webapp (Tomcat/Hibernate/DBCP 1.4) que executa consultas no MySQL e funciona bem para uma determinada carga, digamos 50 consultas por segundo. Quando roteio a mesma carga moderada por meio do HAProxy (ainda usando apenas um único banco de dados), recebo uma falha, talvez uma para cada 500 consultas. Meus relatórios de aplicativos:
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 196,898 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor210.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1117)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3567)
...
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3017)
...
Enquanto isso, o log do HAProxy mostra muitas entradas como:
27] mysql mysql/db03 0/0/34605 2364382 cD 3/3/3/3/0 0/0
Oct 15 15:43:12 localhost haproxy[3141]: 127.0.0.1:35500 [15/Oct/2012:15:42:50.0
O “cD” aparentemente indica um estado de tempo limite do cliente. Então, enquanto meu webapp diz que o HAProxy se recusa a aceitar novas conexões, o HAProxy está dizendo que meu webapp não está aceitando dados de volta.
Não estou incluindo minha configuração do HAProxy porque tentei muitos valores de parâmetros diferentes, com essencialmente o mesmo resultado. Em particular, defini maxconn para valores altos e baixos, nas seções global e de servidor, e o que sempre acontece nas estatísticas é que o máximo de sessões aumenta para não mais do que 7. O tamanho do meu pool JDBC também é alto.
Geralmente é aceitável usar um pool JDBC e um pool HAProxy juntos? As pessoas já enfrentaram esse tipo de problema antes?
Tenho uma ideia de como resolver isso, que é enviar uma "consulta de validação" antes de cada consulta. Mas há uma certa sobrecarga aí, e eu ainda gostaria de saber por que meu webapp é bem-sucedido quando vai direto para o MySQL, mas perde conexões ao passar pelo HAProxy.
Como posso depurar ainda mais e obter mais informações do que apenas “cD”? Tentei executar o HAProxy no modo de depuração, mas não parece revelar mais nada.
ATUALIZAÇÃO - Sexta-feira, 4 de janeiro, 11:49:28 ICT 2013 (resposta a JimB)
A única maneira de obter mais informações do haproxy do que você tem seria usar o comando
show sessorshow sess <id>periodicamente para observar o estado de cada conexão tcp
Aqui estão algumas informações sobre as sessões:
0x31f4310: proto=tcpv4 src=192.168.3.40:60401 fe=FE_mysql be=BE_mysql srv=mysql3 ts=08 age=1m2s calls=2 rq[f=909202h,l=0,an=00h,rx=13s,wx=,ax=] rp[f=109202h,l=0,an=00h,rx=13s,wx=,ax=] s0=[7,18h,fd=0,ex=] s1=[7,18h,fd=1,ex=] exp=13s
0x31fca50: proto=tcpv4 src=192.168.3.40:60423 fe=FE_mysql be=BE_mysql srv=mysql1 ts=08 age=2s calls=2 rq[f=909202h,l=0,an=00h,rx=1m13s,wx=,ax=] rp[f=109202h,l=0,an=00h,rx=1m13s,wx=,ax=] s0=[7,18h,fd=9,ex=] s1=[7,18h,fd=12,ex=] exp=1m13s
O Haproxy tem um tempo limite padrão de 10 segundos (e as configurações de exemplo têm 50 segundos, eu acho). Não estou muito familiarizado com o JDBC, mas seguindo os documentos do Tomcat, há uma configuração
minEvictableIdleTimeMillisque removerá a conexão inativa do pool e o padrão é 60 segundos, e pode levar até 65 segundos porque sãotimeBetweenEvictionRunsMillis5 segundos por padrão. Basicamente, você precisa ter certeza de que o tempo limite do haproxy é alto o suficiente para compensar essas conexões ociosas no pool.
Aumentei timeout clientpara 75 segundos e agora o erro acima parece ocorrer menos do que antes:
04/01/2013 11:59:59 Depuração: falha no link de comunicação
O último pacote recebido com sucesso do servidor foi há 145.255 milissegundos. O último pacote enviado com sucesso ao servidor foi há 10 milissegundos.
Também quero observar que: além do acima, existem alguns erros como este:
Falha no link de comunicação O último pacote enviado com sucesso ao servidor foi há 0 milissegundos. O driver não recebeu nenhum pacote do servidor.
No lado do servidor, às vezes vejo o sDsinalizador de desconexão:
haproxy[15770]: 192.168.3.40:56944 [04/Jan/2013:11:06:55.895] FE_mysql BE_mysql/mysql1 0/0/77153 1954480 sD 1/1/1/1/0 0/0
O timeout servertambém está definido para 75 segundos.
Outra abordagem seria usar
testWhileIdleevalildationQuerymanter as conexões ativas, já que alguns pacotes de tráfego a cada poucos segundos provavelmente também aliviariam o problema.
Eu sugeriria que o desenvolvedor tentasse essas opções se não houvesse outra maneira.
Responder1
A única maneira de obter mais informações do haproxy do que você tem seria usar o comando show sessor show sess <id>periodicamente para observar o estado de cada conexão tcp, embora não tenha certeza se você obteria mais informações úteis.
O cDestado de término é a informação mais útil que você possui. O que isso significa exatamente é que o tempo limite de uma conexão estabelecida com o cliente expirou. Isso é controlado no haproxy por meio do timeout clientparâmetro na configuração, definido globalmente ou em uma seção frontent ou listen.
Você disse que não vê conexões simultâneas ultrapassando 7, e esta entrada de log mostra que a falha ocorreu quando havia apenas 3 conexões, então duvido que você tenha um problema de limite de conexão (mesmo fora do controle do haproxy).
Então, o que parece estar acontecendo é que ocasionalmente o pool adiciona uma nova conexão, que lida com algumas consultas e depois fica ocioso. Quando essa conexão ficar ociosa por mais tempo do que a timeout clientconfiguração no haproxy, o haproxy encerrará a própria conexão. Na próxima vez que essa conexão for usada no pool, você receberá o erro acima.
O Haproxy tem um tempo limite padrão de 10 segundos (e as configurações de exemplo têm 50 segundos, eu acho). Não estou muito familiarizado com o JDBC, mas seguindo os documentos do Tomcat, há uma configuração minEvictableIdleTimeMillisque removerá a conexão inativa do pool e o padrão é 60 segundos, e pode levar até 65 segundos porque são timeBetweenEvictionRunsMillis5 segundos por padrão. Basicamente, você precisa ter certeza de que o tempo limite do haproxy é alto o suficiente para compensar essas conexões ociosas no pool.
Outra abordagem seria usar testWhileIdlee valildationQuerymanter as conexões ativas, já que alguns pacotes de tráfego a cada poucos segundos provavelmente também aliviariam o problema.
[editar] Em resposta às informações adicionais de @quanta:
Mesmo que o tempo limite do haproxy agora seja de 75 segundos, você definitivamente ainda está obtendo tempos limite de sessão. Pode haver algum jogo adicional na vida útil total de uma conexão JDBC que eu não conheço. Como são necessárias pouquíssimas conexões para esse tipo de serviço, também não há nada de errado em aumentar os timeouts para algo extremamente alto, da ordem de uma hora ou mais. Se o pool JDBC realmente estiver tendo problemas para liberar conexões antigas, isso apenas mascararia o problema, mas também poderia ser uma solução fácil.