当前位置:主页 > java教程 > java提升接口吞吐量

java开发接口吞吐量提升10多倍技巧

发布:2023-03-05 17:00:01 59


给大家整理了相关的编程文章,网友盖良俊根据主题投稿了本篇教程内容,涉及到java提升接口吞吐量、java、吞吐量、java提升接口吞吐量相关内容,已被397网友关注,涉猎到的知识点内容可以在下方电子书获得。

java提升接口吞吐量

背景

公司的一个ToB系统,因为客户使用的也不多,没啥并发要求,就一直没有经过压测。这两天来了一个“大客户”,对并发量提出了要求:核心接口与几个重点使用场景单节点吞吐量要满足最低500/s的要求。

当时一想,500/s吞吐量还不简单。Tomcat按照100个线程,那就是单线程1S内处理5个请求,200ms处理一个请求即可。这个没有问题,平时接口响应时间大部分都100ms左右,还不是分分钟满足的事情。

然而压测一开,100 的并发,吞吐量居然只有 50 ...

而且再一查,100的并发,CPU使用率居然接近 80% ...

从上图可以看到几个重要的信息。

最小值: 表示我们非并发场景单次接口响应时长。还不足100ms。挺好!

最大值: 并发场景下,由于各种锁或者其他串行操作,导致部分请求等待时长增加,接口整体响应时间变长。5秒钟。有点过分了!!!

再一看百分位,大部分的请求响应时间都在4s。无语了!!!

所以 1s钟的 吞吐量 单节点只有 50 。距离 500 差了10倍。 难受!!!!

分析过程

定位“慢”原因

这里暂时先忽略 CPU 占用率高的问题

首先平均响应时间这么慢,肯定是有阻塞。先确定阻塞位置。重点检查几处:

  • 锁 (同步锁、分布式锁、数据库锁)
  • 耗时操作 (链接耗时、SQL耗时)

结合这些先配置耗时埋点。

  • 接口响应时长统计。超过500ms打印告警日志。
  • 接口内部远程调用耗时统计。200ms打印告警日志。
  • Redis访问耗时。超过10ms打印告警日志。
  • SQL执行耗时。超过100ms打印告警日志。

上述配置生效后,通过日志排查到接口存在慢SQL。具体SQL类似与这种:

<!-- 主要类似与库存扣减 每次-1 type 只有有限的几种且该表一共就几条数据(一种一条记录)-->
<!-- 压测时可以认为 type = 1 是写死的 -->
update table set field = field - 1 where type = 1 and filed > 1;

上述SQL相当于并发操作同一条数据,肯定存在锁等待。日志显示此处的等待耗时占接口总耗时 80% 以上。

二话不说先改为敬。因为是压测环境,直接改为异步执行,确认一下效果。

PS:当时心里是这么想的: 妥了,大功告成。就是这里的问题!绝壁是这个原因!优化一下就解决了。当然,如果这么简单就没有必要写这篇文章了...

优化后的效果:

嗯...

emm...

好! 这个优化还是很明显的,提升提升了近2倍。

此时已经感觉到有些不对了,慢SQL已经解决了(异步了~ 随便吧~ 你执行 10s我也不管了),虽然对吞吐量的提升没有预期的效果。但是数据是不会骗人的。

最大值: 已经从 5s -> 2s

百分位值: 4s -> 1s

这已经是很大的提升了。

继续定位“慢”的原因

通过第一阶段的“优化”,我们距离目标近了很多。废话不多说,继续下一步的排查。

我们继续看日志,此时日志出现类似下边这种情况:

2023-01-04 15:17:05:347 INFO **.**.**.***.50 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:348 INFO **.**.**.***.21 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:350 INFO **.**.**.***.47 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:465 INFO **.**.**.***.234 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:467 INFO **.**.**.***.123 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:581 INFO **.**.**.***.451 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:702 INFO **.**.**.***.72 [TID: 1s22s72s8ws9w00] **********************

前三行info日志没有问题,间隔很小。第4 ~ 第5,第6 ~ 第7,第7 ~ 第8 很明显有百毫秒的耗时。检查代码发现,这部分没有任何耗时操作。那么这段时间干什么了呢?

  • 发生了线程切换,换其他线程执行其他任务了。(线程太多了)
  • 日志打印太多了,压测5分钟日志量500M。(记得日志打印太多是有很大影响的)
  • STW。(但是日志还在输出,所以前两种可能性很高,而且一般不会停顿百毫秒)

按照这三个思路做了以下操作:

首先,提升日志打印级别到DEBUG。emm... 提升不大,好像增加了10左右。

然后,拆线程 @Async 注解使用线程池,控制代码线程池数量(之前存在3个线程池,统一配置的核心线程数为100)结合业务,服务总核心线程数控制在50以内,同步增加阻塞最大大小。结果还可以,提升了50,接近200了。

最后,观察JVM的GC日志,发现YGC频次4/s,没有FGC。1分钟内GC时间不到1s,很明显不是GC问题,不过发现JVM内存太小只有512M,直接给了4G。吞吐量没啥提升,YGC频次降低为2秒1次。

唉,一顿操作猛如虎。

PS:其实中间还对数据库参数一通瞎搞,这里不多说了。

其实也不是没有收获,至少在减少服务线程数量后还是有一定收获的。另外,已经关注到了另外一个点:CPU使用率,减少了线程数量后,CPU的使用率并没有明显的下降,这里是很有问题的,当时认为CPU的使用率主要与开启的线程数量有关,之前线程多,CPU使用率较高可以理解。但是,在砍掉了一大半的线程后,依然居高不下这就很奇怪了。

此时关注的重点开始从代码“慢”方向转移到“CPU高”方向。

定位CPU使用率高的原因

CPU的使用率高,通常与线程数相关肯定是没有问题的。当时对居高不下的原因考虑可能有以下两点:

  • 有额外的线程存在。
  • 代码有部分CPU密集操作。

然后继续一顿操作:

  • 观察服务活跃线程数。
  • 观察有无CPU占用率较高线程。

在观察过程中发现,没有明显CPU占用较高线程。所有线程基本都在10%以内。类似于下图,不过有很多线程。

没有很高就证明大家都很正常,只是多而已...

此时没有下一步的排查思路了。当时想着,算了打印一下堆栈看看吧,看看到底干了啥~

在看的过程中发现这段日志:

"http-nio-6071-exec-9" #82 daemon prio=5 os_prio=0 tid=0x00007fea9aed1000 nid=0x62 runnable [0x00007fe934cf4000]
   java.lang.Thread.State: RUNNABLE
	at org.springframework.core.annotation.AnnotationUtils.getValue(AnnotationUtils.java:1058)
	at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.resolveExpression(AbstractAspectJAdvisorFactory.java:216)
	at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.<init>(AbstractAspectJAdvisorFactory.java:197)
	at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAnnotation(AbstractAspectJAdvisorFactory.java:147)
	at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAspectJAnnotationOnMethod(AbstractAspectJAdvisorFactory.java:135)
	at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvice(ReflectiveAspectJAdvisorFactory.java:244)
	at org.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.instantiateAdvice(InstantiationModelAwarePointcutAdvisorImpl.java:149)
	at org.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.<init>(InstantiationModelAwarePointcutAdvisorImpl.java:113)
	at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisor(ReflectiveAspectJAdvisorFactory.java:213)
	at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisors(ReflectiveAspectJAdvisorFactory.java:144)
	at org.springframework.aop.aspectj.annotation.BeanFactoryAspectJAdvisorsBuilder.buildAspectJAdvisors(BeanFactoryAspectJAdvisorsBuilder.java:149)
	at org.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator.findCandidateAdvisors(AnnotationAwareAspectJAutoProxyCreator.java:95)
	at org.springframework.aop.aspectj.autoproxy.AspectJAwareAdvisorAutoProxyCreator.shouldSkip(AspectJAwareAdvisorAutoProxyCreator.java:101)
	at org.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.wrapIfNecessary(AbstractAutoProxyCreator.java:333)
	at org.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.postProcessAfterInitialization(AbstractAutoProxyCreator.java:291)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsAfterInitialization(AbstractAutowireCapableBeanFactory.java:455)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1808)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:353)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:233)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean(DefaultListableBeanFactory.java:1282)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean(DefaultListableBeanFactory.java:1243)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveBean(DefaultListableBeanFactory.java:494)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBean(DefaultListableBeanFactory.java:349)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBean(DefaultListableBeanFactory.java:342)
	at cn.hutool.extra.spring.SpringUtil.getBean(SpringUtil.java:117)
        ......  
        ......

上边的堆栈发现了一个点: 在执行getBean的时候,执行了createBean方法。我们都知道Spring托管的Bean都是提前实例化好放在IOC容器中的。createBean要做的事情有很多,比如Bean的初始化,依赖注入其他类,而且中间还有一些前后置处理器执行、代理检查等等,总之是一个耗时方法,所以都是在程序启动时去扫描,加载,完成Bean的初始化。

而我们在运行程序线程堆栈中发现了这个操作。而且通过检索发现竟然有近200处。

通过堆栈信息很快定位到执行位置:

<!--BeanUtils 是 hutool 工具类。也是从IOC容器获取Bean 等价于 @Autowired 注解 -->
RedisTool redisTool = BeanUtils.getBean(RedisMaster.class);

而RedisMaster类

@Component
@Scope("prototype")
public class RedisMaster implements IRedisTool {
    // ......
}

没错就是用了多例。而且使用的地方是Redis(系统使用Jedis客户端,Jedis并非线程安全,每次使用都需要新的实例),接口对Redis的使用还是比较频繁的,一个接口得有10次左右获取Redis数据。也就是说执行10次左右的createBean逻辑 ...

叹气!!!

赶紧改代码,直接使用万能的 new 。

在看结果之前还有一点需要提一下,由于系统有大量统计耗时的操作。实现方式是通过:

long start = System.currentTimeMillis();
// ......
long end = System.currentTimeMillis();
long runTime = start - end;

或者Hutool提供的StopWatch:

这里感谢一下huoger 同学的评论,当时还误以为该方式能够降低性能的影响,但是实际上也只是一层封装。底层使用的是 System.nanoTime()。

StopWatch watch = new StopWatch();
watch.start();
// ......
watch.stop();
System.out.println(watch.getTotalTimeMillis());

而这种在并发量高的情况下,对性能影响还是比较大的,特别在服务器使用了一些特定时钟的情况下。这里就不多说,感兴趣的可以自行搜索一下。

最终结果:

排查涉及的命令如下:

查询服务进程CPU情况: top –Hp pid

查询JVM GC相关参数:jstat -gc pid 2000 (对 pid [进程号] 每隔 2s 输出一次日志)

打印当前堆栈信息: jstack -l pid >> stack.log

总结

结果是好的,过程是曲折的。总的来说还是知识的欠缺,文章看起来还算顺畅,但都是事后诸葛亮,不对,应该是时候臭皮匠。基本都是边查资料边分析边操作,前后花费了4天时间,尝试了很多。

  • Mysql : Buffer Pool 、Change Buffer 、Redo Log 大小、双一配置...
  • 代码 : 异步执行,线程池参数调整,tomcat 配置,Druid连接池配置...
  • JVM : 内存大小,分配,垃圾收集器都想换...

总归一通瞎搞,能想到的都试试。

后续还需要多了解一些性能优化知识,至少要做到排查思路清晰,不瞎搞。

最后5行代码有哪些:

  • new Redis实例:1
  • 耗时统计:3
  • SQL异步执行 @Async: 1(上图最终的结果是包含该部分的,时间原因未对SQL进行处理,后续会考虑Redis原子操作+定时同步数据库方式来进行,避免同时操数据库)

TODO

问题虽然解决了。但是原理还不清楚,需要继续深挖。

为什么createBean对性能影响这么大?

如果影响这么大,Spring为什么还要有多例?

System.currentTimeMillis并发度多少才会对性能产生影响,影响有多大?

很多公司(包括大厂)在业务代码中,还是会频繁的使用System.currentTimeMillis获取时间戳。比如:时间字段赋值场景。所以,性能影响肯定会有,但是影响的门槛是不是很高。

继续学习性能优化知识

  • 吞吐量与什么有关?

首先,接口响应时长。直接影响因素还是接口响应时长,响应时间越短,吞吐量越高。一个接口响应时间100ms,那么1s就能处理10次。

其次,线程数。现在都是多线程环境,如果同时10个线程处理请求,那么吞吐量又能增加10倍。当然由于CPU资源有限,所以线程数也会受限。理论上,在 CPU 资源利用率较低的场景,调大tomcat线程数,以及并发数,能够有效的提升吞吐量。

最后,高性能代码。无论接口响应时长,还是 CPU 资源利用率,都依赖于我们的代码,要做高性能的方案设计,以及高性能的代码实现,任重而道远。

  • CPU使用率的高低与哪些因素有关?

CPU使用率的高低,本质还是由线程数,以及CPU使用时间决定的。

假如一台10核的机器,运行一个单线程的应用程序。正常这个单线程的应用程序会交给一个CPU核心去运行,此时占用率就是10%。而现在应用程序都是多线程的,因此一个应用程序可能需要全部的CPU核心来执行,此时就会达到100%。

此外,以单线程应用程序为例,大部分情况下,我们还涉及到访问Redis/Mysql、RPC请求等一些阻塞等待操作,那么CPU就不是时刻在工作的。所以阻塞等待的时间越长,CPU利用率也会越低。也正是因为如此,为了充分的利用CPU资源,多线程也就应运而生(一个线程虽然阻塞了,但是CPU别闲着,赶紧去运行其他的线程)。

  • 一个服务线程数在多少比较合适(算上Tomcat,最终的线程数量是226),执行过程中发现即使tomcat线程数量是100,活跃线程数也很少超过50,整个压测过程基本维持在20左右。

以上就是java开发接口吞吐量提升10多倍技巧的详细内容,更多关于java提升接口吞吐量的资料请关注码农之家其它相关文章!


参考资料

相关文章

  • 深入了解java.util.Arrays的使用技巧

    发布:2023-04-19

    在这篇文章中,我们将来带大家看看 java.util.Arrays ,我们可以使用 Arrays 创建,比较,排序,搜索,stream 和转化数组,感兴趣的小伙伴可以了解一下


  • Java AQS中闭锁CountDownLatch的使用

    发布:2023-04-17

    CountDownLatch 是一个同步工具类,用来协调多个线程之间的同步,它能够使一个线程在等待另外一些线程完成各自工作之后,再继续执行。被将利用CountDownLatch实现网络同步请求,异步同时获取商品信息组装,感兴趣的可以了解一下


  • java线程池使用后是否需要关闭

    发布:2020-01-10

    这篇文章主要给大家介绍了关于java线程池使用后到底要不要关闭的相关资料,文中通过示例代码介绍的非常详细,对大家的学习或者工作具有一定的参考学习价值,需要的朋友们下面随着小编


  • 详解使用canvas实现围绕旋转动画

    发布:2020-02-29

    这篇文章主要为大家详细介绍了JavaScript canvas实现围绕旋转动画,具有一定的参考价值,感兴趣的小伙伴们可以参考一下


  • Java方法递归的形式和常见递归算法(方法递归结合File类查找文件)

    发布:2023-03-21

    方法递归方法直接调用自己或者间接调用自己的形式称为方法递归( recursion),递归做为一种算法在程序设计语言中广泛应用,这篇文章主要介绍了Java方法递归的形式和常见递归算法-方法递归结合File类查找文件,需要的朋友可以参考下


  • Java用POI解析excel并获取所有单元格数据的方法整理

    发布:2019-08-29

    下面小编就为大家带来一篇Java用POI解析excel并获取所有单元格数据的实例。小编觉得挺不错的,现在就分享给大家,也给大家做个参考。一起跟随小编过来看看吧


  • 实例讲解java怎样利用CountDownLatch实现并行计算

    发布:2020-02-11

    这篇文章主要介绍了java利用CountDownLatch实现并行计算,具有一定的参考价值,感兴趣的小伙伴们可以参考一下


  • Java核心库实现AOP方法详解

    发布:2019-06-21

    给大家分享一下利用Java核心库实现简单的AOP的经验分享和教学,需要的读者们参考下吧。


网友讨论