Uploaded image for project: 'Red Hat Process Automation Manager'
  1. Red Hat Process Automation Manager
  2. RHPAM-286

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

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 7.0.0.GA
    • 6.x.x
    • jBPM Core
      • QuartzScheduler

    Description

      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.

      Attachments

        Issue Links

          is cloned by

          Bug - A problem that impairs or prevents the functions of the product. RHBPMS-4736 [GSS] (6.4.z) QuartzSchedulerService increments NEXT_FIRE_TIME by timeCycle regardless of current time when calling rescheduleJob()

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Verified
          relates to

          Bug - A problem that impairs or prevents the functions of the product. RHPAM-170 Job/Trigger for repeat Timer are deleted on short interval executions with Quartz

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Activity

            People

              swiderski.maciej Maciej Swiderski (Inactive)
              rhn-support-tkobayas Toshiya Kobayashi
              Tomáš Livora Tomáš Livora (Inactive)
              Tomáš Livora Tomáš Livora (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: