深入理解 System.currentTimeMillis() 与时区

今天在解答同事对于 Unix Timestamp 的时区问题的疑问时,看到了这篇文章:

深入理解System.currentTimeMillis()

https://coderdeepwater.cn/2020/12/29/java_source_code/currentTimeMillis/

通过阅读发现,虽然该文章对于这个函数调用的原理解释的非常好,但是却在开头处犯了一个致命的错误,误导了我的同事。在这篇文章中,作者说:

深入理解System.currentTimeMillis()

System.currentTimeMills()的返回值取决于Java运行时系统的本地时区!千万不要忘记这一点!
同一时刻,在英国和中国的两个人同时用System.currentTimeMills()获取当前系统时间,其返回值不是一样的,除非手动将操作系统的时区设置成同一个时区(英国使用UTC+0,而中国使用UTC+8,中国比英国快8个小时).

这个观点是完全错误的,正因为这里的错误误导了我的同事,走入了错误的排查方向。

首先说结论:

  1. System.currentTimeMillis() 的返回值与系统时区无关。在一台时区和时间皆设置正确的机器上,这个函数的返回值总是当前时间与 UTC 0 时的 1970年1月1日 0时0分0秒即 1970-01-01 00:00:00 UTC 的差值
  2. 同一时刻,在地球上任意地点的两个人在时区和时间皆设置正确的机器上同时用 System.currentTimeMills() 获取当前系统时间,其返回值一定一样,与时区无关

首先明确几个概念:

  1. 时间:是一个客观存在的物理量,是物质运动变化的表现
  2. 时间单位:人为了方便对时间进行计量,人为定义了年、月、日、时、分、秒、毫秒等一系列时间单位
  3. 公历日期:人为规定的纪年体系,用来记录准确的时间
  4. 时区:由于地球自转的存在,地球上各个地区的日升日落时间并不一致。因此为了使用方便,人为将地球划分成了 24 个时区,每两个相邻时区间的时间表示相差 1 小时
  5. Unix 时间戳:人为规定的用来描述一个确切时间点的系统。以 1970-01-01 00:00:00 UTC 为基点,计算当前时间与基点的秒数差,不考虑闰秒

从这几个概念中,我们可以知道,Unix 时间戳是用于精确描述一个确定的时间点,具体的方式是计算两个时间点之间的秒数差。由于我们的宇宙只有单时间线,所以计算两个确定的时间点之间的秒数差,在地球上任何地方的时间都是一致的。因此我们可以知道,在一个确定的时间点上,地球上所有人计算得到的当前的 Unix 时间戳,都应当是一致的。

那么,为什么还有人遇到不同时区获取到的时间戳不一致的问题呢?这就要说到实际使用中对时间的展示方式了。

一个简单的例子,如果我说现在是北京时间 2020年01月01日 08时00分00秒,那么这可以表示一个准确的时刻。对于同一个时刻,我还可以说,现在是格林威治时间 2020年01月01日 00时00分00秒。这两个句子实际上表达的是同一个时刻。

但是,如果我只说现在是 2020年01月01日 00时00分00秒,那么不能表示一个准确的时刻。因为在句话里,我没有说明时区信息,导致缺失了定位到准确时刻的必要条件。

因此我们可以发现,我们日常说话时的表述,其实都是不精确的。那么在程序员的世界里,我们最容易犯的错误,也跟这个类似。

当我们查看一个服务器的时间信息的时候,大多数人不会关心时区信息。假设现在有一台 UTC 0 时区的服务器,很多人拿到后,在检查服务器时间时,第一反应是这个服务器的时间不对,因为桌面上的时钟是 2020年01月01日 08时00分00秒,而机器告诉我的是 2020年1月1日 00时00分00秒,晚了 8 小时。于是,使用 date -s "2020/01/01 08:00:00" 一把梭,再看机器的时间,完美!

那么这时候,如果我用 System.currentTimeMills()来获取时间戳,得到的是什么呢?得到的当然是 1577865600000,代表北京时间 2020年01月01日 16时00分00秒。因为机器本身运行在 0 时区,对于机器来说,现在是 0 时区的 8 点,那换算到 +8 的北京时区,自然是 16 点。

这也就是前面为何一直强调时区和时间皆设置正确的原因。刚说的案例就是典型的时间与时区设置不匹配。机器的时区是 0 时区的,但是用户设置进去的时间却是 +8 时区的。在这种情况下,System.currentTimeMills()自然获取不到正确的值。

因此,我们在修改机器的系统时间时,一定要带上时区信息。如:date -s "2020/01/01 08:00:00 +8" 。这样就可以准确的告诉系统我们想要设置的时刻,避免因为自动的时区转换导致调错机器的时间。

使用 Quartz 调度器遇到的一些问题

最近,线上运行的定时任务出现调度失败。调整了相关参数后,虽然遏制了调度失败的情况,却导致任务调度的延迟极度增加。同时还观察到,在多机部署的环境中,负载极不均匀,于是深入代码排查一番。

TL; DR

  1. 不要使用 Spring 提供的 org.springframework.scheduling.quartz.SchedulerFactoryBean#setTaskExecutor 方法自定义工作线程池
  2. 要注意 Spring 与 Quartz 的部分配置默认值不一致,如 org.quartz.threadPool.class
  3. 一般情况下使用 Quartz 提供的 SimpleThreadPool 配合参数 org.quartz.threadPool.threadCount 调整最大线程数即可
  4. 如果需要自定义工作线程池,则必须直接实现 org.quartz.spi.ThreadPool 接口,并一定要实现 blockForAvailableThreads 方法,支持阻塞等待
  5. 适当设置 org.quartz.scheduler.batchTriggerAcquisitionMaxCount 参数,使用批量能力降低 DB 交互带来的延迟

任务调度失败

问题现象

接用户反馈,一个一直正常运行的定时任务,在确认没有进行任何变动的情况下,却突然不再被调度了。经过确认,确实没有找到该任务的任何改动痕迹。因此怀疑问题是出在 Quartz 调度引擎上。

找出原因

看到这个现象,第一反应是 Quartz 里的 Trigger 异常了。因为 Quartz 对于所有状态是异常的 Trigger 都不会再次调度,表现为没有任何操作但是任务不执行。于是查看 QRTZ_TRIGGERS 表,筛选过后果然看到了 STATEERRORTRIGGER。根据 TRIGGER_NAMETRIGGER_GROUP 确定为用户反馈的任务所对应的触发器。

确定了问题是 TRIGGER_STATE 后,就要找到状态变化的点。先查看出现问题时的业务日志,可以看到有这样的记录穿插其中:

[2021-04-16 16:14:08.001][|][quartz-scheduler_QuartzSchedulerThread] ERROR o.s.s.q.LocalTaskExecutorThreadPool:runInThread:84 - Task has been rejected by TaskExecutor
 org.springframework.core.task.TaskRejectedException: Executor [java.util.concurrent.ThreadPoolExecutor@ef3310e[Running, pool size = 50, active threads = 50, queued tasks = 100, completed tasks = 20]] did not accept task: org.quartz.core.JobRunShell@5841bfb6
         at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.execute(ThreadPoolTaskExecutor.java:324)
         at org.springframework.scheduling.quartz.LocalTaskExecutorThreadPool.runInThread(LocalTaskExecutorThreadPool.java:80)
         at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:398)
 Caused by: java.util.concurrent.RejectedExecutionException: Task org.quartz.core.JobRunShell@5841bfb6 rejected from java.util.concurrent.ThreadPoolExecutor@ef3310e[Running, pool size = 50, active threads = 50, queued tasks = 100, completed tasks = 20]
         at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
         at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
         at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
         at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.execute(ThreadPoolTaskExecutor.java:321)
         … 2 common frames omitted
 [2021-04-16 16:14:08.001][|][quartz-scheduler_QuartzSchedulerThread] ERROR o.quartz.core.QuartzSchedulerThread:run:403 - ThreadPool.runInThread() return false!

从日志里可以看到,有一些定时任务被线程池拒绝了。而我们的线程池中有 50 个工作线程,100 个等待队列。也就是说这台机器短时间内承担了 150 个以上的调度任务,就会导致线程池无法承受如此多的任务而导致后续的任务被拒绝执行。因此猜测这部分被拒绝执行的任务导致了 Quartz 的 Trigger 状态异常。

于是查找相关代码,可以看到有一共有四处修改状态为 ERROR 的代码。其中由于 retrieveJob 导致的错误暂时排除,因为 DB 中 Trigger 的数据都是高度相似的。如果是这里出了问题,那么一定是大批量的出现错误,而非个别任务。继续查找,找到如下逻辑:

JobRunShell shell = null;
try {
    // 创建触发器执行环境
    shell = qsRsrcs.getJobRunShellFactory().createJobRunShell(bndle);
    shell.initialize(qs);
} catch (SchedulerException se) {
    qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), Trigger.CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
    continue;
}

// 提交执行并检查提交结果
if (qsRsrcs.getThreadPool().runInThread(shell) == false) {
    // this case should never happen, as it is indicative of the
    // scheduler being shutdown or a bug in the thread pool or
    // a thread pool being used concurrently - which the docs
    // say not to do...
    getLog().error("ThreadPool.runInThread() return false!");
    qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), Trigger.CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
}

从这里可以看到,如果任务提交到线程池的时候失败了,那么就会导致任务被标记为 ERROR。而这刚好符合我们看到的日志现象。由于线程池等待队列满导致的提交异常这种情况只会在等待队列撑满之后才会发生,刚好符合大部分任务没有问题但少部分任务失败的情况,于是确定了问题的原因。

深入分析

虽然找到了调度失败的原因是由于线程池满引起的,但是经过计算,这并不是设计中应该出现的。因为在设计中,业务一共有三台机器分别调度任务,而总任务数量在 300~400 左右。期望中每台机器都应承载 1/3 左右的业务量,也就是约 100~140 个任务左右。在这种情况下,理论上每台机器的线程池都应刚好能满足业务需要的,不应该出现这种情况。而通过查看日志,会发现实际上大部分任务都由一台机器执行,另外两台只分配到了少量任务。这种倾斜直接导致了任务量最大的机器数量爆表,导致线程池处理不及时,进而导致任务提交失败,被 Quartz 标记为异常,停止调度。

误入歧途

既然找到了问题在于 Quartz 调度任务的速度太快,线程池来不及处理,于是想到通过参数配置降低 Quartz 调度线程投递任务的速度,并尝试调升队列缓冲来解决这个问题。通过阅读调度器的代码,找到如下逻辑:

@Override
public void run() {
    int acquiresFailed = 0;

    while (!halted.get()) {
        try {
            // do some process states check

            int availThreadCount = qsRsrcs.getThreadPool().blockForAvailableThreads();
            if(availThreadCount > 0) { // will always be true, due to semantics of blockForAvailableThreads...

                List<OperableTrigger> triggers;

                long now = System.currentTimeMillis();

                clearSignaledSchedulingChange();
                try {
                    triggers = qsRsrcs.getJobStore().acquireNextTriggers(
                            now + idleWaitTime, Math.min(availThreadCount, qsRsrcs.getMaxBatchSize()), qsRsrcs.getBatchTimeWindow());
                    acquiresFailed = 0;
                    if (log.isDebugEnabled())
                        log.debug("batch acquisition of " + (triggers == null ? 0 : triggers.size()) + " triggers");
                } catch (JobPersistenceException jpe) {
                    // do exception process
                    continue;
                } catch (RuntimeException e) {
                    // do exception process 
                    continue;
                }

                if (triggers != null && !triggers.isEmpty()) {

                    now = System.currentTimeMillis();
                    long triggerTime = triggers.get(0).getNextFireTime().getTime();
                    long timeUntilTrigger = triggerTime - now;
                    while(timeUntilTrigger > 2) {
                        synchronized (sigLock) {
                            if (halted.get()) {
                                break;
                            }
                            if (!isCandidateNewTimeEarlierWithinReason(triggerTime, false)) {
                                try {
                                    // we could have blocked a long while
                                    // on 'synchronize', so we must recompute
                                    now = System.currentTimeMillis();
                                    timeUntilTrigger = triggerTime - now;
                                    if(timeUntilTrigger >= 1)
                                        sigLock.wait(timeUntilTrigger);
                                } catch (InterruptedException ignore) {
                                }
                            }
                        }
                        if(releaseIfScheduleChangedSignificantly(triggers, triggerTime)) {
                            break;
                        }
                        now = System.currentTimeMillis();
                        timeUntilTrigger = triggerTime - now;
                    }

                    // do some check

                    if(goAhead) {
                        try {
                            List<TriggerFiredResult> res = qsRsrcs.getJobStore().triggersFired(triggers);
                            if(res != null)
                                bndles = res;
                        } catch (SchedulerException se) {
                            // do exception process
                            continue;
                        }

                    }

                    for (int i = 0; i < bndles.size(); i++) {
                        TriggerFiredResult result =  bndles.get(i);
                        TriggerFiredBundle bndle =  result.getTriggerFiredBundle();
                        Exception exception = result.getException();

                        // do some check

                        JobRunShell shell = null;
                        try {
                            shell = qsRsrcs.getJobRunShellFactory().createJobRunShell(bndle);
                            shell.initialize(qs);
                        } catch (SchedulerException se) {
                            qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
                            continue;
                        }

                        if (qsRsrcs.getThreadPool().runInThread(shell) == false) {
                            // this case should never happen, as it is indicative of the
                            // scheduler being shutdown or a bug in the thread pool or
                            // a thread pool being used concurrently - which the docs
                            // say not to do...
                            getLog().error("ThreadPool.runInThread() return false!");
                            qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
                        }

                    }

                    continue; // while (!halted)
                }
            } else { // if(availThreadCount > 0)
                // should never happen, if threadPool.blockForAvailableThreads() follows contract
                continue; // while (!halted)
            }

            long now = System.currentTimeMillis();
            long waitTime = now + getRandomizedIdleWaitTime();
            long timeUntilContinue = waitTime - now;
            synchronized(sigLock) {
                try {
                    if(!halted.get()) {
                        // QTZ-336 A job might have been completed in the mean time and we might have
                        // missed the scheduled changed signal by not waiting for the notify() yet
                        // Check that before waiting for too long in case this very job needs to be
                        // scheduled very soon
                        if (!isScheduleChanged()) {
                            sigLock.wait(timeUntilContinue);
                        }
                    }
                } catch (InterruptedException ignore) {
                }
            }

        } catch(RuntimeException re) {
            getLog().error("Runtime error occurred in main trigger firing loop.", re);
        }
    } // while (!halted)

    // drop references to scheduler stuff to aid garbage collection...
    qs = null;
    qsRsrcs = null;
}

这段是 Quartz 调度线程的主要逻辑,注意其中的这段:

triggers = qsRsrcs.getJobStore().acquireNextTriggers(
                            now + idleWaitTime, Math.min(availThreadCount, qsRsrcs.getMaxBatchSize()), qsRsrcs.getBatchTimeWindow());

这里可以看到,Quartz 每次从 DB 拉取的任务数量与线程池的可用线程数和一个参数 MaxBatchSize 有关。根据查阅到的一些文章,说此处 Quartz 会每次拉取线程数个任务。因此怀疑这里是由于工作线程池的线程数量过大,导致任务都被一台机器拉取,导致的负载不均衡。于是尝试调小线程池的参数,来缓解拉取任务过多的问题。这里要说下,这个怀疑是错误的!让我误入歧途。具体原因会在后面说明。

问题“解决“

通过调整此处线程池的参数,任务执行出错的问题再也没有出现。本以为所有的问题就这样解决了,没想到却引来了另一个更棘手的问题:调度延迟。

任务调度延迟

问题现象

接用户反馈,部分每分钟执行一次的定时任务,出现了同一分钟内执行两次的情况。在任务的执行历史里可以明显看到 12:01:09 有一次执行,12:01:22 的时候又出现了一次执行。

找出原因

由于 Quartz 调度器本身是不太容易犯重复调度这样的错误的,因此第一时间考虑是任务调度延迟导致的。通过观察用户的定时任务,发现实际上该任务在 11:59:02 12:01:09 和 12:01:22 分别调度一次。因此可以确定,12:01 的两次调度,一次为正常的调度,一次为 12:00 应当调度的任务但是因为某些原因延迟了。这样才导致整个调度看起来就像是在 12:01 的之后重复调度了一次。

那么现在的问题就在于调度延迟了。由于之前比较激进的调整过线程池的参数,因此这里还是主要考虑在线程池周边找问题。通过调大线程池的参数,可以明显的发现总体调度延迟飞速降低。但是在测试的过程中,还是在日志里发现了一点之前忽略的小问题:

[2021-04-16 20:27:00.051][|][threadPoolTaskExecutor-1] Execute task|1|1
[2021-04-16 20:27:00.100][|][threadPoolTaskExecutor-2] Execute task|1|2
[2021-04-16 20:27:00.157][|][threadPoolTaskExecutor-3] Execute task|1|3
[2021-04-16 20:27:00.213][|][threadPoolTaskExecutor-4] Execute task|1|4
[2021-04-16 20:27:00.268][|][threadPoolTaskExecutor-5] Execute task|1|5
[2021-04-16 20:27:00.323][|][threadPoolTaskExecutor-6] Execute task|1|6
[2021-04-16 20:27:00.379][|][threadPoolTaskExecutor-7] Execute task|1|7
[2021-04-16 20:27:00.437][|][threadPoolTaskExecutor-8] Execute task|1|8
[2021-04-16 20:27:00.492][|][threadPoolTaskExecutor-9] Execute task|1|9
[2021-04-16 20:27:00.554][|][threadPoolTaskExecutor-10] Execute task|1|10
[2021-04-16 20:27:00.610][|][threadPoolTaskExecutor-11] Execute task|1|11
[2021-04-16 20:27:00.667][|][threadPoolTaskExecutor-12] Execute task|1|12
[2021-04-16 20:27:00.721][|][threadPoolTaskExecutor-13] Execute task|1|13
[2021-04-16 20:27:00.775][|][threadPoolTaskExecutor-14] Execute task|1|14
[2021-04-16 20:27:00.831][|][threadPoolTaskExecutor-15] Execute task|1|15
[2021-04-16 20:27:00.885][|][threadPoolTaskExecutor-16] Execute task|1|16
[2021-04-16 20:27:00.937][|][threadPoolTaskExecutor-17] Execute task|1|17
[2021-04-16 20:27:00.991][|][threadPoolTaskExecutor-18] Execute task|1|18
[2021-04-16 20:27:01.044][|][threadPoolTaskExecutor-19] Execute task|1|19
[2021-04-16 20:27:01.098][|][threadPoolTaskExecutor-20] Execute task|1|20
[2021-04-16 20:27:01.152][|][threadPoolTaskExecutor-21] Execute task|1|21
[2021-04-16 20:27:01.206][|][threadPoolTaskExecutor-22] Execute task|1|22
[2021-04-16 20:27:01.261][|][threadPoolTaskExecutor-23] Execute task|1|23
[2021-04-16 20:27:01.315][|][threadPoolTaskExecutor-24] Execute task|1|24
[2021-04-16 20:27:01.372][|][threadPoolTaskExecutor-25] Execute task|1|25
[2021-04-16 20:27:01.427][|][threadPoolTaskExecutor-26] Execute task|1|26
[2021-04-16 20:27:01.481][|][threadPoolTaskExecutor-27] Execute task|1|27
[2021-04-16 20:27:01.536][|][threadPoolTaskExecutor-28] Execute task|1|28
[2021-04-16 20:27:01.590][|][threadPoolTaskExecutor-29] Execute task|1|29
[2021-04-16 20:27:01.644][|][threadPoolTaskExecutor-30] Execute task|1|30
[2021-04-16 20:27:01.698][|][threadPoolTaskExecutor-31] Execute task|1|31
[2021-04-16 20:27:01.757][|][threadPoolTaskExecutor-32] Execute task|1|32
[2021-04-16 20:27:01.811][|][threadPoolTaskExecutor-33] Execute task|1|33
[2021-04-16 20:27:01.866][|][threadPoolTaskExecutor-34] Execute task|1|34
[2021-04-16 20:27:01.920][|][threadPoolTaskExecutor-35] Execute task|1|35
[2021-04-16 20:27:01.973][|][threadPoolTaskExecutor-36] Execute task|1|36
[2021-04-16 20:27:02.031][|][threadPoolTaskExecutor-37] Execute task|1|37
[2021-04-16 20:27:02.086][|][threadPoolTaskExecutor-38] Execute task|1|38
[2021-04-16 20:27:02.139][|][threadPoolTaskExecutor-39] Execute task|1|39
[2021-04-16 20:27:02.194][|][threadPoolTaskExecutor-40] Execute task|1|40
[2021-04-16 20:27:02.247][|][threadPoolTaskExecutor-41] Execute task|1|41
[2021-04-16 20:27:02.301][|][threadPoolTaskExecutor-42] Execute task|1|42
[2021-04-16 20:27:02.354][|][threadPoolTaskExecutor-43] Execute task|1|43
[2021-04-16 20:27:02.407][|][threadPoolTaskExecutor-44] Execute task|1|44
[2021-04-16 20:27:02.460][|][threadPoolTaskExecutor-45] Execute task|1|45
[2021-04-16 20:27:02.513][|][threadPoolTaskExecutor-46] Execute task|1|46
[2021-04-16 20:27:02.567][|][threadPoolTaskExecutor-47] Execute task|1|47
[2021-04-16 20:27:02.620][|][threadPoolTaskExecutor-48] Execute task|1|48
[2021-04-16 20:27:02.680][|][threadPoolTaskExecutor-49] Execute task|1|49
[2021-04-16 20:27:02.734][|][threadPoolTaskExecutor-50] Execute task|1|50

可以看到,日志里每两个任务的启动时间,都间隔了 50ms 左右。这个时间并不在预期中。按照设想,Quartz 应该一次性拿可用线程数个任务,然后批量提交才对。如果是批量提交到线程池,正常情况下不应有这么大的启动延迟。就算是因为 CPU 调度的原因,在这台 4C 的机器上,前四个任务的启动时间也不应有特别巨大的偏差才对。而且这台测试机为了避免干扰,除了必要的 SSH 等服务外,没有运行任何其他服务,也不存在 CPU 或内存争抢的情况。

为了确认猜想,使用相同的参数创建了相同的线程池,并使用循环批量提交任务,来测试线程池内线程的启动延迟:

ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
threadPoolTaskExecutor.setCorePoolSize(150);
threadPoolTaskExecutor.setMaxPoolSize(300);
threadPoolTaskExecutor.setQueueCapacity(150);
threadPoolTaskExecutor.initialize();

int count = 0;
while (count < 200) {
    threadPoolTaskExecutor.execute(() -> {
        log.info("Execute start at {}", System.currentTimeMillis());
        try {
            Thread.sleep(2_000);
        } catch (InterruptedException e) {
            log.error("Interrupted exception while execute task!", e);
            Thread.interrupted();
        }
        log.info("Execute end at {}", System.currentTimeMillis());
    });

    count++;
}

经过测试,得到的日志输出是这样的:

[2021-04-17 11:29:06.360][|][ThreadPoolTaskExecutor-1] Execute start
[2021-04-17 11:29:06.361][|][ThreadPoolTaskExecutor-2] Execute start
[2021-04-17 11:29:06.371][|][ThreadPoolTaskExecutor-6] Execute start
[2021-04-17 11:29:06.371][|][ThreadPoolTaskExecutor-5] Execute start
[2021-04-17 11:29:06.372][|][ThreadPoolTaskExecutor-7] Execute start
[2021-04-17 11:29:06.369][|][ThreadPoolTaskExecutor-4] Execute start
[2021-04-17 11:29:06.362][|][ThreadPoolTaskExecutor-3] Execute start
[2021-04-17 11:29:06.374][|][ThreadPoolTaskExecutor-8] Execute start
[2021-04-17 11:29:06.375][|][ThreadPoolTaskExecutor-9] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-11] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-10] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-12] Execute start
[2021-04-17 11:29:06.384][|][ThreadPoolTaskExecutor-13] Execute start
[2021-04-17 11:29:06.384][|][ThreadPoolTaskExecutor-14] Execute start
[2021-04-17 11:29:06.385][|][ThreadPoolTaskExecutor-15] Execute start
[2021-04-17 11:29:06.385][|][ThreadPoolTaskExecutor-16] Execute start
[2021-04-17 11:29:06.386][|][ThreadPoolTaskExecutor-18] Execute start
[2021-04-17 11:29:06.386][|][ThreadPoolTaskExecutor-17] Execute start
[2021-04-17 11:29:06.392][|][ThreadPoolTaskExecutor-19] Execute start
[2021-04-17 11:29:06.393][|][ThreadPoolTaskExecutor-20] Execute start
[2021-04-17 11:29:06.393][|][ThreadPoolTaskExecutor-21] Execute start
[2021-04-17 11:29:06.394][|][ThreadPoolTaskExecutor-22] Execute start
[2021-04-17 11:29:06.394][|][ThreadPoolTaskExecutor-23] Execute start
[2021-04-17 11:29:06.395][|][ThreadPoolTaskExecutor-24] Execute start
[2021-04-17 11:29:06.395][|][ThreadPoolTaskExecutor-25] Execute start
[2021-04-17 11:29:06.396][|][ThreadPoolTaskExecutor-26] Execute start
[2021-04-17 11:29:06.396][|][ThreadPoolTaskExecutor-27] Execute start
[2021-04-17 11:29:06.397][|][ThreadPoolTaskExecutor-28] Execute start
[2021-04-17 11:29:06.397][|][ThreadPoolTaskExecutor-29] Execute start
[2021-04-17 11:29:06.398][|][ThreadPoolTaskExecutor-30] Execute start
[2021-04-17 11:29:06.398][|][ThreadPoolTaskExecutor-31] Execute start
[2021-04-17 11:29:06.399][|][ThreadPoolTaskExecutor-32] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-33] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-34] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-35] Execute start
[2021-04-17 11:29:06.401][|][ThreadPoolTaskExecutor-36] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-37] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-38] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-39] Execute start
[2021-04-17 11:29:06.403][|][ThreadPoolTaskExecutor-40] Execute start
[2021-04-17 11:29:06.410][|][ThreadPoolTaskExecutor-42] Execute start
[2021-04-17 11:29:06.411][|][ThreadPoolTaskExecutor-41] Execute start
[2021-04-17 11:29:06.411][|][ThreadPoolTaskExecutor-43] Execute start
[2021-04-17 11:29:06.412][|][ThreadPoolTaskExecutor-44] Execute start
[2021-04-17 11:29:06.412][|][ThreadPoolTaskExecutor-45] Execute start
[2021-04-17 11:29:06.413][|][ThreadPoolTaskExecutor-46] Execute start
[2021-04-17 11:29:06.421][|][ThreadPoolTaskExecutor-47] Execute start
[2021-04-17 11:29:06.422][|][ThreadPoolTaskExecutor-48] Execute start
[2021-04-17 11:29:06.424][|][ThreadPoolTaskExecutor-49] Execute start
[2021-04-17 11:29:06.424][|][ThreadPoolTaskExecutor-50] Execute start

可以看到,在相同的一台四核的机器上,除了最开始启动较慢外,余下的任务启动时间的偏差基本在 1ms 内50 个任务全部启动也只用了 60ms 左右。前 150 个任务的启动时间总过也就相差 200ms 左右。这个结果表明,定时任务调度时一定还有其他耗时操作穿插其间,导致任务的提交本身存在延迟,才导致了前 50 个任务的启动时间偏差接近 3s。

深入分析

于是回到代码本身,深入分析 Quartz 的任务调度和提交逻辑。参考前面提供的 QuartzSchedulerThread 主调度线程的代码,我们可以把整个调度过程进行一个阶段划分:

  1. 等待工作线程池出现可用线程
  2. 根据可用线程数和最大批量大小从 DB 中取出将要触发的 Trigger
  3. 循环等待,直到离最近一个要出发的 Trigger 的触发时间还有 2ms
  4. 更新 DB 设置当前批次 Trigger 的触发状态
  5. 提交 Trigger 到执行线程池

其中 2 4 两步需要访问 DB 更新 Trigger 的状态,并且需要获取 TRIGGER_ACCESS 锁。按照访问 DB 的一般耗时估算,一次 DB 操作大约会消耗 5~10ms 的时间,那么这两步的 DB 操作大约每次会消耗 15~20ms 左右的时间,刚好与我们之前观察到的 50ms 的延迟接近。

可是按照正常逻辑,此处 Quartz 应该是批量去取 Trigger,应该每一批 Trigger 消耗 50ms 才是正常现象。现在每一个 Trigger 都间隔了 50ms,说明此处的批量处理一定出现了问题。于是单独深入批量拉取 Trigger 这段代码,发现之前被忽略的 maxBatchSize 有问题。由于理所当然的认为该选项的值一定会比较大,不太可能成为瓶颈,之前就没有仔细追踪这个参数。现在经过追溯,发现该值在 org.quartz.core.QuartzSchedulerResources 中存在一个默认值 1。也就是说如果没有特殊配置的话,这里的批量永远是单个拉取。这也说明了,之前的猜测是完全错误的。负载不均匀导致队列爆掉并不是因为 Quartz 批量过大导致的,而是另有原因。

尝试修复

既然找到了这个变量漏设置了值,那就修改这里的默认值,再进行测试。这里这个变量值需要修改 Quartz 的配置文件,增加 org.quartz.scheduler.batchTriggerAcquisitionMaxCount 配置项。这里修改成 50 进行测试,配合线程池的 core size 150,应该可以达到每批次处理 50 个 Trigger 的目的。修改后的日志如下:

[2021-04-17 13:45:00.051][|][threadPoolTaskExecutor-1] Execute task|1|1
[2021-04-17 13:45:00.108][|][threadPoolTaskExecutor-2] Execute task|1|2
[2021-04-17 13:45:00.173][|][threadPoolTaskExecutor-3] Execute task|1|3
[2021-04-17 13:45:00.231][|][threadPoolTaskExecutor-4] Execute task|1|4
[2021-04-17 13:45:00.288][|][threadPoolTaskExecutor-5] Execute task|1|5
[2021-04-17 13:45:00.346][|][threadPoolTaskExecutor-6] Execute task|1|6
[2021-04-17 13:45:00.403][|][threadPoolTaskExecutor-7] Execute task|1|7
[2021-04-17 13:45:00.462][|][threadPoolTaskExecutor-8] Execute task|1|8
[2021-04-17 13:45:00.518][|][threadPoolTaskExecutor-9] Execute task|1|9
[2021-04-17 13:45:00.574][|][threadPoolTaskExecutor-10] Execute task|1|10
[2021-04-17 13:45:00.629][|][threadPoolTaskExecutor-11] Execute task|1|11
[2021-04-17 13:45:00.687][|][threadPoolTaskExecutor-12] Execute task|1|12
[2021-04-17 13:45:00.741][|][threadPoolTaskExecutor-13] Execute task|1|13
[2021-04-17 13:45:00.795][|][threadPoolTaskExecutor-14] Execute task|1|14
[2021-04-17 13:45:00.849][|][threadPoolTaskExecutor-15] Execute task|1|15
[2021-04-17 13:45:00.915][|][threadPoolTaskExecutor-16] Execute task|1|16
[2021-04-17 13:45:00.971][|][threadPoolTaskExecutor-17] Execute task|1|17
[2021-04-17 13:45:01.026][|][threadPoolTaskExecutor-18] Execute task|1|18
[2021-04-17 13:45:01.081][|][threadPoolTaskExecutor-19] Execute task|1|19
[2021-04-17 13:45:01.135][|][threadPoolTaskExecutor-20] Execute task|1|20

奇怪的事情发生了,这个参数的修改完全没有起作用,Quartz 还是一个个任务调度的,而不是批量调度。同时在为了测试专门开启的调度引擎的 Debug 日志中也发现了相关日志:

[2021-04-17 13:45:00.076][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.135][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.201][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.258][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.315][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.373][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.431][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.488][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.545][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.600][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers

从这里可以看出,调度器确实每次只取了一个 Trigger 进行触发。这就很奇怪了,明明我们已经修改了最大批量值的参数,却看起来像没有生效。考虑到这里的批量值是由两个参数决定的,那么问题一定出在二者之间

  1. 线程池可用线程数有问题,获取到的数据不是设置的 150 个线程
  2. maxBatchSize 参数设置没有生效,仍然为 1

由于这两个参数在调度器之外比较用非入侵的方式检测,于是决定直接上 IDEA 用远程调试来解决:

在调度线程批量拉取 Trigger 的地方设置断点,通过查看两个变量的值,发现了问题。这里可以清晰的看到 maxBatchSize 已经变为我们设置的 50 了。但是 availThreadCount 却不是预想中的 150,而是 1。于是检查一下这个线程池:

可以看到,此处用来接收任务的线程池居然是 LocalTaskExecutorThreadPool 类型的线程池,而不是我们在配置里提供给 Quartz 的。而在初始化时提供给 Quartz 的线程池变成了该线程池内部的一个 executor。那这个线程池是哪来的呢?跟进去看下:

可以看到这个线程池是 spring 对于我们实际使用的线程池的一个封装。这个线程池内部的 taskExecutor 才是真正的由我们配置的执行任务的线程池。而这个封装中,由于内部的 executor 是不确定的,所以为了简单,此处的可用线程数查询居然永久返回 1。至此问题的根源找到了:因为 LocalTaskExecutorThreadPool 封装了我们提供给 Quartz 的线程池,且该封装在获取可用线程数时永远返回 1,导致了我们修改 maxBatchSize 没有生效。

再次深入

那么这里其实还有个问题,就是这个 LocalTaskExecutorThreadPool 是从何而来,为何没有直接使用我们构造好的 ThreadPoolTaskExecutor 呢?

经过追踪,发现这个线程池的来源在这里:

org.springframework.scheduling.quartz.SchedulerFactoryBean

可以看到,这是 Spring 对于 Quartz 初始化的一个封装。在这个封装中,如果 Spring 发现我们尝试使用自己配置的一个任务执行器的话,就会默认用 LocalTaskExecutorThreadPool 来做一个包装,除非在配置文件中配置 org.quartz.threadPool.class 显示的覆盖这个参数。而通过阅读配置,我发现这里确实是没有设置值。通过参考 Quartz 本身的初始化过程,猜测当时没有设置这个值的原因是因为 Quartz 本身默认会使用 SimpleThreadPool 来运行任务,因此考虑这个设置是多余的,于是没有进行设置。但是在考虑的过程中却忽略了 Spring 这块,导致实际的效果与预期不一致。

真相大白

至此,这里无法进行批量调度导致调度延迟的各个原因终于复出水面。在这个问题中,由于多个配置之间的互相作用最终导致了这个结果。主要有以下几点:

  1. maxBatchSize 的默认值为 1
  2. LocalTaskExecutorThreadPool 对于可用线程数永远返回 1
  3. Quartz 的默认线程池是 SimpleThreadPool,但 Spring 在使用了自定义工作线程池的情况下默认为 LocalTaskExecutorThreadPool
  4. org.quartz.threadPool.class 的默认行为与 Quartz 匹配,但与 Spring 不匹配

这里针对 3 多说几句。后面经过阅读代码,发现 Quartz 调度线程需要的 ThreadPool 并不是通常使用的 java.util.concurrent.ThreadPoolExecutor 而是 Quartz 自行封装的 org.quartz.spi.ThreadPool。因此,当我们要求 Spring 使用我们自定义的 ThreadPoolExecutor 来执行工作任务时,Spring 别无选择,必须对我们提供的 ThreadPoolExecutor 做一次封装,才能提供给 Quartz 调度线程使用。而一开始在编写代码时对这里没有深入研究则埋下了一个大坑。

因此这里的解决方案也很简单,直接去掉自定义线程池使用 Quartz 提供的 SimpleThreadPool 来处理工作负载即可。而且这里修改为 Quartz 自身的 SimpleThreadPool 来处理工作负载后,原先的调度异常的问题也自然而然的解决了。具体原因见总结。修改配置后再进行测试,看到这样的日志输出:

[2021-04-17 15:50:09.821][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 0 triggers
[2021-04-17 15:50:33.989][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:01.551][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:02.948][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:04.009][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 6 triggers
[2021-04-17 15:51:04.723][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 44 triggers
[2021-04-17 15:51:06.241][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:07.614][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 26 triggers
[2021-04-17 15:51:08.500][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 31 triggers
[2021-04-17 15:51:09.448][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 43 triggers
[2021-04-17 15:51:10.600][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 31 triggers
[2021-04-17 15:51:11.564][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 19 triggers
[2021-04-17 15:51:11.884][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 0 triggers

[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-5] Execute task|1|5
[2021-04-17 15:51:00.806][|][quartz-scheduler_Worker-3] Execute task|1|3
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-20] Execute task|1|20
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-21] Execute task|1|21
[2021-04-17 15:51:00.813][|][quartz-scheduler_Worker-22] Execute task|1|22
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-6] Execute task|1|6
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-9] Execute task|1|9
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-12] Execute task|1|12
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-17] Execute task|1|17
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-13] Execute task|1|13
[2021-04-17 15:51:00.818][|][quartz-scheduler_Worker-26] Execute task|1|26
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-23] Execute task|1|23
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-4] Execute task|1|4
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-10] Execute task|1|10
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-18] Execute task|1|18
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-8] Execute task|1|8
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-19] Execute task|1|19
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-14] Execute task|1|14
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-7] Execute task|1|7
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-16] Execute task|1|16
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-11] Execute task|1|11
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-15] Execute task|1|15
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-1] Execute task|1|1
[2021-04-17 15:51:00.816][|][quartz-scheduler_Worker-24] Execute task|1|24
[2021-04-17 15:51:00.806][|][quartz-scheduler_Worker-2] Execute task|1|2
[2021-04-17 15:51:00.816][|][quartz-scheduler_Worker-25] Execute task|1|25
[2021-04-17 15:51:00.827][|][quartz-scheduler_Worker-27] Execute task|1|27
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-31] Execute task|1|31
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-29] Execute task|1|29
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-32] Execute task|1|32
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-30] Execute task|1|30
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-28] Execute task|1|28
[2021-04-17 15:51:00.830][|][quartz-scheduler_Worker-33] Execute task|1|33
[2021-04-17 15:51:00.831][|][quartz-scheduler_Worker-35] Execute task|1|35
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-34] Execute task|1|34
[2021-04-17 15:51:00.832][|][quartz-scheduler_Worker-36] Execute task|1|36
[2021-04-17 15:51:00.834][|][quartz-scheduler_Worker-37] Execute task|1|37
[2021-04-17 15:51:00.834][|][quartz-scheduler_Worker-38] Execute task|1|38
[2021-04-17 15:51:00.836][|][quartz-scheduler_Worker-41] Execute task|1|41
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-39] Execute task|1|39
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-40] Execute task|1|40
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-42] Execute task|1|42
[2021-04-17 15:51:00.838][|][quartz-scheduler_Worker-43] Execute task|1|43
[2021-04-17 15:51:00.838][|][quartz-scheduler_Worker-44] Execute task|1|44
[2021-04-17 15:51:00.839][|][quartz-scheduler_Worker-45] Execute task|1|45
[2021-04-17 15:51:00.843][|][quartz-scheduler_Worker-48] Execute task|1|48
[2021-04-17 15:51:00.843][|][quartz-scheduler_Worker-46] Execute task|1|46
[2021-04-17 15:51:00.853][|][quartz-scheduler_Worker-49] Execute task|1|49
[2021-04-17 15:51:00.857][|][quartz-scheduler_Worker-47] Execute task|1|47
[2021-04-17 15:51:00.862][|][quartz-scheduler_Worker-50] Execute task|1|50

第一段调度器的日志显示现在已经成功的使用批量的方式来进行 Trigger 的拉取了,每次拉取 50 个。在拉取了 150 个任务之后,由于线程都已在执行任务,所以只有 6 个空闲线程释放,因此拉取了 6 个任务。

第二段是实际的任务执行日志。可以看到在这段执行过程中,大约有 25 个任务在 20ms 内启动完成,50 个任务全部启动也只消耗了约 50ms 的时间,已经比原先大大提升。

同时,对于负载不均匀的问题,在修改前,三台机器的负载为:1:2:497。修改之后再次测试,变为:100:151:249。负载不均匀的问题已经基本解决。

总结

注意事项

通过这次问题排查,认识到了一些在 Quartz 搭配 Spring 使用时需要注意的问题:

  1. 尽量不要使用自定义线程池,而是使用 Quartz 实现的 SimpleThreadPool
  2. 搭配使用时,不光要留意 Quartz 本身对于配置项的默认值处理,也要注意 Spring 对于配置项的处理
  3. Quartz 的调度误差是由多方面原因造成的,需要综合考虑配置项之间的相互作用逻辑
  4. 分析问题时需要严格测试,而不能想当然的进行调整

调度异常&负载不均原因

另外再来看一下最开始遇到的调度异常&负载不均的问题。综合后续的所有分析可知,在默认情况下,Quartz 的调度逻辑是这样的:

可以看到在这个默认配置下,由于存在一个阻塞等待可用线程org.quartz.simpl.SimpleThreadPool#blockForAvailableThreads)的操作,可以保证当本机的线程全部繁忙的时候,本机的调度线程不会去获取锁,自然而然的让别的实例来接手余下的任务调度工作。同时,由于这里的阻塞等待,保证了当本机线程全忙的时候不会有任何新任务进入,也就保证了不会出现提交失败的问题。

而当使用自定义线程池的时候,调度流程变成了这样:

在这个工作模式下,阻塞等待没有了。就算自定义线程池中的线程全忙、队列已满,此处还是会返回有一个可用线程。所以此时,调度线程的工作模式就变成了,不管线程池是否爆满,始终抢夺任务并继续提交。正是因为这里没有判定线程池是否满的逻辑,导致了最初的提交失败。而且由于不再等待可用线程,这里的循环变成了 加锁->拉 Trigger->提交 的循环,从而导致最初最先启动的线程在抢锁的过程中有极大的优势(没抢到锁会强制等待,而等待的时候锁已经又被最先启动的线程抢了),从而导致负载的严重失衡。

所以为了解决提交失败和负载不均的问题,最简单的方法是不要使用自定义线程池,而是通过 org.quartz.threadPool.class 设置使用 SimpleThreadPool,并根据机器负载调节线程数量。如果一定要使用自定义线程池的话,则必须实现 Quartz 提供的 org.quartz.spi.ThreadPool 接口,并实现阻塞等待可用线程的逻辑。千万不能直接使用 Spring 提供的 LocalTaskExecutorThreadPool

调度延迟产生的原因

根据本次分析的过程可以看出,Quartz 的调度延迟主要由以下几个方面组成:

  1. 同步加锁延迟。当 Quartz 使用DB作为集群持久化存储的场景下,为了保证调度秩序,避免重复调度或漏调度,每一次 DB 操作都要进行加锁。而每次调度时,需要先从 DB 读取要触发的 Trigger 信息并更新状态为 ACQUIRED,然后在将要触发时更新状态到 EXECUTING,之后才会向工作线程池提交任务。虽然在读取 Trigger 信息的时候大部分操作都不是批量进行的,但是加锁操作是针对一批任务的。考虑到正常的 DB 读写耗时在 5~10ms 左右,如果不进行批量操作的话,按照 50 个任务一批计算,每一批的加锁时间就白白增加了 250~500ms。因此,进行批量拉取可以有效的减小 DB 加锁操作带来的调度延迟。同时,考虑到锁的竞争会导致线程等待,批量加锁操作还可以有效的降低锁争抢,提升整体效率。如果业务场景对调度延迟比较敏感,应考虑使用性能更好的独立 DB 实例,并尽量降低 Quartz 实例到 DB 之间的网络延迟;
  2. 批量执行排队延迟。如果同时触发的任务数量超过了总集群的线程池上限,则一定会被分为多个批次进行触发,这时就会出现排队延迟。这里每个批次间的排队延迟将取决于任务的执行速度。单个任务执行的越慢则越靠后被触发的批次延迟越大。当总线程数耗尽时,下一次调度一定会等到有线程释放才会开始。理想情况下所有任务都应在一个批次内做完。因此应根据工作负载的情况,对 Quartz 集群进行扩容,增加总线程数,来避免任务进入排队。但是由于成本限制,这个方式往往很难实施。而且在实际使用的过程中,偶尔会出现任务本身的执行耗时不可控的情况。因此在实际使用的过程中,需要根据实际的业务情况,合理调节批量参数和工作线程数。当然在调节工作线程数量时还需要需要考虑到机器实际的负载能力,不能无谓的提高,反而导致负载不均衡的情况出现。同时应当考虑采取异步机制,并通过消息队列等异步化手段,将任务快速分发下去。再结合快速扩容机制,在峰值来临前对执行器进行扩容,来进一步降低延迟。这里推荐异步化任务执行器而不是大量扩容 Quartz 集群的主要原因在于,Quartz 集群本身是一个有状态的集群,相对来说逻辑复杂任务较重,且存在集群锁,不适合进行快速扩缩容。而在需要大批量调度的场景下,我们的工作负载往往都是无状态逻辑简单轻量化的小任务。这种任务最适合配合 K8S 等集群进行快速扩容支撑峰值,并在谷时缩容降低成本;
  3. CPU调度延迟。当调度线程将任务提交给工作线程池后,工作线程池中的线程最终还需要依赖 CPU 时间片来执行,若调度机器的 CPU 负载较高,或线程池数量不合理,那么线程在真正被 CPU 执行前将会有较大等待。为了尽量减少这里的执行延迟,应将工作线程池部署在 CPU 核数较多且负载不高的机器上。同时应该合理设置工作线程数量,避免一次性触发过多任务。

jOOQ 与 Spring 的一些注意事项

jOOQ 全称 Java Object Oriented Querying,即面向 Java 对象查询。它是 Data Geekery 公司研发的 DA 方案 (Data Access Layer),是一个 ORM 框架。

使用 jOOQ,既不像 Hibernate 等框架封装过高,无法触及 SQL 底层;也不像 MyBatis 等,配置太过繁琐。同时还是 Type Safe 的框架,编译时即可最大程度的发现问题。

不过在 jOOQ 配合 String Cloud 使用的时候,还是踩了几个小坑,特别说明一下。随时补充新遇到的问题。

一、事物问题

jOOQ 默认有一套自己的流式 API,来支持事物。不过,在 Spring 里面,我们使用的最多的还是 @EnableTransactionManagement@Transactional 注解。使用这二者可以开启 Spring 内置的基于注解和 Proxy 的事物处理机制,相对更灵活,更优雅。使用起来也更简单。

但是在跟 jOOQ 联动的时候,实际使用却发现事物始终不生效。但是奇怪的是,不论是打断点调试还是加日志,都能发现异常正常抛出了,也被 Spring 正常捕获了,Transaction 的 Rollback 也调用了,但是实际上事物就是没有撤销。

在多次排查 Spring 本身的配置问题后,突然想到问题可能处在 jOOQ 上。经过查找相关文档发现,由于我们的 SQL 都是通过 jOOQ 的 DSLContent 构建并执行的,所以默认情况下并不会受 Spring Transaction Manager 的管理。这里我们需要在配置 jOOQ 的时候,特别配置一下,才能让 @Transactional 注解生效。参考官网的样例,XML 配置如下:

<?xml version="1.0" encoding="UTF-8"?>

<beans xmlns="http://www.springframework.org/schema/beans"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xmlns:tx="http://www.springframework.org/schema/tx"
       xsi:schemaLocation="
            http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
            http://www.springframework.org/schema/tx http://www.springframework.org/schema/tx/spring-tx-3.2.xsd">

    <!-- This is needed if you want to use the @Transactional annotation -->
    <tx:annotation-driven transaction-manager="transactionManager"/>

    <bean id="dataSource" class="org.apache.commons.dbcp2.BasicDataSource" destroy-method="close" >
        <!-- These properties are replaced by Maven "resources" -->
       <property name="url" value="${db.url}" />
       <property name="driverClassName" value="${db.driver}" />
       <property name="username" value="${db.username}" />
       <property name="password" value="${db.password}" />
    </bean>

    <!-- Configure Spring's transaction manager to use a DataSource -->
    <bean id="transactionManager"
        class="org.springframework.jdbc.datasource.DataSourceTransactionManager">
        <property name="dataSource" ref="dataSource" />
    </bean>

    <!-- Configure jOOQ's ConnectionProvider to use Spring's TransactionAwareDataSourceProxy,
         which can dynamically discover the transaction context -->
    <bean id="transactionAwareDataSource"
        class="org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy">
        <constructor-arg ref="dataSource" />
    </bean>

    <bean class="org.jooq.impl.DataSourceConnectionProvider" name="connectionProvider">
        <constructor-arg ref="transactionAwareDataSource" />
    </bean>

    <!-- Configure the DSL object, optionally overriding jOOQ Exceptions with Spring Exceptions -->
    <bean id="dsl" class="org.jooq.impl.DefaultDSLContext">
        <constructor-arg ref="config" />
    </bean>
    
    <bean id="exceptionTranslator" class="org.jooq.example.spring.exception.ExceptionTranslator" />
    
    <!-- Invoking an internal, package-private constructor for the example
         Implement your own Configuration for more reliable behaviour -->
    <bean class="org.jooq.impl.DefaultConfiguration" name="config">
        <property name="SQLDialect"><value type="org.jooq.SQLDialect">H2</value></property>
        <property name="connectionProvider" ref="connectionProvider" />
        <property name="executeListenerProvider">
            <array>
                <bean class="org.jooq.impl.DefaultExecuteListenerProvider">
                    <constructor-arg index="0" ref="exceptionTranslator"/>
                </bean>
            </array>
        </property>
    </bean>
    
    <!-- This is the "business-logic" -->
    <bean id="books" class="org.jooq.example.spring.impl.DefaultBookService"/>
</beans>

核心要点在这段:

<!-- Configure jOOQ's ConnectionProvider to use Spring's TransactionAwareDataSourceProxy,
         which can dynamically discover the transaction context -->
    <bean id="transactionAwareDataSource"
        class="org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy">
        <constructor-arg ref="dataSource" />
    </bean>

    <bean class="org.jooq.impl.DataSourceConnectionProvider" name="connectionProvider">
        <constructor-arg ref="transactionAwareDataSource" />
    </bean>

这里要注意,一定要用 Spring 的 TransactionAwareDataSourceProxy 包装一层前面配置的 DataSource 对象。否则,jOOQ 拿到的就是一个没有被托管的原始 DataSource,那么就不会被 @Transactional 注解所管控。

对应的 Java 方式配置要点如下:

package de.maoxian.config;

import javax.sql.DataSource;

import org.jooq.ConnectionProvider;
import org.jooq.DSLContext;
import org.jooq.SQLDialect;
import org.jooq.impl.DataSourceConnectionProvider;
import org.jooq.impl.DefaultConfiguration;
import org.jooq.impl.DefaultDSLContext;
import org.springframework.beans.factory.annotation.Qualifier;
import org.springframework.boot.context.properties.ConfigurationProperties;
import org.springframework.boot.jdbc.DataSourceBuilder;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.Primary;
import org.springframework.jdbc.datasource.DataSourceTransactionManager;
import org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy;
import org.springframework.transaction.annotation.EnableTransactionManagement;

@Configuration
@EnableTransactionManagement
public class DbConfig {
    @Bean
    @Primary
    @ConfigurationProperties(prefix = "spring.datasource.maoxian")
    public DataSource dataSource() {
        return DataSourceBuilder.create().build();
    }

    @Primary
    @Bean
    public DataSourceTransactionManager transactionManager(DataSource dataSource) {
        return new DataSourceTransactionManager(dataSource);
    }

    @Bean
    public DSLContext dslContext(@Qualifier("maoxian-jooq-conf") org.jooq.Configuration configuration) {
        return new DefaultDSLContext(configuration);
    }

    @Bean("maoxian-jooq-conf")
    public org.jooq.Configuration jooqConf(ConnectionProvider connectionProvider) {
        return new DefaultConfiguration().derive(connectionProvider).derive(SQLDialect.MYSQL);
    }

    @Bean
    public ConnectionProvider connectionProvider(TransactionAwareDataSourceProxy transactionAwareDataSource) {
        return new DataSourceConnectionProvider(transactionAwareDataSource);
    }

    @Bean
    public TransactionAwareDataSourceProxy transactionAwareDataSourceProxy(DataSource dataSource) {
        return new TransactionAwareDataSourceProxy(dataSource);
    }
}

重点在 ConnectionProvider 的配置。此处的 ConnectionProvider 在创建时,必须使用被 Spring 包过的 DataSource。如果直接使用 DataSource 而不是 TransactionAwareDataSourceProxy 则注解失效。


参考文档:

https://www.jooq.org/doc/latest/manual/getting-started/tutorials/jooq-with-spring/

Kapacitor 使用 Proxy 连接小电报 API

由于众所周知的原因,小电报的 Bot API 在某些地方是完全无法访问的。

那么,这导致我们最好用,最快捷的告警方式被掐死了。

于是研究了一下,发现官方有一个回复:

https://community.influxdata.com/t/how-to-set-proxy-for-telegram-and-smtp/3250

The Kapacitor 你懂的 agent uses the golang HTTP client, so you can set that with the environment variables $http_proxy (or $https_proxy). As for SMTP, we don’t currently have logic in place for that, but that sounds like a great feature request.

于是加入环境变量,结果发现一个新问题。由于 Kapacitor 与 InfluxDB 之间的连接也是 HTTP 的,导致 InfluxDB 也走了代理,反而导致不通了。于是再次尝试,发现可以使用 NO_PROXY 变量,最终结果如下:

HTTP_PROXY=http://x.x.x.x:xxxx
HTTPS_PROXY=http://x.x.x.x:xxxx
NO_PROXY=influxdb.xxx.xxx

 

记一则由于整数溢出导致的教科书级的死循环

首先铺垫一下,这段代码的输出是什么?

public static void main(String []args){
    System.out.println(Integer.MAX_VALUE + 1);
}

很多人可能很快就能答出来,正确答案是:-2147483648

那么接下来看这段代码:

public static void main(String []args){
    Long total = Long.MAX_VALUE;
    for (int i = 0; i < total; i++) {
        System.out.println(i);
    }
}

乍看之下似乎没啥大毛病,但是结合前面的铺垫,就会发现:

当 i 增长到 Integer.MAX_VALUE  的时候,“奇迹”出现了。接下来,下一个 i 值变为了 -2147483648。跟 total 一比,还是小,于是循环继续。

周而复始,这个循环就永远停不下来了。

当然,这里因为我的简化,还是能比较容易的看出这个死循环的。而实际使用中,这个 total 的取值往往是外部带来的。正常情况下,可能外部取值不会大过Integer.MAX_VALUE ,也就是 2147483648。但是当恶意请求出现或者是正常请求越过边界之后,问题就出现了。

所以当我们定义循环变量的时候,一定要小心。循环变量本身的取值范围一定要大于判断条件。简单来说,在上面的例子中,i 的取值必须要能够大于等于 total 可能的最大值。也就是说,在 total 是 Long 的情况下,i 也必须至少定义为 Long,才不会出现问题。

简单总结一下,就是对于控制循环的变量定义一定要非常谨慎。否则极有可能出现类似很难测出的 Bug,导致各种各样的问题

MyBatis 获取自增 ID 的小坑

在 MyBatis 中,获取自增 ID 主要有两个方法:

  1. 在 SQL 中增加两个属性,useGeneratedKeys  和 keyProperty
  2. 增加 selectKey  语句块,执行自定义 SQL 获取自增 ID

针对这几种方法,有几个小问题需要注意:

  1. useGeneratedKeys  是基于 JDBC 的 Prepared Statement  实现的,具体做法是调用 JDBC 的 getGeneratedKeys  方法,在 Prepared Statement  对象中取相应的值。当 DB 为 MySQL 的时候,会在响应时返回相应的自增字段值。但是,在某些实现 DB 分库分表的 Proxy 中,由于涉及 SQL 转换、重写的问题,可能对 Prepared Statement  的支持并不完整,导致 useGeneratedKeys  选项无法正常返回对应的自增 ID
  2. selectKey  方式是 MyBatis 自动的在执行完 Insert 语句之前/后自动执行对应的语句块,去生成/获取对于的 ID,并填充进相关的字段。在这里要注意,在某些 Prepared Statement  支持不完整的 Proxy 中,需要增加 statementType=”STATEMENT”  来强制指定不使用 Prepared Statement  来获取 ID
  3. keyProperty 这个参数也有一点需要注意。如果在 Mapper.java 中使用了 @Param  来对传入的参数进行了命名的话,这里接收自增值的属性需要用 paramName.fieldName  这种方式来写。如果只写 fieldName 则无法成功回传。最好的方式是不要用 @Param  来传参,而是全部封装成 bean 来进行传递

JVM DNS IP 地址缓存 (InetAddress)

(本文所有内容基于 Oracle JDK)

JVM IP 地址缓存

JVM 的缓存策略

由于 DNS 解析是一个访问量大的不是很可靠的网络调用,因此通常大部分系统都会对 DNS 解析的结果进行一定程度的缓存。如运营商的 LDNS、常用的浏览器、包括操作系统本身,都会对 DNS 解析的结果进行缓存。在 JVM 中,为了加速 DNS 解析的过程,当然也进行了相关的缓存。

在 Java 中,最常用的进行 DNS 解析的方法就是:

java.net.InetAddress.getAllByName(“www.google.com”);

而这个方法本身也会对解析的结果进行相应的缓存。看官方文档:

InetAddress Caching

The InetAddress class has a cache to store successful as well as unsuccessful host name resolutions.

By default, when a security manager is installed, in order to protect against DNS spoofing attacks, the result of positive host name resolutions are cached forever. When a security manager is not installed, the default behavior is to cache entries for a finite (implementation dependent) period of time. The result of unsuccessful host name resolution is cached for a very short period of time (10 seconds) to improve performance.

If the default behavior is not desired, then a Java security property can be set to a different Time-to-live (TTL) value for positive caching. Likewise, a system admin can configure a different negative caching TTL value when needed.

Two Java security properties control the TTL values used for positive and negative host name resolution caching:

networkaddress.cache.ttl
Indicates the caching policy for successful name lookups from the name service. The value is specified as as integer to indicate the number of seconds to cache the successful lookup. The default setting is to cache for an implementation specific period of time.A value of -1 indicates “cache forever”.
networkaddress.cache.negative.ttl (default: 10)
Indicates the caching policy for un-successful name lookups from the name service. The value is specified as as integer to indicate the number of seconds to cache the failure for un-successful lookups.A value of 0 indicates “never cache”. A value of -1 indicates “cache forever”.

简单来说,在默认情况下,成功解析到 IP 的解析结果会被永久缓存,而解析失败的结果会被缓存 10s。

虽然在一般情况下,这个缓存有利于提高系统的效率,减少网络交互。但是当我们依赖 DNS 进行负载均衡的时候,就会出现问题了。

修改策略

想要修改 JVM 默认的缓存策略,有三种方法实现:

  1. 修改 java.sercurity 配置文件
  2. JVM 启动时添加启动参数
  3. JVM 启动后,通过 System 修改系统类属性

修改配置文件

在 JDK 的 %JAVA_HOME%/jre/lib/security  目录下存在 java.security 文件。通过修改文件中的 networkaddress.cache.ttl  和 networkaddress.cache.negative.ttl  可以达到修改缓存策略的目的。配置信息如下:

#
# The Java-level namelookup cache policy for successful lookups:
#
# any negative value: caching forever
# any positive value: the number of seconds to cache an address for
# zero: do not cache
#
# default value is forever (FOREVER). For security reasons, this
# caching is made forever when a security manager is set. When a security
# manager is not set, the default behavior in this implementation
# is to cache for 30 seconds.
#
# NOTE: setting this to anything other than the default value can have
#       serious security implications. Do not set it unless
#       you are sure you are not exposed to DNS spoofing attack.
#
#networkaddress.cache.ttl=-1

# The Java-level namelookup cache policy for failed lookups:
#
# any negative value: cache forever
# any positive value: the number of seconds to cache negative lookup results
# zero: do not cache
#
# In some Microsoft Windows networking environments that employ
# the WINS name service in addition to DNS, name service lookups
# that fail may take a noticeably long time to return (approx. 5 seconds).
# For this reason the default caching policy is to maintain these
# results for 10 seconds.
#
#
networkaddress.cache.negative.ttl=10

JVM 启动时修改启动参数

同样的可以通过启动参数的方式来改变这个值:

https://docs.oracle.com/javase/8/docs/technotes/guides/net/properties.html

sun.net.inetaddr.ttlThis is a Oracle JDK private system property which corresponds to networkaddress.cache.ttl. It takes the same value and has the same meaning, but can be set as a command-line option. However, the preferred way is to use the security property mentioned above.


sun.net.inetaddr.negative.ttlThis is a Oracle JDK private system property which corresponds to networkaddress.cache.negative.ttl. It takes the same value and has the same meaning, but can be set as a command-line option. However, the preferred way is to use the security property mentioned above.

运行时通过 System 类修改

通过 java.lang.System  类在JVM启动后修改。

System.setProperty("sun.net.inetaddr.ttl", "60");
System.setProperty("sun.net.inetaddr.negative.ttl", "10");

或者

java.security.Security.setProperty("networkaddress.cache.ttl", "60");
java.security.Security.setProperty("networkaddress.cache.negative.ttl", "10");

 

ScheduledExecutorService 一个小坑

今天在排查一个线上问题是发现一个使用 ScheduledExecutorService 执行的定时任务在执行了一次以后就再也没有执行过了。于是 Dump 了内存来检查问题。

首先,搜索对应 Task 的类,发现在堆中找不到这个类的实例。可是明明已经成功执行了一次,为何没有实例?

于是再去找 ScheduledExecutorService  对应的 ScheduledThreadPoolExecutor  类,成功筛选出了用来执行定时任务的实例。在实例的 queue 中,却只看到了 6 个 Task 对象,唯独不见了这个出问题的对象。百思不得解,因为日志中这个对象的 Logger 已经打印出来了,说明至少执行了一次,为啥会从内存中消失呢?

在同事的帮助下,查阅了 API 文档,发现了这么一句话:

If any execution of the task encounters an exception, subsequent executions are suppressed. Otherwise, the task will only terminate via cancellation or termination of the executor. If any execution of this task takes longer than its period, then subsequent executions may start late, but will not concurrently execute.

注意通常的理解,这里的 suppressed 意思应该为抑制、压制,一般意义上理解为可能是说降低频率啊权重啊什么的。可是实际上,这里使用 stoped 更合适。从表现上看,你的 Task 只要出现了异常,就会被彻底扔掉,再也不会执行。

下面给出一个网上同样问题的复现代码:

import java.util.concurrent.Executors;

public class BadAssTask implements Runnable {

        @Override
        public void run() {
                System.out.println("Sleeping ...");
                try {
                        Thread.sleep(100);
                } catch (InterruptedException e) {
                        e.printStackTrace();
                }
                System.out.println("Throwing ... ");
                throw new RuntimeException("bad ass!");
        }

        public static void main(String[] args) {
                Executors.newSingleThreadScheduledExecutor().scheduleAtFixedRate(new BadAssTask(), 1, 1, TimeUnit.SECONDS);
        }

}

当我们注释掉 throw new RuntimeException(“bad ass!”);  的时候,可以看到每个 0.1s 会有一行 Sleeping … 输出。当开启注释时,Throwing … 之后再也没有 Sleeping 输出了。

于是来查看对应的代码,在 ScheduledThreadPoolExecutor  的代码中看到执行 Task 的实际调用方法为:

/**
 * Overrides FutureTask version so as to reset/requeue if periodic.
 */
public void run() {
    boolean periodic = isPeriodic();
    if (!canRunInCurrentRunState(periodic))
        cancel(false);
    else if (!periodic)
        ScheduledFutureTask.super.run();
    else if (ScheduledFutureTask.super.runAndReset()) {
        setNextRunTime();
        reExecutePeriodic(outerTask);
    }
}

注意最后一个 if 语句。当 Task 执行出错的时候, runAndReset  的返回值为 False,所以 if 里面的内容不会执行,因此这个 task 就不会被放回队列,也就再也不会被执行了。

runAndReset 方法的代码如下:

/**
 * Executes the computation without setting its result, and then
 * resets this future to initial state, failing to do so if the
 * computation encounters an exception or is cancelled.  This is
 * designed for use with tasks that intrinsically execute more
 * than once.
 *
 * @return {@code true} if successfully run and reset
 */
protected boolean runAndReset() {
    if (state != NEW ||
        !UNSAFE.compareAndSwapObject(this, runnerOffset,
                                     null, Thread.currentThread()))
        return false;
    boolean ran = false;
    int s = state;
    try {
        Callable c = callable;
        if (c != null && s == NEW) {
            try {
                c.call(); // don't set result
                ran = true;
            } catch (Throwable ex) {
                setException(ex);
            }
        }
    } finally {
        // runner must be non-null until state is settled to
        // prevent concurrent calls to run()
        runner = null;
        // state must be re-read after nulling runner to prevent
        // leaked interrupts
        s = state;
        if (s >= INTERRUPTING)
            handlePossibleCancellationInterrupt(s);
    }
    return ran && s == NEW;
}

注意其中的 setException 方法。这个方法会把 state 设置成出现异常的状态:

/**
 * Causes this future to report an {@link ExecutionException}
 * with the given throwable as its cause, unless this future has
 * already been set or has been cancelled.
 *
 * 

This method is invoked internally by the {@link #run} method * upon failure of the computation. * * @param t the cause of failure */ protected void setException(Throwable t) { if (UNSAFE.compareAndSwapInt(this, stateOffset, NEW, COMPLETING)) { outcome = t; UNSAFE.putOrderedInt(this, stateOffset, EXCEPTIONAL); // final state finishCompletion(); } }

于是在 runAndReset 最后的判断中,s == NEW 不成立,于是返回 False 了。

参考:

http://code.nomad-labs.com/2011/12/09/mother-fk-the-scheduledexecutorservice/

https://docs.oracle.com/javase/8/docs/api/java/util/concurrent/ScheduledExecutorService.html#scheduleAtFixedRate-java.lang.Runnable-long-long-java.util.concurrent.TimeUnit-

记一次 JNI 导致 Java fd 泄露的排查过程

前几天接到反馈,线上某机器上的服务在进行后端调用的时候失败了。查看日志是端口分配失败。通过 netstat -nulp  看到大量端口占用,用户段端口49152 到 65535 全部被占满。于是通过 awk sort 和 uniq 统计出每个进程的端口占用情况,发现某些 Java 服务占用了 2w+ 端口,于是对该服务展开分析。

首先考虑的是应用有大量 Socket 对象没有关闭释放,于是将堆 dump 出来,使用 VisualVM 加载分析。由于泄露的是 UDP 端口,于是考虑查找 Java 中 UDP socket 对应的对象 DatagramSocket 。可是一顿操作之后发现堆中并不存在该类对象,倒是找到了几个 DatagramSocketAdaptor  对象。查看了框架发现使用了 Netty 做 NIO,因此实际使用的是 NioDatagramChannel 和 DatagramSocketAdaptor 对象。经过对比,这些对象都是应用启动时创建 Netty channel 时创建的,数量完全正确,所以排除这方面的问题。

接着考虑 Netty 版本和 JVM 版本的问题。通过搜索发现 Netty 和 JVM 都出现过 fd 没有正确关闭的问题,于是进行升级。升级后发现问题依然存在,排除相关组件的问题。

在排除了几个可能之后,还是没有什么头绪,于是准备从 FD 本身入手。在 Java 中,所有的系统 FD 对应的都是一个 Java 中的 FileDescriptor  类,于是使用各种工具对该类的创建和删除进行了监控。结果通过排查发现,除了第一步中查到的 Netty Channel 持有的 fd 实例外,没有任何的有关网络 Socket 的 fd 实例。这下就很尴尬了,JVM 中的 fd 没有变化,按理说应该不会有 Socket 创建才对。仔细思考了一下,想到了最后一种可能,那就是 native 方法。

在 Java 中,为了支持调用其它语言所编写的方法,提供了 Java Native Interface 即 JNI 作为入口。当我们需要调用一个闭源的 C++ 编写的类库的时候,我们就可以使用 JNI 来进行调用。同时,由于 JNI 实际执行的是第三方类库中的代码,因此这部分代码进行的 fd 操作都不会被 JVM 管理,自然也就不会出现在 Dump 文件中。

既然猜到了可能的问题,接下来就需要排查了。可是由于一些原因,该服务中存在很多的 JNI 类库都会进行网络调用,无法最终确定。于是想了这么一个办法来进行排查:

  1. 在机器上起一个程序不断的对 lsof -a -n -P -i udp -p pid  进行采样对比,遇到两次采样期间有新增的 fd 就打印出来
  2. 同时使用 tcpdump -i any udp -w fd_leak.pcap  进行全量抓包,记录机器上所有的 UDP 网络流量,来对比分析流量发出的进程

经过排查,终于抓到了对应的包,找到了对端的 IP 端口,定位到了对应的组件。于是对这个组件编写复现代码进行测试,最终将代码简化为:

package com.maoxian.test;

import com.maoxian.xxx.NativeAPI;

/**
 * 测试类
 */
public class Test {
    public static void main(String[] args) {
        Thread.sleep(10000);
        int i = 0;
        while (i < 10) {
            i++;
            System.out.println("Start loop " + j + " ...");
            new Thread() {

                @Override
                public void run() {
                    try {
                        System.out.println("Thread " +
                                Thread.currentThread().getId() +
                                " is running...");


                        NativeAPI.doSomething();
                    } finally {
                        System.out.println("Thread " +
                                Thread.currentThread().getId() +
                                " finished.");
                    }
                }
            }.start();
            System.out.println("Finish loop " + j + ".");
        }
        Thread.sleep(60000);
    }
}

这段代码的作用非常简单,就是起 10 个线程去调用这个组件,每个线程调用一次就退出。Sleep 的作用是给 lsof 列出 fd 预留时间。在执行这段代码后可以明显的看到 fd 在 Native 方法调用时分配,但是在线程退出后没有释放。咨询了相关同事后得知,由于在 C++ 中,一般不会使用 Java 中的这种线程池模型,而是使用固定线程模型。当一个线程退出的时候通常意味着整个程序的退出。所以这个组件在制作的时候只考虑了线程安全的问题对每个线程独立分配了资源,但是没有考虑线程终止时候的资源释放

在定位到 fd 泄露与线程创建相关后,对相应的业务框架代码进行了分析。发现框架中创建线程池使用的是:

this.tasks = Executors.newCachedThreadPool(new ThreadFactory() {
    final AtomicInteger TID = new AtomicInteger(0);
    final String GROUP_NAME = "TPWS-" + GID.getAndIncrement();
    @Override
    public Thread newThread(Runnable r) {
        return new Thread(r, GROUP_NAME + TID.getAndIncrement());
    }
});

查看 Executors 的创建线程池的方法:

/**
 * Creates a thread pool that creates new threads as needed, but
 * will reuse previously constructed threads when they are
 * available, and uses the provided
 * ThreadFactory to create new threads when needed.
 * @param threadFactory the factory to use when creating new threads
 * @return the newly created thread pool
 * @throws NullPointerException if threadFactory is null
 */
public static ExecutorService newCachedThreadPool(ThreadFactory threadFactory) {
    return new ThreadPoolExecutor(0, Integer.MAX_VALUE,
                                  60L, TimeUnit.SECONDS,
                                  new SynchronousQueue(),
                                  threadFactory);
}

可以看出,这个方法最终创建了一个最小 0 个线程,最大 Integer.MAX_VALUE 个线程,每个线程 60s 超时时间。于是,当一个业务请求到来时,线程池创建一个新线程处理这个请求,在请求中调用了 Native 方法。当请求处理完后,线程归还线程池。60s 内如果没有新的请求进入,则该线程被线程池销毁,但是 Native 申请的 fd 没有释放。当新的请求到来时,又重新创建线程,重新分配 fd,以此类推,导致 fd 泄露。

这次排查的经理告诉我们,当 Java 调用 Native 方法的时候一定要格外小心。由于虚拟机无法对大多数 Native 方法占用的资源进行管理,因此编写质量差的 Native 类库会直接导致不可预知的奇怪问题。特别是由于 C++ 在多线程、多进程模型上与 Java 有诸多不同,很多库在设计时就没有考虑全面,直接在 Java 内调用的时候可能就会出现在 C++ 中不会遇到的问题。

Tomcat 在处理 Cookie 的时候的几个小坑

今天在代码中调用 HttpServletRequest  对象的 getCookies()  方法时,发现实际得到的 Cookie 数量与提交的不符。实际提交了 17 个 Cookie,但是获取到的只有 14 个。

经过排查,发现如果调用 getHeaders(“Cookie”)  方法,获取原始的 Cookie 串,是可以拿到正确的 17 个 Cookie 组成的字符串的。于是确认应该是 Tomcat 在处理 Cookie 的时候进行了过滤。

经过一番搜索,发现了这个文档:

http://tomcat.apache.org/tomcat-7.0-doc/config/systemprops.html

其中,跟 Cookie 相关的参数有:

org.apache.tomcat.util.http. ServerCookie.ALLOW_EQUALS_IN_VALUE If this is true Tomcat will allow ‘=‘ characters when parsing unquoted cookie values. If false, cookie values containing ‘=‘ will be terminated when the ‘=‘ is encountered and the remainder of the cookie value will be dropped.

If not specified, the default value specification compliant value of false will be used.

org.apache.tomcat.util.http. ServerCookie.ALLOW_HTTP_SEPARATORS_IN_V0 If this is true Tomcat will allow HTTP separators in cookie names and values.

If not specified, the default specification compliant value of false will be used.

org.apache.tomcat.util.http. ServerCookie.ALLOW_NAME_ONLY If this is false then the requirements of the cookie specifications that cookies must have values will be enforced and cookies consisting only of a name but no value will be ignored.

If not specified, the default specification compliant value of false will be used.

org.apache.tomcat.util.http. ServerCookie.ALWAYS_ADD_EXPIRES If this is true Tomcat will always add an expires parameter to a SetCookie header even for cookies with version greater than zero. This is to work around a known IE6 and IE7 bug that causes IE to ignore the Max-Age parameter in a SetCookie header.

If org.apache.catalina.STRICT_SERVLET_COMPLIANCE is set to true, the default of this setting will be false, else the default value will be true.

org.apache.tomcat.util.http. ServerCookie.FWD_SLASH_IS_SEPARATOR If this is true then the / (forward slash) character will be treated as a separator. Note that this character is frequently used in cookie path attributes and some browsers will fail to process a cookie if the path attribute is quoted as is required by a strict adherence to the specifications. This is highly likely to break session tracking using cookies.

If org.apache.catalina.STRICT_SERVLET_COMPLIANCE is set to true, the default of this setting will be true, else the default value will be false.

org.apache.tomcat.util.http. ServerCookie.PRESERVE_COOKIE_HEADER If this is true Tomcat will ensure that cookie processing does not modify cookie header returned by HttpServletRequest.getHeader().

If org.apache.catalina.STRICT_SERVLET_COMPLIANCE is set to true, the default of this setting will be true, else the default value will be false.

org.apache.tomcat.util.http. ServerCookie.STRICT_NAMING If this is true then the requirements of the Servlet specification that Cookie names must adhere to RFC2109 (no use of separators) will be enforced.

If org.apache.catalina.STRICT_SERVLET_COMPLIANCE is set to true, the default of this setting will be true, else the default value will be false.

看了一下相关参数,跟我这个现象有关的是这两个选项:

org.apache.tomcat.util.http. ServerCookie.ALLOW_HTTP_SEPARATORS_IN_V0
org.apache.tomcat.util.http. ServerCookie.ALLOW_NAME_ONLY

于是按照这个选项去搜索,发现了这样一篇文章:

http://www.cnblogs.com/princessd8251/articles/4172103.html

其中详细说明了第一个选项的作用:

在网上查了下,cookie有以下版本:

版本0:由Netscape公司制定的,也被几乎所有的浏览器支持。Java中为了保持兼容性,目前只支持到版本0,Cookie的内容中不能包含空格,方括号,圆括号,等于号(=),逗号,双引号,斜杠,问号,@符号,冒号,分号。

版本1:根据RFC 2109(http://www.ietf.org/rfc/rfc2109.txt)文档制定的. 放宽了很多限制. 上面所限制的字符都可以使用. 但为了保持兼容性, 应该尽量避免使用这些特殊字符。

Tomcat 具体的过滤源码里面包含了这些字符:

如果 org.apache.tomcat.util.http.ServerCookie.FWD_SLASH_IS_SEPARATOR 设为 true (默认 False),’/’也会被作为http分隔符

如果 org.apache.tomcat.util.http.ServerCookie.ALLOW_HTTP_SEPARATORS_IN_V0 设为 true (默认 False),tomcat将会允许cookie的name和value使用http分隔符

tomcat源码中的http分隔符:’\t’, ‘ ‘, ‘\”‘, ‘(‘, ‘)’, ‘,’, ‘:’, ‘;’, ‘<', '=', '>‘, ‘?’, ‘@’, ‘[‘, ‘\\’, ‘]’, ‘{‘, ‘}’

然后第二个选项就很好理解了,如果 Cookie 的 Value 是空,那么直接干掉。

于是,我们传的 Cookie 是这样的:

aaa=@abcdefg

Tomcat 先做了一次截断,将 @ 和后面的内容都去掉了;然后做了一次判断,发现 aaa 这个 Cookie 只有 name 没有 value,于是直接干掉了。

到此真相大白。

 

如果想要解决这个问题,有两个方法:

1. 在 Tomcat 的配置文件 catalina.properties  中设置 org.apache.tomcat.util.http.ServerCookie.ALLOW_HTTP_SEPARATORS_IN_V0=true

2. 在代码中使用 request.getHeader(“Cookie”) 取出原始的 Cookie 串,自行处理。