CODEWITHSUNDEEP
c#.netmultithreadingbackgroundworker
HouseCat
HouseCat

Reputation: 1613

Odd behavior using BackgroundWorker with Thread.Sleep

I have never seen anything before like this. I am using Visual Studio 2015 preview and verified it on Visual Studio 2012.

    private void InitializeBackgroundWorkers()
    {
        MONITOR.WorkerReportsProgress = true;
        MONITOR.WorkerSupportsCancellation = true;
        MONITOR.DoWork += new DoWorkEventHandler(MONITOR_DoWork);
        MONITOR.ProgressChanged += new ProgressChangedEventHandler(MONITOR_ProgressChanged);
        MONITOR.RunWorkerCompleted += new RunWorkerCompletedEventHandler(MONITOR_WorkCompleted);

        MONITOR2.WorkerReportsProgress = true;
        MONITOR2.WorkerSupportsCancellation = true;
        MONITOR2.DoWork += new DoWorkEventHandler(MONITOR2_DoWork);
        MONITOR2.ProgressChanged += new ProgressChangedEventHandler(MONITOR2_ProgressChanged);
    }

The issue occurs in the DoWork Event for a BackgroundWorker. Obviously I have made a mistake somehow.

    private void MONITOR2_DoWork(object sender, DoWorkEventArgs e)
    {
        while (CONTINUE)
        {
            oldClockNow = clockNow;
            //BP1
            clockThen = RunTime.ElapsedTicks;
            Thread.Sleep(1000);
            //BP2
            clockNow = RunTime.ElapsedTicks;

            TS = RunTime.Elapsed;

            MONITOR2.ReportProgress(0);
        }

        RunTime.Stop();
    }

The issue is I noticed for various reasons that ClockThen was always "newer" than ClockNow. I ignored it till now and altered my code to utilize the ClockThen as the ClockNow and vice versa.

I finally had time to look at the code closer with breakpoints. I placed one at clockThen assignment, one at clockNow assignment, and one inside the ReportProgress Event, so I can stop one more time outside of the MONITOR2 stack.

Note: I am using ProgressChanged as a way to update the main UI.

    private void MONITOR2_ProgressChanged(object sender, ProgressChangedEventArgs e)
    {
        double calcClockOld = (((double)oldClockNow) * (1F / Stopwatch.Frequency));
        double calcClockThen = (((double)clockThen) * (1F / Stopwatch.Frequency));
        double calcClockNow = (((double)clockNow) * (1F / Stopwatch.Frequency));

        //BP3
        tbxClockDrift.Text = ((calcClockThen - calcClockNow) * 1000000).ToString("0.#####\\ µs");

        string timestamp = String.Format("{0:00}:{1:00}:{2:00}", TS.Hours, TS.Minutes, TS.Seconds);

        tbxTime.Text = DateTime.Now.ToShortDateString() + " " + DateTime.Now.ToLongTimeString();
        tbxRunTime.Text = timestamp;
        tbxTimeZone.Text = TimeZone.CurrentTimeZone.ToUniversalTime(DateTime.Now).ToString();
    }

The third breakpoint is at tbxClockDrift.Text assignment.

So I have 3 breakpoints total, but when stepped through the code, BP1 always executes twice and I believe its why the value keeps being higher!

So the step through I see this a phantom breakpoint:

Step Through 1, clockThen = RunTime.ElapsedTicks;

Step Through 2, jumps to clockNow = Runtime.ElapsedTicks; after sleeping for a second.

Step Through 3, back to clockThen assignment (verified new values!)

Step Through 4, tbxClockDrift.Text assignment!

Why is clockThen receiving a second assignment!?

Upvotes: 1

Views: 853

Answers (1)

Scott Chamberlain
Scott Chamberlain

Reputation: 127543

The problem is a little more obvious if I rewrite your method a bit to make the sleep the last thing that happens inside the while loop. This code behaves exactly the same as your current code.

private void MONITOR2_DoWork(object sender, DoWorkEventArgs e)
{
    if(CONTINUE)
    {
        oldClockNow = clockNow;
        //BP1
        clockThen = RunTime.ElapsedTicks;
        Thread.Sleep(1000);
        while (true)
        {
            //BP2
            clockNow = RunTime.ElapsedTicks;

            TS = RunTime.Elapsed;

            MONITOR2.ReportProgress(0);
            if(!CONTINUE)
                break;

            oldClockNow = clockNow;
            //BP1
            clockThen = RunTime.ElapsedTicks;
            Thread.Sleep(1000);
        }
    }
    RunTime.Stop();
}

So clockThen is not receiving a 2nd assignment it is just clockThen is the last thing you do before you sleep. Also the processing of ReportProgress does not have to happen right at the time you call the function, calling the function just queues up the event to be fired next time the UI can get around to it.

So what is happening is you assign clockNow, you queue up a progress report, you assign a value to clockThen, finally you start to sleep. While you are sleeping ReportProgress finally gets around to running and you get the value of clockThen you assigned from right before you slept.

Upvotes: 1

Related Questions