搞了 2 周性能优化,QPS 终于翻倍了

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 前段时间我们的服务遇到了性能瓶颈,由于前期需求太急没有注意这方面的优化,到了要还技术债的时候就非常痛苦了。

前段时间我们的服务遇到了性能瓶颈,由于前期需求太急没有注意这方面的优化,到了要还技术债的时候就非常痛苦了。


在很低的 QPS 压力下服务器 load 就能达到 10-20,CPU 使用率 60% 以上,而且在每次流量峰值时接口都会大量报错,虽然使用了服务熔断框架 Hystrix,但熔断后服务却迟迟不能恢复。每次变更上线更是提心吊胆,担心会成为压死骆驼的最后一根稻草,导致服务雪崩。


在需求终于缓下来后,leader 给我们定下目标,限我们在两周内把服务性能问题彻底解决。近两周的排查和梳理中,发现并解决了多个性能瓶颈,修改了系统熔断方案,最终实现了服务能处理的 QPS 翻倍,能实现在极高 QPS(3-4倍)压力下服务正常熔断,且能在压力降低后迅速恢复正常,以下是部分问题的排查和解决过程。


服务器高CPU、高负载

首先要解决的问题就是服务导致服务器整体负载高、CPU 高的问题。


我们的服务整体可以归纳为从某个存储或远程调用获取到一批数据,然后就对这批数据进行各种花式变换,最后返回。由于数据变换的流程长、操作多,系统 CPU 高一些会正常,但平常情况下就 CPU us 50% 以上,还是有些夸张了。


我们都知道,可以使用 top 命令在服务器上查询系统内各个进程的 CPU 和内存占用情况。可是 JVM 是 Java 应用的领地,想查看 JVM 里各个线程的资源占用情况该用什么工具呢?


jmc 是可以的,但使用它比较麻烦,要进行一系列设置。我们还有另一种选择,就是使用 jtop,jtop 只是一个 jar 包,它的项目地址在 yujikiriki/jtop, 我们可以很方便地把它复制到服务器上,获取到 java 应用的 pid 后,使用 java -jar jtop.jar [options] 即可输出 JVM 内部统计信息。


jtop 会使用默认参数 -stack n打印出最耗 CPU 的 5 种线程栈。


形如:

Heap Memory: INIT=134217728  USED=230791968  COMMITED=450363392  MAX=1908932608
NonHeap Memory: INIT=2555904  USED=24834632  COMMITED=26411008  MAX=-1
GC PS Scavenge  VALID  [PS Eden Space, PS Survivor Space]  GC=161  GCT=440
GC PS MarkSweep  VALID  [PS Eden Space, PS Survivor Space, PS Old Gen]  GC=2  GCT=532
ClassLoading LOADED=3118  TOTAL_LOADED=3118  UNLOADED=0
Total threads: 608  CPU=2454 (106.88%)  USER=2142 (93.30%)
NEW=0  RUNNABLE=6  BLOCKED=0  WAITING=2  TIMED_WAITING=600  TERMINATED=0
main  TID=1  STATE=RUNNABLE  CPU_TIME=2039 (88.79%)  USER_TIME=1970 (85.79%) Allocted: 640318696
    com.google.common.util.concurrent.RateLimiter.tryAcquire(RateLimiter.java:337)
    io.zhenbianshu.TestFuturePool.main(TestFuturePool.java:23)
RMI TCP Connection(2)-127.0.0.1  TID=2555  STATE=RUNNABLE  CPU_TIME=89 (3.89%)  USER_TIME=85 (3.70%) Allocted: 7943616
    sun.management.ThreadImpl.dumpThreads0(Native Method)
    sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)
    me.hatter.tools.jtop.rmi.RmiServer.listThreadInfos(RmiServer.java:59)
    me.hatter.tools.jtop.management.JTopImpl.listThreadInfos(JTopImpl.java:48)
    sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    ... ...

通过观察线程栈,我们可以找到要优化的代码点。


在我们的代码里,发现了很多 json 序列化和反序列化和 Bean 复制耗 CPU 的点,之后通过代码优化,通过提升 Bean 的复用率,使用 PB 替代 json 等方式,大大降低了 CPU 压力。


熔断框架优化

服务熔断框架上,我们选用了 Hystrix,虽然它已经宣布不再维护,更推荐使用 resilience4j 和阿里开源的 sentinel,但由于部门内技术栈是 Hystrix,而且它也没有明显的短板,就接着用下去了。


先介绍一下基本情况,我们在控制器接口最外层和内层 RPC 调用处添加了 Hystrix 注解,隔离方式都是线程池模式,接口处超时时间设置为 1000ms,最大线程数是 2000,内部 RPC 调用的超时时间设置为 200ms,最大线程数是 500。


响应时间不正常

要解决的第一个问题是接口的响应时间不正常。在观察接口的 access 日志时,可以发现接口有耗时为 1200ms 的请求,有些甚至达到了 2000ms 以上。由于线程池模式下,Hystrix 会使用一个异步线程去执行真正的业务逻辑,而主线程则一直在等待,一旦等待超时,主线程是可以立刻返回的。所以接口耗时超过超时时间,问题很可能发生在 Hystrix 框架层、Spring 框架层或系统层。


推荐一个 Spring Boot 基础教程及实战示例: https://github.com/javastacks/spring-boot-best-practice


这时候可以对运行时线程栈来分析,我使用 jstack 打印出线程栈,并将多次打印的结果制作成火焰图(参见 应用调试工具-火焰图)来观察。

image.png

如上图,可以看到很多线程都停在 LockSupport.park(LockSupport.java:175) 处,这些线程都被锁住了,向下看来源发现是 HystrixTimer.addTimerListener(HystrixTimer.java:106), 再向下就是我们的业务代码了。


Hystrix 注释里解释这些 TimerListener 是 HystrixCommand 用来处理异步线程超时的,它们会在调用超时时执行,将超时结果返回。而在调用量大时,设置这些 TimerListener 就会因为锁而阻塞,进而导致接口设置的超时时间不生效。


接着排查调用量为什么 TimerListener 特别多。


由于服务在多个地方依赖同一个 RPC 返回值,平均一次接口响应会获取同样的值 3-5 次,所以接口内对这个 RPC 的返回值添加了 LocalCache。排查代码发现 HystrixCommand 被添加在了 LocalCache 的 get 方法上,所以单机 QPS 1000 时,会通过 Hystrix 调用方法 3000-5000 次,进而产生大量的 Hystrix TimerListener。


代码类似于:

@HystrixCommand(
        fallbackMethod = "fallBackGetXXXConfig",
        commandProperties = {
                @HystrixProperty(name = "execution.isolation.thread.timeoutInMilliseconds", value = "200"),
                @HystrixProperty(name = "circuitBreaker.errorThresholdPercentage", value = "50")},
        threadPoolProperties = {
                @HystrixProperty(name = "coreSize", value = "200"),
                @HystrixProperty(name = "maximumSize", value = "500"),
                @HystrixProperty(name = "allowMaximumSizeToDivergeFromCoreSize", value = "true")})
public XXXConfig getXXXConfig(Long uid) {
    try {
        return XXXConfigCache.get(uid);
    } catch (Exception e) {
        return EMPTY_XXX_CONFIG;
    }
}

修改代码,将 HystrixCommand 修改到 localCache 的 load 方法上来解决这个问题。此外为了进一步降低 Hystrix 框架对性能的影响,将 Hystrix 的隔离策略改为了信号量模式,之后接口的最大耗时就稳定了。而且由于方法都在主线程执行,少了 Hystrix 线程池维护和主线程与 Hystrix 线程的上下文切换,系统 CPU 使用率又有进一步下降。


但使用信号量隔离模式也要注意一个问题:信号量只能限制方法是否能够进入执行,在方法返回后再判断接口是否超时并对超时进行处理,而无法干预已经在执行的方法,这可能会导致有请求超时时,一直占用一个信号量,但框架却无法处理。


服务隔离和降级

另一个问题是服务不能按照预期的方式进行服务降级和熔断,我们认为流量在非常大的情况下应该会持续熔断时,而 Hystrix 却表现为偶尔熔断。


最开始调试 Hystrix 熔断参数时,我们采用日志观察法,由于日志被设置成异步,看不到实时日志,而且有大量的报错信息干扰,过程低效而不准确。后来引入 Hystrix 的可视化界面后,才提升了调试效率。


Hystrix 可视化模式分为服务端和客户端,服务端是我们要观察的服务,需要在服务内引入 hystrix-metrics-event-stream 包并添加一个接口来输出 Metrics 信息,再启动 hystrix-dashboard 客户端并填入服务端地址即可。

image.png

通过类似上图的可视化界面,Hystrix 的整体状态就展示得非常清楚了。


由于上文中的优化,接口的最大响应时间已经完全可控,可以通过严格限制接口方法的并发量来修改接口的熔断策略了。假设我们能容忍的最大接口平均响应时间为 50ms,而服务能接受的最大 QPS 为 2000,那么可以通过 2000*50/1000=100 得到适合的信号量限制,如果被拒绝的错误数过多,可以再添加一些冗余。


这样,在流量突变时,就可以通过拒绝一部分请求来控制接口接受的总请求数,而在这些总请求里,又严格限制了最大耗时,如果错误数过多,还可以通过熔断来进行降级,多种策略同时进行,就能保证接口的平均响应时长了。


熔断时高负载导致无法恢复

接下来就要解决接口熔断时,服务负载持续升高,但在 QPS 压力降低后服务迟迟无法恢复的问题。


在服务器负载特别高时,使用各种工具来观测服务内部状态,结果都是不靠谱的,因为观测一般都采用打点收集的方式,在观察服务的同时已经改变了服务。例如使用 jtop 在高负载时查看占用 CPU 最高的线程时,获取到的结果总是 JVM TI 相关的栈。


不过,观察服务外部可以发现,这个时候会有大量的错误日志输出,往往在服务已经稳定好久了,还有之前的错误日志在打印,延时的单位甚至以分钟计。大量的错误日志不仅造成 I/O 压力,而且线程栈的获取、日志内存的分配都会增加服务器压力。而且服务早因为日志量大改为了异步日志,这使得通过 I/O 阻塞线程的屏障也消失了。


之后修改服务内的日志记录点,在打印日志时不再打印异常栈,再重写 Spring 框架的 ExceptionHandler,彻底减少日志量的输出。结果符合预期,在错误量极大时,日志输出也被控制在正常范围,这样熔断后,就不会再因为日志给服务增加压力,一旦 QPS 压力下降,熔断开关被关闭,服务很快就能恢复正常状态。


Spring 数据绑定异常

另外,在查看 jstack 输出的线程栈时,还偶然发现了一种奇怪的栈。

at java.lang.Throwable.fillInStackTrace(Native Method)
at java.lang.Throwable.fillInStackTrace(Throwable.java:783)
  - locked <0x00000006a697a0b8> (a org.springframework.beans.NotWritablePropertyException)
  ...
org.springframework.beans.AbstractNestablePropertyAccessor.processLocalProperty(AbstractNestablePropertyAccessor.java:426)
at org.springframework.beans.AbstractNestablePropertyAccessor.setPropertyValue(AbstractNestablePropertyAccessor.java:278)
  ...
at org.springframework.validation.DataBinder.doBind(DataBinder.java:735)
at org.springframework.web.bind.WebDataBinder.doBind(WebDataBinder.java:197)
at org.springframework.web.bind.ServletRequestDataBinder.bind(ServletRequestDataBinder.java:107)
at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:161)
 ...
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)

jstack 的一次输出中,可以看到多个线程的栈顶都停留在 Spring 的异常处理,但这时候也没有日志输出,业务也没有异常,跟进代码看了一下,Spring 竟然偷偷捕获了异常且不做任何处理。

List<PropertyAccessException> propertyAccessExceptions = null;
List<PropertyValue> propertyValues = (pvs instanceof MutablePropertyValues ?
  ((MutablePropertyValues) pvs).getPropertyValueList() : Arrays.asList(pvs.getPropertyValues()));
for (PropertyValue pv : propertyValues) {
try {
  // This method may throw any BeansException, which won't be caught
  // here, if there is a critical failure such as no matching field.
  // We can attempt to deal only with less serious exceptions.
  setPropertyValue(pv);
}
catch (NotWritablePropertyException ex) {
  if (!ignoreUnknown) {
    throw ex;
  }
  // Otherwise, just ignore it and continue...
}
... ...
}

结合代码上下文再看,原来 Spring 在处理我们的控制器数据绑定,要处理的数据是我们的一个参数类 ApiContext。


控制器代码类似于:


@RequestMapping("test.json")

public Map testApi(@RequestParam(name = "id") String id, ApiContext apiContext) {}

1

按照正常的套路,我们应该为这个 ApiContext 类添加一个参数解析器(HandlerMethodArgumentResolver),这样 Spring 会在解析这个参数时会调用这个参数解析器为方法生成一个对应类型的参数。可是如果没有这么一个参数解析器,Spring 会怎么处理呢?


答案就是会使用上面的那段”奇怪”代码,先创建一个空的 ApiContext 类,并将所有的传入参数依次尝试 set 进这个类,如果 set 失败了,就 catch 住异常继续执行,而 set 成功后,就完成了 ApiContext 类内一个属性的参数绑定。


而不幸的是,我们的接口上层会为我们统一传过来三四十个参数,所以每次都会进行大量的”尝试绑定”,造成的异常和异常处理就会导致大量的性能损失,在使用参数解析器解决这个问题后,接口性能竟然有近十分之一的提升。


小结

性能优化不是一朝一夕的事,把技术债都堆到最后一块解决绝不是什么好的选择。平时多注意一些代码写法,在使用黑科技时注意一下其实现有没有什么隐藏的坑才是正解,还可以进行定期的性能测试,及时发现并解决代码里近期引入的不安定因素。

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
监控 前端开发 JavaScript
不了解 QPS、TPS、RT、并发数、吞吐量,劝你简历别写熟悉高并发
分布式、微服务、Service Mesh目前都是大家耳熟能详的词语了,现在随便一个互联网公司说出来大家都是在搞微服务。 但我们搞来搞去,怎么样来衡量一个应用当前的状态到底是怎么样的?到底需不需要扩容?是需要横向扩容还是进行项目重构?
|
7月前
|
存储 缓存 算法
jvm性能调优实战 - 34十万QPS的社交APP 如何优化GC性能提升3倍?
jvm性能调优实战 - 34十万QPS的社交APP 如何优化GC性能提升3倍?
154 0
jvm性能调优实战 - 34十万QPS的社交APP 如何优化GC性能提升3倍?
|
7月前
|
Java
jvm性能调优 - 17案例实战_每日上亿请求量的电商系统 老轻代垃圾回收参数如何优化
jvm性能调优 - 17案例实战_每日上亿请求量的电商系统 老轻代垃圾回收参数如何优化
204 0
|
7月前
|
人工智能 算法 搜索推荐
某国有银行业务收益提升30倍,它究竟是怎么做到的!
在激烈的银行竞争环境下,释放存量客户的复购潜力成为关注的重点。然而,目前银行销售理财产品过程中存在一系列问题,其中一个主要原因是过度依赖理财经理的个人经验。国有银行也难以避免这些问题在目标客户定位和营销执行过程中的出现。
|
缓存 算法 Cloud Native
面试技巧:如何在有限时间内优化代码性能
面试技巧:如何在有限时间内优化代码性能
75 0
|
设计模式 运维 Java
硬核!阿里P8耗时3月撰写700页性能优化笔记:程序优化提升了7倍
前言 在我看来,Java性能优化是Java进阶的必经之路,性能优化作为Java工程师必备的一种技术,一直热度不减。 Java是目前软件开发领域中使用最广泛的编程语言之一。Java应用程序在许多垂直领域(银行、电信、医疗保健等)中都有广泛使用。帮助开发者通过专注于JVM内部,性能调整原则和最佳实践,以及利用现有监测和故障诊断工具,来提升应用程序在商业环境中的性能。
|
消息中间件 缓存 监控
小记 | 一周上线百万级高并发系统
本文是鱼皮在腾讯实习期间,从零开始一周紧急上线百万高并发系统的相关经验、思路及感悟,分享给大家。花 5 分钟阅读本文,你将收获:1. 加深对实际工作环境、工作状态的了解2. 学习高并发系...
658 0
|
算法 前端开发 Java
面试机会增加100倍,建议收藏!
面试机会增加100倍,建议收藏!
124 0
|
安全 编译器 C++
提升面试成功率:深入理解C++11新特性
C++11是C++语言的一个重大更新,引入了许多新特性,包括自动类型推导、lambda表达式、右值引用、智能指针等等。这些新特性使得C++更加现代化、高效、易用。也是面试容很容易被问到一个问题,下面我将简要介绍一些C++11的新特性
294 0
提升面试成功率:深入理解C++11新特性
|
存储 缓存 NoSQL
每秒30W次的点赞业务,怎么优化?
30WQPS的点赞计数业务,如何设计?
1120 0
每秒30W次的点赞业务,怎么优化?