写点什么

jTDS 驱动导致 cpu 100%

用户头像
顾五木
关注
发布于: 1 小时前
jTDS 驱动导致 cpu 100%

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 高问题

  • 注意循环语句,大量的循环消耗 cpu,从底层代码找循环语句,粗略计算调用频率和循环次数确定是否可能为问题

  • 死循环导致 cpu 占用高,线程安全问题导致 Hashmap 扩容时形成循环链表

  • 通过show-busy-java-threads脚本定位查看 cpu 高的线程

  • 通过 Arthas 查 cpu 过高的线程

链接

  • show-busy-java-threads

https://github.com/oldratlee/useful-scripts/blob/dev-2.x/bin/show-busy-java-threads

  • Arthas 工具

https://github.com/alibaba/arthas/issues/1202

  • 最后在 github 上给 jTDS 提了个 issue

https://github.com/milesibastos/jTDS/issues/17

用户头像

顾五木

关注

还未添加个人签名 2020.08.22 加入

还未添加个人简介

评论

发布
暂无评论
jTDS 驱动导致 cpu 100%