分类 Troubleshooting 相关 下的文章

诊断由于低效的代码引起的 CPU 突然增高

临近大促, 有同事发现某个应用在某些时候 CPU 的使用率很是怪异, 经常在某个水平上持续一段时间. 如下图:
cpu.png

图形看上去像叠罗汉一样, 看上去还很美观 (以后将会有专门的一篇讲各种奇怪的监控图形). 这里来解释一下为什么会出现这种情况: 其实这个是因为这个机器(虚拟机) 有 4 个 CPU 核心, 一旦有一个 CPU 被使用到 100%, 并且持续一段时间, 就会升到将近 25%, 保持一段直线. 若同时有第二个 CPU 被使用到 100%, 那么就保持到将近 50%, 以此类推, 最高到接近 100%. 同样原因, 如果有一个 CPU 从煎熬中解脱, 那么将掉 25% 左右.

一开始, 某个同事做了一段时间的 CPU profiling, 从 profiling 的结果看, CPU 花费在了这段代码上面:

"DefaultThreadPool-24" daemon prio=10 tid=0x00007fa85040e000 nid=0xfee9 runnable [0x00007fa849d4b000]
   java.lang.Thread.State: RUNNABLE
    at java.util.HashMap.get(HashMap.java:421)
    at java.util.Collections$UnmodifiableMap.get(Collections.java:1357)
    at java.util.AbstractMap.equals(AbstractMap.java:460)
    at java.util.Collections$UnmodifiableMap.equals(Collections.java:1394)
    at java.util.ArrayList.indexOf(ArrayList.java:303)
...  省略 ...

当时推测, 是不是又是并发使用 HashMap 导致的死循环?
仔细分析一下, 其实不是, 如果是死循环, 这个线程将永远不会退出来, 除非线程死掉, 可是我们看到某个机器的 CPU 会自动降下来. 于是他又推测, 是不是 HashMap 里面一个 bucket 里面太多了? 如果一个 bucket 里面太多, HashMap 将会根据元素的增多增加 bucket, 所以这也不是.

另外, 通过使用 htop 查看进程的使用情况, 也能看到其实燃烧 CPU 的线程过段时间就变掉.

那么, 如果某个代码某段时间内疯狂循环, 也能把 CPU 加热. 于是, 我们做了 heap dump 查看是不是这种情况. 从 heap dump 看, 上面 stack trace 里面的 ArrayList 有 95733 个元素, 而每个元素都是 HashMap, 每个 HashMap 大概有 10 个元素.
burnCPU.png

这种情况下, 会不会很耗 CPU 呢? 答案是当然: 首先我们看 ArrayList.indexOf() 方法怎么做? 它会遍历每个元素去调用他们的 equals() 方法. 平均对比元素个数为 N/2.

    public int indexOf(Object o) {
        if (o == null) {
            for (int i = 0; i < size; i++)
                if (elementData[i]==null)
                    return i;
        } else {
            for (int i = 0; i < size; i++)
                if (o.equals(elementData[i]))
                    return i;
        }
        return -1;
    }

在看 HashMap 的 equals() 方法: 虽然做了很多快速判断, 但是我们的 case 里大概率还是要每个元素的 key 和 value 都做一次 equals() 对比.

public boolean equals(Object o) {
        if (o == this)
            return true;

        if (!(o instanceof Map))
            return false;
        Map<?,?> m = (Map<?,?>) o;
        if (m.size() != size())
            return false;

        try {
            Iterator<Entry<K,V>> i = entrySet().iterator();
            while (i.hasNext()) {
                Entry<K,V> e = i.next();
                K key = e.getKey();
                V value = e.getValue();
                if (value == null) {
                    if (!(m.get(key)==null && m.containsKey(key)))
                        return false;
                } else {
                    if (!value.equals(m.get(key)))
                        return false;
                }
            }
        } catch (ClassCastException unused) {
            return false;
        } catch (NullPointerException unused) {
            return false;
        }

        return true;
    }

从上面的代码来看, 由于ArrayList 里大量的数据加上每个元素都是 HashMap,最终要花费大量的CPU 时间去做对比, 导致 CPU 在某个时间段过热.

使用 tcpkill 杀掉 tcp 连接

debian/Ubuntu 系列安装 tcpkill

sudo apt install dsniff -y

redhat/CentOS 系列安装 tcpkill

yum -y install dsniff -y

杀掉连接

sudo tcpkill -i eth0 -9 port 50185
sudo tcpkill ip host 10.168.1.1
sudo tcpkill -9 port 32145

查看连接

ss -t

由于频繁 JAXBContext.newInstance 导致应用程序变慢

最近有个应用开始接受一种新的service请求, 请求是由一个 batch 应用触发, 在短时间内产生大量请求, 导致整个应用多个方面出现问题, 比如平均延迟增加, CPU 几乎 100%, GC overhead 在 60% 上下, tomcat 允许的服务线程数达到上限, error 大量增多, timeout 增多.

从已有的数据看, GC overhead 占用 60% 左右, 说明还有 40% 是其它代码占用的. 并且 GC overhead 最终是由引用代码引起的, 从 GC 日志看, heap 总是可以回收, 只是回收慢一些, 说明如果修改了代码的问题, GC 问题大概率会自动修复. 一般由于 transaction time 增加, 会导致停留在内存的短暂数据增加, 导致 GC overhead 升高. 此时, CMS, G1 等 GC 算法之前积累的经验(何时开始回收的时间点) 不适用新的情况.

通过 async-profiler 做出 CPU 的使用火焰图, 发现占用 CPU 40% 的代码绝大部分都是在处理 javax/xml/bind/JAXBContext.newInstance 的事情. 如下:
JAXBContextNewInstance.png

关于为什么 JAXBContext.newInstance 会导致 CPU 比较高的问题, 其实互联网上已经有很多这样的问题: https://www.ibm.com/support/pages/jaxbcontext-initialization-takes-long-time

引用这篇文章里面的:

JAXB context (javax.xml.bind.JAXBContext) object instantiation is a resource intensive operation. JAXB Context instantiation involves the pre-load and pre-creation of contexts (called the pre-caching process) of all packages and classes associated with the context, and then all of the packages and classes which are statically (directly and indirectly) referenced from those. Performance latency will correlate with the number of classes which are passed during JAXB creation during this pre-caching process.

一般对于这种 xxxContext 对象, 都是某个过程, 某个环境只有一个的对象, 对于这个问题当中, 每个请求都尝试创建一个 Request level 的 JAXBContext, 导致应用出现问题.

诊断 mimepull.jar 导致的大量临时文件不能释放的问题

某天某个应用程序的某些服务器突然大量抛出下面异常:

msg=Error executing HystrixCommand 'xxxClient', failureType = COMMAND_EXCEPTION, rootcause=SocketException: Too many open files&st=com.sun.jersey.api.client.ClientHandlerException: java.net.SocketException: Too many open files

很明显, 这个应用打开了太多的文件句柄, 没有关闭. 为了缓解问题, 重启服务器临时解决. 到底哪里出了问题呢? 为什么最近才开始有这种错误? 我们一步步找出事故的原因.

- 阅读剩余部分 -

诊断由于多线程同步写日志竞争引起的上游应用超时

有开发人员抱怨说, 他的应用在某个数据中心有很多超时的错误, 怀疑是不是网络有问题.

SRE 查看了超时的请求, 又查看了提供该服务的应用, 发现在服务提供方有规律的收到大量请求, 一旦请求数量达到一定程度, 它的延时就会增加很多, 如下图:
traffic.png

首先, 我们确定这是跟流量相关的, 一旦流量增加到某个值, 它的 CPU 使用率, GC overhead, latency, 和 忙碌的线程数都同步的增加.

那么最简单的解决方式就是: 加机器. 云计算让加机器变得非常容易.
如果不加机器, 让请求变的更平均, 也是一种方案.

那么有没有可能对服务提供方的代码进行仅仅优化, 就可以满足要求的方式呢?
首先, 我们仔细查看了服务提供方应用的日志, 根据日志, 发现很多情况下, 如果对比流量低的时候, 在某行日志之后总是有大约 1s 的间隔, 这 1s 花费在那里了? 是有好多代码在执行? 还是花费在 I/O 请求上面? 还是花费在 CPU 执行上面?

一开始, 我们怀疑在请求大量增加的情况下, 是不是某些线程池里面的线程不够用了, 先是加了线程池数量, 观察一段时间后, 发现没有效果.
之后, 我们也意识到, 如果是等待线程池, 它的 CPU 不会增加太多, 而我们的观察到的情况是如果流量增加, CPU 使用率增加很多. 那么据此推测, 当流量增加的时候, 有大量的 CPU 消耗.
我们查看了应用的本地日志, 发现该应用大概 1 分钟写 15M 日志. 日志文件里很多线程交叉写的日志, 日志间隔在 1ms 以下, 所以推测, 这里会形成大量的多线程锁竞争.

这些大量的日志都是 warn 级别, 如果我们减少这种 warn 级别, 或者关掉 warn 级别的日志, 会不会有大量提升? 于是, 最简单的办法, 我们修改了日志的级别为 error 级别, 经过一段时间观察, 效果很明显. 于是确定了问题所在.

对于这种问题, 推荐的解决办法是:

  1. 去掉不需要的日志打印;
  2. 设置正确的日志级别;
  3. 把日志改成异步日志, 如 log4j 2.0 异步日志 或者其他异步日志;