关于java:记一次接口慢查排查

本篇文章记录了一次接口慢查问题排查过程，该问题产生的景象迷惑性较高。同时因为问题偶发性高，排查难度也比拟大。排查过程从 druid 数据源“导致”的一个慢查景象作为切入点，逐渐剖析，排除诸多可能性后仍无解。之后从新扫视故障景象，换个角度剖析，找到了问题根因。最初对问题起因进行了验证确认，后果合乎预期。到此，排查过程算是完结了，本文对问题进行记录归档。

前段时间收到业务共事反馈，说他们利用的某台机器间断两天多个接口呈现了两次慢查状况（偶发性较高）。但持续时间比拟短，但很快又复原了。Pinpoint 调用链信息如下：

图 1：长 RT 接口调用链信息

上图是业务同学反馈过去的信息，能够看出从 MyBatis 的 SqlSessionTemplate#selectList 办法到 MySQL 的 ConnectionImpl#prepareStatement 办法之间呈现了 2111 毫秒的距离，正是这个距离导致了接口 RT 升高。接下来针对这个景象进行剖析。

从全链路追踪零碎给出的链路信息来看，问题的起因仿佛很显著，就是 selectList 和 prepareStatement 之间存在着长耗时的操作。实践上只有查出哪里呈现了长耗时操作，以及为什么产生，问题就解决了。于是先不管三七二十一，间接剖析 MyBatis 的源码吧。

public class SimpleExecutor extends BaseExecutor {public <E> List<E> doQuery(MappedStatement ms, Object parameter, RowBounds rowBounds, ResultHandler resultHandler, BoundSql boundSql) throws SQLException {
        Statement stmt = null;
        try {Configuration configuration = ms.getConfiguration();
            StatementHandler handler = configuration.newStatementHandler(wrapper, ms, parameter, rowBounds, resultHandler, boundSql);
            stmt = prepareStatement(handler, ms.getStatementLog());    // 预编译
            return handler.<E>query(stmt, resultHandler);
        } finally {closeStatement(stmt);
        }
    }
 
    private Statement prepareStatement(StatementHandler handler, Log statementLog) throws SQLException {
        Statement stmt;
        Connection connection = getConnection(statementLog);    // 获取数据库连贯
        stmt = handler.prepare(connection, transaction.getTimeout());    // 执行预编译
        handler.parameterize(stmt);
        return stmt;
    }
}

MyBatis 的 SqlSessionTemplate#selectList 办法的调用链比拟长，这里就不一一剖析，感兴趣能够看一下我三年前的文章 MyBatis 源码剖析 – SQL 的执行过程。SqlSessionTemplate#selectList 最终会执行到 SimpleExecutor#doQuery，该办法在执行后续逻辑前，会先调用 SimpleExecutor#prepareStatement 进行预编译。prepareStatement 办法波及到两个内部操作，一个是获取数据库连贯，另一个是执行调用 MySQL 驱动相干办法执行预编译。

从图 1 的监控上看，预编译速度很快，能够确定预编译没有问题。当初，把注意力移到 getConnection 办法上，这个办法最终会向底层的 druid 数据源申请数据库连贯。druid 采纳的是生产者消费者模型来保护连接池，更具体的介绍参考我的另一篇文章。如果连接池中没有可用连贯，这个时候业务线程就会期待 druid 生产者创立连贯。如果生产者创立连贯速度比较慢，或者沉闷连接数达到了最大值，此时业务线程就必须期待了。好在业务利用接了 druid 监控，咱们能够通过监控理解连接池的状况。

图 2：druid 监控图

上图是用 excel 绘制的，数据通过编辑，与过后状况存在肯定的偏差，但不影响后续的剖析。从监控上来看，连接池中的闲暇连贯全副被借出去了，但依然不够，于是生产者不停的创立连贯。这里引发了咱们的思考，为什么沉闷连接数会忽然回升这么多？可能是呈现了慢查。与此同时，业务线程的期待次数和等待时间大幅上涨，这阐明 druid 连贯生产者的“产能”仿佛有余，以至于局部业务线程呈现了期待。什么状况下生产者创立连贯会呈现问题呢？咱们过后思考到的状况如下：

网络呈现了提早或者丢包，造成重传
阿里云 RDS 实例负载很高，无奈及时响应客户端的连贯建设申请

先说第二种状况，RDS 负载的问题很好确认，阿里云上有 RDS 的监控。咱们确认了两次问题产生时的监控曲线，发现实例负载并不高，没有显著稳定，所以状况二能够排除。那状况一呢，网络会不会呈现问题呢？这个猜测不好排除。起因如下：

沉闷连接数失常状况下会很低，暴涨个别都不是失常景象。如果一个 Java 线程从收回 SQL 申请到收到数据耗时 5ms，那么一条连贯能够达到 200 的 QPS。而这个单机 QPS 还有余 200，不应该用掉这么多连贯，除非呈现了慢查。然而咱们用阿里云的 SQL 洞察服务里也没发现慢 SQL，因而能够排除掉慢查的可能性。不是慢查，仿佛只能甩锅给网络了，肯定是过后的网络（接锅好手）出了问题。

如果真是网络出问题了，那么 druid 生产者“产能”有余的问题仿佛也能失去正当的解释。然而通过咱们的剖析，发现了一些矛盾点，如下：

图 3：某个长 RT 申请的链路追踪数据

从链路数据上来看，SQL 的预编译和执行工夫都是很快的，没有呈现显著的等待时间。如果说下面的状况是偶尔，然而咱们翻看了很多链路数据，都发现 SQL 的预编译和执行速度都很快，不存在显著的提早。因而，把锅甩给网络是不适合的。

排查到这里，思路断了。首先没有发现慢查，其次数据库资源也是短缺的，最初网络仿佛也没问题。都没有问题，那问题出在哪里呢？

首先查看了问题机器的 QPS，发现没有突发流量。虽有肯定稳定，但总体依然安稳。

图 4：QPS 折线图

接着看了利用的 CPU 使用率，发现了一点问题，使用率忽然回升了很多。

图 5：CPU 使用率折线图

询问了业务同学，这个点没有定时工作，QPS 与以往类似，没有什么异样。目前不晓得 CPU 为什么会忽然回升这么多，这个信息临时无奈提供无效的帮忙，先放着。最初再看一下网络 I/O 监控。

图 6：网络流量监控图

入站流量与出站流量在问题产生时间段内都呈现了回升，其中出站流量上升幅度很大，阐明过后应该有大量的数据收回去。但具体是哪些接口的行为，目前还不晓得。

接着剖析了一下业务日志，咱们发现了一些 WARN 级别信息：

# 业务线程打出的 WARN 日志，示意期待连贯超时，重试一次
2021-07-20 09:56:42.422 [DubboServerHandler-thread-239] WARN  com.alibaba.druid.pool.DruidDataSource [DruidDataSource.java:1400] - get connection timeout retry : 1
2021-07-20 09:56:42.427 [DubboServerHandler-thread-242] WARN  com.alibaba.druid.pool.DruidDataSource [DruidDataSource.java:1400] - get connection timeout retry : 1
2021-07-20 09:56:42.431 [DubboServerHandler-thread-240] WARN  com.alibaba.druid.pool.DruidDataSource [DruidDataSource.java:1400] - get connection timeout retry : 1

# Dubbo TimeoutFilter 答疑超时日志
2021-07-20 09:56:42.432 [DubboServerHandler-thread-254] WARN  org.apache.dubbo.rpc.filter.TimeoutFilter [TimeoutFilter.java:60] -  [DUBBO] invoke time out. method: xxx arguments: [yyy] , url is dubbo://172.***.***.***:20880/****
2021-07-20 09:56:42.489 [DubboServerHandler-thread-288] WARN  org.apache.dubbo.rpc.filter.TimeoutFilter [TimeoutFilter.java:60] - [DUBBO] invoke time out. method: **** arguments: [***, ***] , url is dubbo://172.***.***.***:20880/****

这两种日志说实话没什么用，因为这些日志是后果，本就应该产生的。除了 WARN 信息，业务日志里找不到任何异样信息。须要阐明的是，咱们并没有设置业务线程获取连贯重试次数，默认重试次数是 0。但这里却进行了一次重试，而咱们预期是业务线程在指定工夫内获取连贯失败后，应抛出一个 GetConnectionTimeoutException 异样。这个应该是 druid 的代码有问题，我给他们提了一个 issue (#4381)，然而没人回复。这个问题修复也很简略，算是一个 good first issue，有趣味的敌人能够提个 Pull Request 修复一下。

业务日志没有太多可用信息，咱们持续寻找其余的线索，这次咱们从 JVM 监控里发现了端倪。

问题产生的那一小段时间内，JVM 产生了屡次的 YGC 和 FGC，而且局部 GC 的耗时很长。

图 7：GC 次数与耗时监控

那么当初问题来了，GC 是起因还是后果？因为 GC 产生的工夫与接口慢查呈现的工夫都在 9.56:30 之后，工夫上大家是重叠的，谁影响了谁，还是相互影响，这都是不分明的。GC 的引入仿佛让排查变得更为简单了。

到这里信息收集的差不多了，然而问题起因还是没有推断进去，非常郁闷。

如果咱们依然从 druid 这个方向排查，很难查出起因。工夫贵重，当初要综合收集的信息从新思考一下了。既然产生了 GC，那么利用的内存耗费肯定是回升了。再综合网络 I/O 的状况，短时间内呈现了比拟大的稳定，如同也能阐明这个状况。但过后网络流量并不是特地大，仿佛还不足以引发 GC。支撑力有余，先放一边。另外，利用的 QPS 没有多大变动，然而 CPU 负载却忽然回升了很多。加之几次 GC 的耗时很长，搞不好它们俩之间有关联，即长时间的 GC 导致了 CPU 负载回升。目前，有两个排查方向，一个是从网络 I/O 方向排查，另一个是从 GC 方向排查。就景象而言，GC 的问题仿佛更大，因而后续抉择从 GC 方向排查。

JVM 进行 GC，阐明内存使用率肯定是下来了。内存回升是一个累积过程，如果咱们把排查工夫从产生长耗时 GC 的时刻 9:57:00 向前推一分钟，没准会发现点什么。于是我到全链路追踪平台上按耗时倒序，拉取了问题利用在 9:56:00 这一分钟内的长 RT 接口列表，发现耗时靠前的十几个都是 queryAll 这个办法。如下：

图 8：queryAll 办法耗时倒序列表

咱们看一下耗时最长申请的调用链信息：

图 9：耗时最长申请的链路信息

首先咱们能够看到 MySQL 驱动的 execute 执行工夫特地长，起因前面剖析。其次 redis 缓存的读取耗时十分短，没有问题。但 redis 客户端写入数据耗时十分长，这就很不失常了。

于是立刻向利用开发要了代码权限，剖析了一下代码。伪代码如下：

public XxxService {

    // 备注：该办法缓存实际上应用了 Spring @Cacheable 注解，而非显示操作缓存
    public List queryAll(int xxxId) {
        // 1、查看缓存，命中则立刻返回
        List xxxDTOs = customRedisClient.get(xxxId);
        if (xxxDTOs != null) return list;
        
        // 2、缓存未命中，查询数据库
        List xxxDOs = XxxDao.queryAll(xxxId);
        xxxDTOS = convert(xxxDOs)
        
        // 3、写入缓存
        customRedisClient.set(xxxId, xxxDTOs, 300s);
        return list;
    }
}

代码做的事件非常简单，那为什么会耗时这么多呢？起因是这样的，如果缓存生效了，queryAll 这个办法一次性会从数据库里取出上万条数据，且表构造蕴含了一些简单的字段，比方业务规定，通讯地址等，所以单行记录绝对较大。加之数据取出后，又进行了两次模型转换（DO → DTO → TO），转换的模型数量比原始模型数量要多一半，约 1.5 万个，TO 数量与 DTO 统一。模型转换结束后，紧接着是写缓存，写缓存又波及序列化。queryAll 办法调用一次会在新生代生成约五份比拟大的数据，第一份是数据集 ResultSet，第二份是 DO 列表，第三份是 DTO 列表，第四份 TO 列表，最初一份是 DTO 列表的序列化内容。加之两秒内呈现了二十多次调用，加剧了内存耗费，这应该能解释为什么 GC 次数会忽然回升这么多。上面还有几个问题，我用 FAQ 的形式解答：

Q：那 GC 耗时长如何解释呢？

A：我猜想可能是垃圾回收器整顿和复制大批量内存数据导致的。

————————————————-✂————————————————-

Q：还有 execute 办法和 set 办法之间为什么会距离这么长时间内？

A：目前的猜想是模型类的转换以及序列化自身须要肯定的工夫，其次这期间应该有多个序列化过程同时在就行，不过这也解释不了工夫为什么这么长。不过如果咱们把 GC 思考进来，就会失去绝对正当的解释。从 9:56:33 ~ 5:56:52 之间呈现了屡次 GC，而且有些 GC 的工夫很长（长时间的 stop the world），造成的景象就是两个办法之间的距离很长。实际上咱们能够看一下 9:56:31 第一个 queryAll 申请的调用链信息，会发现距离并不是那么的长：

图 10：queryAll 失常状况下的耗时状况

因而，咱们能够认为后续调用链 execute 和 set 办法之间的超长距离是因为 CPU 使用率，GC 等因素独特造成的。

————————————————-✂————————————————-

Q：第一个 set 和第二个 set 距离为什么也会这么长？

A：第一个 set 是咱们自定义的逻辑，到第二个 set 之间仿佛没有什么特地的货色，过后没有查出问题。不过好在复现的时候，发现了端倪，前面章节给予解释。

————————————————-✂————————————————-

最初，咱们把眼光移到初始的问题上，即业务共事反馈局部接口 RT 回升的问题。上面仍用 FAQ 的形式解答。

Q：为什么多个接口的 RT 都呈现了回升？调用链参考下图：

图 11：某个长 RT 接口的链路信息

A：局部业务线程在期待 druid 创立数据库连贯，因为 GC 的产生，造成了 STW。GC 对期待逻辑会造成影响。比方一个线程调用 awaitNanos 期待 3 秒钟，后果这期间产生了 5 秒的 GC（STW），那么当 GC 完结时，线程立刻就超时了。在 druid 数据源中，maxWait 参数管制着业务线程的等待时间，代码如下：

public class DruidDataSource extends DruidAbstractDataSource {private DruidPooledConnection getConnectionInternal(long maxWait) throws SQLException {
        // ...
        final long nanos = TimeUnit.MILLISECONDS.toNanos(maxWait);
        if (maxWait > 0) {
            // 尝试在设定工夫内从连接池中获取连贯
            holder = pollLast(nanos);
        } else {holder = takeLast();
        }
        
        // ...
    }
}

通过后面的排查，很多景象都失去了正当的解释，是时候给个论断了：

本次 xxx 利用多个接口在两天间断呈现了两次 RT 大幅回升状况，排查下来，初步认为是 queryAll 办法缓存生效，短时间内几十个申请大批量查问数据、模型转换以及序列化等操作，消耗量大量的内存，触发了屡次长时间的 GC。造成局部业务线程期待超时，进而造成 Dubbo 线程池被打满。

接下来，咱们要依照这个论断进行复现，以证实咱们的论断是正确的。

问题复现还是要尽量模仿过后的状况，否则可能会造成比拟大的误差。为了较为精确的模仿过后的接口调用状况，我写了一个能够管制 QPS 和申请总数的验证逻辑。

public class XxxController {
    
    @Resource
    private XxxApi xxxApi;
    
    public Object invokeQueryAll(Integer qps, Integer total) {RateLimiter rl = RateLimiter.create(qps.doubleValue());
        ExecutorService es = Executors.newFixedThreadPool(50);
        for (Integer i = 0; i < total; i++) {es.submit(() -> {rl.acquire();
                xxxApi.queryAll(0);
            });
        }
        return "OK";
    }
}

复现的成果合乎预期，CPU 使用率，网络 I/O 都下来了（因为监控属于公司外部零碎，就不截图了）。同时 GC 也产生了，而且耗时也很长。GC 日志如下：

2021-07-29T19:09:07.655+0800: 631609.822: [GC (Allocation Failure) 2021-07-29T19:09:07.656+0800: 631609.823: [ParNew: 2797465K->314560K(2831168K), 2.0130187 secs] 3285781K->1362568K(4928320K), 2.0145223 secs] [Times: user=3.62 sys=0.07, real=2.02 secs] 
2021-07-29T19:09:11.550+0800: 631613.717: [GC (Allocation Failure) 2021-07-29T19:09:11.551+0800: 631613.718: [ParNew: 2831168K->314560K(2831168K), 1.7428491 secs] 3879176K->1961168K(4928320K), 1.7443725 secs] [Times: user=3.21 sys=0.04, real=1.74 secs] 
2021-07-29T19:09:13.300+0800: 631615.467: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1646608K(2097152K)] 1965708K(4928320K), 0.0647481 secs] [Times: user=0.19 sys=0.00, real=0.06 secs] 
2021-07-29T19:09:13.366+0800: 631615.533: [CMS-concurrent-mark-start]
2021-07-29T19:09:15.934+0800: 631618.100: [GC (Allocation Failure) 2021-07-29T19:09:15.934+0800: 631618.101: [ParNew: 2831168K->2831168K(2831168K), 0.0000388 secs]2021-07-29T19:09:15.934+0800: 631618.101: [CMS2021-07-29T19:09:17.305+0800: 631619.471: [CMS-concurrent-mark: 3.668/3.938 secs] [Times: user=6.49 sys=0.01, real=3.94 secs] 
 (concurrent mode failure): 1646608K->1722401K(2097152K), 6.7005795 secs] 4477776K->1722401K(4928320K), [Metaspace: 224031K->224031K(1269760K)], 6.7028302 secs] [Times: user=6.71 sys=0.00, real=6.70 secs] 
2021-07-29T19:09:24.732+0800: 631626.899: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1722401K(2097152K)] 3131004K(4928320K), 0.3961644 secs] [Times: user=0.69 sys=0.00, real=0.40 secs] 
2021-07-29T19:09:25.129+0800: 631627.296: [CMS-concurrent-mark-start]
2021-07-29T19:09:29.012+0800: 631631.179: [GC (Allocation Failure) 2021-07-29T19:09:29.013+0800: 631631.180: [ParNew: 2516608K->2516608K(2831168K), 0.0000292 secs]2021-07-29T19:09:29.013+0800: 631631.180: [CMS2021-07-29T19:09:30.733+0800: 631632.900: [CMS-concurrent-mark: 5.487/5.603 secs] [Times: user=9.29 sys=0.00, real=5.60 secs] 
 (concurrent mode failure): 1722401K->1519344K(2097152K), 6.6845837 secs] 4239009K->1519344K(4928320K), [Metaspace: 223389K->223389K(1269760K)], 6.6863578 secs] [Times: user=6.70 sys=0.00, real=6.69 secs]

接着，咱们再看一下那段时间内的接口耗时状况：

图 12：问题复现时的 queryAll 耗时倒序列表

所有接口的耗费工夫都很长，也是合乎预期的。最初再看一个长 RT 接口的链路信息：

图 13：某个长 RT 接口的链路信息

会发现和图片 1，也就是业务同学反馈的问题是统一的，阐明复现成果合乎预期。

验证到这里，能够证实咱们的论断是正确的了。找到了问题的本源，这个问题能够归档了。

出于性能思考，Pinpoint 给出的链路信息力度比拟粗，以致于咱们无奈具体得悉 queryAll 办法的耗时形成是怎么的。为了搞清楚这外面的细节，我对 queryAll 办法耗时状况进行比拟具体的测算。在利用负载比拟低的状况下触发一个申请，并应用 Arthas 的 trace 命令测算链路耗时。失去的监控如下：

图 14：失常状况下 queryAll 办法链路信息

这里我对三个办法调用进行了编号，办法 ① 和 ② 之间存在 252 毫秒的距离，办法 ② 和 ③ 之间存在 294 毫秒的距离。Arthas 打印出的链路耗时状况如下：

图 15：queryAll 办法耗时测量

这里的编号与上图一一对应，其中耗时比拟多的调用我曾经用色彩标注进去了。首先咱们剖析距离 1 的形成，办法 ① 到 ② 之间有两个耗时的操作，一个是批量的模型转换，也就是把 DO 转成 DTO，耗费了约 79.6 毫秒。第二个耗时操作是 Object 的 toString 办法，约 171.6。两者加起来为 251.2，与全链路追踪零碎给出的数据是统一的。这里大家必定很好奇为什么 toString 办法会消耗掉这么多工夫，答案如下：

 public void put(Object key, Object value) {
     // 省略判空逻辑
     
     // 把 key 和 value 先转成字符串，再进行判空
     if (StringUtils.isBlank(key.toString()) || StringUtils.isBlank(value.toString())) {return;}
     CacheClient.set(key, value);
 }

这是办法 ① 和 ② 门路中的一个办法，这段代码看起来人畜有害，问题产生在判空逻辑上（历史代码，不探讨其合理性）。当 value 是一个十分大汇合或数组时，toString 会消耗掉很多工夫。同时，toString 也会生成一个大字符串，无形中耗费了内存资源。这里看似不起眼的一句代码，实际上却是性能黑洞。这也揭示咱们，在操作大批量数据时，要留神时空耗费。

最初，咱们再来看一下办法 ② 和 ③ 之间的距离问题，起因曾经很显著了，就是 value 序列化过程耗费了大量的工夫。另外，序列化好的字节数组也会临时存在堆内存中，也是会耗费不少内存资源的。

到这里整个剖析过程就完结了，通过下面的剖析，咱们能够看出，一次简略的查问居然能引出了这么多问题。很多在以前看起来稠密平时的逻辑，偶然间也会成为性能杀手。日常工作中，还是要常常关注一下利用的性能问题，为利用的稳固运行保驾护航。

因为问题产生时，JVM 只是进行了 FGC，内存并没有溢出，所以没有过后的内存 dump 数据。不过好在问题能够稳固复现，通过对 JVM 进行一些配置，咱们能够让 JVM 产生 FGC 前主动对内存进行 dump。这里应用 jinfo 命令对正在运行的 JVM 过程设置参数：

jinfo -flag +HeapDumpBeforeFullGC $JVM_PID

拿到内存数据后，接下来用 mat 工具剖析一下。首先看一下内存泄露吧：

图 16：利用内存泄露剖析

从内存耗费比例上来看，的确存在一些问题，次要是与 dubbo 的线程无关。轻易选一个线程，在摆布树（dominator tree）视图中查看线程摆布的对象信息：

图 17：dubbo 线程摆布树状况

从上图能够看出，dubbo 线程 retained heap 约为 66 MB，次要由两个大的对象 ArrayList 和 StringBuilder 组成。ArrayList 外面寄存的是 DTO，单个 DTO 的 retained heap 大小约为 5.1 KB。StringBuilder 次要是 toString 过程产生的，耗费了靠近 26 MB 的内存。从 dump 的内存数据中没找到 DO 列表，应该是在 YGC 时被回收了。

好了，对于内存的剖析就到这吧，大略晓得内存耗费是怎么的就够了，更深刻的剖析就不搞了。

因为排查教训较少，这个问题断断续续也花了不少工夫。这两头有找不到起因时的郁闷，也有发现一些猜测合乎预期时的欣慰。不论怎么样，最初还是找到了问题的起因。在帮忙他人的同时，本人也学到了不少货色。总的来说，付出是值得的。本文的最初，对问题排查过程进行简略的总结吧。

一开始，我间接从具体景象开始排查，冀望找到引发景象的起因。进行了各种猜测，然而都没法得出正当的论断。接着扩充信息面，依然无果。之后综合各种信息，思考之后，换个方向排查，找到了起因。最初进行验证，并对一些疑点进行解释，整个过程完结。

最初说说这次排查过程存在的问题吧。第一个问题是没有留神甄别他人反馈过去的信息，没有对信息进行疾速确认，而是间接深刻了。花了很多工夫尝试了各种猜测，最终均无果。因为他人反馈过去的信息通常都是比拟系统全面的，甚至是不正确的。对于这些信息能够疾速确认，侥幸的话能间接找到起因。但如果发现此路不通，就不要钻牛角尖了，因为这个景象可能只是泛滥景象中的一个。在这个案例中，接口长 RT 看起来像是 druid 导致的，实际上却是因为 GC 造成 STW 导致的。持续沿着 druid 方向排查，最终肯定是背道而驰。其余的问题都是小问题，就不说了。另外，排查过程中要留神保留过后的一些日志数据，防止因数据过期而失落，比方阿里云 RDS SQL 洞察是有工夫限度的。

本篇文章到此结束，感激浏览！

本文在常识共享许可协定 4.0 下公布，转载请注明出处
作者：田小波
原创文章优先公布到集体网站，欢送拜访：https://www.tianxiaobo.com

关于java:记一次接口慢查排查

1. 前言

2. 问题形容

3. 排查过程

3.1 直奔主题

3.2 扩充信息面

3.2.1 根本信息

3.2.2 业务日志信息

3.2.3 GC 信息

3.3 从新扫视

3.3.1 综合剖析

3.3.2 换个思路

3.4 初步论断

4. 问题复现

5. 进一步摸索

5.1 耗时测算

5.2 内存耗费测算

6. 总结