search

jlinn / quartz-redis-jobstore

A Quartz Scheduler JobStore using Redis.
Apache License 2.0
137 stars 66 forks source link

jobs not getting fired at correct intervals defined in the triggers #16

Open JG00329142 opened 8 years ago

JG00329142 commented 8 years ago

HI I have 2 jobs with separate triggers, trigger : group1.triggerA For Job key refreshgroup1.refreshjobA will run at: Tue Oct 18 15:23:12 IST 2016 and repeat: 10 times, every 10 seconds trigger : group2.triggerB For Job key refreshgroup1.refreshjobB will run at: Tue Oct 18 15:23:14 IST 2016 and repeat: 10 times, every 7 seconds

But in the output i see that Job A doesnot repeat after 10 sec, Sometime the interval is 20 sec, sometimes it is 14 sec

Same problem for Job B. the interval is not 7 sec as it is configured to be. What am i missing here?

Thanks for your help.

------- Starting Scheduler ---------------- ------- Started Scheduler ----------------- ------- Waiting 90 seconds... ------------- RefreshJob: execute called Tue Oct 18 15:23:19 IST 2016 : for A RefreshJob: execute called Tue Oct 18 15:23:26 IST 2016 : for B RefreshJob: execute called Tue Oct 18 15:23:32 IST 2016 : for B RefreshJob: execute called Tue Oct 18 15:23:39 IST 2016 : for A RefreshJob: execute called Tue Oct 18 15:23:45 IST 2016 : for B RefreshJob: execute called Tue Oct 18 15:23:52 IST 2016 : for A RefreshJob: execute called Tue Oct 18 15:23:59 IST 2016 : for B RefreshJob: execute called Tue Oct 18 15:24:06 IST 2016 : for A RefreshJob: execute called Tue Oct 18 15:24:14 IST 2016 : for B RefreshJob: execute called Tue Oct 18 15:24:21 IST 2016 : for B RefreshJob: execute called Tue Oct 18 15:24:28 IST 2016 : for A RefreshJob: execute called Tue Oct 18 15:24:35 IST 2016 : for B RefreshJob: execute called Tue Oct 18 15:24:42 IST 2016 : for A

jlinn commented 8 years ago

Hmm... this one may be a bit tough to track down. Would you mind posting your setup so that I can have some additional context? (Quartz config, scheduler, job, and trigger initialization, etc.)

JG00329142 commented 7 years ago

Hi jlinn Sorry for the late reply. was stuck with strict deadlines at work. here is the info you requested for.

My demo program + quartz.properties

REdisJobStoreError16.zip

Please do look into this. we Kind of deferred the use of quartz-redis-jobstore as we could not figure out a solution to this. We would want to integrate the use of quartz-redis-jobstore very soon.

jlinn commented 7 years ago

I modified your job code slightly as follows (mainly so I wouldn't have to do math): 

@PersistJobDataAfterExecution
@DisallowConcurrentExecution
public class WorkingRefreshJob implements Job {

    // parameter names specific to this job
    public static final String LOGIN_ID = "loginID";
    private static final String EXECUTION_TIME = "exTime";

    public WorkingRefreshJob() {
    }

    public void execute(JobExecutionContext context) throws JobExecutionException {
        // Grab and print passed parameters

        JobDataMap data = context.getJobDetail().getJobDataMap();

        String loginID = data.getString(LOGIN_ID);

        String previousTime = (String) data.get(EXECUTION_TIME);
        final Date executionTime = new Date();
        String message = "RefreshJob: execute called " + executionTime +" : for " + loginID;
        data.put(EXECUTION_TIME, String.valueOf(executionTime.getTime()));
        if (previousTime != null) {
            message += " last executed " + (executionTime.getTime() - Long.valueOf(previousTime)) + "ms ago";
        }
        System.out.println(message);
    }

}

I then ran the demo locally and got the following output:

------- Initialization Complete --------
------- Scheduling Jobs ----------------
 refreshJobA configured to trigger 5 sec from Sun Dec 11 15:00:59 PST 2016 and repeat every 5 sec for 10 times
 refreshJobA configured to trigger 7 sec from Sun Dec 11 15:00:59 PST 2016 and repeat every 7 sec for 10 times
trigger : group1.triggerA For Job key refreshgroup1.refreshjobA will run at: Sun Dec 11 15:01:04 PST 2016 and repeat: 10 times, every 10 seconds
trigger : group2.triggerB For Job key refreshgroup1.refreshjobB will run at: Sun Dec 11 15:01:06 PST 2016 and repeat: 10 times, every 7 seconds
------- Starting Scheduler ----------------
------- Started Scheduler -----------------
------- Waiting 90 seconds... -------------
RefreshJob: execute called Sun Dec 11 15:01:04 PST 2016 : for A@xyz.com
RefreshJob: execute called Sun Dec 11 15:01:06 PST 2016 : for B@abc.com
RefreshJob: execute called Sun Dec 11 15:01:13 PST 2016 : for B@abc.com last executed 7000ms ago
RefreshJob: execute called Sun Dec 11 15:01:14 PST 2016 : for A@xyz.com last executed 9994ms ago
RefreshJob: execute called Sun Dec 11 15:01:20 PST 2016 : for B@abc.com last executed 7000ms ago
RefreshJob: execute called Sun Dec 11 15:01:24 PST 2016 : for A@xyz.com last executed 10000ms ago
RefreshJob: execute called Sun Dec 11 15:01:27 PST 2016 : for B@abc.com last executed 7000ms ago
RefreshJob: execute called Sun Dec 11 15:01:34 PST 2016 : for A@xyz.com last executed 9999ms ago
RefreshJob: execute called Sun Dec 11 15:01:34 PST 2016 : for B@abc.com last executed 7001ms ago
RefreshJob: execute called Sun Dec 11 15:01:41 PST 2016 : for B@abc.com last executed 6999ms ago
RefreshJob: execute called Sun Dec 11 15:01:44 PST 2016 : for A@xyz.com last executed 10000ms ago
RefreshJob: execute called Sun Dec 11 15:01:48 PST 2016 : for B@abc.com last executed 7000ms ago
RefreshJob: execute called Sun Dec 11 15:01:54 PST 2016 : for A@xyz.com last executed 10000ms ago
RefreshJob: execute called Sun Dec 11 15:01:55 PST 2016 : for B@abc.com last executed 7000ms ago
RefreshJob: execute called Sun Dec 11 15:02:02 PST 2016 : for B@abc.com last executed 7000ms ago
RefreshJob: execute called Sun Dec 11 15:02:04 PST 2016 : for A@xyz.com last executed 10000ms ago
RefreshJob: execute called Sun Dec 11 15:02:09 PST 2016 : for B@abc.com last executed 7000ms ago
RefreshJob: execute called Sun Dec 11 15:02:14 PST 2016 : for A@xyz.com last executed 10000ms ago
RefreshJob: execute called Sun Dec 11 15:02:24 PST 2016 : for A@xyz.com last executed 10000ms ago
------- Shutting Down ---------------------
------- Shutdown Complete -----------------
Executed 19 jobs.

As far as I can tell, the jobs are being executed at the proper times. Are you currently using the latest version of the job store (1.1.7)? If not, please update to the latest version. There have been a few bug fixes released since this issue was created.

JG00329142 commented 7 years ago

Hi Jlinn Thanks for your reply. I updated my job store to 1.1.7 downloaded from (https://mvnrepository.com/artifact/net.joelinn/quartz-redis-jobstore/1.1.7)

But i still see the same behavior...incorrect intervals. (see demo program output below)

Let me know if you need any other info to debug this. ------- jlinnDEMO : Initializing ------------------- SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder". SLF4J: Defaulting to no-operation (NOP) logger implementation SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details. ------- Initialization Complete -------- ------- Scheduling Jobs ---------------- refreshJobA configured to trigger 5 sec from Tue Dec 13 15:30:03 IST 2016 and repeat every 5 sec for 10 times refreshJobA configured to trigger 7 sec from Tue Dec 13 15:30:03 IST 2016 and repeat every 7 sec for 10 times trigger : group1.triggerA For Job key refreshgroup1.refreshjobA will run at: Tue Dec 13 15:30:08 IST 2016 and repeat: 10 times, every 10 seconds trigger : group2.triggerB For Job key refreshgroup1.refreshjobB will run at: Tue Dec 13 15:30:10 IST 2016 and repeat: 10 times, every 7 seconds ------- Starting Scheduler ---------------- ------- Started Scheduler ----------------- ------- Waiting 90 seconds... ------------- jlinnDEMO: RefreshJob: execute called Tue Dec 13 15:30:21 IST 2016 : for A@xyz.com jlinnDEMO: RefreshJob: execute called Tue Dec 13 15:30:32 IST 2016 : for B@abc.com jlinnDEMO: RefreshJob: execute called Tue Dec 13 15:30:45 IST 2016 : for A@xyz.com last executed 24672ms ago jlinnDEMO: RefreshJob: execute called Tue Dec 13 15:31:00 IST 2016 : for B@abc.com last executed 27639ms ago jlinnDEMO: RefreshJob: execute called Tue Dec 13 15:31:10 IST 2016 : for A@xyz.com last executed 25096ms ago jlinnDEMO: RefreshJob: execute called Tue Dec 13 15:31:26 IST 2016 : for B@abc.com last executed 26488ms ago ------- Shutting Down --------------------- jlinnDEMO: RefreshJob: execute called Tue Dec 13 15:31:40 IST 2016 : for A@xyz.com last executed 29857ms ago ------- Shutdown Complete ----------------- Executed 7 jobs.