Bug 653928

Summary: From thread-pool thread, QueueUserWorkItem schedules onto the same thread
Product: [Mono] Mono: Runtime Reporter: Andy Hume <andyhume32>
Component: miscAssignee: Gonzalo Paniagua Javier <gonzalo>
Status: RESOLVED FIXED QA Contact: Mono Bugs <mono-bugs>
Severity: Major    
Priority: P5 - None    
Version: 2.8.x   
Target Milestone: ---   
Hardware: x86   
OS: Windows XP   
Whiteboard:
Found By: --- Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---
Attachments: C# code file containing repro code as described.
Updated -- C# code file containing repro code as described.

Description Andy Hume 2010-11-16 12:13:58 UTC
Created attachment 400473 [details]
C# code file containing repro code as described.

User-Agent:       Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 2.0.50727; .NET CLR 1.1.4322; .NET CLR 3.0.04506.30; .NET CLR 3.0.04506.648; .NET CLR 3.5.21022; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; .NET4.0C; .NET4.0E)

Tested in 2.8 (release).
Only tested on WinXP.

If Delegate.BeginInvoke is called from a thread-pool thread then the target delegate method is *only* run *after* the original thread-pool thread exits.

(I can't really I'm seeing this but its 100% reproducible...)

With the code sample at the bottom we see the following.
* On MSFT and on Mono 2.6.3 (e.g.):
[[
223240953: Calling outer.BeginInvoke
223240953: Outer: calling inner.BeginInvoke
223240953: Outer: pausing...
223240953:     Inner: Was I called only **after** Outer exited??????
223242953: Outer: exiting...
]]

* But on Mono 2.8 we see: :-(
[[
223244187: Calling outer.BeginInvoke
223244390: Outer: calling inner.BeginInvoke
223244390: Outer: pausing...
223246390: Outer: exiting...
223246390:     Inner: Was I called only **after** Outer exited??????
]]

Note the second BeginInvoke does NOT run until the first thread-pool method exits.  (Note the same occurs if ThreadPool.QueueUserWorkItem is used to run the 'outer' method, so its not a problem with BeginInvoke within BeginInvoke).


Code sample, (full code attached):
[[
static void SimpleTest()
{
    int msForOuterToDelay = 2000;
    //
    WaitCallback inner = delegate {
        Console_WriteLine("    Inner: Was I called only **after** Outer exited??????");
    };
    //
    WaitCallback outer = delegate {
        Console_WriteLine("Outer: calling inner.BeginInvoke");
        var arI = inner.BeginInvoke(null, null, null);
        //
        Console_WriteLine("Outer: pausing...");
        Thread.Sleep(msForOuterToDelay);
        Console_WriteLine("Outer: exiting...");
    };
    //
    Console_WriteLine("Calling outer.BeginInvoke");
    var arO = outer.BeginInvoke(null, null, null);
    //
    Thread.Sleep(msForOuterToDelay);
    Thread.Sleep(msForOuterToDelay);
}
]]

Reproducible: Always

Steps to Reproduce:
See attached code sample.
Comment 1 Andy Hume 2010-11-16 13:42:12 UTC
So, according to Thread.ManagedThreadId, the BeginInvoke call schedules the delegate to run on the same thread-pool thread!  No wonder it doesn't run until the originating thread-pool method exits...

Mono 2.8:  Note from thread 2 to thread 2!
[[
* SimpleTest
229027406: Calling outer.BeginInvoke
229027421: Outer: calling inner.BeginInvoke  [TID: 2]
229027421: Outer: pausing...
229029421: Outer: exiting...
229029421:     Inner: Was I called only **after** Outer exited??????  [TID: 2]
]]

Mono 2.6.3:  Note from thread 2 to thread 3. :-)
[[
* SimpleTest
229005656: Calling outer.BeginInvoke
229005656: Outer: calling inner.BeginInvoke  [TID: 2]
229005656: Outer: pausing...
229005656:     Inner: Was I called only **after** Outer exited??????  [TID: 3]
229007656: Outer: exiting...
]]
Comment 2 Andy Hume 2010-11-16 13:55:08 UTC
Created attachment 400512 [details]
Updated -- C# code file containing repro code as described.

Ok, seems it is not Delegate.BeginInvoke specifically...  It's actually any(?) QueueUserWorkItem from within a thread-pool thread!

Mono 2.8, WinXP:
[[
* SimpleTestOuterQuwiInnerQuwi
229827921: Calling QueueUserWorkItem(outer)
229827937: Outer: calling QueueUserWorkItem(inner)  [TID: 2]
229827937: Outer: pausing...
229829937: Outer: exiting...
229829937:     Inner: Was I called only **after** Outer exited??????  [TID: 2]
]]
Comment 3 Andy Hume 2010-11-16 15:46:41 UTC
(Update Summary line)
Comment 4 Gonzalo Paniagua Javier 2010-11-17 03:11:29 UTC
Our threadpool in 2.8 and above behaves more like the .NET 4.0 threadpool. Each thread has a local queue (work-stealing queue) from which other threadpool threads might steal work items when they are idle.

This also means that the order of execution is not (quasi-)guaranteed as it was before and that it is possible that everything you queue from a threadpool thread is executed from the same thread (only under special circumstances: the work items don't take too long, other threadpool threads are busy).

Now, given that you see this problem with Mono on windows, I'd like to test that and see if it's a windows-only problem. How many CPU cores does your machine have?





In my machine with Mono on linux, in the first try:
 [TID: 1]
--------------------
* SimpleTestOuterQuwiInnerQuwi
114342410: Calling QueueUserWorkItem(outer)
114342419: Outer: calling QueueUserWorkItem(inner)  [TID: 2]
114342419: Outer: pausing...
114342519:     Inner: Was I called only **after** Outer exited??????  [TID: 3]
114344419: Outer: exiting...
--------------------
* SimpleTest
114346420: Calling outer.BeginInvoke
114346421: Outer: calling inner.BeginInvoke  [TID: 3]
114346421: Outer: pausing...
114346421:     Inner: Was I called only **after** Outer exited??????  [TID: 2]
114348421: Outer: exiting...
--------------------
* SimpleTestOuterQuwi
114350422: Calling QueueUserWorkItem(outer)
114350422: Outer: calling inner.BeginInvoke  [TID: 3]
114350422: Outer: pausing...
114350422:     Inner: Was I called only **after** Outer exited??????  [TID: 2]
114352422: Outer: exiting...
Comment 5 Andy Hume 2010-11-17 09:01:30 UTC
I've tested only on two oldish boxes, both have only one core (one has 2x HT).
Comment 6 Gonzalo Paniagua Javier 2010-11-17 21:37:34 UTC
Fixed in master (https://github.com/mono/mono/commit/eef96ae0effb98176132320bad1e84163849b256)

It won't make it to 2.8.1, but if there's a 2.8.2, it will be there and also in 2.10.
Comment 7 Andy Hume 2010-11-19 14:54:55 UTC
Thanks Gonzalo.  I'm building locally, so I'll test it when I get a moment. :-)
Comment 8 Andy Hume 2010-11-21 12:59:41 UTC
Tested as fixed this morning.  (Built with msvc).

Many thanks. :-)