jTDS 驱动导致 cpu 100%
保存线上环境相关信息
需要保存的线上环境信息
线程栈信息，连续 dump 3~5 次，使用命令：jstack -l pid，也可通过show-busy-java-threads 保存线程信息
内存空间使用信息, 使用命令：jmap -heap pid
内存中每个类的对象占用大小和实例数排序, 使用命令：jmap -histo:live pid
gc 信息：jstat -gcutil pid interval count 例如：jstat -gcutil 18756 1000 10
分析线上环境信息
分析线程日志
"qtp1434669784-7501" prio=10 tid=0x00007f9c8c00c800 nid=0x9c0 runnable [0x00007f9bd0c52000] java.lang.Thread.State: RUNNABLE at java.lang.String.regionMatches(String.java:1363) at java.lang.String.equalsIgnoreCase(String.java:1119) at net.sourceforge.jtds.jdbc.JtdsResultSet.findColumn(JtdsResultSet.java:976) at net.sourceforge.jtds.jdbc.JtdsResultSet.getTimestamp(JtdsResultSet.java:1319) at net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy.getTimestamp(ResultSetSpy.java:343) at com.alibaba.druid.filter.FilterChainImpl.resultSet_getTimestamp(FilterChainImpl.java:1258) at com.alibaba.druid.filter.FilterAdapter.resultSet_getTimestamp(FilterAdapter.java:1829) at com.alibaba.druid.filter.FilterChainImpl.resultSet_getTimestamp(FilterChainImpl.java:1254) at com.alibaba.druid.filter.FilterAdapter.resultSet_getTimestamp(FilterAdapter.java:1829) at com.alibaba.druid.filter.FilterChainImpl.resultSet_getTimestamp(FilterChainImpl.java:1254) at com.alibaba.druid.proxy.jdbc.ResultSetProxyImpl.getTimestamp(ResultSetProxyImpl.java:740) at com.alibaba.druid.pool.DruidPooledResultSet.getTimestamp(DruidPooledResultSet.java:365) at org.hibernate.type.TimestampType.get(TimestampType.java:30) at org.hibernate.type.NullableType.nullSafeGet(NullableType.java:163) at org.hibernate.type.NullableType.nullSafeGet(NullableType.java:154) at org.hibernate.type.AbstractType.hydrate(AbstractType.java:81) at org.hibernate.persister.entity.AbstractEntityPersister.hydrate(AbstractEntityPersister.java:2101) at org.hibernate.loader.Loader.loadFromResultSet(Loader.java:1380) at org.hibernate.loader.Loader.instanceNotYetLoaded(Loader.java:1308) at org.hibernate.loader.Loader.getRow(Loader.java:1206) at org.hibernate.loader.Loader.getRowFromResultSet(Loader.java:580) at org.hibernate.loader.Loader.doQuery(Loader.java:701) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236) at org.hibernate.loader.Loader.doList(Loader.java:2213) at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2104) at org.hibernate.loader.Loader.list(Loader.java:2099) at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:94) at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1569) at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283) at org.springframework.orm.hibernate3.HibernateTemplate$36.doInHibernate(HibernateTemplate.java:1065) at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:419) at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374) at org.springframework.orm.hibernate3.HibernateTemplate.findByCriteria(HibernateTemplate.java:1055) at org.springframework.orm.hibernate3.HibernateTemplate.findByCriteria(HibernateTemplate.java:1048) at ...org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:599) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:534) at java.lang.Thread.run(Thread.java:662)
复制代码
寻找可疑点
分析线程日志，大部分 RUNNABLE 线程都在执行 java.lang.String.regionMatches(String.java:1363) 方法
public boolean equalsIgnoreCase(String anotherString) { return (this == anotherString) ? true : (anotherString != null) && (anotherString.count == count) && regionMatches(true, 0, anotherString, 0, count); }
public boolean regionMatches(boolean ignoreCase, int toffset, String other, int ooffset, int len) { char ta[] = value; int to = offset + toffset; char pa[] = other.value; int po = other.offset + ooffset; // Note: toffset, ooffset, or len might be near -1>>>1. if ((ooffset < 0) || (toffset < 0) || (toffset > (long)count - len) || (ooffset > (long)other.count - len)) { return false; } while (len-- > 0) { char c1 = ta[to++]; char c2 = pa[po++]; if (c1 == c2) { continue; } if (ignoreCase) { // If characters don't match but case may be ignored, // try converting both characters to uppercase. // If the results match, then the comparison scan should // continue. char u1 = Character.toUpperCase(c1); char u2 = Character.toUpperCase(c2); if (u1 == u2) { continue; } // Unfortunately, conversion to uppercase does not work properly // for the Georgian alphabet, which has strange rules about case // conversion. So we need to make one last check before // exiting. if (Character.toLowerCase(u1) == Character.toLowerCase(u2)) { continue; } } return false; } return true; }
复制代码
疑问：String::equalsIgnoreCase 是一个简单的方法，执行速度应该非常快，为什么大部分线程在执行这个方法？难道是 JDK 的String::equalsIgnoreCase方法有性能问题？
前辈的经验告诉我们，JDK 封装的方法 99.99% 不会有问题。猜测可能是使用的姿势不对，或者上层调用方法频率太高。从 at java.lang.String.equalsIgnoreCase(String.java:1119) 往方法调用链上找。
当问题是 cpu 高时，遇到循环语句就需要格外注意了， 找到上层方法at net.sourceforge.jtds.jdbc.JtdsResultSet.findColumn(JtdsResultSet.java:976) 里面有 for 循环。
public class JtdsResultSet implements ResultSet { /** Cache to optimize findColumn(String) lookups */ private HashMap columnMap; public int findColumn(String columnName) throws SQLException { checkOpen();
if (columnMap == null) { columnMap = new HashMap(columnCount); } else { Object pos = columnMap.get(columnName); if (pos != null) { return ((Integer) pos).intValue(); } }
// Rather than use toUpperCase()/toLowerCase(), which are costly, // just do a sequential search. It's actually faster in most cases. for (int i = 0; i < columnCount; i++) { if (columns[i].name.equalsIgnoreCase(columnName)) { columnMap.put(columnName, new Integer(i + 1));
return i + 1; } }
throw new SQLException(Messages.get("error.resultset.colname", columnName), "07009"); }}
复制代码
调试代码发现这里 columnMap 原本是为了缓存下数据库列名对应的 index ，但是放入缓存 columnMap.put(columnName, new Integer(i + 1)) 的时机不对，因为每次执行 sql 返回结果集都会生成 JtdsResultSet 对象。
由于项目里面涉及到大量高频使用的数据库表都是列比较多的大表，并且通常查所有列，很多表有 500 个字段左右。每次多执行 500 X 500/2 = 125,000 次 ``String::equalsIgnoreCase
验证怀疑点
修改怀疑的问题点
将 JtdsResultSet 类的代码改为第一次 调用 findColumn 时将所有列名和对应的 index 放入 columnMap 中，后面再调用 findColumn 方法时直接从 columnMap 中取，循环次数变为了 N（表的列数），从 Map 里面取时间复杂度约等于 O(1)。这里由于项目里面数据库字段名全是“大写字符”，就没有去兼容小写了。
public class JtdsResultSet implements ResultSet { /** Cache to optimize findColumn(String) lookups */ private HashMap columnMap; public int findColumn(String columnName) throws SQLException { checkOpen();
if (columnMap == null) {// init cache columnMap = new HashMap(columnCount); for (int i = 0; i < columnCount; i++) { columnMap.put(columns[i].name, new Integer(i + 1)); } }
Object pos = columnMap.get(columnName); if (pos != null) { return ((Integer) pos).intValue(); }
// Bottom-up plan // Rather than use toUpperCase()/toLowerCase(), which are costly, // just do a sequential search. It's actually faster in most cases. for (int i = 0; i < columnCount; i++) { if (columns[i].name.equalsIgnoreCase(columnName)) { columnMap.put(columnName, new Integer(i + 1));
return i + 1; } }
throw new SQLException(Messages.get("error.resultset.colname", columnName), "07009"); }}
复制代码
验证
测试环境测试后，代码更新到线上环境验证，经过几天的观察 cpu 比较稳定，问题解决。
总结
排查问题优先
上层应用代码与底层代码，优先排查是否上层应该代码有问题
自己写的代码与同事的代码，优先排查是否同事的代码导致有问题（自信，如果遇到大佬的代码还是先查自己的代码）
公司的代码与知名第三方 jar 包，优先查公司的代码
知名第三方 jar 包里面的代码与 jdk 源码，优先查第三方 jar 包
同事的代码 > 自己的代码 > 知名第三方 jar 包 > jdk 源码
如何查 cpu 高问题
链接
https://github.com/oldratlee/useful-scripts/blob/dev-2.x/bin/show-busy-java-threads
https://github.com/alibaba/arthas/issues/1202
https://github.com/milesibastos/jTDS/issues/17
评论