一则线上MySql连接异常的排查过程

Mysql作为一个常用数据库,在互联网系统应用很多。有些故障是其自身的bug,有些则不是,这里以前段时间遇到的问题举例。

问题

当时遇到的症状是这样的,我们的应用在线上测试环境,JMeter测试过程中,发现每次压力测试开始时访问低前几个http request请求会超时,而之后的请求持续测试中都不会。最后一点是Tomcat的log并没有报什么错误。

压测的内容就是起200线程不停的向这个http页面发送请求,这个页面逻辑也比较简单,会在后端向数据库插入一条数据,连接池采用阿里的Druid(这个坑先留在这),tomcat中运行的是常规web app应用,每个应用的JDBC连接池最大连接数只设了30,就是说就算4个tomcat一起连数据库,最大也没有多少连接。

尝试排查

由于tomcat的log并没有什么错,所以先开始尝试重现错误。 错误重现开始并不容易,因为看起来比较随机,后来经过总结,发现每次都是出现问题都是应用放了一晚上后,测试人员早上过来开始压力测试时出现,开始怀疑跟闲置有关,所以后面的重现都按这个方式来,闲置半小时再开始尝试重现。

找log

没有log,就要看下JVM的stack信息了。重现故障,上该机器上用jstack直接抓问题tomcat 的jvm信息。

jps
列出机器的java进程号
jstack javaid
dump该java进程的stack信息

拿到的stack信息中发现了有用的东西:

“http-bio-8081-exec-4975” daemon prio=10 tid=0x00007f9d4c127000 nid=0x65db runnable [0x00007f9cc4544000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at **com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
- locked <0x0000000684d608c8> (a com.mysql.jdbc.util.ReadAheadInputStream)**
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3014)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3467)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3456)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3997)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.ConnectionImpl.pingInternal(ConnectionImpl.java:4092)
at com.mysql.jdbc.ConnectionImpl.ping(ConnectionImpl.java:4069)
at sun.reflect.GeneratedMethodAccessor94.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.alibaba.druid.pool.vendor.MySqlValidConnectionChecker.isValidConnection(MySqlValidConnectionChecker.java:98)
at com.alibaba.druid.pool.DruidAbstractDataSource.testConnectionInternal(DruidAbstractDataSource.java:1235)
at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:928)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:882)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:872)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:97)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:202)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:372)
at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:417)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:255)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
at com.sun.proxy.$Proxy27.insert(Unknown Source)

可以看到HTTP请求从前端容器直到数据库读取时为止,卡在了数据库读取的地方,而且并不是JDBC驱动代码里的问题,而且出在socket读取的地方:

com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
- locked <0x0000000684d608c8> (a com.mysql.jdbc.util.ReadAheadInputStream)*

根据这个错误搜索了下,唯一有价值的就是N年前mysql官网上报的一个bug,同样的错误,但处理的办法并不治本。如提到了将JDBC连接字串改为:

useReadAheadInput=false&useUnbufferedInput=false

这只是让socket不去预读网络缓冲区,但实际上这个时候Mysql的连接已经断开了,并不知道是web应用这里断的还是Mysql断的。

查找连接池超时

由于根据log看起来是应用的客户端在socket上读不到东西,肯定是应用与mysql的tcp连接断了,所以开始排查应用连接池设置与mysql的连接超时设置。

应用连接池设置

name=”maxWait” value=”60000”
获取连接最大等待60秒
name=”testWhileIdle” value=”true”
测试空闲连接
name=”minEvictableIdleTimeMillis” value=”300000”
name=”timeBetweenEvictionRunsMillis” value=”60000”
Destroy线程会检测连接的间隔时间

应用端的连接池设置没有主动断掉的设置。

mysql连接超时设置

show global variables like ‘%timeout%’

看到mysql维持连接的timeout时间为28800,即8小时,数据库端不会断掉这个连接。

至此,问题的排查进入死胡同,两边都不会主动断开连接,为什么客户端在闲置几分钟后会被断掉?

还有一个疑点是同样的代码,数据库也没什么变动,在另一个纯测试环境完全没有这个问题。

查找网络问题

现在问题的重点怀疑方向就是线上环境网络问题。于是找运维的同事查看了下数据库机器上linux有没有什么异常的配置,结果是没有。

期间也怀疑为什么用了阿里druid的连接池,现在设成每分钟检测连接池里的连接,还是会在拿到连接的时候有失效的连接。

解决

断断续续折腾了2天,抱着死马当活马医去咨询了其他部门的同事,结果那兄弟说是不是闲置后卡在socketRead上?然后问了应用与数据库是不是在不同网段上,马上建议找网络的人查一下防火墙对tcp长连接超时的设置。

这时候基本上就肯定是防火墙设置的问题,排查后发现两个网段间华为交换机的长连接超时设了3分钟,由于java应用的连接池是尽量长时间的维持连接(几个小时,低于数据库的最长8小时设置),而防火墙认为超过3分钟的连接是有问题的,直接断掉了,这时应用与mysql都不知道tcp连接已经被断了。

此次故障还暴露了阿里Druid开源连接池对连接处理逻辑的问题,连接池并没有用单独的线程去检测所有连接有没有断开,查代码后发现其只是在拿到连接时测试连接是否有效,处理逻辑没有老牌c3p0严谨,之后将应用连接池实现更换为c3p0。



文章来自微信平台「麦芽面包」。转载请注明。

时间: 2024-10-24 21:03:54

一则线上MySql连接异常的排查过程的相关文章

【原创】线上环境 SYN flooding 问题排查

问题描述:       线上环境中,公司自研即时通讯软件不定时掉线.  问题排查:       由运维和测试人员发现并报告,线上环境出现网络异常,具体表现为登录服务器虚拟 IP 地址无法 ping 通,即时通讯工具不定时掉线:       在此情况下,现场人员第一反应就是受到了外部攻击(因为以前遇到过攻击情况),因为看到了如下信息  ... Apr 20 18:21:48 localhost kernel: possible SYN flooding on port 80. Sending co

线上mysql数据库不停机的环境下如何添加新的从机

  在工作中,主从环境搭的多了,但是,基本上都是在DB SERVER停机(游戏公司)的情况下搭建的,今天突然被一技术官问,如何在线添加主从,回答的大概思路,但是没有实践过,下面,我就测试一下.各位也可以先想想自己的思路:mysql 5.1版本,二进制日志文件(时间长了,有些二进制日志定期清除了),pos号 注:在mysql 5.6版本中,已经有基于GTID的主从复制(即:不需要知道日志文件和position号),只需还原最新的备份就可实现,这里只讨论mysql 5.1 一.目前的基本环境: 主D

记录一次线上mysql异常

  早上突然收到小伙伴反馈,app用不了了,查看日志发现以下错误:     Packet for query is too large (1118 > 1024). You can change this value on the server by setting the      max_allowed_packet' variable.               网上解决方案是设置max_allowed_packet 这个值,发现300M ,应该没问题,先重启Tomcat发现没用,实在没

百度百科二维码的背后:真实世界与线上信息的无缝连接

李彦宏前年所提出的用互联网帮助http://www.aliyun.com/zixun/aggregation/8150.html">传统行业的理念,似乎真的成为了百度的发展纲领,最近百度在用自身资源与传统结合方面屡屡出手,几乎无孔不入,到了为提供方便不计成本,不顾产出的地步,这真的要引起互联网业界的注意了. 近日,百度百科与北京植物园达成合作,为园内的百余种植物悬挂了4000多个"植物二维码",五一期间进园观光的游客,只要拿起手机扫描这些二维码,即可直接访问百度百科,浏

C2B模式的领跑者:线上教育

(文/黄嘉榔) 百年树人教育为本,教育是一个国家长久兴盛的根本,就中国教育行业而言,很多人都深有感触,是一种填鸭式的教育,教育出来的学子们远远适应不了社会.国内有很多的教育机构,有传统的教育企业:新东方.卓越教育集团:线上教育:正大远程.粉笔网.多贝网:公务员教育:华图教育.中公教育.为何教育行业的企业随着时间的推移而越来越多.原因是否真的像我们所看到的报道一样,学校的教育如何?孩子对学校不喜欢等等?或许不是,每个家长都是想让孩子或者自己赢在起点上面,为了未来而投资. 过往我们接受教育都是需要亲

一次线上OOM故障排查经过

转贴:http://my.oschina.net/flashsword/blog/205266   本文是一次线上OOM故障排查的经过,内容比较基础但是真实,主要是记录一下,没有OOM排查经验的同学也可以参考. 现象 我们之前有一个计算作业.最近经常出现不稳定,无法正常响应的情况.具体表现是:各种连接超时,从mysql.mongodb和zookeeper到netty,能超时的都超时过了.其他看不到太多有效的异常. 所以我们首先怀疑的是网络问题,打电话跟运维确认,运维说网络问题的可能性几乎为0,因

线上性能问题初步排查方法

本文首发于并发网,作者:方腾飞 引言 有时候有很多问题只有在线上或者预发环境才能发现,而线上又不能Debug,所以线上问题定位就只能看日志,系统状态和Dump线程,本文只是简单的介绍一些常用的工具,帮助定位线上问题. 问题定位 1: 首先使用TOP命令查看每个进程的情况,显示如下: top - 22:27:25 up 463 days, 12:46, 1 user, load average: 11.80, 12.19, 11.79 Tasks: 113 total, 5 running, 10

线上PHP问题排查思路与实践

前言 前几天,在一淘网,腾讯网媒和微博商业技术联合组织的技术分享大会上,我分享了<在线PHP问题排查思路与实践>.此博文除了对PPT提供下载外,还会对ppt做简单的注释说明.主题分为三部分,常见问题,解决思路和案例分析. 常见问题 不同用户看到的错误可能不一样.一般用户看到的错误都是表层的现象.如,裸奔的错误页面: <img src="http://www.bo56.com/wp-content/uploads/2015/09/luoben.png" alt=&quo

线上Java应用排查和诊断规范

线上Java应用排查和诊断规范 http://www.iteye.com/topic/1132132 标准做法一:OOM触发HeadpDump 目的: OOM发生时,输出堆栈快照文件,供研发人员分析. 在JVM中,如果98%的时间是用于 GC 且可用的 Heap size 不足2%的时候,将抛出 OOM 异常. 配置操作: Resin/Tomcat 配置文件里追加 -XX:+HeapDumpOnOutOfMemoryError ,当 OutOfMemoryException 错误发生时,会自动生