Scheduled tasks seem to run twice [SPR-6859]

[spring-projects-issues]

Matt Young opened SPR-6859 and commented

I posted this on the forum, but with no response... I wondered if you all could look into it.

I was stubbing out some code that I'd like to run on a schedule, and just to test it, I have it running once every 60 seconds. I noticed that in my logging, the method seems to be executed twice. To make sure it wasn't a logging issue, I put a static int counter into the class and have it increment on each call. So I can confirm the method is actually being run twice.

I suspect that this is something like doing a context:component-scan twice-over and resulting in double execution, but can't seem to locate the problem. I thought I would check first if there were any pointers.

The class
Code:
/**

• Date: Feb 15, 2010

• Time: 10:54:36 AM
  */
  @Component
  public class DataHarvestingServiceImpl implements DataHarvestingService {
  private static final Logger logger = Logger.getLogger(DataHarvestingServiceImpl.class);

  private static int count = 0;

  @Override
  // Every night at 1 AM
  // @Scheduled(cron = "* * 1 * * ?")

  @Scheduled(cron = "0 * * * * ?")
  public void collectSocialMediaData() {
  logger.info("Starting data retrieval at " + new Date(System.currentTimeMillis()));

  logger.info("Finished media data retrieval at " + new Date(System.currentTimeMillis()));
  System.out.println("count is " + count++);
  

  }

}
The configuration

Code:

<?xml version="1.0" encoding="UTF-8"?>

<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:task="http://www.springframework.org/schema/task"
xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd http://www.springframework.org/schema/task http://www.springframework.org/schema/task/spring-task-3.0.xsd">

<!--  This is the bit of configuration that allows spring to search for annotations
      that indicate that particular methods should be run at particular times.  -->

<task:scheduler id="searchScheduler"/>

<task:executor id="searchExecutor" pool-size="1"/>

<task:annotation-driven executor="searchExecutor" scheduler="searchScheduler"/>

</beans>
The output I see:
Code:
11316 [searchScheduler-1] INFO com.vodori.cms.feature.socialMedia.service.impl.DataHarvestingServiceImpl - Starting data retrieval at Mon Feb 15 14:56:00 CST 2010
11321 [searchScheduler-1] INFO com.vodori.cms.feature.socialMedia.service.impl.DataHarvestingServiceImpl - Finished media data retrieval at Mon Feb 15 14:56:00 CST 2010
count is 0
11321 [searchScheduler-1] INFO com.vodori.cms.feature.socialMedia.service.impl.DataHarvestingServiceImpl - Starting data retrieval at Mon Feb 15 14:56:00 CST 2010
11321 [searchScheduler-1] INFO com.vodori.cms.feature.socialMedia.service.impl.DataHarvestingServiceImpl - Finished media data retrieval at Mon Feb 15 14:56:00 CST 2010
count is 1
71318 [searchScheduler-1] INFO xxx.service.impl.DataHarvestingServiceImpl - Starting data retrieval at Mon Feb 15 14:57:00 CST 2010
71318 [searchScheduler-1] INFO xxx.service.impl.DataHarvestingServiceImpl - Finished media data retrieval at Mon Feb 15 14:57:00 CST 2010
count is 2
71318 [searchScheduler-1] INFO xxx.service.impl.DataHarvestingServiceImpl - Starting data retrieval at Mon Feb 15 14:57:00 CST 2010
71318 [searchScheduler-1] INFO xxx.service.impl.DataHarvestingServiceImpl - Finished media data retrieval at Mon Feb 15 14:57:00 CST 2010
count is 3
Any insight very much appreciated.

---

Affects: 3.0 GA

Reference URL: http://forum.springsource.org/showthread.php?t=84747

Issue Links:

• ScheduledAnnotationBeanPostProcessor registers schedules twice in web application [SPR-6656] #11322 ScheduledAnnotationBeanPostProcessor registers schedules twice in web application ("duplicates")
• CronSequenceGenerator fails to accurately compute earliest next date when using second expression [SPR-9459] #14094 CronSequenceGenerator fails to accurately compute earliest next date when using second expression
• CronTrigger is not triggered at correct time [SPR-7004] #11669 CronTrigger is not triggered at correct time

5 votes, 21 watchers

[spring-projects-issues]

Daniel Hodan commented

Hello,

I have still same problem with 3.0.1.RELEASE using @Scheduled annotation.

The workaround for now is to avoid annotation and use XML-based configuration with declaration of scheduled method which works correctly - runs method only once.

[spring-projects-issues]

Rafis Ismagilov commented

The problem still occurs in 3.0.1 for short-running tasks. No annotations, only XML.

<task:scheduler id="scheduler" pool-size="1"/>

<task:scheduled-tasks scheduler="scheduler">
	<task:scheduled ref="DateFilterFactory" method="updateDateFilters" cron="0 * * * * ?"/>
</task:scheduled-tasks>

Sometimes task starts a little earlier than a next scheduled time (at 14:31:00,000):

2010-06-02 14:30:59,998 [scheduler-1] DEBUG com.agi.apollo.search.filter.DateFilterFactory  - start
2010-06-02 14:30:59,999 [scheduler-1] DEBUG com.agi.apollo.search.filter.DateFilterFactory  - finish

The task is finished earlier than the scheduled time, and it rescheduled again at the same time according to code in CronTrigger.nextExecutionTime(TriggerContext triggerContext):

2010-06-02 14:31:00,001 [scheduler-1] DEBUG com.agi.apollo.search.filter.DateFilterFactory  - start
2010-06-02 14:31:00,002 [scheduler-1] DEBUG com.agi.apollo.search.filter.DateFilterFactory  - finish

It seems the source of the problem is accuracy of method System.currentTimeMillis() used in ReschedulingRunnable.schedule() and in java.util.Date default constructor.

I executed the following code on my Windows Vista x64:

for (int i = 0; i < 10000; i++) {
     System.out.println(System.currentTimeMillis());
}

and received the output:

1275478646948
...
1275478646948
1275478646964
...
1275478646964
1275478646979
...
1275478646979
...
1275478646979
1275478646995
...
1275478646995
1275478647010
...
1275478647010
1275478647026
...

Time was updated in 5-16 milliseconds.

I suggest to use in CronTrigger.nextExecutionTime(TriggerContext triggerContext) the latest of TriggerContext.lastCompletionTime() and TriggerContext.lastCompletionTime(). It helps to avoid double execution at the same time.

[spring-projects-issues]

Juergen Hoeller commented

See #11669: Fortunately, this should be fixed in the latest 3.0.3 snapshots already.

Juergen

[spring-projects-issues]

Rafis Ismagilov commented

Cool! Thanks.

[spring-projects-issues]

Paul Zolnierczyk commented

So I'm experiencing this issue on 3.0.5 . I have a task that is scheduled to run every ten minutes (I'm still in development). All it does is query the database for users that meet a specific criteria and then I send them an e-mail reminder. All I did to enable this was add in my XML

<context:component-scan base-package="my base package is in here" />
	 
<task:annotation-driven/>

and then I annotated like this:

@Scheduled(fixedDelay = 1000 * 60 * 10)

I'm also on JDK 1.6 and developing on windows XP. For some reason I wonder if it's a dual core issue?

[spring-projects-issues]

Paul Zolnierczyk commented

Silly me, I was loading the application context twice!

[spring-projects-issues]

Bahman Kalali commented

I am experiencing the same the same problem where the methods that are scheduled to run every 2 and 1 minutes respectively are invoked twice at specified fixed rate.

Here is the xml fragment of my spring app context ( the XML app context is called edgeServerContext.xml)

<task:scheduled-tasks>
	<task:scheduled ref="IEdgeDeviceStatePollerService"
		method="process" fixed-rate="120000" />
	<task:scheduled ref="IEdgeDeviceResultsPollerService"
		method="process" fixed-rate="60000" />
</task:scheduled-tasks>

The only difference with my issue and the rest of other commentators is that my spring xml context is imported into mule-config.xml as follows:

<?xml version="1.0" encoding="UTF-8"?>

<mule xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://www.mulesoft.org/schema/mule/core"
xmlns:spring="http://www.springframework.org/schema/beans"
xmlns:context="http://www.springframework.org/schema/context"

xsi:schemaLocation="
http://www.springframework.org/schema/context
      http://www.springframework.org/schema/context/spring-context-3.0.xsd
		http://www.mulesoft.org/schema/mule/core http://www.mulesoft.org/schema/mule/core/3.1/mule.xsd
		http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.0.xsd">

<spring:beans>
	<spring:import resource="classpath:edgeServerContext.xml" />
</spring:beans>

</mule>

I am not sure this issue is related to mule or spring. It seems that schedulers are initialized twice when deployed two a mule server. I am using mule 3.1.2, spring 3.0.6.RELEASE, jdk1.6.0_25

I appreciated it any insight on this issue...

BR//Bahman

[spring-projects-issues]

Sidharth Kaushik commented

I am using Spring 3.0.5. Trying to schedule a simple job
@Service
public class HelloWorldScheduler2 {
public void process() {
System.out.println("################processing next########## at " + new Date()+ " SidddThe Milli time is : " + System.currentTimeMillis());
}
}
For Scheduling this the XML I am using is:

<?xml version="1.0" encoding="UTF-8"?>

<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:context="http://www.springframework.org/schema/context"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:util="http://www.springframework.org/schema/util"
xmlns:task="http://www.springframework.org/schema/task"
xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.0.xsd
http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd
http://www.springframework.org/schema/util http://www.springframework.org/schema/util/spring-util-3.0.xsd
http://www.springframework.org/schema/task http://www.springframework.org/schema/task/spring-task-3.0.xsd">

<context:spring-configured />

<context:annotation-config/>

  
<bean id="scheduler" class="com.mystudyweb.schedulers.HelloWorldScheduler2" />
<task:scheduled-tasks>
	<task:scheduled ref="scheduler" method="process" cron="${cron}"/>
</task:scheduled-tasks>

</beans>

The cron expression is read from properties file as : 3/10 * * * * ?

On running the application on TOMCAT, the output in console is ################processing next########## at Tue Dec 13 13:10:43 IST 2011 SidddThe Milli time is : 1323762043001
################processing next########## at Tue Dec 13 13:10:43 IST 2011 SidddThe Milli time is : 1323762043001

How can I stop the job from being called twice. When I run it as a simple standalone application, it works fine. Also, my context xml is being loaded correctly and only once.

Regards,
Sidharth.

[spring-projects-issues]

Hoshiar Ravesh commented

Hi,

I am having the same problem that scheduled task is being executed twice with Spring 3.1.1 Release using both the XML configurations and Annotations.

My Dispatcher-servlet.xml:

<?xml version="1.0" encoding="UTF-8"?>

<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:context="http://www.springframework.org/schema/context"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:mvc="http://www.springframework.org/schema/mvc"
xmlns:task="http://www.springframework.org/schema/task"
xsi:schemaLocation="
http://www.springframework.org/schema/beans
http://www.springframework.org/schema/beans/spring-beans-3.0.xsd
http://www.springframework.org/schema/mvc
http://www.springframework.org/schema/mvc/spring-mvc-3.0.xsd
http://www.springframework.org/schema/context
http://www.springframework.org/schema/context/spring-context-3.0.xsd
http://www.springframework.org/schema/task
http://www.springframework.org/schema/task/spring-task-3.0.xsd">

<task:executor id="myExecutor" pool-size="1"/>      
<task:scheduler id="myScheduler" pool-size="1"/>

<task:scheduled-tasks scheduler="myScheduler">
	<task:scheduled ref="DateFilterFactory" method="sendEmail" cron="0 54 11 * * ?"/>
</task:scheduled-tasks>

<bean id="DateFilterFactory" class="com.MailService"/>

</beans>

[spring-projects-issues]

Hoshiar Ravesh commented

The issue is still reproducing in 3.1.1 Release

[spring-projects-issues]

Paul Boonyarungsrit commented

I had this issue and found a solution for it. In my case, one of my applicationContext*.xml that I have was loaded by both root application context (contextConfigLocation in web.xml) and by web application context (via DispatcherServlet). Putting <tasks:scheduler /> in the config that is loaded by both contexts causes 2 scheduler threads to be created, one for each context.

Making sure that <tasks:scheduler /> is loaded by the root application context only fixes my issue. It would be nice if Spring can detect that, but at least you can avoid this issue yourself.

[spring-projects-issues]

suresh m commented

This issue is coming in Spring 3.1.0 RELEASE, any workaround

[spring-projects-issues]

Juergen Hoeller commented

As of 3.2.2, we've done everything we can do to avoid a repeat of the current execution time as next scheduled time: CronTrigger uses the later of lastCompletionTime and lastScheduledExecutionTime to calculate from, and CronSequenceGenerator explicitly recalculates from the next second if it ends up computing the same time as the original timestamp.

In other words, if you're still running into double execution with only one scheduler set up (please always double-check that), then we have no idea how that could happen. I'll mark this issue as resolved for that reason. If you happen to be able to reproduce this under proper circumstances against 3.2.2, please create a more specific issue as a follow-up.

Juergen

[spring-projects-issues]

Assaf commented

I have just tried this on 3.2.2 and it still does not work. My configuration is as follows:

<!-- Scheduler -->

<task:annotation-driven scheduler="taskScheduler"/>
<task:scheduler id="taskScheduler" pool-size="2"/>

and the class:
@Service
public class RankingEngine {

.....

@Scheduled(cron="0 10 18 * * *")
public void calculateRankings(){

The method is being called twice

[spring-projects-issues]

James Hunvanich commented

I also have 3.2.2, and this is still a problem.

Similar configs as users above. I tripled-check to make sure context was not being loaded more than once.

Trying to use java.util.Timer also gets run twice if initiated from @PostConstruct:

...
@PostConstruct
public void init() {
log.trace("Initializing"); //This is verified to be called only once.

Timer timer = new Timer();
timer.schedule(new TimerTask() {
@Override
public void run() {
log.trace("Timer task running...");
}
}, 60 * 1000, 60 * 1000);
}
...

Result:
03-21 14:37:55,249 INFO [ Timer-0] Timer task running...
03-21 14:38:02,414 INFO [ Timer-1] Timer task running...