有开发人员发现他们的某些 server 上的业务时间偶尔变长, 再看 gc overhead 指标, 发现已经超过10%, 怀疑内存泄漏. 通过对 GC 日志的分析, heap dump的分析, 我们找到泄漏的根本原因.

1. 首先看数据趋势, 可以看到业务时间从某个时间点之后变长, CPU 跟着增加, CPU 增加的原因就在于 GC 的耗时增加;
   

2. 看 verbose GC log 的具体日志, 我们可以看到 CMS GC 老年代的频率很高, 耗时也很多. 从34s 到52s 就要做3次老年代的 GC, 说明每次回收都无法获得足够多的空闲内存, 只能加快回收.

   2021-11-17T09:39:34.726-0700: 1459219.285: [CMS-concurrent-mark-start]
   2021-11-17T09:39:37.142-0700: 1459221.701: [CMS-concurrent-mark: 2.408/2.416 secs] [Times: user=2.90 sys=0.04, real=2.42 secs] 
   ...
   2021-11-17T09:39:37.434-0700: 1459221.993: [CMS-concurrent-sweep-start]
   2021-11-17T09:39:39.055-0700: 1459223.614: [CMS-concurrent-sweep: 1.616/1.621 secs] [Times: user=1.90 sys=0.00, real=1.62 secs] 
   2021-11-17T09:39:39.055-0700: 1459223.614: [CMS-concurrent-reset-start]
   2021-11-17T09:39:39.059-0700: 1459223.618: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
   2021-11-17T09:39:41.063-0700: 1459225.622: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1348577K(1433600K)] 1792358K(2170880K), 0.1895637 secs] [Times: user=0.75 sys=0.00, real=0.19 secs] 
   ...
   2021-11-17T09:39:41.253-0700: 1459225.811: [CMS-concurrent-mark-start]
   2021-11-17T09:39:43.632-0700: 1459228.191: [CMS-concurrent-mark: 2.375/2.379 secs] [Times: user=2.84 sys=0.01, real=2.38 secs] 
   2021-11-17T09:39:43.632-0700: 1459228.191: [CMS-concurrent-preclean-start]
   ...
   2021-11-17T09:39:44.000-0700: 1459228.559: [CMS-concurrent-sweep-start]
   2021-11-17T09:39:45.590-0700: 1459230.149: [CMS-concurrent-sweep: 1.590/1.590 secs] [Times: user=1.81 sys=0.01, real=1.60 secs] 
   2021-11-17T09:39:45.590-0700: 1459230.149: [CMS-concurrent-reset-start]
   2021-11-17T09:39:45.594-0700: 1459230.153: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
   ...
   2021-11-17T09:39:52.122-0700: 1459236.681: [CMS-concurrent-mark-start]

3. 捕获一个 heap dump, 从 heap dump 的 leak 分析可以看到 ClassLoader 保持的内存过多, 通常情况下 ClassLoader 只是引用类定义, 但是它可以通过 static 字段引用实例对象. 下面的 ClassLoader 使用了660M+ 内存, 具有很大的可疑. 如果我们不是很确定, 可以有2个办法来确定: 1) 重启服务器, 等服务器稳定运行在做一个 heap dump, 对比二者的这个 ClassLoader 使用的内存数量, 是不是差别比较大. 2) 增大 heap size, 让它一直运行, 直到再出现问题, 这时候这个 ClassLoader 使用的内存会更大.
   
4. 从这个 ClassLoader 出发, 我们找到了对象的聚集地: ClassLoader -> BulkGet*Processer Class -> completionService -> CompletionQueue.
   
5. 那么为什么这个 CompletionQueue 里这么多对象呢? 为什么不能回收?
   原来在代码 BulkGet*Processer 类里面, 定义了一个静态的 CompletionService, 当有 request 要处理的时候, 就把 Task submit 到这个 completionService 里面, 可是这个没有去拿结果. 可是 CompletionService 是要求把结果都要通过 poll 或 take 取出来, 然后才能从 completionQueue 结果集里面去除这个结果. 因为没有去拿这个结果, 结果导致它的 CompletionQueue 的结果越来越多, 最后把老年代占满.

有个内部员工报了一个 issue, 支付成功之后, 弹出支付成功, 可是还能看到 "支付" 按钮. 过一段时间刷新页面, 还仍旧能看到那个"支付"按钮. 找到对应的开发团队, 开发团队检查之后, 发现整体趋势没有看到任何问题, 特地检查他这一笔, 发现有个事件通知的消息没有消费成功. 到底哪里出问题了? 诊断这种问题从架构/设计/实现技术角度有没有更好的办法?

开发团队仔细检查这笔交易, 发现支付成功之后, 有个支付成功的异步消息需要被某个 service 应用A 去消费, 应用A 消费这个消息的时候, 需要调用下游某个应用B, 可是调用应用B 的时候, 应用B 返回了 403, 导致整个事件没有被成功消费. 索性有不断的重试机制, 过了一段使用后这个事件被成功消费了.

那么问题变成了: 为什么一开始应用B 返回 403, 后来又调用成功了呢?

在应用A 的日志里, 能看到应用B 返回了 403, 但是日志里面没有抛出任何 error/Exception, 这导致应用A 里很难过滤并聚集这种错误类型. 同时整个处理的 Transaction 虽然失败了, 没有消费成功, 可是这个业务却没有报任何错误. 这种吃掉异常的错误做法导致有问题很难被发现.

在应用A 的日志里, 虽然有些 403, 但是没有给出更多信息. 通常我们的应用都会返回一个 unique 的 logID, 它能唯一定位整个 site 的唯一条业务的日志, 虽然这个 403 在 header 里返回了这个 logID, 但是却没有打印出来, 导致不能很快定位到有问题的下游日志. 所以, 我们推荐在平时返回 2xx 的时候, 这些 logID 可以不打印日志, 但是一旦非 2xx, 打印出请求的 header & payload 以及 response 的 header & payload 非常重要.

尝试在已知的下游应用的日志里面搜索某些特定 ID 去查找服务端的处理日志, 不断的扩大范围, 总是找不到. 这个时候就想在客户端应用A 这边是不是通过抓 tcp 包的形式, 能抓到具体的 request/response. 通常这些下游应用的 endpoint 都可以通过某些管理页面暴露出来, 可是这个 servcie 调用竟然不遵循常规的协议, 没有暴露出来. 只能尝试通过查看网络连接状态的方式去模糊匹配. 由于这个到下游的连接并不多, 也不是长连接(keep-alive) 导致几乎找不到一个模糊匹配的. 最后通过查看Java 的 DNS 的 history 信息, 模糊匹配到一条记录. 这里我们发现几个问题: 1) 如果请求不是特别少, 使用长连接(keep-alive) 没有什么坏处; 2) 遵循常规的协议, 方便大家按照统一的思路去查问题.

通过对找到的这个 endpoint 的 IP 地址抓包, 我们找到了几条返回 403 请求的 response, response header 里面的 logID 帮助我们很快定位到了下游处理这个请求的日志. 非常奇特的是: 这个服务端的 server 竟然是另外一个 service 的server. 也就是说我们使用的 endpoint 是对的, 不过这个 endpoint 的 LB 后面错误挂了另外一个 service 的 server 去处理这个请求. 所幸的是这个是 http 的请求, 不是 https, 我们抓包很容易就能看到具体的 request/response. 如果是 https, 那么就导致要通过代码注入的方式去观察更多日志了.

到此, 如何导致了这个问题, 从 LB 错配之后基本搞明白. 就是 LB 后边错挂了一个 server, 导致如果命中这个 server 那么就有问题, 否则就是好的. 因为是处理异步事件, 不成功会继续尝试, 只要不是一直命中这个错误的 server, 总归会成功.

获得

1. 有任何错误, 请一定不要吃掉, 请及时报告, 写到日志里面标记出来;
2. 微服务的环境里如果有调用非 2xx 的response, 最好把 request 的 header & payload 以及 response 的 header & payload 都打印出来, 方便查看原因或重试;
3. 如果有共同的规范暴露一些信息, 请遵循特定的规范, 它方便拍错.
4. 大量的微服务, 一定要有办法通过某种方式把日志串起来, 比如通过 logID;
5. 暴露最近查询的 DNS 非常有必要;
6. 可以设置某些开关, 打印出错的更多信息.

收到告警, 发现有个应用里面有 4 台服务器(虚拟,非真实物理服务器)挂了. 幸亏这个服务后面的服务器足够多, 并没有什么影响. 同时去查看这个应用的各项指标, 都是正常. 即使显示挂了的这 4 台, CPU, 内存, tomcat 服务线程, 磁盘等各方面也是正常, 也就是说这 4 台服务器还在不断的主动更新自己的状态, 并且状态良好, 那么为什么检测告警这边认为他们挂了呢?

检测告警服务为什么认为这 4 台服务器挂了?

检测告警这边每分钟都在不断主动检测每台服务器的健康状况, 类似下面的 URL

http://host1.tianxiaohui.com:8080/status/health

每次访问, 总是不能建立连接, 导致检测告警这边认为这几台服务器挂了. 手工测试了一下这个 URL, 确实不能建立连接. 尝试任何其他合理的 URL, 总是不能建立连接.
这个服务根据是否管理端口,是否承接不同的来源的请求等, 实际上开了 4 个 http 端口, 分别是: 8080, 8081, 8082, 8083. 分别对 4 个端口测试, 发现只有 8081 端口还能正常访问. 服务检测只测试 8080, 所以它认为这 4 台服务器挂了.

为什么不能建立 http 连接?

为什么其它 3 个端口不能在连接 http 连接? 我们登上其中 1 台服务器, 查看连接状况, 发现特别多的 CLOSE_WAIT 状态的连接. 表明这些连接对方已经发了 FIN 准备断开, 可是我们服务器的进程这边还没发 FIN, 没有断开连接. 再次查看监听的端口方面, 看到如下的情况:

$ ss -l -t -n
State       Recv-Q       Send-Q     Local Address:Port                Peer Address:Port
LISTEN    101            100           *:8080                           *:*
LISTEN      0            100           *:8081                           *:*
LISTEN    101            100           *:8082                           *:*
LISTEN    101            100           *:8083                           *:*

上面只展示了我们监听的 4 个端口部分, 可以看到我们还在监听(listen) 4 个端口(8080, 8081,8082, 8083).

Send-Q 在 listen 的行表示当我们 open 这个 socket 的时候, 设置的 backlog 大小(参看 java.net.ServerSocket的构造函数). Java 默认值是 50, 可以自己设置, Tomcat 默认设置的值是 100, 也就是我们上面看到的值 100.

Recv-Q 表示 listen backlog 现在的连接数, 它表示 Linux 已经完成了 3 次握手, 从 syn backlog 移到 listen backlog, 可是应用程序还没有取走( accept()), 只能待在 listen backlog. 一旦应用程序(Tomcat)接受这个请求(accept()), 那么这个请求就会从 listen backlog 取走, 进入应用程序待处理队列, 同时 listen backlog 释放出一个位置. 通常你看到的这列的值都是 0, 因为应用处理的足够快, 如果是一个稍大值, 就要担心你的应用了.

从上面的结果看出, 我们的应用有问题, 导致 Recv-Q 满了. 通常情况下, Tomcat 处理 I/O 的线程会接收这个请求, 然后把这个请求放到自己的任务队列里, 然后 tomcat worker 线程会到任务队列去取任务执行. 如果这个 listen backlog 满了, 我们就不能再建立新的 tcp 连接, 就是我们遇到的这种情况. 那么我们的 Tomcat 处理 I/O 的线程到底怎么了?

Tomcat 处理 I/O 的线程怎么了?

当时为了做 RCA 分析, 又不影响服务, 我们选择了做 heap dump, 并且立即重启了服务. 从后面的 heap dump 可以看到, 我们的 8080, 8082, 8083 端口的 Tomcat I/O Acceptor 处理线程不见了, 只有 8081 端口的 I/O Acceptor 线程还活着.

不知道什么原因, 另外 3 个 Tomcat I/O 处理线程 Crash 了. 从其它指标看之前有段时间这 4 台机器发生过OOM, 也许相关, 可是相关的 log 已经被覆盖了.

关于 Linux 上 syn backlog, listen backlog, tomcat 处理队列, 参看: http://www.tianxiaohui.com/index.php/default/Tomcat-7-NIO-handling-request-on-Linux.html

最近遇到多次有依赖的多层子任务共享固定数值的线程池导致业务卡死的问题, 这里简单描述一下这个场景.

如下图所示, 这里有一个请求进来, 它被拆分成 3 个子任务(task0, task1, task2) 分别去执行, 这 3 个子任务都是由一个包含 3 个线程的线程池 Pool_A 去执行. Tomcat 主线程分发完任务之后, 就等待 3 个子任务的完成结果.

同时, 这 3 个子任务由分别每个都派发出 3 个新任务, 所以我们看到 9 个 level 2 层的 sub-task. 同时这 9 个 sub-task 也是交由线程池 Pool_A 去执行.

一种可能产生的如下图的结果是:

1. 当主线程产生 3 个子任务之后, task0, 和 task1 分别获得一个线程来执行, 并且产生了二层的 6 个子任务, 分别是 task0-0, task0-1, task0-2, task1-0, task1-1, task1-2.
2. 这时共有 9 个任务, 其中一层任务 task0, task1 分别在执行, 并且在等他们的下层任务的结果, task3 没有被执行(我们假设任务并不是 FIFO 被执行).
3. 第三个线程从已有的 7 个任务中先后选取了 task0-0, task0-1, task1-0, task1-2 去执行.
4. 接着第三个线程选取了 第一层任务 task2, 然后接着也产生 3 个子任务, 分别是 task2-0, task2-1, task2-2. 然后它也 block 在了等它的 3 个二层子任务完成.
5. 到此, 所有线程池 Pool_A 里面的线程全部被用光, 剩下的子任务没有线程在去执行,大家都变成了死等.

网上有些web工具, 可以分析 Java thread dump, 通常是根据栈的情况作出火焰图, 指出死锁, 根据线程优先级, 线程组的名字做分类. 我在公司内部也做了一个这么一个工具. 基本思路是通过正则表达式匹配各种行, 然后重新组装成栈的模型. 然后做分析报告.
最近 2 天有人抱怨说, 我写的这个工具在分析他们的 thread dump 的时候, 总是报 5xx 内部错误. 于是, 根据提供的 thread dump 去分析原因. 原来这个工具在分析下面一个线程栈的时候, 出错了:

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=4.41ms elapsed=1059.54s tid=0x00007f072ce76000 nid=0x151d in Object.wait()  [0x00007f0704976000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(java.base@11.0.11/Native Method)
    - waiting on <0x00000006c0001478> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(java.base@11.0.11/ReferenceQueue.java:155)
    - waiting to re-lock in wait() <0x00000006c0001478> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(java.base@11.0.11/ReferenceQueue.java:176)
    at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.11/Finalizer.java:170)

   Locked ownable synchronizers:
    - None

具体的出错在识别下面这行的处理中:

- waiting to re-lock in wait() <0x00000006c0001478> (a java.lang.ref.ReferenceQueue$Lock)

为什么处理这行会出错呢?

根据这个栈的信息, 我们可以看到, 栈顶说正在等待这个锁: 0x00000006c0001478, 而下面一行又说 在 wait 里面要 relock 这个锁. 并且是在 remove 方法里面. 这里到底发生了什么事情呢?

重新认识一下最基础的 java.lang.Object 的 wait(), wait(timeout), notify(), notifyAll() 方法

wait 方法表示当前线程主动让出 cpu, 等待其它线程通过 notify()/notifyAll() 方法唤醒, 或者被 inerrupt 唤醒, 或者设置 timeout等着超时唤醒
notify/notifyAll 方法告诉之前让出 CPU 进入 wait 的线程, 你可以醒了.
那么 wait 和 notify 机制的载体是什么呢? 就是 wait 方法和 notify 方法所在的实体对象(object/instance). 更具体一点就是这个实体对象的锁(Monitor).
所以要调用一个实体对象的 wait 方法, 你必须先获得这个实现对象的锁, 否则虽然编译通过, 运行时也会报错. 比如:

try {
  lockObj.wait();
} catch (InterruptedException e) {
  e.printStackTrace();
}

运行时出错:

Exception in thread "main" java.lang.IllegalMonitorStateException
  at java.base/java.lang.Object.wait(Native Method)
  at java.base/java.lang.Object.wait(Object.java:328)

正确的做法是这样:

synchronized (lock) {//获得锁, 如果不能获得, 进入等待队列
  try {
    lock.wait();//释放锁, 进入 sleep 队列, 被 notify 之后, 重新尝试去获得锁
  } catch (InterruptedException e) {
    e.printStackTrace();
  }
}

必须在另外一个线程 notify 上面的等待线程, 否则上面的线程将死等在这. 除非设置timeout 或者被 interrupt. 唤醒代码(这里的 lock 对象就是上面的同一个 lock 对象):

lock.notify(); // 或者 lock.notifyAll()

关于这里的 2 个队列

这里涉及 2 个队列: 1) 该锁对象的等待队列(wait queue); 2) 该锁对象的睡眠队列 (sleep queue);
当一个线程尝试获得某个锁, 而不能获得的时候, 就会进入一个这个锁的等待队列(逻辑上,实际代码实现不一定是队列). 每当等待队列里面的线程获得 CPU 时间片的时候, 它就尝试再去获得一次, 直到获得锁.
当一个线程执行 wait 方法的时候, 它肯定已经获得了这个锁. 虽然获得了这个锁, 可能业务上某个其它条件不满足, 必须等在这里, 而又不能阻碍其它线程获得之前这个锁, 所以, 它进入 wait 方法之后的第一件事就是释放之前已经获得这个锁, 同时当前线程进入一个逻辑上的这个锁的睡眠队列(sleep)队列, 之后这个线程不会被分配 CPU 时间, 直到有 1)有其他线程调用这个锁的 notify/notifyAll 方法, 唤醒它 2) 被 interrupt, 3) 设置了 timeout, 到了超时时间. 当这个线程被唤醒之后, 它首先尝试去获得之前释放的锁, 如果立马获得, 则退出 wait 方法, 继续执行. 否则进入这个锁的等待队列, 在里面排队, 直到再次获得这个锁, 然后从 wait 方法退出, 继续执行.

关于重新获得锁 re-lock

根据上面的描述, 当一个线程被唤醒(notify/notifyAll, 被 interrupt, 或 timeout 到), 它要再次获得这个锁. 所以在这个JDK 的 task (https://bugs.openjdk.java.net/browse/JDK-8130448) 当中, 有人就想把第一次想获得这个锁和进入 wait 方法之后再次获得锁的这 2 种情况区分开来, 于是在 thread dump 中, 就有了 re-lock 这行.

为什么我们遇到的栈里面的 re-lock 不对?

我们可以找出我们看到的情况的源代码(java.lang.ref.ReferenceQueue.remove(long)方法):

    public Reference<? extends T> remove(long timeout)
        throws IllegalArgumentException, InterruptedException
    {
        if (timeout < 0) {
            throw new IllegalArgumentException("Negative timeout value");
        }
        synchronized (lock) {
            Reference<? extends T> r = reallyPoll();
            if (r != null) return r;
            long start = (timeout == 0) ? 0 : System.nanoTime();
            for (;;) {
                lock.wait(timeout);
                r = reallyPoll();
                if (r != null) return r;
                if (timeout != 0) {
                    long end = System.nanoTime();
                    timeout -= (end - start) / 1000_000;
                    if (timeout <= 0) return null;
                    start = end;
                }
            }
        }
    }

从上面的代码可以看出, 该线程已经在 synchronized (lock) { 这行获得了锁, 可是我们从 thread dump 里面读出的是: "waiting to re-lock in wait", 这明显是与事实不符的. 这行应该是获得了锁, 虽然之后释放了.
同时从 lock.wait(timeout) 这行, 我们可以知道, 等到 timeout 或者被唤醒, 这个线程应该要重新获得锁, 所以这里标记为 re-lock 比较合适.
根据这个逻辑, 我们确实找到了有人早就上报了这个问题, 并且已经修复: https://bugs.openjdk.java.net/browse/JDK-8150689. 不过从这个 bug 给出的信息看, 这个 bug 由于是低优先级, 要到 JDK 12 里面才有 fix. 所以我们公司大部分 JVM 都无法有这个修复.