记一次线上排查异步任务失败问题
问题描述
今天有客服反馈说,从某一天开始到现在有很一些订单属于没有代买状态(可以理解为没有创建订单的意思)。
然后我就登上线上机器查看相关方法的调用日志。从日志中看出,发现了SQL异常日志,没有调用到其他系统的创建订单方法。
异常日志如下:
2020-05-10 16:43:05,721 ERROR ThreadPoolTaskExecutor-82 interceptor.SimpleAsyncUncaughtExceptionHandler:39 - Unexpected exception occurred invoking async method: public void xxx.xxx.xxxServiceImpl.placeOrder(java.lang.String) throws xxx.xxx.ServerExceptionorg.springframework.jdbc.BadSqlGrammarException: StatementCallback; bad SQL grammar [...省略...错误的sql]; nested exception is java.sql.SQLSyntaxErrorException: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near "xxxxxxsql" at line 1
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:234)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1442)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:387)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:451)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:461)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:472)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:479)
at com.xeshop.dao.db.impl.OrderDaoImpl.countOrder(OrderDaoImpl.java:78)
...省略...
现象
系统分为两个web模块,API 和 ADMIN 模块,线上订单自动下单是 API 模块。ADMIN 模块用于后台管理。
我通过 admin 模块手动触发创建订单接口,发现了只打印了创建订单的日志,然后过了一段时间(大概 10 分钟)才在工作日志中发现下单失败。
工日日志记录了失败的原因,原因是最新上线的一个功能因为某个特殊参数导致的 SQL 错误,从而导致的下单方法失败。
这里有几个问题:
- 为什么线上触发自动异步下单时,只是打了一行日志以及相关的错误日志,没有记录工作日志?
- 为什么现在手动调用异步下单,过了一段时间才出现工作日志?
分析
仔细看下代码的异步信息和重试配置相关的代码。
admin 模块配置
@EnableWebSecurity@EnableRetry
@EnableEurekaClient
@EnableCircuitBreaker
@EnableAspectJAutoProxy(proxyTargetClass = true, exposeProxy = true)
public class AdminStartupApplication {
public static void main(String[] args) {
SpringApplication app = new SpringApplication(AdminStartupApplication.class);
app.run(args);
}
}
api 模块配置
@EnableEurekaClient@EnableCircuitBreaker
@EnableAspectJAutoProxy(proxyTargetClass = true, exposeProxy = true)
public class ApiStartupApplication {
public static void main(String[] args) {
SpringApplication app = new SpringApplication(ApiStartupApplication.class);
app.run(args);
}
}
执行创建订单的方法如下
// 创建订单方法,异步+重试
@Override
@Async
@Retryable(value = Exception.class, backoff = @Backoff(delay = 180 * 1000, maxDelay = 600 * 1000, multiplier = 2))
public void createOrder(String orderSn) throws ServerException {
log.info("create order, orderSn:{}", orderSn);
// do something...
}
// 重试失败调用的方法
@Recover
private void recordCreateOrderFailedLog(Exception e, String orderSn) throws ServerException {
log.info("create order failed, error msg: {} ", e.getMessage());
// 添加工作日志
}
异步任务线程池的配置信息
@Configuration@EnableAsync
@EnableScheduling
public class ServiceConfig implements AsyncConfigurer, SchedulingConfigurer {
@Override
public Executor getAsyncExecutor() {
ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
// 核心线程数是 100
executor.setCorePoolSize(100);
// 最大线程数 500
executor.setMaxPoolSize(500);
// 任务队列容量 500
executor.setQueueCapacity(500);
/*
线程池拒绝策略:
ABORT(缺省):抛出TaskRejectedException异常,然后不执行
DISCARD:不执行,也不抛出异常即放弃该线程
DISCARD_OLDEST:丢弃queue中最旧的那个任务
CALLER_RUNS:不在新线程中执行任务,而是由调用者所在的线程来执行(不再异步),但是如果主线程已经结束,则任务会被拒绝
*/
executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
executor.initialize();
return executor;
}
// 其他配置
}
分析下代码:
创建订单的方法是异步方法,通过配置的异步任务线程池,来执行该方法。
线程池的核心大小是 100 个线程,最大线程数 500,任务队列容量是 500 ,采用的任务拒绝策略是 CallerRunsPolicy 主线程执行。
下单方法的重试策略配置如下:
@Retryable(value = Exception.class, backoff = @Backoff(delay = 180 * 1000, maxDelay = 600 * 1000, multiplier = 2))
介绍一下几个注解
- @EnableRetry能否重试。当proxyTargetClass属性为true时,使用CGLIB代理。默认使用标准JAVA注解。在spring Boot中此参数写在程序入口即可。
- @Retryable 标注此注解的方法在发生异常时会进行重试
- value:指定处理的异常类
- include:指定处理的异常类和value一样,默认为空,当exclude也为空时,默认所有异常
- exclude:指定异常不处理,默认空,当include也为空时,默认所有异常
- maxAttempts:最大重试次数。默认3次
- backoff: 重试等待策略。默认使用@Backoff注解
- @Backoff 重试等待策略
- 不设置参数时,默认使用FixedBackOffPolicy(指定等待时间),重试等待1000ms
- 设置delay,使用FixedBackOffPolicy(指定等待时间),重试等待填写的时间
- 设置delay和maxDealy时,重试等待在这两个值之间均态分布
- 设置delay、maxDealy、multiplier,使用 ExponentialBackOffPolicy(指数级重试间隔的实现 ),multiplier即指定延迟倍数,比如delay=5000l,multiplier=2,则第一次重试为5秒,第二次为10秒,第三次为20秒……
- @Recover 用于@Retryable重试失败后处理方法,此注解注释的方法参数一定要是@Retryable抛出的异常,否则无法识别,可以在该方法中进行日志处理。
value 是 Exception.class,backoff 是重试失败回退策略,delay 参数表示延迟执行的时间,单位毫秒,maxDelay 参数表示最大延迟执行的时间,单位毫秒,multiplier 参数下一次回退乘法倍率。
上面的配置的意思是说,这个方法执行时遇到 Exception 类型的异常可以进行重试,默认的重试次数是 3 次。并且是以重试回退策略的方式执行重试。重试回退策略是:以 180 秒的延迟时间,每次重试延迟时间以二倍倍率增长,最大延迟时间是 600 秒,即,第一次重试时间是 180 秒,第二次是 180 * 2 = 360 秒,第三次是 (360 * 2 = 640 秒)< 600 秒,是 600 秒,也就是 10 分钟。
三次重试失败后,执行 recordCreateOrderFailedLog 方法,打印错误日志,记录工作日志数据。
那么,我们解决下上面提到的问题:
- 为什么线上触发自动异步下单时,只是打了一行日志,没有记录到工作日志?
答:
线上触发自动异步下单的代码是在 api 模块中,API 模块中的 springboot 启动类上没有增加 @EnableRetry 注解,所以下单方法先执行打印日志代码那进行日志打印,然后执行逻辑操作,此时发生了 SQL异常,不会执行重试操作,当然也不会执行到带有 @Recover 注解的方法,自然也不会记录工作日志了。
刚开始找问题的思路,一直围绕着线程池队列满的情况下任务被拒绝策略方向上,后来想了想那时候订单量并不是很多,线程池中的核心线程数很充裕,不会出现任务被拒绝的情况,并且任务已经被执行,哪怕是重试也不会出现被线程池拒绝的情况。
- 为什么现在手动调用异步下单,过了一段时间才出现工作日志?
答:
手动调用异步下单功能是在 admin 模块中,改模块使用 @EnableRetry 启动了重试功能,所以该下单方法在出现了 BadSqlGrammarException 异常(属于 Exception 异常),触发了重试,并且按照重试失败回退策略重试执行了三次,一共 600 秒,然后三次重试都失败,最后被 @Recover 注解标记的方法 recordCreateOrderFailedLog 方法 cover 住,记录工作日志。
解决
- 修复特殊参数导致 SQL 的错误的 BUG;
- 在 api 模块的 springboot 启动类上加入 @EnableRetry 注解,开启支持重试操作功能;
- 重新上线,解决问题。
总结
- 开发完毕业务除了测试一些基本 case,边缘的 case 也要考虑到;
- 平时自己开发代码时,遇到别人写的代码不懂的需要及时查阅资料,不能一知半解;
- 项目中用到相关的框架 API 技术需要充分的学习它的文档,了解各个参数说明和应用场景,不能为了用而用;
- 遇到问题先解决,事后及时做总结。
参考
在Spring Boot中使用Spring Retry
以上是 记一次线上排查异步任务失败问题 的全部内容, 来源链接: utcz.com/z/516395.html