搞了 2 周性能优化，QPS 终于翻倍了！
共 10418字，需浏览 21分钟
·
2021-12-17 12:03
来源：https://zhenbianshu.github.io/
服务器高CPU、高负载
jtop，jtop 只是一个 jar 包，它的项目地址在 yujikiriki/jtop， 我们可以很方便地把它复制到服务器上，获取到 java 应用的 pid 后，使用 java -jar jtop.jar [options] 即可输出 JVM 内部统计信息。-stack n打印出最耗 CPU 的 5 种线程栈。另外，JVM 系列面试题和答案全部整理好了，微信搜索互联网架构师，在后台发送：2T，可以在线阅读。形如：
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 框架层或系统层。
这时候可以对运行时线程栈来分析，我使用 jstack 打印出线程栈，并将多次打印的结果制作成火焰图（参见 应用调试工具-火焰图）来观察。
LockSupport.park(LockSupport.java:175) 处，这些线程都被锁住了，向下看来源发现是 HystrixTimer.addTimerListener(HystrixTimer.java:106), 再向下就是我们的业务代码了。@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;
}
}
服务隔离和降级
另一个问题是服务不能按照预期的方式进行服务降级和熔断，我们认为流量在非常大的情况下应该会持续熔断时，而 Hystrix 却表现为偶尔熔断。
最开始调试 Hystrix 熔断参数时，我们采用日志观察法，由于日志被设置成异步，看不到实时日志，而且有大量的报错信息干扰，过程低效而不准确。后来引入 Hystrix 的可视化界面后，才提升了调试效率。
hystrix-metrics-event-stream 包并添加一个接口来输出 Metrics 信息，再启动 hystrix-dashboard 客户端并填入服务端地址即可。
由于上文中的优化，接口的最大响应时间已经完全可控，可以通过严格限制接口方法的并发量来修改接口的熔断策略了。假设我们能容忍的最大接口平均响应时间为 50ms，而服务能接受的最大 QPS 为 2000，那么可以通过 2000*50/1000=100 得到适合的信号量限制，如果被拒绝的错误数过多，可以再添加一些冗余。
这样，在流量突变时，就可以通过拒绝一部分请求来控制接口接受的总请求数，而在这些总请求里，又严格限制了最大耗时，如果错误数过多，还可以通过熔断来进行降级，多种策略同时进行，就能保证接口的平均响应时长了。
熔断时高负载导致无法恢复
接下来就要解决接口熔断时，服务负载持续升高，但在 QPS 压力降低后服务迟迟无法恢复的问题。
不过，观察服务外部可以发现，这个时候会有大量的错误日志输出，往往在服务已经稳定好久了，还有之前的错误日志在打印，延时的单位甚至以分钟计。大量的错误日志不仅造成 I/O 压力，而且线程栈的获取、日志内存的分配都会增加服务器压力。而且服务早因为日志量大改为了异步日志，这使得通过 I/O 阻塞线程的屏障也消失了。
之后修改服务内的日志记录点，在打印日志时不再打印异常栈，再重写 Spring 框架的 ExceptionHandler，彻底减少日志量的输出。结果符合预期，在错误量极大时，日志输出也被控制在正常范围，这样熔断后，就不会再因为日志给服务增加压力，一旦 QPS 压力下降，熔断开关被关闭，服务很快就能恢复正常状态。
另外，Spring 系列面试题和答案全部整理好了，微信搜索互联网架构师，在后台发送：面试，可以在线阅读。
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.心态崩了！税前2万4，到手1万4，年终奖扣税方式1月1日起施行~
