Java timer few milliseconds difference.

[akloaklo]

Hey guys,

I'm currently doing a task application for my company with java and encountered another problem but i'm not sure if it is common to encounter it.

I'm using SPRING framework for the easy to use @scheduler annotation,
I tested a method to run every min. Just a simple db query + logging and nothing else.

It is critical for me to get this right but the timer seemed inconsistent.

For example the output in my log:

Method ran @ 2014-03-06 16:50:00.668 (4:50:00pm 668 millisecs)
Method ran @ 2014-03-06 16:51:00.002
Method ran @ 2014-03-06 16:51:59.887

Notice the problem here?

The first 2 were the expected output, millisecond doesn't concern me as long as the minutes+seconds are correct but look at the 3rd example, suddenly the minutes/seconds is wrong due the slower milliseconds. Now this is giving me problem as i'm not sure if it is suppose to be like this.

I'm using @schedule(cron= 0 * * * * *) //Runs every min forever
Basically the above is just a crontab that specific to run every min forever.
Although i'm not familiar with crontab, it seemed from my output that it is correct but some how the millisecond is not consistent.

The first thing that came to mind is to just add some method to round up/round down the milliseconds if it is not at 00 seconds and google seemed to support that. Anyway i'm wondering if that is the expected behavior or not?

Any one with inputs? Not looking for solution but feel free to suggest what to do.
Just want to know if it is a known problem with the timer or is it with spring framework.

 

[davidktw]

Hey guys,

I'm currently doing a task application for my company with java and encountered another problem but i'm not sure if it is common to encounter it.

I'm using SPRING framework for the easy to use @scheduler annotation,
I tested a method to run every min. Just a simple db query + logging and nothing else.

It is critical for me to get this right but the timer seemed inconsistent.

For example the output in my log:

Method ran @ 2014-03-06 16:50:00.668 (4:50:00pm 668 millisecs)
Method ran @ 2014-03-06 16:51:00.002
Method ran @ 2014-03-06 16:51:59.887

Notice the problem here?

The first 2 were the expected output, millisecond doesn't concern me as long as the minutes+seconds are correct but look at the 3rd example, suddenly the minutes/seconds is wrong due the slower milliseconds. Now this is giving me problem as i'm not sure if it is suppose to be like this.

I'm using @schedule(cron= 0 * * * * *) //Runs every min forever
Basically the above is just a crontab that specific to run every min forever.
Although i'm not familiar with crontab, it seemed from my output that it is correct but some how the millisecond is not consistent.

The first thing that came to mind is to just add some method to round up/round down the milliseconds if it is not at 00 seconds and google seemed to support that. Anyway i'm wondering if that is the expected behavior or not?

Any one with inputs? Not looking for solution but feel free to suggest what to do.
Just want to know if it is a known problem with the timer or is it with spring framework.

With only 3 cron output, it is not conclusive to indicate that there is anything wrong. The accuracy to logging can be inaccurate as oppose to the execution of the task. You will also need to consider the precision of the timer. The question is do you get a skew after some time, meaning if the inaccuracies keep stacking up as your timer run. If it's in the range of +/-1%, for example, it is perfectly fine. Not unless you are running a mission critical application that requires sub-milliseconds accuracy.

You will also need to consider that at some point, the latency of the execution is due to garbage collector running, most likely not full GC, but partial depending on which GC algorithm you have chosen. Do read up more on this topic.

 

[akloaklo]

Thanks for your reply.

The 3 cron output is just an example of the difference. The problem occurs randomly. It could be 5 mins or 15mins into the program or even as fast as 2 mins and yes, it is a difference or +/- 1second due to the milliseconds difference but isn't it weird when I specify it to run every 1 minutes but it gives me:

1.00.500
1.59.001 <==dangg , this ain't 1 minute. This is 59 seconds.
3.00.228

Not sure if there is another function to ignore the millisecond...need to find if there are any documentation on that.

As for GC, i'm not familiar with that. Only know that after sometime if my variables are not reference then it will be gc'ed. Not sure how it will affect the timer when I specifically want it to run on the 00 second.

I also thought it was the logger that was slow but I did a println of my JODA date time and it is the same as the logger's time stamp.

I guess the only way is to find a work around like rounding up the seconds to the minute.

 

[mgx-alander]

I dun think crond provides accuracy up to ms, you have to understand that you are not running a real time system and does not ensure such accuracy.

Crond always synchronizes to the top of the minute, checking the current time against the list of possible jobs. The list is stored such that the scan goes very quickly, and crond can deal with several thousand entries without taking any noticable amount of cpu.
Source: http://progkor.inf.elte.hu/unix/crond.html

You can try this solution tho:
Avoid the "top of the minute problem" - space out your cronjobs - Ask Bjørn Hansen

adjust to your needs accordingly.

 

[ykgoh]

Read this: https://www.ibm.com/developerworks/library/j-rtj1/

Applications that must strictly meet real-world timing requirements are typically called hard RT applications.

-snip-

Standard Java applications running on a general-purpose JVM on a general-purpose operating system can only hope to meet soft RT requirements at the level of hundreds of milliseconds.

 

[davidktw]

Thanks for your reply.

The 3 cron output is just an example of the difference. The problem occurs randomly. It could be 5 mins or 15mins into the program or even as fast as 2 mins and yes, it is a difference or +/- 1second due to the milliseconds difference but isn't it weird when I specify it to run every 1 minutes but it gives me:

1.00.500
1.59.001 <==dangg , this ain't 1 minute. This is 59 seconds.
3.00.228

Not sure if there is another function to ignore the millisecond...need to find if there are any documentation on that.

As for GC, i'm not familiar with that. Only know that after sometime if my variables are not reference then it will be gc'ed. Not sure how it will affect the timer when I specifically want it to run on the 00 second.

I also thought it was the logger that was slow but I did a println of my JODA date time and it is the same as the logger's time stamp.

I guess the only way is to find a work around like rounding up the seconds to the minute.

Perhaps this will answer your doubts
Quartz scheduler and job 'firing' a second early