Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HashedWheelTimerScheduler is spending 35% of execution time in sleep #4031

Closed
IgorFedchenko opened this issue Nov 11, 2019 · 5 comments · Fixed by #6435
Closed

HashedWheelTimerScheduler is spending 35% of execution time in sleep #4031

IgorFedchenko opened this issue Nov 11, 2019 · 5 comments · Fixed by #6435

Comments

@IgorFedchenko
Copy link
Contributor

I used Akka.IO TcpOperationBenchmark as a sample to apply profiling, and it turns out that it is spending ~35% of time in sleep (Sleep function is my wrapper over Thread.Sleep that is used in scheduler). See the picture:

image

So, 1/3 of execution time scheduler is waiting for the next tick. This may slow down actors messaging pretty much. I am going to open PR for it.

@IgorFedchenko IgorFedchenko changed the title HashedWheelTimerScheduler is spending 35% of execution time in sleep HashedWheelTimerScheduler is spending 35% of execution time in sleep Nov 11, 2019
@IgorFedchenko
Copy link
Contributor Author

IgorFedchenko commented Nov 11, 2019

I have added simple static public fields to track how much scheduler should wait (in ticks, ideally), and how much is looses because of inaccurate windows clock.
Like this:

                    var stopWatch = Stopwatch.StartNew();
                    
#if UNSAFE_THREADING
                    try
                    {
                        Thread.Sleep(TimeSpan.FromMilliseconds(sleepMs));
                    }
                    catch (ThreadInterruptedException)
                    {
                        if (_workerState == WORKER_STATE_SHUTDOWN)
                            return long.MinValue;
                    }
#else
                    Thread.Sleep(TimeSpan.FromMilliseconds(sleepMs));
#endif
                    
                    stopWatch.Stop();
                    _totalTicksRequiredToWaitStrict += deadline - currentTime;
                    _totalTicksRequiredToWait += sleepMs * TimeSpan.TicksPerMillisecond;
                    _totalTicksLost += stopWatch.ElapsedTicks - sleepMs * TimeSpan.TicksPerMillisecond;

It turned out, that:

  1. _totalTicksRequiredToWait is about 1.01 * _totalTicksRequiredToWaitStrict to 1.1 * _totalTicksRequiredToWaitStrict , so we are loosing ~1-10% of sleep time because we have to round ticks to milliseconds to call Thread.Sleep. And _totalTicksRequiredToWaitStrict is 3+ seconds in my test, which means that it is just load loaded with work, that's why it is sleeping so much.
  2. _totalTicksLost is almost always about 1.1 * _totalTicksRequiredToWait, so we are constantly adding 10% of time due to windows clock delays.

Scala is doing special rounding for Windows:

val sleepMs = if (Helpers.isWindows) (nanos + 4 999 999) / 10 000 000 * 10 else (nanos + 999 999) / 1 000 000

I will try this and some other ideas to reduce useless waiting.

Update: did not help. Still +10% to the expected waiting time.

@Aaronontheweb
Copy link
Member

This is great work @IgorFedchenko - keep going with it.

@IgorFedchenko
Copy link
Contributor Author

I think I have found partial solution for this problem, which may give some performance boost for long running actively scheduled scenarios. See my PR attached.

@Aaronontheweb Aaronontheweb added this to the 1.4.0 milestone Nov 12, 2019
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.0, 1.4.1 and Later Feb 11, 2020
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.2, 1.4.3, 1.4.4 Mar 13, 2020
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.4, 1.4.5 Mar 31, 2020
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.5, 1.4.6 Apr 29, 2020
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.6, 1.4.7 May 12, 2020
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.7, 1.4.8 May 26, 2020
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.8, 1.4.9 Jun 17, 2020
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.9, 1.4.10 Jul 21, 2020
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.10, 1.4.11 Aug 20, 2020
@Aaronontheweb Aaronontheweb removed this from the 1.4.11 milestone Nov 5, 2020
@Aaronontheweb Aaronontheweb added this to the 1.4.26 milestone Sep 8, 2021
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.26, 1.4.27 Sep 28, 2021
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.27, 1.4.28 Oct 11, 2021
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.28, 1.4.29 Nov 10, 2021
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.29, 1.4.30 Dec 13, 2021
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.30, 1.4.32 Dec 20, 2021
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.32, 1.4.33 Jan 18, 2022
@Aaronontheweb
Copy link
Member

I suspect this issue is responsible for some of the high idle CPU numbers we're seeing here: #5400 (comment)

Aaronontheweb added a commit to Aaronontheweb/akka.net that referenced this issue Jan 28, 2022
close akkadotnet#4031

An experiment for the time being - looking to see how it performs in benchmarks and in the test suite.

Ideally, need to refactor this so it runs on the `/system` dispatcher but that will require changing the constructor arguments.
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.33, 1.4.34 Feb 14, 2022
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.34, 1.4.35 Mar 7, 2022
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.35, 1.4.36 Mar 18, 2022
@Aaronontheweb Aaronontheweb modified the milestones: 1.4.36, 1.4.40 Jun 7, 2022
@Aaronontheweb Aaronontheweb removed this from the 1.4.40 milestone Jul 27, 2022
@Aaronontheweb
Copy link
Member

Marking this as "won't fix" - there isn't a cheaper way to do this. We've tried. Plus it barely registers on our large scale tests.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment