1、 异常问题:2023-03-16 15:48:08左右用户反馈应用发布卡住
用户在内部构建发布平台上构建发布操作,超过10~20分钟均显示“等待执行”
收到问题后,我们立即登录机器,top&jstat分析机器负载和jvm均为正常状态。
同时结合对应系统页面接口能正常返回数据,只是任务不能正常运行,基本判断与翼集内流水线任务运行功能有关。
查询工程代码,找到对应定时任务触发器核心代码逻辑,检索关键日志,发现自下午3点36开始,后有半个多小时,未扫描待运行任务逻辑。
2、 排查解决过程
1、2023-03-16 16:56:00打印当时jstack日志,分析进程信息:
可以看到369个线程在time_waiting,线程无blocked、waiting等需重点关注状态线程情况。
疑问:为什么这么多线程在time_waiting?
2、继续分析当时业务日志,确认卡顿原因,得到一些推断。
对着代码来看,
发现:线程只执行到了43行代码处,超过半小时没有执行到50行代码处。
由于在执行任务时,没有超时保护,对应定时器在执行某个子任务时如果子任务一直不正常结束,整个定时器将不再继续执行。
到这里,基本确认到:3/16下午3点半时,在执行673012这个任务时发生了半小时内未结束,进而导致翼集当时半小时一直没有运行用户新触发的流水线。
这里同时观测到,有不少time_waiting线程属于okhttp线程,同时结合卡顿发生时,重启了jenkins能临时恢复系统的情况,作出猜测:任务在执行时,由于一直拿不到jenkins连接,所以一直在time_waiting。
同时,翼集生产环境在经过重启服务端和jenkins后,流水线功能逐渐恢复。
3、2023-03-16 22:00:00 增加日志,更新服务
由于之前的业务执行里,缺少对应JenkinsClient执行日志和一些线程业务日志,紧急添加日志。示例如下,在jenkinsApi入口处增加日志:
4、 2023-03-17 20:22:00 构建发布慢问题重现
拿到业务日志过滤发现,在3/17 19:46时开始jenkins调用出现大量无响应问题。
同时,参考对应日志上的线程池属于agent-caller标识,结合工程代码,发现这段业务作用是:
调用jenkinsApi拉起jenkinsAgent连接应用的主机执行查询进程等指令逻辑。
同时结合周四、周五的请求日志,均在此故障时间点,均产生“云桌面”租户在翼集内查看主机部署详情记录,由此推断:
主机部署详情查询时会触发agent-caller调用,而agent-caller的批量调用会导致jenkins服务端连接占满,且长时间占用不释放;而其他任务调用jenkinsApi时会一直阻塞等待获取连接。
到这里,卡顿的根因基本理清:
1、任务流转的执行方式有缺陷:即子任务如果长时间不结束,整个父任务不会继续执行。
2、jenkinsApi调用未配置超时时间:agent-caller批量调用时,会导致其他jenkinsApi一直停留在等待获取连接的状态。
5、 确认对应解决方案并修改代码
针对1,由于是整个系统执行架构,不好完全改造,只能给每个任务设置超时配置。
针对2,在jenkins服务端agent-caller插件配置超时时间解决。
6、 2023-03-19 22:00:00~23:00 解决方案验证
验证步骤:
1、解决方案更新前,复现故障:登录“云桌面”租户,打开监控运维页面,选择生产环境,部署方式选为主机部署,点击详情。
jenkinsclient返回连接失败,翼集。即故障复现。
2、解决方案对应的组件更新后,重复上述操作,翼集上的流水线功能能正常运行,即初步来看故障得到解决。
3、后记
1、系统出现关键功能卡顿,可根据以下步骤来初步排查
top /top -Hp pid分析进程情况,jstat分析jvm情况,jmap、jstack快照到进程的堆栈状态信息。
2、业务日志分析:
业务日志是关键的信息,根据异常出现的时间日志,以及结合工程代码能有效的帮助做出一些推断。
3、合理的推断并论证:
在进程状态正常,栈日志也无法得到最终的原因时,可根据业务日志、以及当时紧急恢复的变更作出较合理的推测。并根据推测来作出一些必要的复现验证,找出问题原因后再制定相应的优化措施。