4

We have a quartz based scheduler application which runs about 1000 jobs per minute which are evenly distributed across seconds of each minute i.e. about 16-17 jobs per second. Ideally, these 16-17 jobs should fire at same time, however our first statement, which simply logs the time of execution, of execute method of the job is being called very late. e.g. let us assume we have 1000 jobs scheduled per minute from 05:00 to 05:04. So, ideally the job which is scheduled at 05:03:50 should have logged the first statement of the execute method at 05:03:50, however, it is doing it at about 05:06:38. I have tracked down the time taken by the scheduled job which comes around 15-20 milliseconds. This scheduled job is fast enough because we just send a message on an ActiveMQ queue. We have specified the number of threads of quartz to be 100 and even tried with increasing it to 200 and more, but no gain. One more thing we noticed is that logs from scheduler are coming sequential after first 1 minute i.e.

[Quartz_Worker_28] <Some log statement>
..
..
[Quartz_Worker_29] <Some log statement>
..
..
[Quartz_Worker_30] <Some log statement>
..
..

So it suggesting that after some time quartz is running threads almost sequential. May be this is happening due to the time taken in notifying the job completion to persistence store (which is a separate postgres database in this case) and/or context switching.

What can be the reason behind this strange behavior?

EDIT: More detailed Log

[06/07/12 10:08:37:192][QuartzScheduler_Worker-34][INFO] org.quartz.plugins.history.LoggingTriggerHistoryPlugin - Trigger [<trigger_name>] fired job [<job_name>] scheduled at:  06-07-2012 10:08:33.458, next scheduled at:  06-07-2012 10:34:53.000
[06/07/12 10:08:37:192][QuartzScheduler_Worker-34][INFO] <my_package>.scheduler.quartz.ScheduledLocateJob - execute begin--------- ScheduledLocateJob with key: <job_name> started at Fri Jul 06 10:08:37 EDT 2012
[06/07/12 10:08:37:192][QuartzScheduler_Worker-34][INFO] <my_package>.scheduler.quartz.ScheduledLocateJob <some log statement>
[06/07/12 10:08:37:192][QuartzScheduler_Worker-34][INFO] <my_package>.scheduler.quartz.ScheduledLocateJob <some log statement>
[06/07/12 10:08:37:192][QuartzScheduler_Worker-34][INFO] <my_package>.scheduler.quartz.ScheduledLocateJob <some log statement>
[06/07/12 10:08:37:220][QuartzScheduler_Worker-34][INFO] <my_package>.scheduler.quartz.ScheduledLocateJob - execute end--------- ScheduledLocateJob with key: <job_name> ended at Fri Jul 06 10:08:37 EDT 2012
[06/07/12 10:08:37:220][QuartzScheduler_Worker-34][INFO] org.quartz.plugins.history.LoggingTriggerHistoryPlugin - Trigger [<trigger_name>] completed firing job [<job_name>] with resulting trigger instruction code: DO NOTHING. Next scheduled at:  06-07-2012 10:34:53.000

I am doubting on this section of the above log

scheduled at:  06-07-2012 10:08:33.458, next scheduled at:  06-07-2012 10:34:53.000

because this job was scheduled for 10:04:53, but it fired at 10:08:33 and still quartz didn't consider it as misfire. Shouldn't it be a misfire?

vikas
  • 1,535
  • 1
  • 13
  • 22
  • 1
    Can you post a thread dump of your threads when this process is running? Post it here or as a Gist/pastebin. Also consider using [`LoggingTriggerHistoryPlugin`](http://nurkiewicz.blogspot.no/2012/04/quartz-scheduler-plugins-hidden.html) – Tomasz Nurkiewicz Jul 06 '12 at 12:15
  • I have already stated the sample of logs being dumped by our scheduler app, however, I don't have the quartz thread dump because we haven't used any History plugin yet. I would try to get the dump after enabling the history plugin. – vikas Jul 06 '12 at 12:53
  • I mean a JVM thread dump (use tools like `jps` or `jvisualvm`), the plugin isn't required for that. I want to see what Quartz threads are doing in the meantime. – Tomasz Nurkiewicz Jul 06 '12 at 13:08
  • Actually, I changed the content. Here it is [link](https://gist.github.com/raw/3060608/1eca8b1257f5bc59d339689097ab779309363885/qrtz_thread_dump). – vikas Jul 06 '12 at 14:53
  • Thank you for this details output. How do you define trigger(s) for `ScheduledLocateJob`? Isn't this job statefull? (which interfaces does it implement, what annotations) Indeed your job is executed only by one thread, remaining ones are idle. – Tomasz Nurkiewicz Jul 06 '12 at 16:57
  • It implements org.quartz.Job without any annotation and job it self is stateless and I think by default Quartz will assume job to be stateless, right? Trigger is created as CronTrigger ct = newTrigger().withIdentity(triggerName, triggerGroup) .withSchedule(cronSchedule(expression)).build(); – vikas Jul 07 '12 at 04:56

1 Answers1

3

Try to play with the followings, it should improve the behavior

org.quartz.scheduler.batchTriggerAcquisitionMaxCount
org.quartz.jobStore.acquireTriggersWithinLock
org.quartz.scheduler.idleWaitTime
SudhirJ
  • 161
  • 1
  • 8
  • 1
    Setting batchTriggerAcquisitionMaxCount to the number of jobs which are scheduled exactly at the same time did the trick. We are still trying to optimize it by setting it equal to the number quartz threads we set in quartz.properties. – vikas Jul 08 '12 at 11:59