How to prioritize misfired jobs?

[Keen13]

Hi there,

I run several jobs on schedule, and sometimes the first of them takes very long, so that the others misfire. I this case I want one of misfired jobs to be always run first. For legacy code (Net 4.8) there was high priority assigned to that task, and it worked well.

            var trigger = TriggerBuilder.Create()
                .WithIdentity($"{job.JobName}Trigger")
                .ForJob(quartzJob.Key)
                .WithSchedule(CronScheduleBuilder.CronSchedule(job.Cron))
                .WithPriority(job.Priority)
                .Build();

After switching to NET Core prioritizing for misfired jobs stopped working (still works for "regular" jobs though). So, is there a way to prioritize misfired jobs now? Couldn't find anything relevant in Quartz documentation.

Quartz.Net 3.5.0
.NET SDK 6.0.401

[lahma]

So is there a behavioral change just by running same version of Quartz on NET 6 vs full framework or did Quartz version change too in the process?

[Roganik]

Hi @lahma, Yes, changing from net48 to net6 changes behavior.

---

You can find an example in this repository: https://github.com/Roganik/Quartznet-MisfireOrderExample

1. Quartz is created with StdSchedulerFactory with such properties:

 public static NameValueCollection GetConfig()
    {
        var misfireThresholdMilliseconds = 1 * 1000; // 1 second

        return new NameValueCollection()
        {
            { "quartz.threadPool.threadCount", "1" },
            { "quartz.jobStore.misfireThreshold", misfireThresholdMilliseconds.ToString() },
            { "quartz.scheduler.instanceName", "MyProjQuartzScheduler" }
        };
    }

2. Depending on the framework behavior of tests changes

In Scenario 1 it's expected that TestJob2 with biggest priority will be executed before other jobs.

Output example for Test Scenario 1

net48 - TestJob2 executed before other jobs.

ScheduleJob -> BlockingTestJob to run at 19 30 17 ? * * with Priority 0
ScheduleJob ->        TestJob1 to run at 24 30 17 ? * * with Priority 0
ScheduleJob ->        TestJob2 to run at 29 30 17 ? * * with Priority 1
ScheduleJob ->        TestJob3 to run at 34 30 17 ? * * with Priority 0
BlockingTestMyJob created. Job Execute Time is 20 secs.
Starting at 19 30 17
Executed at 39 30 17
TestMyJob2 created. Job Execute Time is 2 secs.
Starting at 39 30 17
Executed at 41 30 17
TestMyJob1 created. Job Execute Time is 2 secs.
Starting at 41 30 17
Executed at 43 30 17
TestMyJob3 created. Job Execute Time is 2 secs.
Starting at 43 30 17
Executed at 45 30 17

net6 - TestJob2 executed after TestJob1. Behavior is different in comparison to net48. Priority is ignored.

ScheduleJob -> BlockingTestJob to run at 52 36 17 ? * * with Priority 0
ScheduleJob ->        TestJob1 to run at 57 36 17 ? * * with Priority 0
ScheduleJob ->        TestJob2 to run at 2 37 17 ? * * with Priority 1
ScheduleJob ->        TestJob3 to run at 7 37 17 ? * * with Priority 0
BlockingTestMyJob created. Job Execute Time is 20 secs.
Starting at 52 36 17
Executed at 12 37 17
TestMyJob1 created. Job Execute Time is 2 secs.
Starting at 12 37 17
Executed at 14 37 17
TestMyJob2 created. Job Execute Time is 2 secs.
Starting at 14 37 17
Executed at 16 37 17
TestMyJob3 created. Job Execute Time is 2 secs.
Starting at 16 37 17
Executed at 18 37 17

---

Hope it helps

[Keen13]

Hi @lahma,
So, any suggestion where we can start looking for the root of the issue?

[Keen13]

UPD: I did some research and that's what I found out.

RAMJobStore.AcquireNextTriggers(...) method takes triggers one by one until it finds the next trigger to run.
When it takes a misfired trigger, it re-schedules that trigger according to current MisfireInstruction.
For our test case - CronTrigger with MisfireInstruction.SmartPolicy - a misfired trigger is re-scheduled for Quartz.SystemTime.UtcNow(), which is effectively System.DateTime.UtcNow.

Now, here's the root cause.
Under net48 all consecutive calls of DateTime.UtcNow within the same method (RAMJobStore.AcquireNextTriggers(...)) return the same value, so all misfired jobs become re-scheduled for the exact same time. So when it comes to taking the next trigger to run, priority kicks in.
Under net6 consecutive calls of DateTime.UtcNow returns different values, so TestJob1 is re-scheduled earlier than TestJob2, since it goes first in the original schedule. The difference can be less than 1ms in case of our tests, but that's enough for Quartz to run TestJob1 before TestJob2 without paying attention to priority.

Hope it would help to decide how and if this behaviour should be fixed.

[lahma]

That's some great investigative work there, thank you for doing it! From the top of my head I don't see a reason why the timestamp couldn't be a snapshot shared by the loop, especially as this is in-memory job store where timings should be in milliseconds.

Would you like to create a PR against the 3.x branch to fix this case for you?

[Keen13]

Hi @lahma,
I've finally got around to fix it. Could you please check the draft version of my fix before I refine it and create a PR. I tried to keep my changes limited to the described case only, but maybe you see more simple or elegant way to share a timestamp snapshot.

main...Keen13:quartznet:MisfireWithPriorityFix-draft

Also I'd like to know if I should add some tests for this case, and where they should be placed. I checked my changes against tests provided by @Roganik in his example.
https://github.com/Roganik/Quartznet-MisfireOrderExample

[Keen13]

Here are some logs showing what happens inside RAMJobStore.AcquireNextTriggers(...) method for better understanding.
Job2 is expected be run before Job1 because of higher priority.

== Before the fix ==

/* All 3 triggers misfired because of a long running job */
AcquireNextTriggers: Looking for triggers to fire on or before 01:18:25.1176331

ApplyMisfire for trigger: TestJob1Trigger
Misfire time: 01:17:54.1177037
Current TriggerNextFireTime: 01:17:40.0000000
Updated TriggerNextFireTime: 01:17:55.1186568
Misfire triggered for: TestJob1Trigger (new trigger added)

ApplyMisfire for trigger: TestJob2Trigger
Misfire time: 01:17:54.1188875
Current TriggerNextFireTime: 01:17:45.0000000
Updated TriggerNextFireTime: 01:17:55.1189286
Misfire triggered for: TestJob2Trigger (new trigger added)

ApplyMisfire for trigger: TestJob3Trigger
Misfire time: 01:17:54.1189352
Current TriggerNextFireTime: 01:17:50.0000000
Updated TriggerNextFireTime: 01:17:55.1189429
Misfire triggered for: TestJob3Trigger (new trigger added)

/* Each trigger gets different  TriggerNextFireTime inside one AcquireNextTriggers loop */
/* TestJob1Trigger is chosen here because it has the earliest TriggerNextFireTime */
ApplyMisfire for trigger: TestJob1Trigger 
Misfire time: 01:17:54.1189493
Current TriggerNextFireTime: 01:17:55.1186568
ApplyMisfire: Misfire did not happen. TestJob1Trigger will be triggered next

== After the fix ==

/* All 3 triggers misfired because of a long running job */
AcquireNextTriggers: Looking for triggers to fire on or before 01:21:33.1149638

ApplyMisfire for trigger: TestJob1Trigger
Misfire time: 01:21:02.1150310
Current TriggerNextFireTime: 01:20:48.0000000
Updated TriggerNextFireTime: 01:21:03.1150310
Misfire triggered for: TestJob1Trigger (new trigger added)

ApplyMisfire for trigger: TestJob2Trigger
Misfire time: 01:21:02.1150310
Current TriggerNextFireTime: 01:20:53.0000000
Updated TriggerNextFireTime: 01:21:03.1150310
Misfire triggered for: TestJob2Trigger (new trigger added)

ApplyMisfire for trigger: TestJob3Trigger
Misfire time: 01:21:02.1150310
Current TriggerNextFireTime: 01:20:58.0000000
Updated TriggerNextFireTime: 01:21:03.1150310
Misfire triggered for: TestJob3Trigger (new trigger added)

/* All triggers get the same TriggerNextFireTime inside one AcquireNextTriggers loop */
/* TestJob2Trigger is chosen here because trigger.Priority kicks in */
ApplyMisfire for trigger: TestJob2Trigger 
Misfire time: 01:21:02.1150310
Current TriggerNextFireTime: 01:21:03.1150310
ApplyMisfire: Misfire did not happen. TestJob2Trigger will be triggered next

[Keen13]

@lahma, any thoughts on the proposed fix?

[lahma]

Sorry folks that I've dropped the ball here a bit. I'm thankful for all the repro steps and great samples you've provided. I'll try to find the time to concentrate on this a bit better but at the moment busy work schedule has changed into busy vacationing schedule with the family. This thing has not been forgotten!