3 Replies Latest reply on Oct 28, 2011 11:04 AM by Martin Heinemann

    @Schedule does not consider timing declaration

    Martin Heinemann Newbie

      Hi,

       

      i'm currently creating a timing application that makes use of the @Schedule annotation.

      I created a singleton bean as followed:

       

       

      @Singleton
      @Startup
      @ConcurrencyManagement( ConcurrencyManagementType.BEAN )
      public class MailSender {
      
          @Inject
          Logger log;
      
          @Schedule( minute = "*" )
          public void sendUnsentMails() {
              log.info( "tick tick tick" );
          }
      
      }
      
      

       

      I would assume that the method is executed every minute, but instead it runs, .. well, more often (see log dump)

       

      15:01:15,038 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-1) tick tick tick
      15:01:16,038 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-10) tick tick tick
      15:01:17,037 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-2) tick tick tick
      15:01:18,036 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-7) tick tick tick
      15:01:19,044 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-9) tick tick tick
      15:01:20,037 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-6) tick tick tick
      15:01:20,070 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-5) tick tick tick
      15:01:21,045 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-3) tick tick tick
      15:01:22,044 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-4) tick tick tick
      15:01:23,044 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-8) tick tick tick
      15:01:24,052 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-1) tick tick tick
      15:01:25,034 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-10) tick tick tick
      15:01:26,034 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-2) tick tick tick
      15:01:27,033 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-7) tick tick tick
      15:01:28,033 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-9) tick tick tick
      15:01:29,032 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-6) tick tick tick
      15:01:30,040 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-3) tick tick tick
      15:01:30,091 INFO  [d.v.ex.test.service.mailing.control.MailSender] (pool-4-thread-5) tick tick tick
      
      

       

       

      The singleton is deployed inside an ejb->ear and runs on JBoss AS 7.1.0.Alpha2-SNAPSHOT "Ahoy!"

       

       

      If i undeploy the ear, the JBoss keeps writing these logstatements in an infinite loop:

       

       

      15:04:52,034 INFO  [org.jboss.as.ejb3.timerservice.mk2.task.TimerTask] (pool-4-thread-9) Timer: [id=1f36f92d-316f-4c41-ade4-d08a6c38315d timedObjectId=MailSender auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.mk2.TimerServiceImpl@1a46a171 initialExpiration=Wed Oct 26 00:00:00 CEST 2011 intervalDuration(in milli sec)=0 nextExpiration=Wed Oct 26 15:04:53 CEST 2011 timerState=IN_TIMEOUT will be retried
      15:04:52,035 INFO  [org.jboss.as.ejb3.timerservice.mk2.task.TimerTask] (pool-4-thread-9) Retrying timeout for timer: [id=1f36f92d-316f-4c41-ade4-d08a6c38315d timedObjectId=MailSender auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.mk2.TimerServiceImpl@1a46a171 initialExpiration=Wed Oct 26 00:00:00 CEST 2011 intervalDuration(in milli sec)=0 nextExpiration=Wed Oct 26 15:04:53 CEST 2011 timerState=IN_TIMEOUT
      15:04:52,066 ERROR [org.jboss.as.ejb3.timerservice.mk2.task.TimerTask] (pool-4-thread-9) Error during retyring timeout for timer: [id=1f36f92d-316f-4c41-ade4-d08a6c38315d timedObjectId=MailSender auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.mk2.TimerServiceImpl@1a46a171 initialExpiration=Wed Oct 26 00:00:00 CEST 2011 intervalDuration(in milli sec)=0 nextExpiration=Wed Oct 26 15:04:53 CEST 2011 timerState=RETRY_TIMEOUT: java.lang.IllegalStateException: Component is stopped
       at org.jboss.as.ee.component.BasicComponent.waitForComponentStart(BasicComponent.java:98) [jboss-as-ee-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
       at org.jboss.as.ee.component.BasicComponent.createInstance(BasicComponent.java:77) [jboss-as-ee-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
       at org.jboss.as.ejb3.component.singleton.SingletonComponent.getComponentInstance(SingletonComponent.java:127) [jboss-as-ejb3-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
       at org.jboss.as.ejb3.timerservice.SingletonTimedObjectInvokerImpl.callTimeout(SingletonTimedObjectInvokerImpl.java:46) [jboss-as-ejb3-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
       at org.jboss.as.ejb3.timerservice.mk2.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:73) [jboss-as-ejb3-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
       at org.jboss.as.ejb3.timerservice.mk2.task.TimerTask.run(TimerTask.java:119) [jboss-as-ejb3-7.1.0.Alpha2-SNAPSHOT.jar:7.1.0.Alpha2-SNAPSHOT]
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [:1.6.0_26]
       at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [:1.6.0_26]
       at java.util.concurrent.FutureTask.run(FutureTask.java:138) [:1.6.0_26]
       at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_26]
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_26]
       at java.lang.Thread.run(Thread.java:662) [:1.6.0_26]
       at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.0.0.GA.jar:2.0.0.GA]
      
      

       

       

      I don't know if these two issues are related or not. Anyone an idea?

       

        • 1. Re: @Schedule does not consider timing declaration
          jaikiran pai Master

          Martin Heinemann wrote:

           

           

          
           
              @Schedule( minute = "*" )
              public void sendUnsentMails() {
                  log.info( "tick tick tick" );
              }
           
          }
           
          

           

          I would assume that the method is executed every minute, but instead it runs, .. well, more often (see log dump)

           

          Actually, that doesn't mean every minute. The hour, minute and second attributes by default are "0". So in your case, this expression means, run the timer every minute when the hour is 0 (midnight) and second is (0). So it's supposed to be triggred at mid-night and be triggered 60 times before re-triggering the mid night of next day.

           

          But even then, I wouldn't expect the output that you are seeing. Are you sure it's picking the right bean/schedule?

          • 2. Re: @Schedule does not consider timing declaration
            dev0 Newbie

            The following code will run every minute:

             

            @Schedule(minute="*/1",hour="*", persistent=false)
            public void doWork(){
                 System.out.println("MyTimer: =========== DO WORK! ===========");
                 LOGGER.info(">>>>> TIMERSERVICE= " + Calendar.getInstance().getTime());
            }
            

             

            And the output - after a few minutes:

             

            15:04:00,010 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
            15:04:00,011 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:04:00 CEST 2011
            15:05:00,004 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
            15:05:00,005 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:05:00 CEST 2011
            15:06:00,004 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
            15:06:00,005 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:06:00 CEST 2011
            15:07:00,004 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
            15:07:00,004 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:07:00 CEST 2011
            15:08:00,004 INFO  [stdout] (pool-7-thread-1) MyTimer: =========== DO WORK! ===========
            15:08:00,005 INFO  [com.company.MyTimer] (pool-7-thread-1) >>>>> TIMERSERVICE= Fri Oct 28 15:08:00 CEST 2011
            
            • 3. Re: @Schedule does not consider timing declaration
              Martin Heinemann Newbie

              Hell yeah.

              Must have been the "wrong" time format.

              Is used

               

              @Schedule( second = "*/5", minute = "*/1", hour = "*", persistent = false )

               

              And now it runs every 5 seconds. And even with

               

              @Schedule( second = "*/5", minute = "*", hour = "*", persistent = false )

               

              Strange. Thanks alot!