背景:做了一个定时job的需求,本地测试没有问题,上线后发现定时job执行超时,询问相关人员,说是调用下游服务失败,经查看代码,发现逻辑中确实调用了下游服务
排查过程:
1.本地可以正常run,但是上到测试环境有问题,第一个思路是:是不是本地和测试环境的环境变量不一致导致的?
于是仔细对比了本地和测试环境,发现没有区别
2.开启debug模式,发现在debug的过程中,在第一次调用下游服务的时候,偶现可以拿到数据,但基本上拿不到数据,且client报NPE,于是一直在排查为啥没有拿到数据,没有结果
本地去调用第三方服务,相同的参数完全可以拿到数据,到底是为什么呢?
3.debug无果后,直接看日志信息,通过日志发现,在调用下游服务时,第二次拿到的结果为空,那是不是下游服务没有返回?查看了下游服务的日志,发现两次请求都返回了,但是服务能拿到第一次返回结果,拿不到第二次返回结果,且日志中报出了中断异常
4.第一反应中断异常是不是由于线程问题导致的?且从日志中可以看到调用下游的接口是报了Unkown Source,所以当时严重怀疑是线程问题,于是在第二次调用下游服务的时候进行了sleep,但发现解决不了问题
5.最后经过排查发现日志:
com.xxl.job.core.thread.JobThread,这一行日志表示线程池是有超时控制的,既然有超时,那调整下超时时间,果然成功了!!
为什么排查那么久?
1.debug过程中发现client NPE ,误以为问题一定是出现在调用下游服务有问题,且这个NPE让人以为是没有拿到bean,导致无法正常获取数据,在这块上耗费了不少时间
2.有对线程问题进行过怀疑,毕竟报出了中断异常,但一直考虑的是不是两次rpc调用的时候出现问题,导致第二次调用rpc被中断,还是围绕rpc来排查问题
解决和反思:
专注于最初的日志,其实日志中已经报出来是中断异常,但是当时想到的是线程控制,应该可以看到更下沉的日志信息,这样就可以很清楚的看到是定时job超时导致的问题