协程不是银弹：历时半年，终于搞清了每分钟120次YGC的真相

Ryana
0 阅读15分钟

前言： 该问题现象较为奇怪，特征隐蔽，且基本无规律可循，我们历时半年才最终解决。在这过程中更换过各种思路，例如从现象推理本质，从本质倒推现象等等。

一、背景与问题

1.1 背景

问题出现的背景是，运维同学发现并通知我们某个应用最近出现了数据库慢查询的问题。

img

于是我们看了一下应用最近的数据库查询耗时。

发现max最大确实可能会来到将近15s。

img

至于为什么标题是GC问题，而背景却是慢查询问题，下文将展开说明。

1.2 解决慢sql

我们首先找到出现慢查询的SQL ：

select
    ...
from
    merchant_shelf_ ?
where
    seller_merchant_id = ?
    and item_id = ?

发现是一个简单的查询，用了两个where条件，难道是没有用到索引？

然后查看对应的表结构：

CREATE TABLE `merchant_shelf_0` (
  `id` bigint unsigned NOT NULL COMMENT 'id',
  ...,
  PRIMARY KEY (`id`),
  UNIQUE KEY `uniq_idx_merchant_seller_1` (`seller_merchant_id`,`item_id`,`status`),
  UNIQUE KEY `uniq_idx_merchant_seller_2` (`seller_merchant_id`,`category_id`,`item_id`),
  UNIQUE KEY `uniq_idx_merchant_seller_3` (`seller_merchant_id`,`active_status`,`item_id`,`category_id`)
)

发现该表中存在三个索引，根据最左匹配原则，理论上应能完全命中索引 1。

UNIQUE KEY **uniq_idx_merchant_seller_1** (seller_merchant_id,item_id,status)

那我们试着explain一下 sql

explain select * from seller_shelf_10 where  item_id in ('777741') and seller_merchant_id = '5010'

但是结果发现，该条sql语句并没有使用索引1，而是使用的索引3。

UNIQUE KEY uniq_idx_merchant_seller_3**(seller_merchant_id,active_status,item_id,category_id)

使用索引3的话根据最左匹配原则会导致只有* seller_merchant_id字段能够用到索引，而item_id字段用不到索引。*

这是因为Mysql的服务端在根据查询条件选择使用哪个索引的时候是从多个维度考虑的，而像这种以固定的seller_merchant_id开头的有三个索引，就可能导致没有选择最优的索引。

因此我们可以强制指定索引：

select
    ...
from
    seller_shelf_ ? FORCE INDEX (uniq_idx_merchant_seller_1)
where
    `seller_merchant_id` = ?
    and `item_id` in (?)

1.3 客户端慢查询

上线后，我们发现该操作并未解决问题，线上仍然存在慢查询。这是第一次处理。

联系DBA帮忙排查后发现，我们的慢查询属于客户端慢查询，而非服务端慢查询。

  • 客户端慢查询： 是指从客户端发起 SQL 请求到接收完结果的全流程耗时超阈值，耗时包含网络传输、客户端处理等非数据库执行的开销。一般可能由客户端GC导致。
  • 服务端慢查询： 服务端执行 SQL 语句的耗时（从接收请求到执行完成），只包含数据库内部的执行开销，与网络、客户端无关。一般可能由于单表数量级大、错误使用索引等情况导致。

我们对比一下GC的情况和慢查询出现的情况：

img

img

发现果然是对得上的，基本上每次GC耗时很高的时候，就会导致客户端慢查。因此基本上可以确认是频繁GC导致了慢查询。

因此我们的排查方向就从慢查询转移到了频繁GC的方向。

二、排查历程

该应用是一个Task类型的应用，主要承载Kafka、RocketMq、定时任务等中间件的异步任务。

2.1 关闭大批量数据处理任务

我们首先回顾是否存在大批量数据处理任务，并根据时间区间定位发生 GC 的任务。该任务会大量下载文件并进行处理，产生大量临时对象，可能导致频繁 YGC。

于是我们先停掉该任务进行观察。

img

发现在13号关闭了该任务后，后面三天都没有出现频繁GC的情况。

好景不长，过了一段时间后又发现了慢查询，而此时的GC情况已经达到了一分钟126次。

img

2.2 系统分析

我们首先查看了一下该节点的CPU和内存。

img

其中CPU的突刺为频繁GC带来的，而内存则无明显变化。

其次GC基本上都是YGC，没有FGC，基本上可以排除内存泄漏的问题。

img

此外Eden区、Survivor区、Old区无明显变化。

img

2.3 从现象出发

我们最开始尝试从现象推理本质。

思路是根据出现频繁GC前的时间点，去看各个中间件的调用量是否有上涨。

我们期望能找到一个类似于这样的场景：某个业务在调用量突增后，发现该应用开始频繁GC。

img

事实上，我们也确实发现了某个Kafka的topic在频繁GC之前的调用量突增，并且该topic的处理逻辑也确实比较重。这个几乎就能确认是该topic的问题。

但是为了确认是否真的是这个topic，在下一次出现频繁GC的时候，我们重新观察了这个topic的情况。诡异的是，第二天这个topic确实几乎没有异常波动。

img

像这样的情况，我们当时排查了一周仍然没有明确的结论。

最终不得不选择放弃这条路，考虑的点主要有三个：

  1. 前文提到该应用是Task应用，接入了很多异步中间件，会消费近百个topic以及有几十个定时任务Task。排查起来十分困难，每次出现几乎都要把对应的监控看一遍。
  2. 每次出现问题前的业务并不固定，有可能今天明显是这个Topic导致的频繁GC，而明天却换成了另一个。甚至有时候都找不到是哪个业务带来的问题。
  3. 此外还有一个最重要的点是，监控粒度都是分钟级别，很多因果关系不好确定。例如出现问题时同时会导致RPC调用基本上全量失败，但是因为监控粒度比较粗，在这一分钟内不能确定是调用失败导致的频繁GC还是频繁GC导致的失败。

因此我们最终放弃了从现象出发的路径。

2.4 从本质出发

源码之下，了无秘密 。

既然我们无法从业务现象出发，那我们可以从底层的JVM入手，看看到底是什么业务在频繁地创建对象。

而分析JVM无非有两种方式：

  • 分析GC日志
  • 分析Dump文件

而现在有个难点在于，该应用出现的GC完全没有规律，并且持续时间很短。 想要通过手工dump文件的方式几乎不可能。

img

从图中可以看出GC持续时间非常短，基本上1-2分钟左右，并且时间点非常随机，有时候是上午有时候是半夜。这个时间点需要登录到服务器上并且进行dump内存非常困难，除非有人24小时看守。

因此我们可以选择通过在服务器上部署脚本的方式帮我们去做这件事，主要的实现逻辑为：

  1. 首先获取当前GC的次数
  2. 然后过一定的间隔（例如10S之后）再次获取当前GC次数，并计算增量的GC次数
  3. 检查在这个间隔内产生的GC次数是否大于阈值（例如10秒10次）。
  4. 如果大于该阈值，则说明此时可能已经处于频繁YGC的阶段，那么就执行Dump命令保存此时的JVM内存快照和堆栈信息快照。

我们按照这个逻辑写出的脚本主要代码如下：

# 主监控循环
monitor_loop() {
    while true; do
        # 检查应用是否仍在运行
        if ! ps -p "$PID" > /dev/null; then
            log "应用已停止, 退出监控"
            exit 0
        fi
        
        # 获取当前GC统计
        GC_STATS=$(jstat -gc "$PID" 2>/dev/null | tail -1)
        
        # 检查jstat是否成功
        if [ -z "$GC_STATS" ]; then
            log "警告: 获取GC统计失败! 等待下一周期..."
            sleep "$INTERVAL"
            continue
        fi
        
        # 解析GC统计
        CURRENT_YGC=$(echo "$GC_STATS" | awk '{print $13}')
        
        # 计算YGC增量
        log "上一次GC次数: $LAST_YGC ，本次GC次数: $CURRENT_YGC ，YGC增量: $YGC_DELTA "
        YGC_DELTA=$((CURRENT_YGC - LAST_YGC))
        LAST_YGC=$CURRENT_YGC
​
        # 解析内存使用情况
        HEAP_USED=$(echo "$GC_STATS" | awk '{printf("%.1f", ($3 + $4 + $6 + $8)/1024)}')
        HEAP_MAX=$(echo "$GC_STATS" | awk '{printf("%.1f", ($5 + $7 + $9)/1024)}')
        PERCENT_USED=$(echo "$GC_STATS" | awk '{printf("%.1f", ($3 + $4 + $6 + $8)/($5 + $7 + $9)*100)}' 2>/dev/null)
        
        # 记录监控状态
        if [ -n "$PERCENT_USED" ]; then
            log "YGC增量: $YGC_DELTA | 堆使用: ${HEAP_USED}M/${HEAP_MAX}M (${PERCENT_USED}%)"
        else
            log "YGC增量: $YGC_DELTA | 堆使用: ${HEAP_USED}M/${HEAP_MAX}M"
        fi
        
        # 检查是否超过阈值
        if [ "$YGC_DELTA" -ge "$THRESHOLD" ]; then
            log "警告: YGC增量超过阈值 (${YGC_DELTA} >= ${THRESHOLD})"
            
            if [ "$DUMP_COUNT" -lt "$MAX_DUMPS" ]; then
                # 生成dump文件名
                TIMESTAMP=$(date +%Y%m%d_%H%M%S)
                DUMP_FILE="${DUMP_DIR}/heapdump_${PID}_${TIMESTAMP}_ygc${YGC_DELTA}.hprof"
                THREAD_DUMP="${DUMP_DIR}/threaddump_${PID}_${TIMESTAMP}.txt"
                
                # 创建堆转储
                create_heap_dump "$PID" "$DUMP_FILE"
                
                # 创建线程转储
                create_thread_dump "$PID" "$THREAD_DUMP"
                
                DUMP_COUNT=$((DUMP_COUNT + 1))
                log "当前dump计数: $DUMP_COUNT/$MAX_DUMPS"
            else
                log "已达最大dump次数($MAX_DUMPS), 跳过转储"
            fi
        fi
        
        # 等待下一个监控周期
        sleep "$INTERVAL"
    done
}

2.4.1 GC日志

首先分析GC日志 。

img

我们分析临近的两次日志可以得出两个结论：

  1. 每次GC的原因基本上都是因为Eden区内存不足，而非老年代空间不足、元空间满等其他原因。
  2. 两次GC间隔的时间很短，基本上就间隔了1.2S就触发了下一次GC。

根据第二个结论，我们这个应用的节点配置是16G内存，Eden区大约5.2G，换句话说，我们的应用在1.2S内产生了5.2G的对象。

这个速率还是非常恐怖的。

那么我们根据GC日志可以得出：

该应用确实存在问题，出现频繁GC的原因是Eden区不够用而且其他区域也存在某个任务会在极短时间内产生大量对象。

但是这些产生的对象是什么只能从 dump文件中获取信息。

2.4.2 Dump内存

我们使用JProfiler查看内存快照：

img

可以看到相对来说对象的分布还比较均匀，没有哪个类型的对象特别大。

再点开引用的占用空间最大的类型"byte[]"。

img

同样也发现所有引用byte[]的对象占用比例也十分平均，最大的一个才24%，没有发现某些类型的对象大量占用了byte[]。

因此，我们从dump的内存快照中也没有找到有效的信息。

至此，我们的思路就卡住了。

2.4.3 async-profiler

我们重新梳理一下思路，我们现在就差临门一脚。我们已经知道现在确实是有任务在短时间内创建大量对象，但是通过dump的内存快照的方式不知道或者不好分析这些对象都是什么。

那么我们是不是可以用别的工具呢？

通过询问AI，AI给出了建议我们使用的插件。

async-profiler。

它可以帮我们产生三部分信息：

  1. 统计周期内创建的对象全部数量
  2. 每种对象是由哪行代码创建的，并且这部分对象的数量、占用空间以及比例！
  3. 统计周期内所有对象的类型数量以及占比

img

img

而第二部分正是我们需要的。

因此我们修改了脚本重新检测情况，在发现GC达到阈值时，不再进行dump内存，转而使用分析async-profiler一分钟内所有对象的创建情况。

三、解决问题

3.1 Hive鉴权问题

在经过以上的部署后，我们终于通过async-profiler获得了一份分析报告。

img

该报告中有两个结论：

  1. 在1分钟的统计周期内，通过这个堆栈创建的byte[]数组的大小达到了22GB。 而这个数据和我们之前通过GC观察到的日志是能够对应上的
  2. 我们终于找到了是哪一块代码创建的这些超大对象组。发现这个代码是由Kafka的client包产生的。

其逻辑是Kafka在获取从Hive中同步的MQ消息时，会进行鉴权操作，而每次鉴权操作都会产生一个Token。

我们迅速联系了对应中间件团队的支持同学，确认了上述结论。而该支持同学反馈说获取token的操作可以进行缓存，没必要每次都创建新的Token。

img

这是我们第三次处理问题。

3.2 协程调度问题

同样的好景不长，在使用Token缓存后，发现GC的次数确实是变少了，从之前的每分钟120次到现在的每分钟60次。但是问题仍然没有解决，频率仍然和之前差不多。

img

我们通过检测日志发现确实没有了创建Token的操作，但是会多了一些别的操作。

img

貌似是Kafka的客户端在请求的一些操作。

中间件支持团队反馈可能跟我们开启了协程有关。

我们设置了一个协程的调度参数。

img

这是我们第四次处理。

设置完成之后，我们发现确实有效果。GC次数已经降低到了每分钟25次左右，不出意料的是，仍然还会出现这个问题。

img

3.3 禁用协程

我们最终选择尝试禁用协程。

img

这是我们的第五次处理， 最终，该方案生效了。

img

可以看到在近24小时之内，每个应用的GC次数基本上都在5次以下。而该GC频率已经属于正常的阈值范围了。

四、为什么使用了协程会导致这个问题？

4.1 为什么使用协程时Kafka会有问题

img

如前文所述，Kafka的client在poll消息时会在一分钟内产生远大于22G堆内存的对象，其中一共有3814个样本，平均每个样本占用3.2MB空间，而这肯定是不合理的。

那么问题是出现在单个样本的空间大小上还是数量上呢？

我们可以对比看一下正常情况下一分钟内产生的poll请求数。

img

可以看到两者的单个样本占用空间是差不多的，而数量却多了很多。

也就是说，在使用协程时，Kafka的client会在一分钟内产生将近4000次poll消息的请求。而在正常情况下，不使用协程只会产生78次请求，是后者的48倍之多。

4.2 Kafka拉取消息的策略

为什么使用协程会导致Kafka这么频繁地拉取消息呢？

先看一下Kafka在poll消息的策略。

    public ConsumerRecords<byte[], byte[]> retryIfNeed(KafkaConsumer<byte[], byte[]> kafkaConsumer, AtomicBoolean shutDown) {
        //循环调用数据
        while (true) {
            try {
                //单次拉取消息时最多等待5S
                return kafkaConsumer.poll(SECONDS.toMillis(5));
            } catch (WakeupException e) {
                ...
            } catch (Throwable e) {
                ...            }
        }
    }

首先，Kafka的client在启动时会启动一个线程进入循环，在每次循环中尝试从Broker中拉取数据，而每次拉取数据时有两种情况会返回结果。

  1. 从Broker中拉取到数据可以消费。
  2. 当指定的时长（5s）仍没有拉取到数据则发起下一次请求。
  • 首先针对第一种情况，有没有可能是我们的应用在短时间内一直有消息生产，那么Kafka的client就会一直poll消息？

理论上来说是有可能的，但是从业务实际上来说几乎不可能。

3814 次 / 分钟 ≈ 63.6 次 / 秒，即平均每 15.7ms 就要完成一次「拉取消息（poll）+ 处理消息」的完整循环。这是判断可行性的基础阈值：

若max.poll.records=500（默认值） ：需 Topic 分区的生产速率 ≥ 63.6 次 / 秒 × 500 条 / 次 = 31800 条 / 秒（≈190 万条 / 分钟）；

  • 那么针对第二种情况有没有可能是使用了WISP协程导致没有等待到足够的时间就提前返回了呢？

Wisp 会把线程变成“协程容器”，执行模型是：

协程调度器认为阻塞不可接受* *。

任何潜在阻塞点都可能被 纤程化（coroutinized） 或 以某种方式提前 wakeup

KafkaConsumer 内部依赖“阻塞等待数据”的地方被 Wisp 改写行为。

于是 poll() 不再 sleep 或阻塞，而是：

不断快速返回，没有拿到数据，于是立即再 poll —— 形成 busy-loop 空转* 。*

4.3 问题总结

按照我们现在的思路，之前的问题都是可以解释的了。

首先 ， 在我们没有处理Hive的鉴权问题时，使用WISP会导致产生大量无效的请求对象。而因为请求Hive时需要先获取Token进行鉴权，就会进一步加剧我们的问题。

反映到现象上就是：

每分钟GC超120次。

img

然后我们使用了鉴权的Token缓存，但是因为WISP的问题同样存在，每分钟的GC次数下降到60次左右。

再然后我们调整了协程的轮询等待时间，GC次数下降到25次左右。

img

而最后我们关闭了协程，发现近10天应用的GC次数每分钟都不会超过5次。最终解决问题。

五、总结

5.1 排查思路总结

在本次问题中，我们从最开始的数据库慢查询开始，到后面发现是频繁YGC的问题。但是由于发生的时间比较偶发并且持续时间短，很难保留现场，所以我们使用监控脚本自动dump内存。而在对内存分析时发现并不好用，转而使用了async-profiler定位到了最终是kafka的client和wisp协程不兼容的问题。

5.2 async-profiler

在大对象的场景中，dump的内存快照是比较好用的工具。而在这种对象比较小并且比较分散的情况下，可以考虑使用async-profiler搭配监控脚本的形式分析是什么代码在创建对象。

5.3 修改JVM参数时可以设置对照组

我们之前开启协程是通过修改 JVM 参数实现的，后续可采用灰度修改方式，例如仅修改某个机房的某台机器，观察一段时间确认无异常后再逐步修改其他节点。

avatar
文章
阅读
粉丝