首页 工具 问题

前言

这讲述的是一个没有解决的问题，希望下次遇见能解决

起因

3月13号 上午，同事反馈基础组提供的调度平台未能按时调用他们的服务。根据配置的时间间隔，存在延迟高达28倍的情况，这让我立即开始排查这个“古董”。记得上次出问题还是因为线程数未释放，这次难道是内存问题导致的卡顿吗？

问题描述

  • 任务 2 秒执行一次，3月13号 10:20:00 - 10:21:00 时间段仅在10:20:06 时触发一次，再之后是 10:21:02 分触发，间隔56秒，按配置时间相当于少执行了27次。
  • 调度平台内部调度使用 Quartz 任务调度框架，版本1.8.6 (比较低)
  • 10:20:00 - 10:21:00 时间段，调度平台一共触发了 65 个任务，相同时间段前三天11、12、13号 351、350、350个任务，相差巨大
  • 日志无明显异常输出，值得注意的是在这段时间多了很多Handling the first 10 triggers that missed their scheduled fire-time. More misfired triggers remain to be processed. 类似说明有任务未在规定时间执行，这是 Quartz 的日志。

分析过程

分析未在规定时间执行的日志来源

定位来源：org.quartz.impl.jdbcjobstore.JobStoreSupport#recoverMisfiredJobs
根据注释或类名分析此处逻辑

  1. 逻辑入口：org.quartz.impl.jdbcjobstore.JobStoreSupport.MisfireHandler#run
  2. 这线程是不停的查询要 triggers 是否有异常的（比如规定时间未执行）
  3. 更新 triggers 的状态以及执行时间，实现恢复任务 (因为有另一个线程根据指定时间状态拿数据)
    流程图如下
    20240315124731877.png

结论：这个行日志无法定位问题

Quartz 调度框架理解

一句话介绍

我认为 Quartz 任务调度框架原理就是：单线程通过循环拿任务，将拿到的任务放到线程池执行。
20240315140903753.png

单线程拿任务逻辑

首先，这个应用部署了两个实例。按照之前所描述的Quartz原理，这种部署方式确实会存在任务重复执行的问题。为了解决这一问题，Quartz 采用了加锁机制，但并不是依赖于Redis或其他中间件进行限制。它通过在MySQL数据库悲观锁来实现。加锁逻辑主要是查询qrtz_locks表中的某条记录，并在查询末尾添加for update语句，触发行锁。当应用其他部署的实例尝试执行相同操作时，它们将受到阻塞，必须等待当前事务提交或回滚。通过这种方式，Quartz 成功防止了任务的重复执行。

然而，这种机制也带来了一些性能问题。因为每次执行任务前都需要进行数据库加锁操作，这在一定程度上增加了系统的开销，尤其是在高并发场景下，可能会成为性能瓶颈。

逻辑图如下
1711358183618.png
文字

  1. 应用实例A和任务调度器尝试执行一个任务。
  2. 任务调度器查询qrtz_locks表，并尝试对某条记录加上悲观锁（for update）。
  3. 如果成功加上锁，应用实例A的任务得以执行；否则，它将被阻塞，等待锁释放。
  4. 同时，如果应用实例B也尝试执行相同的任务，它将因为无法获取到锁而被阻塞。
  5. 当应用实例A的任务执行完毕后，它释放锁，此时应用实例B可以获取到锁并执行任务。

排查是哪个环节慢了

quartz 的日志是真的少，我最有用的可能就是Handling 1 trigger(s) that missed their scheduled fire-time日志，说明很多任务未在规定时间内执行，看了线程数和堆栈信息也没什么异常。
系统内部监控任务执行日志也正常，就是慢了，看起来就是执行日志打印慢了

直到通过阿里云的RDS监控，cpu，内存都没问题，仅发现这系统的几个会话Sleep耗时比较久，但也无法看出在执行什么sql语句，最后反正也会执行，业务死锁
阿里云整体 sql 记录没有开，慢 sql 也没有。

为了解决问题，就先重启了。

重启后在阿里云监控筛选发现了如下监控，再经过几天查看，基本可以确认加锁执行的事务有关系，再加上会话数下降了一倍多。
只能得出。

  1. 有什么误操作导致 quartz 的补偿补救机制逻辑 bug 导致锁争抢慢了
  2. 要么就是锁住后事务执行的其它sql有数据量问题，导致sql慢了

1711336844269.png

最后解决方案，先补上阿里云 ARMS 监控，以及对 quartz 1.8.6版本源码增加日志，重启后下次分析

第一次遇见总结

首先排查过程是比较”随意“的，有多方面因素，如系统非常重要，改动影响非常大（比如通过Arthas 分析），也有是老系统，JDK1.8，各种监控也没开启，个人权限也不够。
个人分析过程：纯日志，看源码，看GC日志，查活跃线程数都做了，但想到还不够多，申请 RDS 权限太慢了，因为其它事情想晚点分析，没想到 RDS 会自动删除之前的记录，导致无法分析什么时候行锁耗时上来的，虽然上来了估计也无法定位问题。
等待下次分析

  1. 先看什么时候上来的
  2. 再看对应的日志有无特殊
  3. 再看 arms 监控有无耗时长的线程 (因为JDK1.7，无法使用 arthas 做主动剖析)

感谢语

感谢你的阅读，如果你遇到了这个类似的问题，希望你能告诉我答案

推荐文章

推荐一篇 Quartz 2.3.0 版本的分析文章
冷饭新炒 | 深入Quartz核心运行机制