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

.NET 6: PeriodicTimer scheduler replacement for dedicated thread #6435

Merged
merged 21 commits into from
Aug 23, 2023

Conversation

Aaronontheweb
Copy link
Member

@Aaronontheweb Aaronontheweb commented Feb 23, 2023

Changes

close #4031

Checklist

For significant changes, please ensure that the following have been completed (delete if not relevant):

Latest dev Benchmarks

Include data from the relevant benchmark prior to this change here.

This PR's Benchmarks

Include data from after this change here.

@Aaronontheweb
Copy link
Member Author

Testing this on the build server first to see if the .NET 6 impl falls apart compared to .NET Framework and .NET Core 3.1

@Aaronontheweb
Copy link
Member Author

Measured clock drift for dev:

C:\Users\aaron\AppData\Local\JetBrains\Toolbox\apps\Rider\ch-0\223.8617.53\plugins\dpa\DotFiles\JetBrains.DPA.Runner.exe --handle=3616 --backend-pid=209260 --etw-collect-flags=3 --detach-event-name=dpa.detach.3616 D:/Repositories/olympus/AkkaDotNet-Profiler-Food/src/Akka.SchedulerStress/bin/Debug/net7.0/Akka.SchedulerStress.exe
[INFO][02/27/2023 12:34:36.067][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 0 - Cumulative Time: expected [02/27/2023 12:34:36.040Z], found [02/27/2023 12:34:36.066Z] Drift: [00:00:00.0260583]
[INFO][02/27/2023 12:34:39.226][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 100 - Cumulative Time: expected [02/27/2023 12:34:38.040Z], found [02/27/2023 12:34:39.226Z] Drift: [00:00:01.1861098]
[INFO][02/27/2023 12:34:39.227][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 100 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0327206]
[INFO][02/27/2023 12:34:42.366][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 200 - Cumulative Time: expected [02/27/2023 12:34:40.040Z], found [02/27/2023 12:34:42.366Z] Drift: [00:00:02.3260677]
[INFO][02/27/2023 12:34:42.366][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 200 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0310745]
[INFO][02/27/2023 12:34:45.505][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 300 - Cumulative Time: expected [02/27/2023 12:34:42.040Z], found [02/27/2023 12:34:45.505Z] Drift: [00:00:03.4651280]
[INFO][02/27/2023 12:34:45.505][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 300 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0311091]
[INFO][02/27/2023 12:34:48.654][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 400 - Cumulative Time: expected [02/27/2023 12:34:44.040Z], found [02/27/2023 12:34:48.654Z] Drift: [00:00:04.6145305]
[INFO][02/27/2023 12:34:48.654][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 400 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0320034]
[INFO][02/27/2023 12:34:51.814][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 500 - Cumulative Time: expected [02/27/2023 12:34:46.040Z], found [02/27/2023 12:34:51.814Z] Drift: [00:00:05.7746171]
[INFO][02/27/2023 12:34:51.814][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 500 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0309290]
[INFO][02/27/2023 12:34:54.971][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 600 - Cumulative Time: expected [02/27/2023 12:34:48.040Z], found [02/27/2023 12:34:54.971Z] Drift: [00:00:06.9315897]
[INFO][02/27/2023 12:34:54.971][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 600 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0320782]
[INFO][02/27/2023 12:34:58.130][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 700 - Cumulative Time: expected [02/27/2023 12:34:50.040Z], found [02/27/2023 12:34:58.130Z] Drift: [00:00:08.0900952]
[INFO][02/27/2023 12:34:58.130][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 700 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0321680]
[INFO][02/27/2023 12:35:01.267][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 800 - Cumulative Time: expected [02/27/2023 12:34:52.040Z], found [02/27/2023 12:35:01.267Z] Drift: [00:00:09.2272884]
[INFO][02/27/2023 12:35:01.267][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 800 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0322075]
[INFO][02/27/2023 12:35:04.418][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 900 - Cumulative Time: expected [02/27/2023 12:34:54.040Z], found [02/27/2023 12:35:04.418Z] Drift: [00:00:10.3786395]
[INFO][02/27/2023 12:35:04.418][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 900 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0311100]
[INFO][02/27/2023 12:35:07.562][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1000 - Cumulative Time: expected [02/27/2023 12:34:56.040Z], found [02/27/2023 12:35:07.562Z] Drift: [00:00:11.5223257]
[INFO][02/27/2023 12:35:07.562][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1000 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0315052]
[INFO][02/27/2023 12:35:10.701][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1100 - Cumulative Time: expected [02/27/2023 12:34:58.040Z], found [02/27/2023 12:35:10.701Z] Drift: [00:00:12.6609697]
[INFO][02/27/2023 12:35:10.701][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1100 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0319963]
[INFO][02/27/2023 12:35:13.842][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1200 - Cumulative Time: expected [02/27/2023 12:35:00.040Z], found [02/27/2023 12:35:13.842Z] Drift: [00:00:13.8021290]
[INFO][02/27/2023 12:35:13.842][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1200 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0301082]
[INFO][02/27/2023 12:35:16.968][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1300 - Cumulative Time: expected [02/27/2023 12:35:02.040Z], found [02/27/2023 12:35:16.968Z] Drift: [00:00:14.9280321]
[INFO][02/27/2023 12:35:16.968][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1300 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0311767]
[INFO][02/27/2023 12:35:20.124][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1400 - Cumulative Time: expected [02/27/2023 12:35:04.040Z], found [02/27/2023 12:35:20.124Z] Drift: [00:00:16.0844506]
[INFO][02/27/2023 12:35:20.124][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1400 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0306540]
[INFO][02/27/2023 12:35:23.276][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1500 - Cumulative Time: expected [02/27/2023 12:35:06.040Z], found [02/27/2023 12:35:23.276Z] Drift: [00:00:17.2358507]
[INFO][02/27/2023 12:35:23.276][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1500 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0321173]
[INFO][02/27/2023 12:35:26.420][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1600 - Cumulative Time: expected [02/27/2023 12:35:08.040Z], found [02/27/2023 12:35:26.420Z] Drift: [00:00:18.3805732]
[INFO][02/27/2023 12:35:26.420][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1600 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0311772]
[INFO][02/27/2023 12:35:29.555][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1700 - Cumulative Time: expected [02/27/2023 12:35:10.040Z], found [02/27/2023 12:35:29.555Z] Drift: [00:00:19.5154962]
[INFO][02/27/2023 12:35:29.555][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1700 - Interval Drift: expected [00:00:00.0200000], found [00:00:00.0319121]

@Aaronontheweb
Copy link
Member Author

I must have written something wrong in this implementation of the timer - it is taking an eternity for ticks to be processed.

@Aaronontheweb Aaronontheweb modified the milestones: 1.5.0, 1.5.1 Mar 2, 2023
@Aaronontheweb Aaronontheweb modified the milestones: 1.5.1, 1.5.2 Mar 15, 2023
@Aaronontheweb Aaronontheweb modified the milestones: 1.5.2, 1.5.3 Apr 6, 2023
@Aaronontheweb Aaronontheweb modified the milestones: 1.5.3, 1.5.4, 1.5.5 Apr 20, 2023
@Aaronontheweb Aaronontheweb modified the milestones: 1.5.5, 1.5.6, 1.5.7 May 4, 2023
@Aaronontheweb Aaronontheweb modified the milestones: 1.5.7, 1.5.8 May 17, 2023
Arkatufus and others added 2 commits August 21, 2023 09:12
* Fix implementation and code cleanup

* Fix clock drift calculation
@Arkatufus
Copy link
Contributor

Measured clock drift on old code path in this PR:

[INFO][08/21/2023 14:22:49.907Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 100 - Cumulative Time: expected [00:00:01], found [00:00:02.8241153] Drift: [00:00:01.8241153]
[INFO][08/21/2023 14:22:49.908Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 100 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0282411], min [00:00:00.0149530], max [00:00:00.0320383]
[INFO][08/21/2023 14:22:52.750Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 200 - Cumulative Time: expected [00:00:02], found [00:00:05.6669776] Drift: [00:00:03.6669776]
[INFO][08/21/2023 14:22:52.750Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 200 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0284286], min [00:00:00.0149530], max [00:00:00.0321563]
[INFO][08/21/2023 14:22:55.557Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 300 - Cumulative Time: expected [00:00:03], found [00:00:08.4743623] Drift: [00:00:05.4743623]
[INFO][08/21/2023 14:22:55.557Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 300 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0280738], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:22:58.390Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 400 - Cumulative Time: expected [00:00:04], found [00:00:11.3072572] Drift: [00:00:07.3072572]
[INFO][08/21/2023 14:22:58.390Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 400 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0283289], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:01.206Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 500 - Cumulative Time: expected [00:00:05], found [00:00:14.1236750] Drift: [00:00:09.1236750]
[INFO][08/21/2023 14:23:01.206Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 500 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0281641], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:04.048Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 600 - Cumulative Time: expected [00:00:06], found [00:00:16.9650800] Drift: [00:00:10.9650800]
[INFO][08/21/2023 14:23:04.048Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 600 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0284140], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:06.880Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 700 - Cumulative Time: expected [00:00:07], found [00:00:19.7976801] Drift: [00:00:12.7976801]
[INFO][08/21/2023 14:23:06.880Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 700 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0283260], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:09.700Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 800 - Cumulative Time: expected [00:00:08], found [00:00:22.6172792] Drift: [00:00:14.6172792]
[INFO][08/21/2023 14:23:09.700Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 800 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0281959], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:12.526Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 900 - Cumulative Time: expected [00:00:09], found [00:00:25.4437272] Drift: [00:00:16.4437272]
[INFO][08/21/2023 14:23:12.526Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 900 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0282644], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:15.347Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1000 - Cumulative Time: expected [00:00:10], found [00:00:28.2640755] Drift: [00:00:18.2640755]
[INFO][08/21/2023 14:23:15.347Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1000 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0282034], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:18.189Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1100 - Cumulative Time: expected [00:00:11], found [00:00:31.1067975] Drift: [00:00:20.1067975]
[INFO][08/21/2023 14:23:18.189Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1100 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0284272], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:21.016Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1200 - Cumulative Time: expected [00:00:12], found [00:00:33.9329537] Drift: [00:00:21.9329537]
[INFO][08/21/2023 14:23:21.016Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1200 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0282615], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:23.827Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1300 - Cumulative Time: expected [00:00:13], found [00:00:36.7441336] Drift: [00:00:23.7441336]
[INFO][08/21/2023 14:23:23.827Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1300 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0281117], min [00:00:00.0148022], max [00:00:00.0321563]
[INFO][08/21/2023 14:23:26.640Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1400 - Cumulative Time: expected [00:00:14], found [00:00:39.5577889] Drift: [00:00:25.5577889]
[INFO][08/21/2023 14:23:26.640Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1400 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0281365], min [00:00:00.0147362], max [00:00:00.0321625]
[INFO][08/21/2023 14:23:29.471Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1500 - Cumulative Time: expected [00:00:15], found [00:00:42.3885260] Drift: [00:00:27.3885260]
[INFO][08/21/2023 14:23:29.471Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1500 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0283073], min [00:00:00.0147362], max [00:00:00.0321625]
[INFO][08/21/2023 14:23:32.296Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1600 - Cumulative Time: expected [00:00:16], found [00:00:45.2136486] Drift: [00:00:29.2136486]
[INFO][08/21/2023 14:23:32.296Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1600 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0282512], min [00:00:00.0147362], max [00:00:00.0321625]
[INFO][08/21/2023 14:23:35.119Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1700 - Cumulative Time: expected [00:00:17], found [00:00:48.0367250] Drift: [00:00:31.0367250]
[INFO][08/21/2023 14:23:35.119Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1700 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0282307], min [00:00:00.0147362], max [00:00:00.0321625]
[INFO][08/21/2023 14:23:37.946Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1800 - Cumulative Time: expected [00:00:18], found [00:00:50.8629646] Drift: [00:00:32.8629646]
[INFO][08/21/2023 14:23:37.946Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1800 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0282623], min [00:00:00.0147362], max [00:00:00.0321625]
[INFO][08/21/2023 14:23:40.756Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1900 - Cumulative Time: expected [00:00:19], found [00:00:53.6729740] Drift: [00:00:34.6729740]
[INFO][08/21/2023 14:23:40.756Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 1900 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0281000], min [00:00:00.0147362], max [00:00:00.0321625]
[INFO][08/21/2023 14:23:43.597Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 2000 - Cumulative Time: expected [00:00:20], found [00:00:56.5149231] Drift: [00:00:36.5149231]
[INFO][08/21/2023 14:23:43.598Z][Thread 0032][ClockDriftRunnable (akka://MyActorSystem)] Tick 2000 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0284194], min [00:00:00.0147362], max [00:00:00.0321625]

@Arkatufus
Copy link
Contributor

Measured clock drift on new code path in this PR:

[INFO][08/21/2023 14:27:27.389Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 100 - Cumulative Time: expected [00:00:01], found [00:00:01.0042174] Drift: [00:00:00.0042174]
[INFO][08/21/2023 14:27:27.389Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 100 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100421], min [00:00:00.0000007], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:28.398Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 200 - Cumulative Time: expected [00:00:02], found [00:00:02.0142838] Drift: [00:00:00.0142838]
[INFO][08/21/2023 14:27:28.398Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 200 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0101006], min [00:00:00.0000007], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:29.400Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 300 - Cumulative Time: expected [00:00:03], found [00:00:03.0164463] Drift: [00:00:00.0164463]
[INFO][08/21/2023 14:27:29.400Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 300 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100216], min [00:00:00.0000004], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:30.394Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 400 - Cumulative Time: expected [00:00:04], found [00:00:04.0101494] Drift: [00:00:00.0101494]
[INFO][08/21/2023 14:27:30.394Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 400 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0099370], min [00:00:00.0000004], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:31.400Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 500 - Cumulative Time: expected [00:00:05], found [00:00:05.0161544] Drift: [00:00:00.0161544]
[INFO][08/21/2023 14:27:31.400Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 500 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100600], min [00:00:00.0000004], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:32.392Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 600 - Cumulative Time: expected [00:00:06], found [00:00:06.0081837] Drift: [00:00:00.0081837]
[INFO][08/21/2023 14:27:32.392Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 600 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0099202], min [00:00:00.0000004], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:33.395Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 700 - Cumulative Time: expected [00:00:07], found [00:00:07.0107881] Drift: [00:00:00.0107881]
[INFO][08/21/2023 14:27:33.395Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 700 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100260], min [00:00:00.0000004], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:34.398Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 800 - Cumulative Time: expected [00:00:08], found [00:00:08.0141004] Drift: [00:00:00.0141004]
[INFO][08/21/2023 14:27:34.398Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 800 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100331], min [00:00:00.0000004], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:35.397Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 900 - Cumulative Time: expected [00:00:09], found [00:00:09.0132220] Drift: [00:00:00.0132220]
[INFO][08/21/2023 14:27:35.397Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 900 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0099912], min [00:00:00.0000004], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:36.403Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1000 - Cumulative Time: expected [00:00:10], found [00:00:10.0192643] Drift: [00:00:00.0192643]
[INFO][08/21/2023 14:27:36.403Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1000 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100604], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:37.392Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1100 - Cumulative Time: expected [00:00:11], found [00:00:11.0082726] Drift: [00:00:00.0082726]
[INFO][08/21/2023 14:27:37.392Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1100 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0098900], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:38.394Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1200 - Cumulative Time: expected [00:00:12], found [00:00:12.0098177] Drift: [00:00:00.0098177]
[INFO][08/21/2023 14:27:38.394Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1200 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100154], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:39.394Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1300 - Cumulative Time: expected [00:00:13], found [00:00:13.0103686] Drift: [00:00:00.0103686]
[INFO][08/21/2023 14:27:39.394Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1300 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100055], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:40.395Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1400 - Cumulative Time: expected [00:00:14], found [00:00:14.0109384] Drift: [00:00:00.0109384]
[INFO][08/21/2023 14:27:40.395Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1400 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100056], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:41.403Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1500 - Cumulative Time: expected [00:00:15], found [00:00:15.0189477] Drift: [00:00:00.0189477]
[INFO][08/21/2023 14:27:41.403Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1500 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100800], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:42.396Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1600 - Cumulative Time: expected [00:00:16], found [00:00:16.0121563] Drift: [00:00:00.0121563]
[INFO][08/21/2023 14:27:42.396Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1600 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0099320], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:43.400Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1700 - Cumulative Time: expected [00:00:17], found [00:00:17.0159804] Drift: [00:00:00.0159804]
[INFO][08/21/2023 14:27:43.400Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 1700 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100382], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:44.399Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1800 - Cumulative Time: expected [00:00:18], found [00:00:18.0151100] Drift: [00:00:00.0151100]
[INFO][08/21/2023 14:27:44.399Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1800 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0099912], min [00:00:00.0000003], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:45.394Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1900 - Cumulative Time: expected [00:00:19], found [00:00:19.0099018] Drift: [00:00:00.0099018]
[INFO][08/21/2023 14:27:45.394Z][Thread 0030][ClockDriftRunnable (akka://MyActorSystem)] Tick 1900 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0099479], min [00:00:00.0000002], max [00:00:00.0285066]
[INFO][08/21/2023 14:27:46.394Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 2000 - Cumulative Time: expected [00:00:20], found [00:00:20.0101733] Drift: [00:00:00.0101733]
[INFO][08/21/2023 14:27:46.394Z][Thread 0028][ClockDriftRunnable (akka://MyActorSystem)] Tick 2000 - Mean Interval Drift: expected [00:00:00.0100000], found [00:00:00.0100027], min [00:00:00.0000002], max [00:00:00.0285066]

@Aaronontheweb
Copy link
Member Author

@Arkatufus have approximately 20 test failures on this PR - can you run locally?

@Arkatufus
Copy link
Contributor

will do

@@ -52,6 +52,9 @@ public HashedWheelTimerScheduler(Config scheduler, ILoggingAdapter log) : base(s
if (SchedulerConfig.IsNullOrEmpty())
throw ConfigurationException.NullOrEmptyConfig<HashedWheelTimerScheduler>();

if (!Util.MonotonicClock.IsHighResolution)
Log.Warning("HashedWheelTimerScheduler depends on the availability of high resolution performance counter which is not available in this system");
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When would the high resolution timer not be available?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When the runtime could not provide one

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it not able to provide one on the build server?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No idea, but its there as a preventative measures, just in case this happens in the future

Copy link
Member Author

@Aaronontheweb Aaronontheweb left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Feedback for @Arkatufus


_shutdownTimeout = SchedulerConfig.GetTimeSpan("akka.scheduler.shutdown-timeout", null);
_shutdownTimeout = SchedulerConfig.GetTimeSpan("akka.scheduler.shutdown-timeout", TimeSpan.Zero);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So this will result in an instant shutdown?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, it would, because TimeSpan.Zero is an illegal value

src/core/Akka/Actor/Scheduler/HashedWheelTimerScheduler.cs Outdated Show resolved Hide resolved

static MonotonicClock()
{
TicksFrequency = (double)TicksInSecond / Stopwatch.Frequency;
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is this here? Please add a comment in the code to explain, as it's non-obvious why this is needed.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TickFrequency is a constant scaling value to normalize operating system reported performance counter clock tick to .NET internal definition of a "tick".

Stopwatch.ElapsedTicks returns the raw operating system level performance clock ticks, which is not the same definition as .NET DateTime or TimeSpan definition.

.NET DateTime or TimeSpan definition of a "tick" is 100 nanosecond, which is true for all windows platforms that support performance counter clock (win8+). This is not true for linux platforms, their definition of a "tick" is 1 nanosecond.

@Arkatufus Arkatufus marked this pull request as ready for review August 22, 2023 15:35
@Aaronontheweb
Copy link
Member Author

Can you run the RemotePingPong benchmarks with before and after numbers for this?

Copy link
Member Author

@Aaronontheweb Aaronontheweb left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@Aaronontheweb Aaronontheweb enabled auto-merge (squash) August 23, 2023 14:35
@Arkatufus
Copy link
Contributor

RemotePingPong Benchmark

Median value of 5 benchmark runs

Benchmark Computer

OSVersion: Microsoft Windows NT 10.0.19045.0
ProcessorCount: 24
ClockSpeed: 0 MHZ
Actor Count: 48
Messages sent/received per client: 200000 (2e5)
Is Server GC: True
Thread count: 132

Dev Branch

Num clients Total [msg] Msgs/sec Total [ms] Start Threads End Threads
1 200000 121877 1641.09 134 161
5 1000000 582751 1716.67 169 171
10 2000000 642468 3113.71 179 182
15 3000000 639523 4691.83 192 193
20 4000000 655523 6102.53 202 194
25 5000000 649351 7700.79 206 190
30 6000000 645509 9295.46 196 183

New Code

Num clients Total [msg] Msgs/sec Total [ms] Start Threads End Threads
1 200000 126024 1587.36 131 159
5 1000000 596659 1676.26 167 173
10 2000000 635931 3145.31 178 180
15 3000000 644746 4653.57 188 189
20 4000000 646726 6185.34 197 192
25 5000000 637837 7839.79 212 196
30 6000000 638978 9390.50 204 182

@Aaronontheweb
Copy link
Member Author

Benchmark numbers look good

@Aaronontheweb Aaronontheweb merged commit c5b1320 into akkadotnet:dev Aug 23, 2023
10 of 12 checks passed
@Aaronontheweb Aaronontheweb deleted the threading-timer-scheduler branch August 23, 2023 17:06
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

HashedWheelTimerScheduler is spending 35% of execution time in sleep
2 participants