api接口的一次qps提升排查过程.md

最新推荐文章于 2024-08-23 14:50:19 发布

DDF_YiChen

最新推荐文章于 2024-08-23 14:50:19 发布

阅读量2.4k

点赞数 2

分类专栏：问题排查过程文章标签：线程阻塞排查

本文链接：https://blog.csdn.net/yichen0429/article/details/108600707

版权

问题排查过程专栏收录该内容

2 篇文章 0 订阅

订阅专栏

文章目录

前言

初版接口测试给出的数据，并发30，响应时间控制在200ms左右，最终达到的qps是240左右。

机器配置为4核4G

该接口为统一封装多个供应商的功能接口，然后聚合使用。最终统一提供给其它客户使用当前接口。
包含功能

ip白名单
验签
白名单
调用第三方接口（模拟睡眠110ms）
黑名单
人审策略
记录审核业务数据和日志（业务数据要求同步，日志这里采用的是本地集合缓存定时批量同步）

排查过程

工具下载安装准备

自行下载安装arthas, 运行arthas, attach对应java进程

cpu和线程相关

首先肯定是最简单的top，查看负载情况， CPU达到了388%
与线程相关的命令参数
查看cpu占用过高的线程
```
# 按cpu占用排行看前5个
thread -n 5
```
这里我们发现也没有特别过分的说某一个线程占用cpu过高了，所以问题也不是出在某个线程有死循环出不来了。

倒是这里可以看到这个线程的状态是TIMED_WAITTING，这个要额外说一下，在这里是正常的。因为在这里模拟调用第三方接口，在这里睡眠了110ms
查看是否有blocked的线程

# arthas命令，查看当前是否有阻塞线程
thread -b

不看不知道，一看吓一跳，有一百多个线程因为一个竞争关系而阻塞住了

查看当前线程的详细情况，该线程是tomcat处理用户请求的线程，对应id为125

# arthas命令，查看对应线程id的堆栈详情
thread 125

然后从堆栈详情中观察是否有自己写的代码还是某些第三方应用包的问题，这里发现所有阻塞的线程都是由于本地代码的ApiHelper的第74行而阻塞

没别的，查看本地代码，到底写了啥

就是想获取一个验证器对象，手动对参数进行校验，这里就是创建一个验证器对象而已，从表面看出来啥讲究。

点进去源码看看里面到底写的啥，原谅我，点进去之后这代码比想象中的复杂的多，看了一圈稀里糊涂的。但是让我看到了这个。没啥好犹豫的，既然都已经说了这个实例是可以缓存下来共享使用的，那就说明这个是线程安全的。而线程安全的就能够说明大量的请求被接收处理之后，都会重复的去执行这一段代码，然后内部为了保证线程安全，使用了同步锁，所以这一块有竞争关系。问题还在于所有的请求都会重复的竞争创建再竞争创建，这实在是有些太恐怖了。

为了验证上面这个情况的严重性，现在来看一下目前tomcat创建的线程数。由于每个请求线程都需要竞争阻塞，会导致请求线程被blocked,继而线程无法释放。然后外面大量的请求依然还在源源不断的打到系统，线程池中又由于这个原因,没有可以直接使用的线程，就会继续创建新的线程

# arthas命令，由于没有找到直接根据线程名称过滤的参数，这里换了个思路，尽量把要显示出来的线程数量写大，进而达到要查看所有线程的目的，然后再通过名称过滤
thread -n 5000 | grep http-nio | wc -l
209

没什么好说的，既然是这个原因，将创建验证对象设置为静态常量，初始化创建即可
重新运行压测结果，出乎意料的好用

内存占用过大，无法释放

有了1的结果之后，对压测参数进行了调整，并发200，持续运行1200s。然后发现qps在最开始的时间内一直持续不断的往上累加，一直飙到1500左右。但是慢慢的随着时间推移，qps开始缓慢的一点点下降，等到压测结束，竟然又跳水到了700左右，又是一顿无语。

使用dashboard命令来个概览查看下应用情况

目前一共为当前应用分配了一个G的堆内存大小，从下图来看，老年代的空间已经被完全塞满了

查看下当前的gc日志

# 目前和gc相关的启动参数
-XX:+UseParallelGC -XX:ParallelGCThreads=8 -XX:+UseParallelOldGC -XX:+UseAdaptiveSizePolicy -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps -XX:+HeapDumpOnOutOfMemoryError  -XX:HeapDumpPath=./ -Xloggc:./gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M

在当前目录下查看gc日志，可以发现，已经在频繁的full gc了，但是没鸟用，回收不掉

-XX:+UseParallelGC -XX:ParallelGCThreads=8 -XX:+UseParallelOldGC -XX:+UseAdaptiveSizePolicy -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps -XX:+HeapDumpOnOutOfMemoryError  -XX:HeapDumpPath=./ -Xloggc:./gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M

下图可以清楚的看到每隔几百毫秒就要发生一次Full GC，已经频繁到令人发指，最可怕的是每次只能回收掉三四十兆新生区，而老年代的空间回收后依然近乎雷打不动，而每次的回收用时都已经达到了1.5s到2s之间。

这种情况基本上就是发生内存泄漏了，对象存在引用导致垃圾回收期无法回收。

这个时候就需要用到dump命令了，将当前应用的堆内存使用情况dump下来，借助于工具分析.

JDK原生提供了对dump支持的命令，详细可以看这篇文章jps/jmap/jstat使用记录总结

既然现在装了arthas, 现在使用arthas来执行dump操作
```
heapdump --live /data/api/dump.hprof
```
文件会比较大，将文件下载到本地，然后使用工具分析。这里使用的是JDK自带的jvisualvm，位于安装目录下的bin目录下

查看类的占用内存情况，可以看到几乎全被字符串占用了

点击一个类，查看这个类的具体实例数，这里就需要根据实际代码联系起来了。可以看到有大量的字符串被保存到一个LocalCache类里的LOCAL_API_HISTORY变量里，这个变量的类型是CopyOnWriteArrayList

这个需要来讲解一下，由于当前这个系统封装了多个第三方接口，然后统一提供给客户端使用。所以为了方便排查多方请求耗时或错误问题，提供了一个日志表。由于这个数据不要求实时性和必须持久化，而且又不想每来一个请求就操作一次数据库，因此提供了一个策略，就是上面那个集合。在每个请求结束后，将产生的日志加入到集合中。然后每隔两分钟同步一次数据库，可以直接一个sql将所有的日志批量插入到数据库中，可以减少数据库操作。

但是很显然，目前这里出问题了。。
可怕的不是出问题，而是不知道问题出在哪里，既然确定了是这个集合里的数据没有被回收，就要来看一下同步的代码到底有没有出问题了

每次同步的时候，将原始集合初始化给本地变量，然后就迅速清空本地变量中的数据。后续操作都是操作本地方法栈中的变量，方法结束后就不会有问题了，目前来看并没有发现什么问题。
```
CopyOnWriteArrayList<LogApi> copyOnWriteArrayList = new CopyOnWriteArrayList<>(LocalCache.LOCAL_API_HISTORY);
if (CollUtil.isNotEmpty(copyOnWriteArrayList)) {
    // 在读取到数据到clear之前，这段空隙依然会有请求进来，这里会误删，但目前数据不敏感，相对于复杂的同步操作，这种后果是可以接受的
    LocalCache.LOCAL_API_HISTORY.clear();
}
```
那就来验证一下本地内存中的这个集合中到底是不是存在数据吧

具体操作，可以参考这个别人写的arthas的用户示例Alibaba Arthas实践–获取到Spring Context，然后为所欲为

这里傻逼了，没截图完整

这里也傻逼了，没截图调用size方法直接看这个集合的大小

通过上述方法，更加确信了自己认为这个集合中的对象没有被回收掉。然后思维就被固定在这个地方，想破脑袋的去想场景，为什么没有被回收掉。

CopyOnWriteArrayList的clear方法是需要获取锁的，而这个锁对象和写要获取锁对象是同一个，毕竟清除也是某种意义上的写嘛。

然后就想到了一个场景，由于压测，客户端的大量请求是源源不断的，而每个请求最终都会要获取写锁去写数据，是否在这个时候发生了锁饥饿现象。这个clear没有竞争过其它的写请求，导致这里一直被阻塞。（提前暴露一下吧，毕竟每个人排查问题的过程都不是一蹴而就的，有想法就不怕对错，最终证明其实不是这个原因）。

但还是说明一下当时为了这个想法而去做的尝试，毕竟过程是很重要的，哪怕它是错的。

之前在调用集合的清除方法也已经说明过了，那里为了写请求的性能和简单，存在数据会被删除的情况。但是如果使用同步锁，依然解决不了竞争的问题。那么就提供一个变量，只让同步线程有资格去竞争，一旦同步线程正在执行，就将这个值标记为我正在同步。然后其它写线程发现正在同步，就阻塞写请求。这样就可以保证同步线程有最大的执行权。而且所谓的同步就是上面贴出来的代码，只是一个赋值和清除代码，所以并不会阻塞很久。

于是，出现了下面一些代码

/**
 * 是否正在同步日志
 */
public static volatile boolean logIsSync = false;

/**
 * 增加日志记录到缓存
 * @param logApi
 */
public void addApiLog(LogApi logApi) {
    if (!apiProperties.isPersistenceApiLog()) {
        return;
    }
    // 写请求的同步交给Java自己的容器去解决， 但是有一个定时同步的任务，要读取数据和清除数据必须独占,如果使用锁，同步任务存在竞争不过写请求的可能
    // com.company.content.risk.order.schedule.ScheduleTask.syncApiLog
    addApiLogPool.execute(() -> {
        // 如果同步线程正在执行任务，写请求必须阻塞暂停， 这个时间会很短
        while (LocalCache.logIsSync) {
            try {
                Thread.sleep(20);
            } catch (InterruptedException ignored) {}
        }
        LocalCache.LOCAL_API_HISTORY.add(logApi);
    });
}

/**
 * 将内存中日志数据读取后删除，然后持久化到数据库中
 */
public void syncApiLog() {
    if (LocalCache.LOCAL_API_HISTORY.size() > 0) {
        LocalCache.logIsSync = true;
        CopyOnWriteArrayList<LogApi> copyOnWriteArrayList = new CopyOnWriteArrayList<>(LocalCache.LOCAL_API_HISTORY);
        LocalCache.LOCAL_API_HISTORY.clear();
        LocalCache.logIsSync = false;
    }
}

很遗憾，这并没有解决我的问题。。。。。

这个时候就是很难受的时候了，明明觉得问题就是出在这里，可是现实偏偏打了脸。只能修改源代码打日志了，看程序到底阻塞在什么地方。

由于打info级别日志，现在请求这么多，会完全刷的看不到自己想看的数据。所以临时加的一行日志的级别被打成了error级别，这样我只要查看error日志文件即可

日志打在进入请求，复制本地集合，清除集合，调用插入方法之前和数据插入完成。

然后就发现了令人开心的一幕，哈哈。

开心是因为发现出了新的问题，之前的思路有问题。从图中可以看到在同步时候发现本次有2W多条数据需要插入，但是他么的竟然执行了近三分钟。。。。

太恶劣了。这里要说明下，插入方法已经采用了批量插入的方法，而且还修改了mysql的max_allowed_packet，以避免数据包过大无法执行。所以这里就是单纯的插入执行太慢。。。

两分钟的插入时间，而这2W条数据仅仅是我第一次同步任务产生的，同步任务这里已经改成了10s一次，然后由于本次同步持续的时间已经足够再次产生N倍于两万条数据的记录，就会导致下一次的插入会更慢，而更慢的插入，就会导致下次任务定时被延迟的更久，然后就意味着集合会堆积更大的日志。。然后恶性循环，直到程序内存完全撑不住，崩溃掉。
说到底日志这一块的处理采取了以内存换时间的方式，即使我存第三方缓存，一个是造成了程序的复杂性。第二个依然还是要大内存支持，而且会有大量的网络请求。那么干脆将这部分内存分配给虚拟机，让虚拟机消化即可。所以无论后续处理方式如何，目前1G的内存，可以再调大些。当然内存更大，会在请求没打满内存之前保持不错的响应，但一旦并发还是达到了最大承受能力，更大的内存则意味着更多的内存需要回收，那么其实同时增加的还有gc的时间。
针对于这么慢的sql写入内心还是有很大的疑惑的，然后就去看了Mysql对应的主机，然后发现所剩内存只有100多兆，磁盘也已经使用了近乎100%，为啥呢。因为服务器他么的是1核2G的。然后就把磁盘清了清，数据库中日志数据清了清，重启了mysql服务，最终也只是还剩不到1个g的内存。
经过8和9的调整，重新进行压测， 200个并发持续1800s，然后观察结果。这个时候内存无法回收的问题就被解决掉了。每隔一段时间，同步任务一执行，内存就会被释放出来。而由于内存现在分配的足够大，且同步时间很短，内存基本上在新生代就完成了回收, 回收时间也很乐观，再也没有Full GC作祟了。
但是问题还是有的，qps的顶峰提高到了1800甚至2000左右之后又是开始非常缓慢的持续下降到700到900不等。这个时候就真的是完全没有一点办法了。线程偶尔阻塞，也是因为自己模拟接口时的sleep，而且也不存在某个线程cpu占用很高的问题。就是偶有阻塞线程的堆栈信息，是druid的连接池在获取连接时的阻塞，目前连接池配置了最小为5，最大连接数为30，然后尝试降下来为10发现也并没有什么区别。关于连接池数量的选择不是很有心得。
多次尝试性的查看是否有阻塞线程，发现了CopyOnWriteArrayList在复制数组时的阻塞代码，最初选用CopyOnWriteArrayList是因为可以接受读数据时的延迟性，所以没有选择使用读写锁来控制。但是上面在同步容器中数据的时候已经改为使用优先级最高的状态变量来完成读的独占且保持数据一致性了，所以这里再使用这个容器就没有意义了。反而由于存在大量的写请求，而CopyOnWriteArrayList内部每次写数据都会复制原数组进行添加数据，最后再将原始数据指向新的数组，而这个复制在写多读少的情况下已经完全不合适了，直接替换为同步集合，这个改动最终经过测试提升了近200qps。
```
@Getter
public static final List<LogApi> LOCAL_API_HISTORY = Collections.synchronizedList(new ArrayList<>());
```
到这里之后个人已经没有办法来排查问题所在了，只能认为这个并发以及系统这个配置，这可能已经算是它的一般成绩了吧。再牛逼的调优已经是大神级别的了，可能这个日志我就不应该记。就算记，这个量是否可以考虑其它中间件。于是最终只能从代码层面再舍弃一些。由于当前每次同步的日志量确实不小，于是定义了一些参数用来决定每次同步批次允许的最大同步数量，还有慢日志的时间参数。如果当前同步批次小于最大允许的同步数量，则将当前这一个批次的日志全部持久化。而如果当前日志数量大于允许同步的日志数量，则优先统计这一个批次数量中的错误日志数量，如果错误日志数量依然大于最大允许的数量，则截取日志，最终只保留最大允许数量的错误日志；而如果错误日志没有达到最大批次数量，则将剩下的非错误日志过滤那些响应时间大于参数定义的慢日志界定的日志保存下来。

如果所有的慢日志加上之前的错误日志还是大于批次数量，则将慢日志从响应时间从大到小排列，然后只保存剩余允许数量的慢日志。最终其它日志就会被舍弃，不再持久化到数据库。

但是作为弥补，额外创建一张表，针对当前批次数据做一个统计，实际数量，最终保留的数量，响应时间在200-400毫秒不同阶段的占比，以及错误数量占比等，最终保证详情数据丢失了，但统计信息不丢失。说到底这个统计只是为了刚上线时能对系统有一个认知，并不是业务上的统计。
针对YGC频繁会不会影响吞吐量，上述图片也能看出来gc占用的时间并不长。但是由于有大量临时对象，所以是否可以提高新生代大小呢？提高新生代大小，可以降低gc的次数，但回收的内存大了必然会造成回收时间变长。这个值自己无法界定，于是尝试将垃圾回收器切换为G1

删除原并行gc相关配置
```
-XX:+UseParallelGC -XX:ParallelGCThreads=4 -XX:+UseParallelOldGC -XX:+UseAdaptiveSizePolicy
```
替换为
```
-XX:+UseG1GC -XX:MaxGCPauseMillis=100
```
看一下G1垃圾回收的日志

新生代的大小一直在调整，但gc时间也都在一个比较理想的时间。但是两者最后的结果都在1250左右，没有什么差别。
最终结果，250个并发，持续时间16分钟左右，响应时间尚可， qps在1200左右，无论如何，自己尽力了。