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

监测发现CPU占用率超高

# uptime
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信息。

PID=7636
jps -l
top -H -p $PID
jstack -l $PID > /tmp/jvm_jstack_out_${PID}.txt
jstat -gcutil $PID  > /tmp/jvm_jstat_gc_out_${PID}.txt
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信息，发现该线程如下。

"org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-10" prio=10 tid=0x00007f4599046800 nid=0x1e61 runnable [0x00007f455e6e4000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAvailable(Native Method)
at java.net.AbstractPlainSocketImpl.available(AbstractPlainSocketImpl.java:478)
- locked <0x0000000764908370> (a java.net.SocksSocketImpl)
at java.net.SocketInputStream.available(SocketInputStream.java:245)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:71)
at com.mysql.jdbc.util.ReadAheadInputStream.skip(ReadAheadInputStream.java:299)
at com.mysql.jdbc.MysqlIO.clearInputStream(MysqlIO.java:948)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1895)
at com.mysql.jdbc.ConnectionImpl.pingInternal(ConnectionImpl.java:4072)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2626)
- locked <0x000000076490c820> (a java.lang.Object)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2571)
at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1464)
- locked <0x000000076490c820> (a java.lang.Object)
at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:73)
at com.mchange.v2.c3p0.impl.DefaultConnectionTester.statusOnException(DefaultConnectionTester.java:143)
at com.mchange.v2.c3p0.AbstractConnectionTester.statusOnException(AbstractConnectionTester.java:82)
at com.mchange.v2.c3p0.impl.NewPooledConnection.handleThrowable(NewPooledConnection.java:437)
- locked <0x00000007648c7bd8> (a com.mchange.v2.c3p0.impl.NewPooledConnection)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.execute(NewProxyPreparedStatement.java:1003)
。。。
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:311)
at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:113)
at org.quartz.core.JobRunShell.run(JobRunShell.java:206)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:548)
- locked <0x000000074d27be20> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

Locked ownable synchronizers:
- None

百度得知，这是一个kernel bug引发的mysql connector的bug。


解决方法是，升级connector到Connector/J 5.1.32

或在数据源配置中设置connection timeout。