Bug 31488 - Starting Tasks or thread pool work items can briefly pause existing Tasks or work items
Summary: Starting Tasks or thread pool work items can briefly pause existing Tasks or ...
Status: VERIFIED FIXED
Alias: None
Product: Runtime
Classification: Mono
Component: General ()
Version: 4.0.0
Hardware: PC Mac OS
: --- normal
Target Milestone: ---
Assignee: Ludovic Henry
URL:
: 30936 ()
Depends on:
Blocks: 30936
  Show dependency tree
 
Reported: 2015-06-30 00:32 UTC by Brendan Zagaeski (Xamarin Team, assistant)
Modified: 2016-01-25 22:24 UTC (History)
4 users (show)

Tags: BZFC6S1
Is this bug a regression?: ---
Last known good build:


Attachments
Test case (1.58 KB, application/octet-stream)
2015-06-30 00:32 UTC, Brendan Zagaeski (Xamarin Team, assistant)
Details


Notice (2018-05-24): bugzilla.xamarin.com is now in read-only mode.

Please join us on Visual Studio Developer Community and in the Xamarin and Mono organizations on GitHub to continue tracking issues. Bugzilla will remain available for reference in read-only mode. We will continue to work on open Bugzilla bugs, copy them to the new locations as needed for follow-up, and add the new items under Related Links.

Our sincere thanks to everyone who has contributed on this bug tracker over the years. Thanks also for your understanding as we make these adjustments and improvements for the future.


Please create a new report on GitHub or Developer Community with your current version information, steps to reproduce, and relevant error messages or log files if you are hitting an issue that looks similar to this resolved bug and you do not yet see a matching new report.

Related Links:
Status:
VERIFIED FIXED

Description Brendan Zagaeski (Xamarin Team, assistant) 2015-06-30 00:32:21 UTC
Created attachment 11786 [details]
Test case

Starting Tasks or thread pool work items can briefly pause existing Tasks or work items


This is a companion bug for non-public Bug 30936. The idea for this bug is to discuss a small desktop Mono test case that shows a potentially interesting behavior. I suspect that this behavior might be "acceptable," and not anything that the Mono team will choose to optimize right now, but I am filing the bug anyway to at least provide some documentation about the behavior.


The test case has 2 pieces. One piece is a loop that runs approximately once every 50 ms, using `Task.Delay(50)` to perform the idle timeout. The other piece is a set of thread pool "work items" that starts each time a key is typed into the console input. Each time these work items start, the `Task.Delay(50)` in the loop takes longer than usual to return.


This might be related to Bug 1653?




## Steps to reproduce

1. Adjust the parameter "4" in `i < 4` in the `for` loop so that the program queues at least as many work items as the number of logical cores on the testing computer.

2. Build and run the attached test case using Mono on OS X.

3. Press the return key.

4. Wait a couple seconds to allow the queued work items to complete.

5. Repeat steps 3 and 4 several times.




## Results in Mono on OS X

(Filtered through `grep -A3 '=='` in this example for brevity.)

> ==
> delay: 807.859
> delay: 51.596
> delay: 53.035
> --
> ==
> delay: 889.042
> delay: 50.147
> delay: 50.112
> --
> ==
> delay: 893.512
> delay: 51.187
> delay: 52.207
> --
> ==
> delay: 765.366
> delay: 53.349
> delay: 53.689
> --
> ==
> delay: 877.25
> delay: 53.638
> delay: 52.282
> --
> ==
> delay: 971.736
> delay: 53.713
> delay: 51.97




## Results in .NET on Windows 8.1 in VMWare Fusion Version 6.0.6 (2684343), with 2 logical CPU cores assigned

(Filtered through `grep -A3 '=='` in this example for brevity.)

Note in particular how the first "delay" message after each key press eventually "levels-out" so that it becomes approximately equal to the other delays.

> ==
> delay: 829.0888
> delay: 187.4678
> delay: 61.9134
> --
> ==
> delay: 749.3613
> delay: 266.1115
> delay: 62.514
> --
> ==
> delay: 62.4899
> delay: 62.4931
> delay: 62.5231
> --
> ==
> delay: 63.3742
> delay: 750.039
> delay: 62.0165
> --
> ==
> delay: 61.6527
> delay: 63.2026
> delay: 62.7247
> --
> ==
> delay: 62.3622
> delay: 62.645
> delay: 62.5173
> --
> ==
> delay: 62.3125
> delay: 62.2152
> delay: 63.3524
> --
> ==
> delay: 63.1628
> delay: 62.4845
> delay: 61.6198
> --
> ==
> delay: 62.5067
> delay: 61.5632
> delay: 62.4155




## "Workarounds"

- Replace `await Task.Delay(50);` with `Thread.Sleep(50);`

- Replace `ThreadPool.QueueUserWorkItem()` with "heavy-weight" threads: `new Thread().Start()`.

- Reduce the number of work items queued in the `for` loop so that there are fewer than the number of logical cores on the testing computer.


Any of these options appears to eliminate the pauses in Mono on OS X.




## Changes that have _no_ effect

- Replace `ThreadPool.QueueUserWorkItem()` with `Task.Factory.StartNew()` or vice versa. 




## Regression status: not an immediate regression

The behavior is the same on Mono 3.12.1 (detached/0849ec7) and Mono 4.0.2.




## Version information

Mono 4.0.2 (detached/c99aa0c)

OS X 10.10.3

MacBook Air 5,2
Logical cores (`sysctl -n hw.ncpu`): 4
Comment 1 Ludovic Henry 2016-01-25 17:53:03 UTC
The threadpool implementation has changed since Mono 4.0, as it now uses the Microsoft implementation with Mono 4.2. I also tried to reproduce with Mono 4.2.2 (explicit/4732507), and I couldn't observe such huge delays as you have here.

@Brendan if you can confirm this behavior with Mono 4.2, please reopen the bug. Thank you!
Comment 2 Brendan Zagaeski (Xamarin Team, assistant) 2016-01-25 21:33:03 UTC
## Verification status: verified fixed in Mono 4.2



### GOOD: Mono 4.2.1 (6dd2d0d)

> ==
> delay: 109.061
> delay: 54.813
> delay: 52.041
> --
> ==
> delay: 50.11
> delay: 50.152
> delay: 51.511
> --
> ==
> delay: 53.564
> delay: 52.264
> delay: 51.318
> --
> ==
> delay: 50.724
> delay: 53.378
> delay: 50.152
> --
> ==
> delay: 52.136
> delay: 52.528
> delay: 51.445
> --
> ==
> delay: 50.08
> delay: 52.989
> delay: 52.443
> --
> ==
> delay: 52.567
> delay: 51.681
> delay: 52.924
> --
> ==
> delay: 50.138
> delay: 50.357
> delay: 50.122
> --
> ==
> delay: 50.098
> delay: 53.062
> delay: 50.25



### BAD: Mono 4.0.5 (1d8d582)

> ==
> delay: 51.152
> delay: 1060.353
> delay: 53.153
> --
> ==
> delay: 721.676
> delay: 53
> delay: 51.295
> --
> ==
> delay: 954.461
> delay: 51.248
> delay: 51.24
> --
> ==
> delay: 680.87
> delay: 51.106
> delay: 52.639
> --
> ==
> delay: 906.925
> delay: 51.597
> delay: 51.904
> --
> ==
> delay: 720.871
> delay: 51.643
> delay: 53.635
> --
> ==
> delay: 824.744
> delay: 50.217
> delay: 50.171
> --
> ==
> delay: 74.992
> delay: 51.955
> delay: 50.816
> --
> ==
> delay: 968.804
> delay: 50.159
> delay: 51.13
Comment 3 Brendan Zagaeski (Xamarin Team, assistant) 2016-01-25 22:24:41 UTC
*** Bug 30936 has been marked as a duplicate of this bug. ***