Bug 16416 - SemaphoreSlim performance problem
Summary: SemaphoreSlim performance problem
Status: RESOLVED FIXED
Alias: None
Product: Class Libraries
Classification: Mono
Component: mscorlib ()
Version: unspecified
Hardware: PC Mac OS
: Normal normal
Target Milestone: Untriaged
Assignee: Marek Safar
URL:
Depends on:
Blocks:
 
Reported: 2013-11-23 13:11 UTC by Philippe Monteil
Modified: 2015-01-20 16:36 UTC (History)
5 users (show)

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

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:
RESOLVED FIXED

Description Philippe Monteil 2013-11-23 13:11:21 UTC
Description of Problem:

The following code she that there is a performance problem with the Mono implementation
of the SemaphoreSlim problem, observed with Xamarin.Mac, .iOS and .Android

Using MS'S .Net, the SemaphoreSlim based test is slightly faster than the AutoResetEvent one.
On Xamarin.Mac, .iOS, ... using SemaphoreSlim is much-h slower than AutoResetEvent:
an easy workaround, but it took me a while to figure it out :-) 

The code looks like:

        Console.WriteLine(TestTask(8, 10000, true));
        Console.WriteLine(TestTask(8, 10000, false));

        #region --- Test_SemaphoreSlim

        static Object s_pMonitorLog = new object();
        static long s_LogTime0;
        static StringBuilder s_pStringBuilderLog;

        static void Log(string Txt)
        {
            try
            {
                Monitor.Enter(s_pMonitorLog);

                if (s_pStringBuilderLog == null) s_pStringBuilderLog = new StringBuilder(100000);

                if (s_LogTime0 == 0) s_LogTime0 = DateTime.Now.Ticks;
                long _dt_us = (DateTime.Now.Ticks - s_LogTime0) / 10;

                #if _DVW8_
                int _threadID = Environment.CurrentManagedThreadId;
                #else
                int _threadID = Thread.CurrentThread.ManagedThreadId;
                #endif
                string _log = string.Format("[{0}]({1}.{2}) {3}", _threadID, _dt_us / 1000, _dt_us % 1000, Txt);
                s_pStringBuilderLog.AppendLine(_log);
            }
            finally
            {
                Monitor.Exit(s_pMonitorLog);
            }
        }

        static string FlushLog()
        {
            try
            {
                Monitor.Enter(s_pMonitorLog);
                if (s_pStringBuilderLog == null) return null;
                return s_pStringBuilderLog.ToString();
            }
            finally
            {
                s_pStringBuilderLog = null;
                Monitor.Exit(s_pMonitorLog);
            }
        }

        static string TestTask(int TaskCount, int TestCount, bool UseSemaphoreSlim)
        {
            try
            {
                Log(string.Format("TestTask(-) TaskCount={0} TestCount={1} UseSemaphoreSlim={2}", TaskCount, TestCount, UseSemaphoreSlim));

                // Warmup
                {
                    for (int i = 0; i < TaskCount; i++)
                    {
                        Task _task = new Task(() =>
                            {
                                Thread.Sleep(100);
                            });
                        _task.Start();
                    }
                    Thread.Sleep(2000);
                }

                AutoResetEvent[] _aAutoResetEvent = new AutoResetEvent[TaskCount];
                for (int i = 0; i < TaskCount; i++)
                {
                    _aAutoResetEvent[i] = new AutoResetEvent(false);
                }

                SemaphoreSlim _pSemaphoreSlim_Test = new SemaphoreSlim(1);
                AutoResetEvent _pAutoResetEvent = new AutoResetEvent(true);

                for (int i = 0; i < TaskCount; i++)
                {
                    int _ixTask = i;
                    Task _task = new Task(() =>
                        {
                            long _ti = 0;
                            long _loopcount = 0;
                            try
                            {
                                Log(string.Format("Task[{0}](-)", _ixTask));

                                _aAutoResetEvent[_ixTask].WaitOne();

                                _ti = DateTime.Now.Ticks;

                                for (int j = 0; j < TestCount; j++)
                                {
                                    try
                                    {
                                        if (UseSemaphoreSlim)
                                        {
                                            _pSemaphoreSlim_Test.Wait();
                                        }
                                        else
                                        {
                                            _pAutoResetEvent.WaitOne();
                                        }
                                    }
                                    finally
                                    {
                                        if (UseSemaphoreSlim)
                                        {
                                            _pSemaphoreSlim_Test.Release();
                                        }
                                        else
                                        {
                                            _pAutoResetEvent.Set();
                                        }
                                        _loopcount++;
                                    }
                                }

                            }
                            finally
                            {
                                long _tf = DateTime.Now.Ticks;
                                long _dt_us = (_tf - _ti) / 10;
                                long _dtu_us = _dt_us / _loopcount;
                                Log(string.Format("Task[{0}](+) _dt_ms={1}.{2} _loopcount={3} _dtu_us={4}", _ixTask, _dt_us / 1000, _dt_us % 1000, _loopcount, _dtu_us));
                                _aAutoResetEvent[_ixTask].Set();
                            }
                        });
                    _task.Start();

                }

                //
                Thread.Sleep(500);

                for (int i = 0; i < TaskCount; i++)
                {
                    _aAutoResetEvent[i].Set();
                }

                //
                Thread.Sleep(500);

                // Wait for the Tasks completion
                for (int i = 0; i < TaskCount; i++)
                {
                    Log(string.Format("TestTask() _aAutoResetEvent[{0}].Wait()(-)", i));
                    _aAutoResetEvent[i].WaitOne();
                    Log(string.Format("TestTask() _aAutoResetEvent[{0}].Wait()(+)", i));
                }

            }
            finally
            {
                Log(string.Format("TestTask(+) UseSemaphoreSlim={0}", UseSemaphoreSlim));
            }

            return FlushLog();
        }

        #endregion

and it generates the following output, on the same machine running W8 and OSX, using MS .Net and Xamarin.Mac:

#if _DOC

//
// Test / W8
//

[1](0.0) TestTask(-) UseSemaphoreSlim=True
[7](2031.553) Task[0](-)
[3](2031.553) Task[2](-)
[10](2031.553) Task[1](-)
[8](2031.553) Task[3](-)
[5](2031.553) Task[7](-)
[4](2031.553) Task[4](-)
[9](2031.553) Task[5](-)
[6](2031.553) Task[6](-)
[1](3047.251) TestTask() _aAutoResetEvent[0].Wait()(-)
[9](3375.378) Task[5](+) _dt_ms=828.199 _loopcount=10000
[7](3391.1) Task[0](+) _dt_ms=843.822 _loopcount=10000
[1](3391.1) TestTask() _aAutoResetEvent[0].Wait()(+)
[1](3391.1) TestTask() _aAutoResetEvent[1].Wait()(-)
[8](3391.1) Task[3](+) _dt_ms=843.822 _loopcount=10000
[4](3391.1) Task[4](+) _dt_ms=843.822 _loopcount=10000
[5](3406.626) Task[7](+) _dt_ms=859.446 _loopcount=10000
[6](3406.626) Task[6](+) _dt_ms=859.446 _loopcount=10000
[3](3406.626) Task[2](+) _dt_ms=859.446 _loopcount=10000
[10](3406.626) Task[1](+) _dt_ms=859.446 _loopcount=10000
[1](3406.626) TestTask() _aAutoResetEvent[1].Wait()(+)
[1](3406.626) TestTask() _aAutoResetEvent[2].Wait()(-)
[1](3406.626) TestTask() _aAutoResetEvent[2].Wait()(+)
[1](3406.626) TestTask() _aAutoResetEvent[3].Wait()(-)
[1](3406.626) TestTask() _aAutoResetEvent[3].Wait()(+)
[1](3406.626) TestTask() _aAutoResetEvent[4].Wait()(-)
[1](3406.626) TestTask() _aAutoResetEvent[4].Wait()(+)
[1](3406.626) TestTask() _aAutoResetEvent[5].Wait()(-)
[1](3406.626) TestTask() _aAutoResetEvent[5].Wait()(+)
[1](3406.626) TestTask() _aAutoResetEvent[6].Wait()(-)
[1](3406.626) TestTask() _aAutoResetEvent[6].Wait()(+)
[1](3406.626) TestTask() _aAutoResetEvent[7].Wait()(-)
[1](3406.626) TestTask() _aAutoResetEvent[7].Wait()(+)
[1](3406.626) TestTask(+) UseSemaphoreSlim=True

...

[1](4609.929) TestTask(-) UseSemaphoreSlim=False
[3](6625.716) Task[0](-)
[10](6625.716) Task[1](-)
[7](6625.716) Task[4](-)
[8](6625.716) Task[6](-)
[5](6625.716) Task[5](-)
[9](6625.716) Task[7](-)
[6](6625.716) Task[2](-)
[11](6625.716) Task[3](-)
[1](7657.24) TestTask() _aAutoResetEvent[0].Wait()(-)
[3](8094.525) Task[0](+) _dt_ms=953.182 _loopcount=10000
[1](8094.525) TestTask() _aAutoResetEvent[0].Wait()(+)
[1](8094.525) TestTask() _aAutoResetEvent[1].Wait()(-)
[10](8094.525) Task[1](+) _dt_ms=953.182 _loopcount=10000
[7](8094.525) Task[4](+) _dt_ms=953.182 _loopcount=10000
[9](8094.525) Task[7](+) _dt_ms=953.182 _loopcount=10000
[1](8094.525) TestTask() _aAutoResetEvent[1].Wait()(+)
[1](8094.525) TestTask() _aAutoResetEvent[2].Wait()(-)
[6](8094.525) Task[2](+) _dt_ms=953.182 _loopcount=10000
[8](8094.525) Task[6](+) _dt_ms=953.182 _loopcount=10000
[11](8094.525) Task[3](+) _dt_ms=953.182 _loopcount=10000
[1](8094.525) TestTask() _aAutoResetEvent[2].Wait()(+)
[1](8094.525) TestTask() _aAutoResetEvent[3].Wait()(-)
[1](8094.525) TestTask() _aAutoResetEvent[3].Wait()(+)
[1](8094.525) TestTask() _aAutoResetEvent[4].Wait()(-)
[1](8094.525) TestTask() _aAutoResetEvent[4].Wait()(+)
[1](8094.525) TestTask() _aAutoResetEvent[5].Wait()(-)
[5](8094.525) Task[5](+) _dt_ms=953.182 _loopcount=10000
[1](8094.525) TestTask() _aAutoResetEvent[5].Wait()(+)
[1](8094.525) TestTask() _aAutoResetEvent[6].Wait()(-)
[1](8094.525) TestTask() _aAutoResetEvent[6].Wait()(+)
[1](8094.525) TestTask() _aAutoResetEvent[7].Wait()(-)
[1](8094.525) TestTask() _aAutoResetEvent[7].Wait()(+)
[1](8094.525) TestTask(+) UseSemaphoreSlim=False

...

#endif

#if _DOC_

//
// Test / Xamarin.Mac
//

[1](57295.760) TestTask(-) TaskCount=8 TestCount=10000 UseSemaphoreSlim=True
[8](59296.308) Task[0](-)
[11](59296.553) Task[1](-)
[9](59296.563) Task[2](-)
[4](59296.570) Task[3](-)
[7](59296.576) Task[4](-)
[10](59296.582) Task[5](-)
[5](59296.588) Task[6](-)
[6](59296.595) Task[7](-)
[1](60297.445) TestTask() _aAutoResetEvent[0].Wait()(-)
[6](66572.200) Task[7](+) _dt_ms=6774.759 _loopcount=10000 _dtu_us=677
[8](66612.532) Task[0](+) _dt_ms=6815.151 _loopcount=10000 _dtu_us=681
[1](66612.547) TestTask() _aAutoResetEvent[0].Wait()(+)
[1](66612.552) TestTask() _aAutoResetEvent[1].Wait()(-)
[5](66700.676) Task[6](+) _dt_ms=6903.244 _loopcount=10000 _dtu_us=690
[9](67040.141) Task[2](+) _dt_ms=7242.716 _loopcount=10000 _dtu_us=724
[4](67454.373) Task[3](+) _dt_ms=7656.946 _loopcount=10000 _dtu_us=765
[10](67455.549) Task[5](+) _dt_ms=7658.111 _loopcount=10000 _dtu_us=765
[11](67456.959) Task[1](+) _dt_ms=7659.560 _loopcount=10000 _dtu_us=765
[1](67456.971) TestTask() _aAutoResetEvent[1].Wait()(+)
[1](67456.975) TestTask() _aAutoResetEvent[2].Wait()(-)
[1](67456.978) TestTask() _aAutoResetEvent[2].Wait()(+)
[1](67456.980) TestTask() _aAutoResetEvent[3].Wait()(-)
[1](67456.984) TestTask() _aAutoResetEvent[3].Wait()(+)
[1](67456.986) TestTask() _aAutoResetEvent[4].Wait()(-)
[7](67457.173) Task[4](+) _dt_ms=7659.761 _loopcount=10000 _dtu_us=765
[1](67457.185) TestTask() _aAutoResetEvent[4].Wait()(+)
[1](67457.187) TestTask() _aAutoResetEvent[5].Wait()(-)
[1](67457.190) TestTask() _aAutoResetEvent[5].Wait()(+)
[1](67457.192) TestTask() _aAutoResetEvent[6].Wait()(-)
[1](67457.196) TestTask() _aAutoResetEvent[6].Wait()(+)
[1](67457.198) TestTask() _aAutoResetEvent[7].Wait()(-)
[1](67457.200) TestTask() _aAutoResetEvent[7].Wait()(+)
[1](67457.203) TestTask(+) UseSemaphoreSlim=True

[1](67457.602) TestTask(-) TaskCount=8 TestCount=10000 UseSemaphoreSlim=False
[6](69458.724) Task[0](-)
[8](69458.741) Task[1](-)
[4](69458.770) Task[2](-)
[9](69458.803) Task[4](-)
[7](69458.866) Task[6](-)
[5](69458.915) Task[3](-)
[10](69458.924) Task[5](-)
[11](69458.962) Task[7](-)
[1](70459.835) TestTask() _aAutoResetEvent[0].Wait()(-)
[6](70722.210) Task[0](+) _dt_ms=762.419 _loopcount=10000 _dtu_us=76
[1](70722.222) TestTask() _aAutoResetEvent[0].Wait()(+)
[1](70722.226) TestTask() _aAutoResetEvent[1].Wait()(-)
[9](70722.467) Task[4](+) _dt_ms=762.623 _loopcount=10000 _dtu_us=76
[5](70723.895) Task[3](+) _dt_ms=764.63 _loopcount=10000 _dtu_us=76
[11](70724.929) Task[7](+) _dt_ms=765.54 _loopcount=10000 _dtu_us=76
[7](70725.502) Task[6](+) _dt_ms=765.636 _loopcount=10000 _dtu_us=76
[10](70726.315) Task[5](+) _dt_ms=766.457 _loopcount=10000 _dtu_us=76
[4](70726.646) Task[2](+) _dt_ms=766.815 _loopcount=10000 _dtu_us=76
[8](70726.661) Task[1](+) _dt_ms=766.854 _loopcount=10000 _dtu_us=76
[1](70726.670) TestTask() _aAutoResetEvent[1].Wait()(+)
[1](70726.672) TestTask() _aAutoResetEvent[2].Wait()(-)
[1](70726.675) TestTask() _aAutoResetEvent[2].Wait()(+)
[1](70726.679) TestTask() _aAutoResetEvent[3].Wait()(-)
[1](70726.682) TestTask() _aAutoResetEvent[3].Wait()(+)
[1](70726.684) TestTask() _aAutoResetEvent[4].Wait()(-)
[1](70726.686) TestTask() _aAutoResetEvent[4].Wait()(+)
[1](70726.688) TestTask() _aAutoResetEvent[5].Wait()(-)
[1](70726.690) TestTask() _aAutoResetEvent[5].Wait()(+)
[1](70726.693) TestTask() _aAutoResetEvent[6].Wait()(-)
[1](70726.696) TestTask() _aAutoResetEvent[6].Wait()(+)
[1](70726.698) TestTask() _aAutoResetEvent[7].Wait()(-)
[1](70726.700) TestTask() _aAutoResetEvent[7].Wait()(+)
[1](70726.703) TestTask(+) UseSemaphoreSlim=False

#endif
Comment 1 Marius Ungureanu 2014-10-07 06:38:38 UTC
Changed this to the (hopefully) correct product.
Comment 2 Marek Safar 2015-01-20 16:36:42 UTC
Fixed in master

Results on my machine

[1](1.918) TestTask(-) TaskCount=8 TestCount=10000 UseSemaphoreSlim=True
[4](2012.597) Task[1](-)
[5](2012.634) Task[0](-)
[6](2023.722) Task[2](-)
[7](2525.540) Task[3](-)
[1](3019.910) TestTask() _aAutoResetEvent[0].Wait()(-)
[8](3030.88) Task[4](-)
[5](3369.242) Task[0](+) _dt_ms=852.433 _loopcount=10000 _dtu_us=85
[1](3369.279) TestTask() _aAutoResetEvent[0].Wait()(+)
[1](3369.282) TestTask() _aAutoResetEvent[1].Wait()(-)
[5](3372.876) Task[5](-)
[5](3379.432) Task[5](+) _dt_ms=6.542 _loopcount=10000 _dtu_us=0
[5](3379.443) Task[6](-)
[6](3390.764) Task[2](+) _dt_ms=873.952 _loopcount=10000 _dtu_us=87
[6](3390.781) Task[7](-)
[6](3397.142) Task[7](+) _dt_ms=6.348 _loopcount=10000 _dtu_us=0
[7](3400.614) Task[3](+) _dt_ms=875.57 _loopcount=10000 _dtu_us=87
[4](3413.96) Task[1](+) _dt_ms=896.239 _loopcount=10000 _dtu_us=89
[1](3413.117) TestTask() _aAutoResetEvent[1].Wait()(+)
[1](3413.120) TestTask() _aAutoResetEvent[2].Wait()(-)
[1](3413.124) TestTask() _aAutoResetEvent[2].Wait()(+)
[1](3413.126) TestTask() _aAutoResetEvent[3].Wait()(-)
[1](3413.129) TestTask() _aAutoResetEvent[3].Wait()(+)
[1](3413.131) TestTask() _aAutoResetEvent[4].Wait()(-)
[5](3414.337) Task[6](+) _dt_ms=34.882 _loopcount=10000 _dtu_us=3
[8](3418.588) Task[4](+) _dt_ms=388.485 _loopcount=10000 _dtu_us=38
[1](3418.609) TestTask() _aAutoResetEvent[4].Wait()(+)
[1](3418.613) TestTask() _aAutoResetEvent[5].Wait()(-)
[1](3418.617) TestTask() _aAutoResetEvent[5].Wait()(+)
[1](3418.619) TestTask() _aAutoResetEvent[6].Wait()(-)
[1](3418.622) TestTask() _aAutoResetEvent[6].Wait()(+)
[1](3418.624) TestTask() _aAutoResetEvent[7].Wait()(-)
[1](3418.629) TestTask() _aAutoResetEvent[7].Wait()(+)
[1](3418.645) TestTask(+) UseSemaphoreSlim=True

[1](3423.411) TestTask(-) TaskCount=8 TestCount=10000 UseSemaphoreSlim=False
[8](5428.453) Task[0](-)
[4](5428.461) Task[3](-)
[6](5428.494) Task[4](-)
[5](5428.519) Task[1](-)
[7](5428.551) Task[2](-)
[9](5551.504) Task[5](-)
[10](6055.210) Task[6](-)
[5](6329.682) Task[1](+) _dt_ms=396.492 _loopcount=10000 _dtu_us=39
[5](6329.703) Task[7](-)
[9](6406.801) Task[5](+) _dt_ms=473.594 _loopcount=10000 _dtu_us=47
[8](6409.950) Task[0](+) _dt_ms=476.756 _loopcount=10000 _dtu_us=47
[1](6437.849) TestTask() _aAutoResetEvent[0].Wait()(-)
[1](6437.861) TestTask() _aAutoResetEvent[0].Wait()(+)
[1](6437.865) TestTask() _aAutoResetEvent[1].Wait()(-)
[1](6437.870) TestTask() _aAutoResetEvent[1].Wait()(+)
[1](6437.874) TestTask() _aAutoResetEvent[2].Wait()(-)
[4](6440.599) Task[3](+) _dt_ms=507.407 _loopcount=10000 _dtu_us=50
[7](6445.801) Task[2](+) _dt_ms=512.610 _loopcount=10000 _dtu_us=51
[1](6445.822) TestTask() _aAutoResetEvent[2].Wait()(+)
[1](6445.832) TestTask() _aAutoResetEvent[3].Wait()(-)
[1](6445.847) TestTask() _aAutoResetEvent[3].Wait()(+)
[1](6445.851) TestTask() _aAutoResetEvent[4].Wait()(-)
[6](6451.849) Task[4](+) _dt_ms=518.642 _loopcount=10000 _dtu_us=51
[1](6451.880) TestTask() _aAutoResetEvent[4].Wait()(+)
[1](6451.886) TestTask() _aAutoResetEvent[5].Wait()(-)
[1](6451.892) TestTask() _aAutoResetEvent[5].Wait()(+)
[1](6451.898) TestTask() _aAutoResetEvent[6].Wait()(-)
[10](6457.410) Task[6](+) _dt_ms=402.184 _loopcount=10000 _dtu_us=40
[1](6457.425) TestTask() _aAutoResetEvent[6].Wait()(+)
[1](6457.440) TestTask() _aAutoResetEvent[7].Wait()(-)
[5](6463.911) Task[7](+) _dt_ms=134.193 _loopcount=10000 _dtu_us=13
[1](6463.934) TestTask() _aAutoResetEvent[7].Wait()(+)
[1](6463.939) TestTask(+) UseSemaphoreSlim=False