分类 Troubleshooting 相关 下的文章

诊断不正确的 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 释放了很多.

Apache HttpClient 连接池泄漏诊断思路

经常在线上看到一些应用直接因为连接池无法获得连接, 导致整个应用不在响应任何请求. 常见的有数据库连接池连接泄漏, Http 连接池泄漏. 对于这种连接泄漏的问题, 一般是应用没有考虑到某些特殊情况, 特殊异常的处理导致不能用完之后返回连接到连接池. 这里就针对 Apache HttpClient 连接池泄漏这种清楚, 分析一下基本的求解思路.

- 阅读剩余部分 -