Uploaded image for project: 'JBoss BPMS Platform'
  1. JBoss BPMS Platform
  2. RHBPMS-4736

[GSS] (6.4.z) QuartzSchedulerService increments NEXT_FIRE_TIME by timeCycle regardless of current time when calling rescheduleJob()

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • 6.4.4, 7.0.0.GA
    • 6.4.0
    • jBPM Core
      • QuartzScheduler

      QuartzSchedulerService increments NEXT_FIRE_TIME by timeCycle regardless of current time when calling rescheduleJob()

      QuartzSchedulerService increments NEXT_FIRE_TIME by the timeCycle regardless of current time. So if we reboot BPMS with some interval larger than (timeCycle + misfireThreshold), NEXT_FIRE_TIME becomes always older than (now - misfireThreshold).

      In this case, MisfireHandler has to amend the NEXT_FIRE_TIME so the execution cycle always relies on MisfireHandler so cannot be shorter than "misfireThreshold".

      See the attached reproducer 01793010_quartz_misfire_h2_BPMS640.zip.

      • StartTimerEvent timeCycle = 10s
      • misfireThreshold = 60000
      • idleWaitTime = 30000 (default)

      After RuntimeManager restart, you will see StartTimerEvent is triggered only with 60 seconds interval which depends on misfireThreshold.

      Below is the output example with debug logging:

      @@ -171,6 +171,7 @@ public class QuartzSchedulerService implements GlobalSchedulerService {
                 scheduler.addJob(jobq, true);
                 triggerq.setJobName(quartzJobHandle.getJobName());
                 triggerq.setJobGroup(quartzJobHandle.getJobGroup());
+                logger.info("############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = " + triggerq.getStartTime());
                 scheduler.rescheduleJob(quartzJobHandle.getJobName()+"_trigger", quartzJobHandle.getJobGroup(), triggerq);
             }

      2017-05-12 19:03:24,396 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler meta-data: Quartz Scheduler (v1.8.5) 'jBPMClusteredScheduler' with instanceId 'tkobayas.nrt.csb1494583404379'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 5 threads.
  Using job-store 'org.quartz.impl.jdbcjobstore.JobStoreCMT' - which supports persistence. and is clustered.

2017-05-12 19:03:24,396 INFO  [main] [org.quartz.impl.StdSchedulerFactory] Quartz scheduler 'jBPMClusteredScheduler' initialized from specified file: 'quartz-definition.properties' in the class resource path.
2017-05-12 19:03:24,396 INFO  [main] [org.quartz.impl.StdSchedulerFactory] Quartz scheduler version: 1.8.5
2017-05-12 19:03:24,399 INFO  [main] [org.drools.persistence.TransactionManagerFactory] Using org.drools.persistence.jta.JtaTransactionManagerFactory@5e922647
2017-05-12 19:03:26,421 INFO  [Thread-6] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583404379 started.
2017-05-12 19:03:34,755[jBPMClusteredScheduler_Worker-1] --- Process started : piid = 1
2017-05-12 19:03:35,757[jBPMClusteredScheduler_Worker-1] --- work done
2017-05-12 19:03:35,915 INFO  [jBPMClusteredScheduler_Worker-1] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] ############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = Fri May 12 19:03:44 JST 2017
=== closing RuntimeManager
2017-05-12 19:03:36,948 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583404379 shutting down.
2017-05-12 19:03:36,949 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583404379 paused.
2017-05-12 19:03:36,961 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583404379 shutdown complete.
=== sleeping
=== sleep done
2017-05-12 19:04:57,102 INFO  [main] [org.quartz.core.SchedulerSignalerImpl] Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2017-05-12 19:04:57,103 INFO  [main] [org.quartz.core.QuartzScheduler] Quartz Scheduler v.1.8.5 created.
2017-05-12 19:04:57,103 INFO  [main] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Using db table-based data access locking (synchronization).
2017-05-12 19:04:57,103 INFO  [main] [org.quartz.impl.jdbcjobstore.JobStoreCMT] JobStoreCMT initialized.
2017-05-12 19:04:57,103 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler meta-data: Quartz Scheduler (v1.8.5) 'jBPMClusteredScheduler' with instanceId 'tkobayas.nrt.csb1494583497101'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 5 threads.
  Using job-store 'org.quartz.impl.jdbcjobstore.JobStoreCMT' - which supports persistence. and is clustered.

2017-05-12 19:04:57,103 INFO  [main] [org.quartz.impl.StdSchedulerFactory] Quartz scheduler 'jBPMClusteredScheduler' initialized from specified file: 'quartz-definition.properties' in the class resource path.
2017-05-12 19:04:57,103 INFO  [main] [org.quartz.impl.StdSchedulerFactory] Quartz scheduler version: 1.8.5
2017-05-12 19:04:59,127 INFO  [Thread-11] [org.quartz.impl.jdbcjobstore.JobStoreCMT] ClusterManager: detected 1 failed or restarted instances.
2017-05-12 19:04:59,128 INFO  [Thread-11] [org.quartz.impl.jdbcjobstore.JobStoreCMT] ClusterManager: Scanning for instance "tkobayas.nrt.csb1494583404379"'s failed in-progress jobs.
2017-05-12 19:04:59,136 INFO  [Thread-11] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583497101 started.
2017-05-12 19:04:59,152 INFO  [QuartzScheduler_jBPMClusteredScheduler-tkobayas.nrt.csb1494583497101_MisfireHandler] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Handling 1 trigger(s) that missed their scheduled fire-time.
2017-05-12 19:04:59,214[jBPMClusteredScheduler_Worker-1] --- Process started : piid = 2
2017-05-12 19:05:00,215[jBPMClusteredScheduler_Worker-1] --- work done
2017-05-12 19:05:00,269 INFO  [jBPMClusteredScheduler_Worker-1] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] ############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = Fri May 12 19:03:54 JST 2017
2017-05-12 19:05:59,148 INFO  [QuartzScheduler_jBPMClusteredScheduler-tkobayas.nrt.csb1494583497101_MisfireHandler] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Handling 1 trigger(s) that missed their scheduled fire-time.
2017-05-12 19:05:59,232[jBPMClusteredScheduler_Worker-2] --- Process started : piid = 3
2017-05-12 19:06:00,233[jBPMClusteredScheduler_Worker-2] --- work done
2017-05-12 19:06:00,287 INFO  [jBPMClusteredScheduler_Worker-2] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] ############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = Fri May 12 19:04:04 JST 2017
2017-05-12 19:06:59,144 INFO  [QuartzScheduler_jBPMClusteredScheduler-tkobayas.nrt.csb1494583497101_MisfireHandler] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Handling 1 trigger(s) that missed their scheduled fire-time.
2017-05-12 19:06:59,229[jBPMClusteredScheduler_Worker-3] --- Process started : piid = 4
2017-05-12 19:07:00,229[jBPMClusteredScheduler_Worker-3] --- work done
2017-05-12 19:07:00,283 INFO  [jBPMClusteredScheduler_Worker-3] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] ############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = Fri May 12 19:04:14 JST 2017

      You also see that triggerq.getStartTime() is always old.

      I guess QuartzSchedulerService.internalSchedule() should set (now + timeCycle) to SimpleTrigger.startTime.

        1. 01793010_quartz_misfire_h2_BPMS640.zip
          79 kB

              swiderski.maciej Maciej Swiderski (Inactive)
              rhn-support-tkobayas Toshiya Kobayashi
              Dominik Hanak Dominik Hanak
              Dominik Hanak Dominik Hanak
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: