Tengo una aplicación web (Tomcat/Hibernate/DBCP 1.4) que ejecuta consultas en MySQL, y esto funciona bien para una carga determinada, digamos 50 consultas por segundo. Cuando direcciono la misma carga moderada a través de HAProxy (todavía usando una única base de datos), obtengo un error, tal vez uno por cada 500 consultas. Mi aplicación informa:
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)
...
Mientras tanto, el registro de HAProxy muestra muchas 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
El "cD" aparentemente indica un estado de tiempo de espera del cliente. Entonces, mientras mi aplicación web dice que HAProxy se niega a aceptar nuevas conexiones, HAProxy dice que mi aplicación web no acepta datos.
No incluyo mi configuración de HAProxy porque probé muchos valores de parámetros diferentes y obtuve esencialmente el mismo resultado. En particular, configuré maxconn en valores altos y bajos, tanto en la sección global como en la del servidor, y lo que siempre sucede en las estadísticas es que el número máximo de sesiones aumenta a no más de aproximadamente 7. El tamaño de mi grupo JDBC también es alto.
¿En general, está bien utilizar un grupo JDBC y un grupo HAProxy juntos? ¿La gente se ha topado con este tipo de problema antes?
Tengo una idea sobre cómo resolver esto, que consiste en enviar una "consulta de validación" antes de cada consulta. Pero hay una cierta sobrecarga allí, y todavía me gustaría saber por qué mi aplicación web tiene éxito cuando va directamente a MySQL, pero se interrumpen las conexiones al pasar por HAProxy.
¿Cómo puedo depurar más y obtener más información que solo "cD"? Intenté ejecutar HAProxy en modo de depuración, pero no parece revelar nada más.
ACTUALIZACIÓN: viernes 4 de enero 11:49:28 ICT 2013 (Respuesta a JimB)
La única forma de obtener más información de haproxy de la que tiene sería usar el comando
show sessoshow sess <id>periódicamente para observar el estado de cada conexión tcp.
Aquí tenéis información sobre las sesiones:
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 tiene un tiempo de espera predeterminado de 10 segundos (y creo que las configuraciones de ejemplo tienen 50 segundos). No estoy muy familiarizado con JDBC, pero según los documentos de Tomcat, hay una configuración
minEvictableIdleTimeMillisque expulsará la conexión inactiva del grupo y tiene un valor predeterminado de 60 segundos, y puede ser de hasta 65 segundos porquetimeBetweenEvictionRunsMillisson 5 segundos de forma predeterminada. Básicamente, debe asegurarse de que el tiempo de espera de su haproxy sea lo suficientemente alto como para tener en cuenta estas conexiones inactivas en el grupo.
Aumenté el tiempo timeout clienta 75 segundos y ahora el error anterior parece ocurrir menos que antes:
2013-01-04 11:59:59 Depuración: falla en el enlace de comunicaciones
El último paquete recibido con éxito del servidor fue hace 145.255 milisegundos. El último paquete enviado con éxito al servidor fue hace 10 milisegundos.
También quiero señalar que: además de lo anterior, hay algunos errores como este:
Fallo en el enlace de comunicaciones El último paquete enviado exitosamente al servidor fue hace 0 milisegundos. El controlador no ha recibido ningún paquete del servidor.
En el lado del servidor, en algún momento veo el sDindicador al desconectarse:
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
El timeout servertambién está fijado en 75 segundos.
Otro enfoque sería utilizar
testWhileIdleyvalildationQuerymantener las conexiones activas, ya que unos pocos paquetes de tráfico cada pocos segundos probablemente también aliviarían el problema.
Sugeriría al desarrollador que pruebe estas opciones si no hay otra manera.
Respuesta1
La única forma de obtener más información de haproxy de la que tiene sería usar el comando show sesso show sess <id>periódicamente para observar el estado de cada conexión tcp, aunque no estoy seguro de si obtendría más información útil.
El cDestado de terminación es la información más útil que tiene. Lo que significa exactamente es que se agotó el tiempo de espera de una conexión establecida con el cliente. Esto se controla en haproxy a través del timeout clientparámetro en la configuración, configurado globalmente, o en una sección frontal o de escucha.
Dijiste que no ves conexiones simultáneas superiores a 7, y esta entrada de registro muestra que la falla ocurrió cuando solo había 3 conexiones, por lo que dudo que tengas un problema de límite de conexión (incluso fuera del control de haproxy).
Entonces, lo que parece que está sucediendo es que ocasionalmente el grupo agrega una nueva conexión, que maneja algunas consultas y luego permanece inactiva. Cuando esa conexión permanece inactiva por más tiempo que la timeout clientconfiguración en haproxy, haproxy finalizará la conexión. La próxima vez que se utilice esa conexión desde el grupo, aparecerá el error anterior.
Haproxy tiene un tiempo de espera predeterminado de 10 segundos (y creo que las configuraciones de ejemplo tienen 50 segundos). No estoy muy familiarizado con JDBC, pero según los documentos de Tomcat, hay una configuración minEvictableIdleTimeMillisque expulsará la conexión inactiva del grupo y tiene un valor predeterminado de 60 segundos, y puede ser de hasta 65 segundos porque timeBetweenEvictionRunsMillisson 5 segundos de forma predeterminada. Básicamente, debe asegurarse de que el tiempo de espera de su haproxy sea lo suficientemente alto como para tener en cuenta estas conexiones inactivas en el grupo.
Otro enfoque sería utilizar testWhileIdley valildationQuerymantener las conexiones activas, ya que unos pocos paquetes de tráfico cada pocos segundos probablemente también aliviarían el problema.
[editar] En respuesta a la información adicional de @quanta:
Aunque el tiempo de espera de haproxy ahora es de 75 segundos, definitivamente todavía estás recibiendo tiempos de espera de sesión. Puede haber algún juego adicional en la vida útil total de una conexión JDBC que no conozco. Dado que se necesitan muy pocas conexiones para este tipo de servicio, tampoco hay nada de malo en aumentar los tiempos de espera a algo extremadamente alto, del orden de una hora o más. Si el grupo JDBC realmente tiene problemas para liberar conexiones antiguas, esto sólo enmascararía el problema, pero también podría ser una solución fácil.