linux内核3.6版本及以下的bug引发的故障--cpu使用率100%

Posted 2020-10-02 刨根问底_liang

现象： 
        旗舰店运价库cpu使用率100%，load升高，导致后续的请求失败。 
        重启服务器，cpu、load恢复正常。

触发条件： 
       （1）linux内核3.6版本及以下。 （线上机器大部分是2.6.32）
       （2）mysql-connector-java5.1.31版本及以下。（各业务线需要自己check）
       （3）mysql-client没有设置socketTimeout。 （各业务线需要自己check）
       （4）杀死mysql-server与mysql-client的连接处于mysql-server端的线程。 (dba经常会杀死慢查询)
        当（1）（2）（3）同时具备，只要触发（4），客户端连接线程就会死循环。杀死一个mysql-server端线程，客户端就会死循环一个，占用一个cpu内核。

具体原因：

    Linux kernels version 3.6 and earlier (including 2.6.32) have a bug [1] which makes requests for the amount of available bytes to read in a socket in CLOSE_WAIT state to return 1 even after the EOF has been read.

    This bug makes SocketInputStream.available return 1 for sockets in CLOSE_WAIT state and causes a seemly infinite loop in MysqlIO.clearInputStream where it attempts to read from the socket until the number of available bytes reaches 0, but there is nothing to read.

         出处：  https://bugs.mysql.com/bug.php?id=73053

mysql官网5.1.32版本的变更记录，有提到这个bug：

        A bug in the Linux kernel version 3.6 and earlier caused the MysqlIO.clearInputStream() method to enter an endless loop. This fix changes the way the looping condition is evaluated, in order to avoid the problem. (Bug #19022745, Bug #73053)

        出处：https://dev.mysql.com/doc/relnotes/connector-j/5.1/en/news-5-1-32.html

mysql高版本（已兼容linux低版本内核的bug），附截图：

       

解决方案: 
      （1）升级mysql-connector-java版本到5.1.32及以上。 或者
      （2）升级linux内核版本到3.7及以上。                         或者
      （3）客户端设置socket读超时时间。（杀死server端线程，客户端线程立马释放，没有到达超时时间。为什么能生效，不是很清楚，有知道的可以回复邮件） 
       推荐使用（1）

当时分析问题的线程栈信息如下： 
      at java.net.PlainSocketImpl.socketAvailable(Native Method)
      at java.net.AbstractPlainSocketImpl.available(
      AbstractPlainSocketImpl.java:478)
      - locked <0x000000070ed04a40> (a java.net.SocksSocketImpl)
      at java.net.SocketInputStream.available(SocketInputStream.java:245)
      at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:72)
      at com.mysql.jdbc.util.ReadAheadInputStream.skip(ReadAheadInputStream.java:300)
      at com.mysql.jdbc.MysqlIO.clearInputStream(MysqlIO.java:948)
      at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2404)
      at com.mysql.jdbc.ConnectionImpl.pingInternal(Unknown Source)
      at com.mysql.jdbc.ConnectionImpl.execSQL(Unknown Source)
      - locked <0x000000070ed04c10> (a com.mysql.jdbc.JDBC4Connection)  
     at com.mysql.jdbc.ConnectionImpl.execSQL(Unknown Source)
     at com.mysql.jdbc.StatementImpl.execute(Unknown Source)
     - locked <0x000000070ed04c10> (a com.mysql.jdbc.JDBC4Connection)
     at com.mysql.jdbc.StatementImpl.execute(Unknown Source)

查问题的过程：
       1. 重启机器，cpu使用率恢复正常。 但是保留一台机器做现场。
       2. 使用jstack命令与top命令分析现场机器，发现执行时间长和cpu使用率高的线程，死循环在MysqlIO.clearInputStream()。
       3. 在网上查阅资料，发现是linux内核3.6版本及以下的bug导致。 但是不知道怎么触发。
       4. 询问dba，当时dba在杀死mysql-server端的慢查询，时间是吻合的。 猜测触发条件之一是，杀死mysql-server与mysql-client的连接 处于mysql-server端的线程。

复现过程：
       1. 使用内核版本2.6.32的linux部署应用服务，应用服务使用的mysql-connector-java版本为5.1.21, mysql-client没有设置socketTimeout。 （与线上环境一致）
       2. 更改应用服务里的sql语句，其实是增加了休眠，方便能在mysql-server端查看此线程。 sql语句由select... 变为 select sleep(10) ...
       3. 调用http接口，触发测试的查询语句。
       4. 登录mysql-server，使用命令 show processlist; 查看测试的查询语句，得到线程id。 kill + 线程id， 杀死正在执行的线程。
       5. 应用服务器，cpu其中1核使用率达到100%， 并且http接口，一直没有响应返回（应用服务器线程死循环了）。
       6. 重复步骤（3）、（4），每杀死mysql-server端的一个线程，cpu的一个核使用率就会达到100%。

 

       注意：如果应用服务器 打过补丁tcp: fix FIONREAD/SIOCINQ， 无法复现。   

解决方案确定的过程：
       1. 升级mysql-connector-java版本到5.1.34，其他条件不变。 杀死mysql-server端的线程，应用服务器cpu没有变化，http接口响应立马返回。
       2. 升级linux内核版本到3.18.48，其他条件不变。 杀死mysql-server端的线程，应用服务器cpu没有变化，http接口响应立马返回。
       3. 设置mysql-client端超时时间2分钟，其他条件不变。 杀死mysql-server端的线程，应用服务器cpu没有变化，http接口响应立马返回。没有等到2分钟超时，http接口响应才返回。