分类 Troubleshooting 相关 下的文章

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

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

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 异步日志 或者其他异步日志;

诊断不正确的 JSONArray 引起的死循环导致 CPU 使用率高

最近有个应用经常 CPU 使用率经常非常高, 一旦升上去, 很难再下来, 除非进行重启. 使用 htop 观察, 出现 CPU 使用率高的并不是一个线程. 然后使用 async-profiler 查看, 发现代码很像死循环, 99%以上的栈都被 JSONArray 初始化占用了:
jsonArray.png

看上去一个很正常的 JSONArray 初始化为什么会占用这么多 CPU 时间呢? 难道是处理的业务较多? 一开始开发人员认为最近的促销导致业务量暴涨导致的. 其实做一个 heap dump 很快发现了事情的元凶.

我们的这段代码是这么写的(这里只是展示基本含义, 没做其它验证):

String str = "some string";
if (str.startWith("[")) {
   new org.codehaus.jettison.json.JSONArray(str);
} else {
   //something else
}

问题就出现在这个 str, 如果它的格式有问题, 不是真正的数组, 那么就会出现问题, 比如下面的代码:

       public static void main(String[] args) {
        String str = "[*/*A25] **";
        try {
            System.out.println("start");
            System.out.println(new JSONArray(str));
            System.out.println("end");
        } catch (JSONException e) {
            e.printStackTrace();
        }
    }

如果 debug 上面的代码, 就会发现出现了死循环, 线程再也无法退出. stuck 在了 JSONTokener L179 ~ 188 -> next() -> back() -> next(). 一直 next(), back().

于是给这个 lib 提了一个 issue: https://github.com/jettison-json/jettison/issues/36

Java 无法 attach 到目标进程, 使用 core dump 转换为 Java heap dump

有时候, 当我们尝试对一个已经 GC overhead 非常高的 Java 应用进程去做 heap dump 的时候, 或者使用 jstack/jcmd 去做 thread dump 的时候, 发现我们跟本没办法 attach 到目标 Java 进程, 得到下面的错误:

/usr/bin/jcmd 7674 GC.heap_dump /tmp/heap.log.hprof
7674:
com.sun.tools.attach.AttachNotSupportedException: Unable to open socket file: target process not responding or HotSpot VM not loaded
at sun.tools.attach.LinuxVirtualMachine.<init>(LinuxVirtualMachine.java:106)
at sun.tools.attach.LinuxAttachProvider.attachVirtualMachine(LinuxAttachProvider.java:63)
at com.sun.tools.attach.VirtualMachine.attach(VirtualMachine.java:213)
at sun.tools.jcmd.JCmd.executeCommandForPid(JCmd.java:140)
at sun.tools.jcmd.JCmd.main(JCmd.java:129)

一般我们会多尝试几次, 期望有哪次可以 attach 到目标 Java 进程, 不过有时候, 尝试好多次都无法达到目的.

除了这种尝试的方法之外, 我们还可以尝试另外一种方式: 先获得目标进程的 core dump, 再从 core dump 转成 Java heap dump.

具体的方法步骤是:

  1. 安装 gcore

    $ sudo apt install gdb -y   #gcore command in gdb package
  2. 设置 core dump 可允许的大小. 通常生产环境的 core dump 都是禁止的, 一方面 core dump 特别大, 占用磁盘比较大, 另外 core dump 可能包含运行时内存的敏感数据. 如果你的生产环境的 core size 是 unlimited 的或者特别大, 可以忽略这步.

    $ sudo cp /etc/security/limits.conf /etc/security/limits.d/   # 复制limits.conf模板文件到配置文件夹
    $ sudo vim /etc/security/limits.d/limits.conf     # 编辑配置文件, 修改我们目标 Java 进程的用户的配置
    #### 我们假设我们的目标进程使用 appUser 运行, 给他设置 core file 的 hard, soft 允许大小
             appUser hard core unlimited
             appUser soft core unlimited
    
    $ sudo su appUser  # 切换到 appUser
    $ ulimit -a        # 查看它的 core file size 的 hard, soft 大小   
    ### 有时候, 即便你改好了, 还是看到 core size 是0, 不过不要悲观, 继续下去, 可以参数 core dump.                                                                         
    $ exit             # 退出 appUser 
  3. 获取 core dump

    $ pgrep java   # 显示查看目标进程的 pid
    $ sudo gcore <pid>     # 使用 gcore 获取 core dump, 根据目标进程的内存占用大小, 可能会花费不同的时间
    ### 有时候使用别的用户, 即使使用 sudo 也不能 ptrace, 会得到 ptrace 无法 attach 的错误, 这时候, 切换到
    ### appUser 用户, 直接 gcore <pid> 就行. 如果报无法写入, 看你在哪个文件夹, 到一个可写的文件夹就好了
    $ ls -lah core.<pid>   # 查看获取的 core dump 的大小, 通常在当前目录
  4. 把 core file 的 hard, soft 修改的配置改回来

    $ sudo rm -f /etc/security/limits.d/limits.conf # 之前我们把模板加到这个文件, 现在删掉
  5. 转换 core dump 到 Java heap dump. 一定要使用运行对应目标进程运行的 JDK.
    如果你是 Hotspot JDK (Oracle 或者 OpenJDK):

    $ find /app -name jmap     # 找到运行目标进程的 JDK 里面的 jmap 命令
    $ sudo /usr/bin/jmap  -dump:format=b,file=heap.hprof  /usr/bin/java ./core.<pid>   #转换

    如果你是 IBM J9 JDK:

    $ find /app -name jextract  # 找到运行目标进程的 JDK 里面的 jextract 命令
    $ jextract core.<pid>       # 从 core dump 转成 heap dump core.<pid>.zip
    ## 对于这个 core.<pid>.zip 使用 MAT 并且安装的 dtfj 插件, 可以打开, 或者使用 IBM JDK 的 jdmpview 工具里 
    ## 面的 heapdump 命令, 可以把 这个 zip 文件转换成 IBM PHD 格式的 heap dump, 然后使用带 DTFJ 插件的 MAT 
    ## 工具分析. 
    $ /usr/bin/jdmpview 
    $ heapdump
    $ ls -lah
    -rw-r--r--  1 root    root    7.5G Aug 21 17:51 core.16751
    -rw-rw-r--  1 user1   user1   926M Aug 21 19:09 core.16751.zip
    -rw-rw-r--  1 user1   user1    19M Aug 21 19:46 core.16751.zip.phd

    到这里, 获取 heap dump 的过程结束, 下面是怎么从 prod 环境复制 heap dump 到本地环境. 你可以选择使用 scp 或者 rsync 复制到本地, 也可以向下面一样, 使用 nc 建立一个下载服务器, 从本地下载.

  6. 设置 nc 下载服务

    $ sudo apt install netcat -y # 若 nc 没有安装, 则安装
    $ sudo nc -4 -v -l 7070 < ./heap.hprof   # 一种 nc 支持这种参数
    $ sudo nc -v -l -p 7070 < ./heap.hprof   # 另外一种支持这种参数
  7. 下载到本地

    1. 使用浏览器访问 http://<;host>:7070/
    2. 或者使用 curl 命令去下载 → curl "http://<host>:7070/" --output heap.hprof
  8. 清理

    $ rm core.<pid>  dump.hprof

    有了 Heap dump, 你就可以使用 MAT 或者 JVisualVM 查看里面的内容了.

诊断一台服务器 CPU 稍微偏高的问题案例

运行同一Java web 应用的一个集群里面, 有台服务器最近 CPU 的使用率持续偏高一些, 其它服务器的 CPU 使用率大概都在5%一下, 而这台服务器却保持在15%左右. 它运行的代码和其它server 的代码一模一样. 另外即便重启应用, 还是一样的问题.
cpualittlehigh.png

那么这台服务器为什么会出现这种问题呢? 首先做了 profiling, 发现它的火焰图和其它服务器的火焰图并无二致. 如果登上机器, 使用 top 命令查看, 明显看到它的 CPU 使用率要相对高一些. 另外, 我们发现这台服务器上的所有的进程的 CPU 使用率相对其它同样服务器高一些.

使用 vmstat 命令, 我们可以看到, 它的 interrupt 和 context switch 明显比其他服务器高:
inter&cs.png

于是进一步查看 /proc/interrupts, 也能明显确认 Rescheduling Interrupts 也明显高(这个是累计, 可以使用 procinfo 查看 per second):
res.png

一般来说, 这种 Interrupts 都是由于某个进程持续不断的发出中断导致的, 这种发出中断的进程要想一只发生中断, 那么它也也要不断的运行, 它的 CPU 使用率也不会太低. 所以经常见的就是排除法 -> shutdown 某个进程, 看系统 CPU 使用率有没有改进. 于是我们尝试了对 CPU 使用率较高的几个进程使用了排除法. 可以仍然没有奏效.

考虑到这个 server 是一个 VM (使用 KVM), 所以我们有进一步查看了同一个 Hypervisor 上面的其它 VM, 发现其它 VM 也有相同的问题, 于是我们转而怀疑问题出现在 Hypervisor 上面.

于是对 Hypervisor 上的进程使用排除法, 实际排除的时候先找最像的. 于是我们找到了这个元凶进程 -> kswapd0:
image2020-8-18_2-4-41.png

从上面截图可以看到这个 kswapd 进程 CPU 使用率并不低, swap 的使用量(used)的是3.9G, 其实最开始发现它的时候是 swap 14个G, 后来截图的时候, 已经通过 swapoff 释放了很多.