HAProxy, timeouts do cliente ao conectar-se a partir do pool JDBC

Question

Eu tenho um webapp (Tomcat / Hibernate / DBCP 1.4) que executa consultas no MySQL, e isso funciona bem para uma certa carga, digamos 50 consultas por segundo. Quando eu roteio a mesma carga moderada através de HAProxy (ainda usando apenas um 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 está mostrando 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 está dizendo que o HAProxy está se recusando a aceitar novas conexões, o HAProxy está dizendo que meu webapp não está aceitando dados de volta.

Eu não estou incluindo minha configuração HAProxy, porque eu tentei muitos valores de parâmetro diferentes, com essencialmente o mesmo resultado. Em particular, configurei maxconn para valores altos e baixos, nas seções globais e de servidor, e o que sempre acontece nas estatísticas é que o número máximo de sessões aumenta para não mais que 7. Meu tamanho de conjunto JDBC também é alto.

Geralmente, é aceitável usar um pool JDBC e um pool HAProxy juntos? As pessoas já se depararam com esse tipo de problema antes?

Eu tenho uma ideia de como resolver isso, que é enviar uma "consulta de validação" antes de cada consulta. Mas há uma certa sobrecarga lá, e eu ainda gostaria de saber por que meu webapp é bem-sucedido quando vai direto para o MySQL, mas obtém conexões abandonadas ao passar pelo HAProxy.

Como posso depurar 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 - Sex. 4 de janeiro 11:49:28 ICT 2013 (à resposta de JimB)

The only way to get more info from haproxy than what you have, would be to use the show sess or show sess <id> command periodically to watch the state of each tcp connection

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

Haproxy has a default timeout of 10 seconds (and the example configs have 50 seconds I think). I'm not too familiar with JDBC, but going from Tomcat's docs, there is a setting minEvictableIdleTimeMillis, which will evict idle connection from the pool, and defaults to 60 seconds, and may be up to 65 seconds because the timeBetweenEvictionRunsMillis is 5 seconds by default. Basically, you need to make sure your haproxy timeout is high enough to account for these idle connections in the pool.

Eu aumentei o timeout client para 75 segundos e agora o erro acima parece ocorrer menos do que antes:

2013-01-04 11:59:59 Debug: Communications link failure

The last packet successfully received from the server was 145,255 milliseconds ago. The last packet sent successfully to the serv er was 10 milliseconds ago.

Eu também quero observar que, além do acima, há alguns erros como este:

Communications link failure The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.

No lado do servidor, em algum momento, vejo o sinal sD na 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 server também está definido para 75 segundos.

Another approach would be to use testWhileIdle and valildationQuery to keep the connections active, since a few packets of traffic every few seconds would probably alleviate the issue as well.

Gostaria de sugerir ao desenvolvedor que tente essas opções, se não houver outra maneira.

    

Answer 1

A única maneira de obter mais informações do haproxy do que você usa seria usar o comando show sess ou show sess <id> periodicamente para observar o estado de cada conexão tcp, embora não tenha certeza se você obteria qualquer informação mais útil.

O estado da terminação cD é a informação mais útil que você tem. O que significa exatamente é que uma conexão estabelecida com o cliente foi esgotada. Isso é controlado no haproxy por meio do parâmetro timeout client na configuração, definido globalmente ou em uma seção frontent ou listen.

Você disse que não vê conexões simultâneas em 7, e essa entrada de log mostra que a falha ocorreu quando havia apenas 3 conexões, por isso duvido que você tenha um problema de limite de conexão (mesmo fora do controle do haproxy).

Então, o que parece que está acontecendo é que, ocasionalmente, o pool adiciona uma nova conexão, que lida com algumas consultas e fica inativa. Quando essa conexão fica ociosa por mais tempo do que a configuração timeout client no haproxy, o haproxy terminará a conexão em si. Da próxima vez que a conexão for usada no pool, você receberá o erro acima.

O haproxy tem um tempo limite padrão de 10 segundos (e o exemplo de configuração tem 50 segundos). Eu não estou muito familiarizado com o JDBC, mas indo de documentos do Tomcat, há uma configuração minEvictableIdleTimeMillis , que irá despejar conexão ociosa do pool, e padrão de 60 segundos, e pode ser de até 65 segundos, porque o timeBetweenEvictionRunsMillis é 5 segundos por padrão. Basicamente, você precisa garantir que o tempo limite de haproxy seja alto o suficiente para considerar essas conexões ociosas no pool.

Outra abordagem seria usar testWhileIdle e valildationQuery para manter as conexões ativas, já que alguns pacotes de tráfego a cada poucos segundos provavelmente aliviam o problema também.

[edit] Em resposta a informações adicionais do @quanta:

Embora o tempo limite haproxy seja agora de 75 segundos, você ainda está recebendo tempos limite da sessão. Pode haver alguma reprodução adicional no tempo de vida total de uma conexão JDBC da qual não conheço. Como há muito poucas conexões necessárias para esse tipo de serviço, também não há nada de errado em aumentar os tempos limite para algo extremamente alto, na ordem de uma hora ou mais. Se o pool JDBC realmente está tendo problemas para liberar conexões antigas, isso estaria apenas mascarando o problema, mas também poderia ser uma correção fácil.