JVM性能监测 -- mysql connector/j的bug导致jvm占用 100%
监测发现CPU占用率超高
由于是4核CPU,所以负责到4,说明每个核心占用率将近100%。
通过TOP发现是被java虚拟机占用。进程号为7636。
然后通过以下命令采集JVM信息。
其中,top -H可以显示线程,从这里可以得到
占用CPU高的线程id,然后到jstack的输出中查找。
jstack数据JVM当前线程堆栈。-l可以数据lock的信息。线程id是以16进制显示的,所以需要转换一下( python -c 'hex(7769)')
查看jstack信息,发现该线程如下。
百度得知,这是一个kernel bug引发的mysql connector的bug。
http://bugs.mysql.com/bug.php?id=73053
分类: Mysql/postgreSQL
- # uptime
- 09:28:55 up 247 days, 17:19, 1 user, load average: 4.11, 3.99, 3.46
通过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
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。
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.