记录一次使用JobRunr的踩坑经历

一、问题记录

使用JobRunr创建周期性任务，同一时间会生成多个执行任务Jobs。不管是schedule类型的、还是cron类型的任务都会出现。

BackgroundJob.scheduleRecurrently("xxx-task-1","*/5 * * * * *", () -> {
    task.run(Map.of("userName", "xxxxxx", "phoneNum", "18555555555", "age", 18));
})

使用的官方例子，创建一个每5s执行一次的定时任务,jobrunr会在数据库jobrunr_recurring_jobs中创建一条周期性任务信息。

但是实际数据库jobrunr_jobs表中会生成3条需要执行的任务。

按理说，一个周期任务在到达时间只会创建一条执行任务出来，对于这样相对成熟的框架来说，这个问题不应该出现才对。首先怀疑的就是自己的使用姿势可能有问题，但是又有疑惑，这只是一个简单demo，还是根据官方文档来的。哎，跟跟源码排查下问题吧。

二、排查过程

查看控制台日志，发现一条日志

点进ProcessRecurringJobsTask类，发现是toScheduledJobs 方法中，jobsToSchedule 这个集合大于1了，继续看getJobsToSchedule方法排查

List<Job> toScheduledJobs(RecurringJob recurringJob, Instant from, Instant upUntil) {
    List<Job> jobsToSchedule = getJobsToSchedule(recurringJob, from, upUntil);
    if (jobsToSchedule.isEmpty()) {
        LOGGER.trace("Recurring job '{}' resulted in 0 scheduled job.", recurringJob.getJobName());
    } else if (jobsToSchedule.size() > 1) {
        LOGGER.info("Recurring job '{}' resulted in {} scheduled jobs. This means a long GC happened and JobRunr is catching up.", recurringJob.getJobName(), jobsToSchedule.size());
    } else if (isAlreadyScheduledEnqueuedOrProcessing(recurringJob)) {
        LOGGER.debug("Recurring job '{}' is already scheduled, enqueued or processing. Run will be skipped as job is taking longer than given CronExpression or Interval.", recurringJob.getJobName());
        jobsToSchedule.clear();
    } else if (jobsToSchedule.size() == 1) {
        LOGGER.debug("Recurring job '{}' resulted in 1 scheduled job.", recurringJob.getJobName());
    }
    registerRecurringJobRun(recurringJob, upUntil);
    return jobsToSchedule;
}

private List<Job> getJobsToSchedule(RecurringJob recurringJob, Instant runStartTime, Instant upUntil) {
    Instant lastRun = recurringJobRuns.getOrDefault(recurringJob.getId(), runStartTime);
    return recurringJob.toScheduledJobs(lastRun, upUntil);
}

RecurringJob类：这里是最终创建job的地方，说明这个while循环，执行了3次。注意到while条件nextRun.isBefore(upTo),说明多次未达到结束时间，而循环中每次都会重新计算nextRun下一次执行时间，那就继续看getNextRun是怎么计算的，发现只是获取任务的一个周期表达式。这里至少明白，这个方法是判断在开始时间和结束时间中，根据你设定的周期任务（比如我的例子是5s执行一次）,生成多个执行任务出来，这里感觉没什么问题。那就说明这里传入的开始时间和结束时间可能不是我们所期望的。继续排查看是什么地方传入的这些参数。

/**
* Creates all jobs that must be scheduled between the given start and end time.
* 创建必须在给定的开始和结束时间之间安排的所有作
*
* @param from the start time from which to create Scheduled Jobs
* @param upTo the end time until which to create Scheduled Jobs
* @return creates all jobs that must be scheduled
*/
public List<Job> toScheduledJobs(Instant from, Instant upTo) {
    List<Job> jobs = new ArrayList<>();
    Instant nextRun = getNextRun(from);
    while (nextRun.isBefore(upTo)) {
        jobs.add(toJob(new ScheduledState(nextRun, this)));
        nextRun = getNextRun(nextRun);
    }
    return jobs;
}

public Instant getNextRun(Instant sinceInstant) {
    return ScheduleExpressionType
            .getSchedule(scheduleExpression)
            .next(createdAt, sinceInstant, ZoneId.of(zoneId));
}

那就反向排查，ProcessRecurringJobsTask类中getJobsToSchedule方法中有一段Instant lastRun = recurringJobRuns.getOrDefault(recurringJob.getId(), runStartTime);获取到了最后一次执行时间。然后Instant upUntil 结束时间是由外部传入的，继续往外排查，最终到runTask方法中。

private List<Job> getJobsToSchedule(RecurringJob recurringJob, Instant runStartTime, Instant upUntil) {
    Instant lastRun = recurringJobRuns.getOrDefault(recurringJob.getId(), runStartTime);
    return recurringJob.toScheduledJobs(lastRun, upUntil);
}

@Override
protected void runTask() {
    LOGGER.trace("Looking for recurring jobs... ");

    Instant from = runStartTime();
    Instant upUntil = runStartTime().plus(backgroundJobServerConfiguration().getPollInterval());
    List<RecurringJob> recurringJobs = getRecurringJobs();
    convertAndProcessManyJobs(recurringJobs,
            recurringJob -> toScheduledJobs(recurringJob, from, upUntil),
            totalAmountOfJobs -> LOGGER.debug("Found {} jobs to schedule from {} recurring jobs", totalAmountOfJobs, recurringJobs.size()));
}

发现upUntil时间是由Instant upUntil = runStartTime().plus(backgroundJobServerConfiguration().getPollInterval());得来。发现是从配置文件中pollInterval 属性来的，而这个属性在配置文件中默认设置了15s。

public static final Duration DEFAULT_POLL_INTERVAL = Duration.ofSeconds(15);

Duration pollInterval = DEFAULT_POLL_INTERVAL;

三、问题原因

其实这里，我们大概能知道是什么问题了。我们再debug下，看看具体计算出的时间是什么。

回顾上面所提到的创建任务的逻辑，根据任务的周期在开始和结束时间之间创建任务，我们的任务周期设置是每5s执行一次，那么在2024-09-03 03:47:31和2024-09-03 03:47:46之间就有3个任务需要被创建。这就是我们开头所看到的，同一时间有多个执行任务出现。

至此，问题的根源已经找到。Jobrunr设定了一个自己的最小任务调度周期时间15s，如果创建任务的周期时间小于15，可能会被创建多个执行任务出来。

在此记录，避免以后再遇到，也给各位提供一个参考。