We have a quartz-based scheduler application that runs about 1000 tasks per minute, which are evenly distributed between the seconds of every minute, that is, about 16-17 tasks per second. Ideally, these 16-17 tasks should work at the same time, however, our first operator, which simply records the execution time, of the method for completing the task is called very late. for example, suppose we have 1000 tasks scheduled per minute from 05:00 to 05:04. So, ideally, the task, which is scheduled for 05:03:50, was supposed to register the first statement of the execute method at 05:03:50, however, it does this at about 05:06:38. I tracked the time spent on a scheduled task, which is about 15-20 milliseconds. This scheduled task is fast enough because we just send a message to the ActiveMQ queue. We indicated the number of quartz strands equal to 100 and even tried to increase it to 200 or more, but no gain. Another thing that we noticed is that the logs from the scheduler arrive sequentially after the first 1 minute i.e.
[Quartz_Worker_28] <Some log statement> .. .. [Quartz_Worker_29] <Some log statement> .. .. [Quartz_Worker_30] <Some log statement> .. ..
So, this suggests that after some time, quartz works with flows almost sequentially. Perhaps this is due to the time taken to notify the completion of the job in the storage store (in this case, a separate postgres database) and / or context switching.
What could be causing this strange behavior?
EDIT: A More Detailed Journal
[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 doubt 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 task was scheduled for 10:04:53, but it shot at 10:08:33, and so far the quartz has not considered it a misfire. Isn't that a misfire?