Search code examples
c#delaynservicebus

Timing delays using Schedule for NServiceBus

When using the Schedule method for NServiceBus, I'm seeing there's a consistent delay between elapsed jobs. If I have my interval set to a minute. Instead of seeing the next job happen exactly one minute away, there appears to be an additional 5 second delay.

If I set my interval down to only be a second, the additional delay also scales down to just 0.7 seconds. Going over a minute, the delay is still staying at about 5 seconds.

Below is a code snippet using the minute interval:

previousTime = DateTime.Now.TimeOfDay;            
Schedule.Every(TimeSpan.FromSeconds(60)).Action(() =>
{
    DateTime currentTime = DateTime.Now;
    ServiceBus.WriteToLog(string.Format("Start of Schedule: {0}, {1} delay", currentTime, currentTime.TimeOfDay - previousTime));
    previousTime = DateTime.Now.TimeOfDay;
});

Here's a snippet from my logs:

2013-03-26 12:20:58,483 [3] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:20:58 PM, 00:01:04.9931640 delay

2013-03-26 12:22:03,514 [19] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:22:03 PM, 00:01:05.0302735 delay

2013-03-26 12:23:08,532 [4] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:23:08 PM, 00:01:05.0185546 delay

2013-03-26 12:24:13,553 [3] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:24:13 PM, 00:01:05.0206625 delay

2013-03-26 12:25:18,577 [4] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:25:18 PM, 00:01:05.0244141 delay

2013-03-26 12:26:24,451 [22] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:26:24 PM, 00:01:05.8740234 delay

2013-03-26 12:27:28,695 [3] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:27:28 PM, 00:01:04.2441406 delay

2013-03-26 12:28:33,739 [22] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:28:33 PM, 00:01:05.0439454 delay

2013-03-26 12:29:38,753 [4] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:29:38 PM, 00:01:05.0138266 delay

2013-03-26 12:30:39,029 [19] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:30:39 PM, 00:01:00.2757029 delay

2013-03-26 12:31:43,878 [19] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:31:43 PM, 00:01:04.8492417 delay

2013-03-26 12:32:48,951 [4] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:32:48 PM, 00:01:05.0732422 delay

2013-03-26 12:33:53,950 [3] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:33:53 PM, 00:01:04.9990235 delay

2013-03-26 12:34:58,950 [3] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:34:58 PM, 00:01:04.9999930 delay

2013-03-26 12:36:03,950 [3] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:36:03 PM, 00:01:05 delay

2013-03-26 12:37:08,970 [22] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:37:08 PM, 00:01:05.0195313 delay

2013-03-26 12:38:10,185 [22] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:38:10 PM, 00:01:01.2150069 delay

2013-03-26 12:39:14,354 [3] INFO RollingFileAppender [(null)] - Start of Schedule: 3/26/2013 12:39:14 PM, 00:01:04.1694596 delay

Solution

  • The 5sec delay is because we actually only poll every 5secs, see this code
    I've raised an issue in gihub to fix this, see https://github.com/NServiceBus/NServiceBus/issues/1077

    If you set an interval <= 1sec, then you won't have a 5sec delay because we bypass the polling and execute that code straight away, see this code.
    So the 0.7sec delay is the code executing straight away.