Cacheable注解导致线程block

优质博文：IT-BLOG-CN

环境：jdk8/tomcat7

一、问题现象

应用系统再一次发布回退时，cpu util突然徒增到100%以上，与此同时，服务响应时间大幅度增加，依赖该服务的应用接连抛出超时异常，发生熔断。

二、问题分析

根据实际监控情况，发现除了cpu负载和超时引起的错误突然提高外，剩余指标mem并无明显变化，所以排除掉OOM的情况，推测可能与回退时生产的并发请求相关。

根据上述分析，在cat上对堡垒机进行ThreadDump(一个选项栏)，发现如下异常：
【1】http的线程数在blacking时出现大幅度增加，增大到线程池最大值1024。blocking的线程数也是大幅度增长，由于业务代码中没有加锁的操作，所以第一反应是很不合理。
【2】http线程出现大量锁竞争，并且都是在相同的方法中获取锁时产生的block。

当我们点击block中的线程时，可以看到如下详细信息：

当点击 锁竞争详情 按钮时，可以看到具体的错误代码位置。

三、问题排查

代码分析： 点击锁竞争详情可以看到在Excutable类中的declaredAnnotations()方法存在临界区，该方法是一个同步方法，存在加锁的情况。

结合调用栈可知是服务获取城市基础数据时，调用了ROC框架中的标有@Cacheable注解的getData()缓存方法，其中AOP代码中会调用方法Method对象的getAnnotation()方法，进而调用了Excutable类的declaredAnnotations()来解析注解数据。

Executable.class

private transient volatile Map<Class<? extends Annotation>, Annotation> declaredAnnotations;
private synchronized  Map<Class<? extends Annotation>, Annotation> declaredAnnotations() {if (declaredAnnotations == null) {// 获取declaredAnnotations}return declaredAnnotations;
}

CityCacheRepository.class

@Cacheable(cacheNames = Cache.BASIC_DATA_CACHE_NAME, key = "#key")
public CityDataWrapper getData(String key) {// 计算返回CityDataWrapper
}

原因分析：
【1】分析业务代码可知，代码中存在三处调用CityRepository.getData()方法，但由于业务代码中存在不合理的无效调用和多层嵌套循环，使得一次http请求会产生多达200次的getData()方法调用。
【2】服务的单台机器的tps可达80，所以计算下来每秒getData()方法调用次数可达16000次，这使得接入流量的瞬间在declaredAnnotations()方法上产生线程阻塞，并迅速消费完线程池中的所有线程，还导致cpu负载变高，响应变量的现象。

四、问题总结

解决办法： 减少getData()方法的调用次数，优化后的一次http请求，平均只需要调用7次getData()方法，并通过压测发现cpu利用率不再异常升高，也不再出现线程block的情况。

思考总结：
【1】在业务代码中，尤其是在高qps场景下，需要注意服务调用过程中的临界区，压测作为一种重要的测试手段，通过并发测试可以提高暴露线程安全的问题。
【2】在业务多层嵌套的场景中，任何一种方法的不当调用可能就会产生令人难以置信的调用风暴，尤其是在高qps情况下更需要注意，合理减少嵌套层数或者减少调用次数。

五、深入拓展

对于@Cacheable注解，由于declaredAnnotations()方法存在临界区，所以这里需要测量它对于普通服务一次请求调用的影响范围。

环境： 1c2g的docker机器，order jdk8/tomcat7，其线程池保持默认的1024个。应用中定义一个使用@cacheable注解的方法，并暴露出rest接口。

压测过程：
【1】使用jmeter请求rest接口，并调用@Cacheable注解的方法，并保证一次http请求会调用一次@Cacheable注解的方法。
【2】通过不断提升qps，观察服务响应结果错误率、响应时间RT以及机器cpu状态，确保在结果错误率在0.1%以下时，观察各项指标数据。

压测结果：
【1】通过观察，在0.1%的错误率下，压测的qps最高可达800qps，此时的平均RT为35ms，根据c=qps*RT，可以计算出该应用的最大并发数c=30。
【2】此时观察机器状态，发现cpu利用率达到74%，并且没有出现线程block状态。

压测结论： 一次http请求调用一次@Cacheable注解方法场景下，服务在接收所能承受的最大qps时，其并没有出现线程block的情况，说明在此场景下，并不需要关注@Cacheable带来的limit。

一次请求调用多次Cacheable方法时对服务的影响

环境： 与上述一致

压测过程： 这里使用jmeter请求rest接口，与上述不同的是http请求传递一个数值参数，保证一次请求可以循环调用指定数量的@Cacheable方法。

压测结果：
【1】通过观察qps=100的时候，当循环次数达到700左右的时候，也会出现线程block的情况。
【2】此时cpu利用率超过100%，响应时间会大幅度增加，但由于qps没有达到最大值，所以错误率仍在0.1下。

压测结果：
【1】此时可以计算出在qps=100时，@Cacheable注解方法调用qps达到7w左右，此时会出现线程阻塞现象，所以在一次请求中如果多次调用@Cacheable方法需要注意可能存在线程阻塞影响。
【2】由于在不同qps下，其线程并发情况不一样，所以在不同的qps下其线程block的循环次数也是不一样的，其都需要根据具体情况而定。
【3】不管是一次请求调用一次@Cacheable方法还是一次请求调用多次@Cacheable方法，都无法精确计算出由于@Cacheable导致阻塞的并发线程数，所以这里只能通过qps的维度来衡量线程阻塞的阈值。

Excutable 类

【1】在jdk1.8中declaredAnnotations()方法加锁其实是通过一个单例实现的，使得线程在调用该方法时，无论单例字段是否有数据，都需要先拿锁，所以在多线程调用的情况下，会出现线程阻塞现象。
【2】@Cacheable注解代表的是一大类使用注解的方法，因此对于运行时的注解，一般都需要解析注解里的数据，也就需要调用declaredAnnotations()方法，所以在调用服务时，如果存在高频使用包括但不限于@Cacheable注解的时候，防止出现线程阻塞，最好的方式就是做压测。

jdk8中Executable.class类

// 单例字段
private transient volatile Map<Class<? extends Annotation>, Annotation> declaredAnnotations;
// 线程进来先拿锁，这里会出现线程阻塞
private synchronized  Map<Class<? extends Annotation>, Annotation> declaredAnnotations() {if (declaredAnnotations == null) {// 获取declaredAnnotations}return declaredAnnotations;
}

jdk11中对该方法的实现进行了优化，使用了懒加载的线程安全的单例模式，并不再方法上加锁，所以这块不在是瓶颈，不会长时间出现线程阻塞现象。

// 单例字段
private transient volatile Map<Class<? extends Annotation>, Annotation> declaredAnnotations;
// 线程进来先观察字段是否为null，所以只有在第一次初始化字段时，才会出现部分线程的阻塞，之后不再存在阻塞现象
private Map<Class<? extends Annotation>, Annotation> declaredAnnotations() {Map<Class<? extends Annotation>, Annotation> declAnnos;if ((declAnnos = declaredAnnotations) == null) {synchronized (this) {if ((declAnnos = declaredAnnotations) == null) {// 获取declaredAnnotations}}}return declAnnos;
}