Issues with System.Threading.Timer ManagedThreadId

[MaschMaker]

TinyCLR 0.8.0
VS2017
FEZ Spider (EMX)

I've got a couple issues with the System.Threading.Timer stemming from whether or not the callback function runs on a new thread or the same thread as it's parent (the thread that created the timer).

1. When the timer callback runs on a new thread, the ManagedThreadId has the same value as the parent thread when instead it should have a new value. The same ManagedThreadId value should not be used for two different thread objects.
2. If the parent thread is sleeping when the callback fires, then it appears that the timer uses the parent thread and does not create it's own new thread.

This code shows issue 1.

using System;
using System.Threading;
using System.Diagnostics;

namespace MaschMaker
{
    class Program
    {
        static void Main()
        {
            Trace.WriteLine($"Parent before timer > ManagedThreadId = {Thread.CurrentThread.ManagedThreadId}, Hash Code = {Thread.CurrentThread.GetHashCode()}");

            done = false;
            Timer timer = new Timer(TimerCallback, null, 100, Timeout.Infinite);
            while (!done) Thread.Sleep(50);

            Thread.Sleep(200);
            Trace.WriteLine($"Parent after timer  > ManagedThreadId = {Thread.CurrentThread.ManagedThreadId}, Hash Code = {Thread.CurrentThread.GetHashCode()}");
        }

        static bool done = false;
        static void TimerCallback(Object stateInfo)
        {
            Trace.WriteLine($"Timer callback      > ManagedThreadId = {Thread.CurrentThread.ManagedThreadId}, Hash Code = {Thread.CurrentThread.GetHashCode()}");
            done = true;
        }
    }
}

The output is:

Parent before timer > ManagedThreadId = 0, Hash Code = -266232568
Timer callback      > ManagedThreadId = 0, Hash Code = -751040398
Parent after timer  > ManagedThreadId = 0, Hash Code = -266232568

Notice that the ManagedThreadId for the timer callback is the same value (zero) as the parent thread. However, the hash code for the timer callback is different, which tells me that it is running on a different thread. If it's running on a different thread then the ManagedThreadId should also differ from the parent thread.

Now, commenting out the while-loop //while (!done) Thread.Sleep(50); shows issue 2. And, that output is:

Parent before timer > ManagedThreadId = 0, Hash Code = -266232568
Timer callback      > ManagedThreadId = 0, Hash Code = -266232568
Parent after timer  > ManagedThreadId = 0, Hash Code = -266232568

This time the hash code in the timer callback is the same which tells me the timer is running on the parent thread. I'm assuming the timer is running on the parent thread because the main thread is on Thread.Sleep(200);. I'm not sure, if the timer callback running on the parent thread is deliberate or a bug.

I ran the same exact code in a console app and no matter whether the while-loop was commented out or not, the timer callback always ran on a new thread with a different ManagedThreadId and Hash Code than the parent thread.

For issue 1, I do believe that for the same ManagedThreadId in the same application domain, we should always get the same hash code. So this appears to be a bug to me, please confirm.

For issue 2, please confirm if a timer callback should always run on a new thread or not. If not, what circumstances should it use the parent thread?

Thanks,
Rick

[Arke64]

So there is a bug here. ManagedThreadId gets lost, but all threads behave as you would expect. The callback is indeed fired on its own thread, not the parent thread.

There's a separate native instance for each thread that is always kept around. Thread.CurrentThread will return the existing managed instance of the thread if there is one, but if there isn't, it creates a new one, but does not copy over the managed thread id to the new instance, which is why it returns 0 and is the actual bug.

You can observe this with a similar test:

static void Main() {
    var j = 0;

    while (true) {
        for (var i = 0; i < 5; i++) {
            var ii = i;
            var jj = j;

            new Thread(() => {
                while (true) {
                    Debug.WriteLine($"{jj} {ii} {Thread.CurrentThread.ManagedThreadId}");
                    Thread.Sleep(500);
                }
            }).Start();
        }

        j++;

        Thread.Sleep(2000);
    }
}

After a while the existing managed instance of the thread gets collected so the IDs begin to return 0. If we modify the test to add them to a list, the IDs stick around:

static void Main() {
    var j = 0;
    var lst = new ArrayList();

    while (true) {
        for (var i = 0; i < 5; i++) {
            var ii = i;
            var jj = j;

            var th = new Thread(() => {
                while (true) {
                    Debug.WriteLine($"{jj} {ii} {Thread.CurrentThread.ManagedThreadId}");
                    Thread.Sleep(500);
                }
            });
            th.Start();
            lst.Add(th);
        }

        j++;

        Thread.Sleep(2000);
    }
}

GetHashCode is calculated from the internal state of an object if it's not overridden, so once the internal ID field goes to 0 (among other fields that change), it too will hit the same value. The loop you comment out changes how things execute internally so that it arrives at that state sooner.

So the fixes here are to correctly copy over ManagedThreadId and to match the behavior of the desktop .NET which returns the thread ID as the hash code.

[MaschMaker]

Thanks for the insight. Can you guys add the Name property for thread objects while your at it? Or would I need to open a new issue to request it? Really appreciate your help.

[Arke64]

A new thread would be best for that.

We've split this issue up into two internal issues so will be tracking this there, closing this one.

[Arke64]

In the next release ManagedThreadId no longer gets lost and GetHashCode returns the thread id.

[MaschMaker]

Thanks for the heads up and appreciate all your very quick responses to issues/questions.

[MaschMaker]

@Arke64 I've upgraded to v0.10.0 and still think there's an issue here. I'm getting the same ManagedThreadId of zero for both the parent thread and timer thread. Since the parent thread is still alive when the timer runs, I expected a different ManagedThreadId than the Parent.

Here's the output I get:

Parent before timer > ManagedThreadId = 0, Hash Code = 0
Timer callback      > ManagedThreadId = 0, Hash Code = 0
Parent after timer  > ManagedThreadId = 0, Hash Code = 0

[Arke64]

Looks like there was a second part to this bug that we missed. It's been fixed for the next release.

For managed thread wrappers that got GC'd, we correctly restored the ID on subsequent creation. However, the initial managed wrappers for the system threads (timer, static constructors, and the main thread) were never actually initialized with the correct ID so they're wrong from the beginning (and only until recreation after GC in 0.10.0). We've fixed that now.