Event timer delayed in .NET not in Mono. Is it a bug?

Question

DotNet alternative (MONO-http://www.go-mono.com/mono-downloads/download.html) handles the short timer condition properly (down to ~12 ms firing time) Yet, DotNet appears to take longer then expected and "Misses". So, which behavior is correct? Does mono properly track its event firing?, is it fudging its number with an incorrect stopwatch? or does DotNet have a "lazy" event timer? With my testing, clearly, it is not a underlying windows issue.

.NET 200ms+ Interval minimum

Mono 12ms+ Interval minimum

This inquiry in similar to this: Timer takes 10 ms more than interval.

However consider the code:

In .NET missed events will slowly tick up:

Total Runtime/Interval - Actual Events = Missed Events

Code:

class Program
{
    const int Interval = 60; //ms Event fireing

    Stopwatch TotalRunTime = new Stopwatch();//Full runtime.
    Stopwatch Calctime = new Stopwatch(); //Used to load up the Event to 66 percent

    System.Timers.Timer TIMER; //Fireing Event handler.
    int TotalCycles = 0; //Number of times the event is fired.
    int Calcs_per_cycle = 100; // Number of calcs per Event.

    static void Main(string[] args)
    {
        Program P = new Program();
        P.MainLoop();
    }

    void MainLoop()
    {
        Thread.CurrentThread.Priority = ThreadPriority.Highest;

        TIMER = new Timers.Timer();
        TIMER.Interval = Interval;
        TIMER.Elapsed += new ElapsedEventHandler(MS_Calc);
        TIMER.AutoReset = true;
        TIMER.Enabled = true; //Start Event Timer
        TotalRunTime.Start(); //Start Total Time Stopwatch;

        while (true)
        {
            Thread.Sleep(Interval * 5);
            Console.Clear();
            PrintAtPos(2, "Missed Events " + (((TotalRunTime.ElapsedMilliseconds / Interval) - TotalCycles).ToString()));

        }

    }
    public void MS_Calc(object source, System.Timers.ElapsedEventArgs E)// public void MS_Calc(object source, ElapsedEventArgs E)
    {
        TotalCycles++;
        Calctime.Start();
        for (int i = 0; i < Calcs_per_cycle; i++)
        {
            int A = 2;
            int B = 2;
            int c = A + B;
        }
        PrintAtPos(1, "Garbge Collections G1: " + GC.CollectionCount(0) + "  G2: " + GC.CollectionCount(1) + "  G3: " + GC.CollectionCount(2) + " ");
        Calctime.Stop();
        if (Interval * 0.667 > Calctime.ElapsedMilliseconds) //only fill the even timer 2/3s 
        //full to make sure we finish before the next event
        {
            Calcs_per_cycle = (int)(Calcs_per_cycle * 1.035);
        }
        Calctime.Reset();
        PrintAtPos(0, "Calc Time : " + (DateTime.Now - E.SignalTime).Milliseconds + "  Calcs/Cycle: " + Calcs_per_cycle);
    }

    private static void PrintAtPos(int Vertical_Pos, string Entry)
    {
        Console.SetCursorPosition(0, Vertical_Pos);
        Console.Write(Entry);
    }
}

Side note: you have multithreaded code without any synchronization... As it stands now it does not prove anything... — Alexei Levenkov, Dec 20 '12 at 05:26
@AlexeiLevenkov the only field accessed by multiple threads is `TotalCycles` (in fact it is only being written by one thread) and the results are the same if you make it `volatile` and use `Interlocked.Increment`. — Mike Zboray, Dec 20 '12 at 05:47
@AlexeiLevenkov I guess you could argue the handler fires on a thread pool thread so you have no idea what thread it is on. However `calcs_per_cycle` is capped so that it won't grow larger than the 2/3 of the interval (I honestly see no point in that loop). All that is largely irrelevant because the crux of the issue is the "missed" events not the 0 GCs or how long a spin loop is taking. — Mike Zboray, Dec 20 '12 at 06:10
@mikez, yes. Whole handler could have been dropped from sample leaving just `totalCycles++` for the same effect (or `Thread.Sleep((int)(Interval * 0.667));` to simulate "heavy computation"). — Alexei Levenkov, Dec 20 '12 at 06:24

score 4 · Accepted Answer · edited May 23 '17 at 12:34

The issue is that the Windows system clock is not precise on the time scale you have used and I believe in Microsoft's implementation of Timer is using the system clock to determine when to fire the Elapsed event. I am assuming this because you get a fairly accurate description of the observed behavior when you account for the (in)accuracy of the system clock.

The system clock is only accurate to 15.6 ms (the reason is to preserve battery life, see this question). Thus the Elapsed event does not fire every 60 ms exactly, but only every 62.4 ms. That 2.4 ms difference aggregates and you have "missed" events. I ran your program for 33009 ms and had 22 missed events reported. I would expect a difference of 33009 * (1/60 - 1/62.4) = 21.2 events. That's about as close as you are going to get, given that we don't have that 15.6 ms number to a higher accuracy. (For example, if the elapsed time is 62.5 ms you get 22.0 expected misses).

You sample certainly demonstrates that the framework implementation of Timer could be more accurate. I don't know why Mono's implementation is more accurate, but generally timers are not for precise millisecond timing. There are other timing methods that are more accurate than the system clock which are used by Stopwatch class when available.

@mike z I agree it is a good description of the mechanism at work. An interval of 78 ms does resolve the "missing" issue. However shouldn't this correct the 15.6ms issue? It doesn't seem too for Timer. ` [DllImport("winmm.dll", EntryPoint = "timeBeginPeriod", SetLastError = true)] private static extern uint TimeBeginPeriod(uint uMilliseconds);` — PizzaRoll, Dec 20 '12 at 13:52

Event timer delayed in .NET not in Mono. Is it a bug?

1 Answers1