CPU负载过高

JVM性能监测 -- mysql connector/j的bug导致jvm占用 100% 

分类： Mysql/postgreSQL

监测发现CPU占用率超高

1. # uptime
2. 09:28:55 up 247 days, 17:19, 1 user, load average: 4.11, 3.99, 3.46

由于是4核CPU，所以负责到4，说明每个核心占用率将近100%。

通过TOP发现是被java虚拟机占用。进程号为7636。

然后通过以下命令采集JVM信息。

1. PID=7636
2. jps -l
3. top -H -p $PID
4. jstack -l $PID > /tmp/jvm_jstack_out_${PID}.txt
5. jstat -gcutil $PID > /tmp/jvm_jstat_gc_out_${PID}.txt
6. jmap -histo:live $PID > /tmp/jvm_jmap_out_${PID}.txt

其中，top -H可以显示线程，从这里可以得到占用CPU高的线程id，然后到jstack的输出中查找。
jstack数据JVM当前线程堆栈。-l可以数据lock的信息。线程id是以16进制显示的，所以需要转换一下（python -c 'hex(7769)'）

查看jstack信息，发现该线程如下。

1. "org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-10" prio=10 tid=0x00007f4599046800 nid=0x1e61 runnable [0x00007f455e6e4000]
2. java.lang.Thread.State: RUNNABLE
3. at java.net.PlainSocketImpl.socketAvailable(Native Method)
4. at java.net.AbstractPlainSocketImpl.available(AbstractPlainSocketImpl.java:478)
5. - locked <0x0000000764908370> (a java.net.SocksSocketImpl)
6. at java.net.SocketInputStream.available(SocketInputStream.java:245)
7. at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:71)
8. at com.mysql.jdbc.util.ReadAheadInputStream.skip(ReadAheadInputStream.java:299)
9. at com.mysql.jdbc.MysqlIO.clearInputStream(MysqlIO.java:948)
10. at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1895)
11. at com.mysql.jdbc.ConnectionImpl.pingInternal(ConnectionImpl.java:4072)
12. at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2626)
13. - locked <0x000000076490c820> (a java.lang.Object)
14. at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2571)
15. at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1464)
16. - locked <0x000000076490c820> (a java.lang.Object)
17. at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:73)
18. at com.mchange.v2.c3p0.impl.DefaultConnectionTester.statusOnException(DefaultConnectionTester.java:143)
19. at com.mchange.v2.c3p0.AbstractConnectionTester.statusOnException(AbstractConnectionTester.java:82)
20. at com.mchange.v2.c3p0.impl.NewPooledConnection.handleThrowable(NewPooledConnection.java:437)
21. - locked <0x00000007648c7bd8> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
22. at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.execute(NewProxyPreparedStatement.java:1003)
23. 。。。
24. at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
25. at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
26. at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
27. at java.lang.reflect.Method.invoke(Method.java:606)
28. at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
29. at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:311)
30. at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:113)
31. at org.quartz.core.JobRunShell.run(JobRunShell.java:206)
32. at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:548)
33. - locked <0x000000074d27be20> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
34. 
    
35. Locked ownable synchronizers:
36. - None

百度得知，这是一个kernel bug引发的mysql connector的bug。
http://bugs.mysql.com/bug.php?id=73053

解决方法是，升级connector到Connector/J 5.1.32 或在数据源配置中设置connection timeout。

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.