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

🔬Research perf of StopWatch #865

Open
3 tasks done
CalvinWilkinson opened this issue Jan 10, 2024 · 0 comments
Open
3 tasks done

🔬Research perf of StopWatch #865

CalvinWilkinson opened this issue Jan 10, 2024 · 0 comments
Assignees
Labels
high-priority High Priority preview Done while in preview 🔬research Research collection / investigation

Comments

@CalvinWilkinson
Copy link
Member

CalvinWilkinson commented Jan 10, 2024

Complete The Item Below

  • I have updated the title without removing the 🔬 emoji.

What To Research

Research different uses of the StopWatch class to see if there is a possibility for improvements to performance.

Currently, the Start(), Stop(), and Reset() methods are being used in conjunction with the Elapsed property to measure time.

Another option to try and use is the Stopwatch.GetTimestamp() method. This method is static and returns a long data type which represents the current ticks. The idea here is to see if the current implementation is more or less performant than using the StopWatch.GetTimestamp() method.

Note

The current use needs to get the time in milliseconds, but the new method is ticks. Math operations will need to be performed to convert ticks to milliseconds. This math needs to be included in the performance measurements for an honest comparison.

If it turns out that StopWatch.GetTimestamp() is more performant, create an issue to do the work.

Additional Info:

This is all implemented in the types StopWatchWrapper and TimerService.

Research Results

Test Results With Raw Stopwatch Calls

// Benchmark Process 10080 has exited with code 0.

Mean = 259.471 ms, StdErr = 0.312 ms (0.12%), N = 15, StdDev = 1.209 ms
Min = 258.051 ms, Q1 = 258.371 ms, Median = 259.098 ms, Q3 = 260.495 ms, Max = 261.363 ms
IQR = 2.123 ms, LowerFence = 255.187 ms, UpperFence = 263.679 ms
ConfidenceInterval = [258.178 ms; 260.764 ms] (CI 99.9%), Margin = 1.293 ms (0.50% of Mean)
Skewness = 0.3, Kurtosis = 1.38, MValue = 2

// ** Remained 0 (0.0%) benchmark(s) to run. Estimated finish 2025-01-18 16:12 (0h 0m from now) **
Successfully reverted power plan (GUID: 6fecc5ae-f350-48a5-b669-b472cb895ccf FriendlyName: Turbo)
// ***** BenchmarkRunner: Finish  *****

// * Export *
  BenchmarkDotNet.Artifacts\results\StopWatchPerf.StopwatchBenchmarks-report.csv
  BenchmarkDotNet.Artifacts\results\StopWatchPerf.StopwatchBenchmarks-report-github.md
  BenchmarkDotNet.Artifacts\results\StopWatchPerf.StopwatchBenchmarks-report.html

// * Detailed results *
StopwatchBenchmarks.Start/Stop: Job-URWFVG(MinIterationTime=110ms, InvocationCount=1, UnrollFactor=1) [IterationCount=10000000]
Runtime = .NET 9.0.1 (9.0.124.61010), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 283.474 ms, StdErr = 0.584 ms (0.21%), N = 14, StdDev = 2.185 ms
Min = 280.600 ms, Q1 = 281.832 ms, Median = 283.255 ms, Q3 = 285.106 ms, Max = 288.001 ms
IQR = 3.274 ms, LowerFence = 276.921 ms, UpperFence = 290.017 ms
ConfidenceInterval = [281.010 ms; 285.938 ms] (CI 99.9%), Margin = 2.464 ms (0.87% of Mean)
Skewness = 0.57, Kurtosis = 2.06, MValue = 2
-------------------- Histogram --------------------
[279.793 ms ; 289.191 ms) | @@@@@@@@@@@@@@
---------------------------------------------------

StopwatchBenchmarks.GetTimeStamp: Job-URWFVG(MinIterationTime=110ms, InvocationCount=1, UnrollFactor=1) [IterationCount=10000000]
Runtime = .NET 9.0.1 (9.0.124.61010), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 259.471 ms, StdErr = 0.312 ms (0.12%), N = 15, StdDev = 1.209 ms
Min = 258.051 ms, Q1 = 258.371 ms, Median = 259.098 ms, Q3 = 260.495 ms, Max = 261.363 ms
IQR = 2.123 ms, LowerFence = 255.187 ms, UpperFence = 263.679 ms
ConfidenceInterval = [258.178 ms; 260.764 ms] (CI 99.9%), Margin = 1.293 ms (0.50% of Mean)
Skewness = 0.3, Kurtosis = 1.38, MValue = 2
-------------------- Histogram --------------------
[257.408 ms ; 262.007 ms) | @@@@@@@@@@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet v0.14.0, Windows 11 (10.0.26100.2894)
Intel Core Ultra 9 185H, 1 CPU, 22 logical and 16 physical cores
.NET SDK 9.0.102
  [Host]     : .NET 9.0.1 (9.0.124.61010), X64 RyuJIT AVX2
  Job-URWFVG : .NET 9.0.1 (9.0.124.61010), X64 RyuJIT AVX2

MinIterationTime=110ms  InvocationCount=1  UnrollFactor=1

| Method       | IterationCount | Mean     | Error   | StdDev  | Allocated |
|------------- |--------------- |---------:|--------:|--------:|----------:|
| Start/Stop   | 10000000       | 283.5 ms | 2.46 ms | 2.18 ms |     400 B |
| GetTimeStamp | 10000000       | 259.5 ms | 1.29 ms | 1.21 ms |     112 B |

// * Hints *
Outliers
  StopwatchBenchmarks.Start/Stop: MinIterationTime=110ms, InvocationCount=1, UnrollFactor=1 -> 1 outlier  was  removed (303.52 ms)

// * Legends *
  IterationCount : Value of the 'IterationCount' parameter
  Mean           : Arithmetic mean of all measurements
  Error          : Half of 99.9% confidence interval
  StdDev         : Standard deviation of all measurements
  Allocated      : Allocated memory per single operation (managed only, inclusive, 1KB = 1024B)
  1 ms           : 1 Millisecond (0.001 sec)

// * Diagnostic Output - MemoryDiagnoser *


// ***** BenchmarkRunner: End *****
Run time: 00:00:13 (13.38 sec), executed benchmarks: 2

Global total time: 00:00:18 (18.5 sec), executed benchmarks: 2

New stopwatch and timer service types

// Benchmark Process 64440 has exited with code 0.

Mean = 33.746 ms, StdErr = 0.028 ms (0.08%), N = 12, StdDev = 0.098 ms
Min = 33.656 ms, Q1 = 33.679 ms, Median = 33.688 ms, Q3 = 33.805 ms, Max = 33.961 ms
IQR = 0.126 ms, LowerFence = 33.489 ms, UpperFence = 33.995 ms
ConfidenceInterval = [33.621 ms; 33.871 ms] (CI 99.9%), Margin = 0.125 ms (0.37% of Mean)
Skewness = 0.87, Kurtosis = 2.37, MValue = 2

// ** Remained 0 (0.0%) benchmark(s) to run. Estimated finish 2025-01-21 16:43 (0h 0m from now) **
Successfully reverted power plan (GUID: 8c5e7fda-e8bf-4a96-9a85-a6e23a8c635c FriendlyName: High performance)
// ***** BenchmarkRunner: Finish  *****

// * Export *
  BenchmarkDotNet.Artifacts\results\StopWatchPerf.StopwatchBenchmarks-report.csv
  BenchmarkDotNet.Artifacts\results\StopWatchPerf.StopwatchBenchmarks-report-github.md
  BenchmarkDotNet.Artifacts\results\StopWatchPerf.StopwatchBenchmarks-report.html

// * Detailed results *
StopwatchBenchmarks.'Orig TimeService': Job-IYTSVO(InvocationCount=1, UnrollFactor=1) [IterationCount=1000000]
Runtime = .NET 9.0.1 (9.0.124.61010), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 517.314 ms, StdErr = 2.526 ms (0.49%), N = 16, StdDev = 10.105 ms
Min = 499.523 ms, Q1 = 510.190 ms, Median = 518.687 ms, Q3 = 524.958 ms, Max = 534.793 ms
IQR = 14.768 ms, LowerFence = 488.038 ms, UpperFence = 547.111 ms
ConfidenceInterval = [507.026 ms; 527.603 ms] (CI 99.9%), Margin = 10.288 ms (1.99% of Mean)
Skewness = -0.3, Kurtosis = 2.01, MValue = 2
-------------------- Histogram --------------------
[494.260 ms ; 506.122 ms) | @@
[506.122 ms ; 526.755 ms) | @@@@@@@@@@@@@
[526.755 ms ; 540.056 ms) | @
---------------------------------------------------

StopwatchBenchmarks.'New TimeService': Job-IYTSVO(InvocationCount=1, UnrollFactor=1) [IterationCount=1000000]
Runtime = .NET 9.0.1 (9.0.124.61010), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 33.746 ms, StdErr = 0.028 ms (0.08%), N = 12, StdDev = 0.098 ms
Min = 33.656 ms, Q1 = 33.679 ms, Median = 33.688 ms, Q3 = 33.805 ms, Max = 33.961 ms
IQR = 0.126 ms, LowerFence = 33.489 ms, UpperFence = 33.995 ms
ConfidenceInterval = [33.621 ms; 33.871 ms] (CI 99.9%), Margin = 0.125 ms (0.37% of Mean)
Skewness = 0.87, Kurtosis = 2.37, MValue = 2
-------------------- Histogram --------------------
[33.600 ms ; 34.017 ms) | @@@@@@@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet v0.14.0, Windows 11 (10.0.26100.2894)
Intel Core Ultra 9 185H, 1 CPU, 22 logical and 16 physical cores
.NET SDK 9.0.102
  [Host]     : .NET 9.0.1 (9.0.124.61010), X64 RyuJIT AVX2
  Job-IYTSVO : .NET 9.0.1 (9.0.124.61010), X64 RyuJIT AVX2

InvocationCount=1  UnrollFactor=1

| Method             | IterationCount | Mean      | Error     | StdDev    | Allocated |
|------------------- |--------------- |----------:|----------:|----------:|----------:|
| 'Orig TimeService' | 1000000        | 517.31 ms | 10.288 ms | 10.105 ms |     400 B |
| 'New TimeService'  | 1000000        |  33.75 ms |  0.125 ms |  0.098 ms |     112 B |

// * Warnings *
MinIterationTime
  StopwatchBenchmarks.'New TimeService': InvocationCount=1, UnrollFactor=1 -> The minimum observed iteration time is 33.656ms which is very small. It's recommended to increase it to at least 100ms using more operations.

// * Hints *
Outliers
  StopwatchBenchmarks.'New TimeService': InvocationCount=1, UnrollFactor=1 -> 3 outliers were removed (34.91 ms..35.41 ms)

// * Legends *
  IterationCount : Value of the 'IterationCount' parameter
  Mean           : Arithmetic mean of all measurements
  Error          : Half of 99.9% confidence interval
  StdDev         : Standard deviation of all measurements
  Allocated      : Allocated memory per single operation (managed only, inclusive, 1KB = 1024B)
  1 ms           : 1 Millisecond (0.001 sec)

// * Diagnostic Output - MemoryDiagnoser *


// ***** BenchmarkRunner: End *****
Run time: 00:00:15 (15.42 sec), executed benchmarks: 2

Global total time: 00:00:21 (21.24 sec), executed benchmarks: 2
// * Artifacts cleanup *
Artifacts cleanup is finished

The main area that this increases performance is when calculating the frames per second in the main GLWindow class
and is in the game loop hot path.

  1. The measurements stated in the raw stop watch calls above show that before the perf improvement of 8.46%.
  2. After playing around with performance improvements of using the Stopwatch.GetTimestamp() method, we were able to increase the performance of the TimerService implementation by 93.011%!!

Acceptance Criteria

The items to complete in order to satisfy the Definition of Done.

Preview Give feedback

ToDo Items

The items to complete in order to satisfy the Definition of Done.

Preview Give feedback

Issue Dependencies

No response

Related Work

No response

Additional Information:

Priority Type Labels

Priority Type Label
Low Priority low priority
Medium Priority medium priority
High Priority high priority

Code of Conduct

  • I agree to follow this project's Code of Conduct.
@CalvinWilkinson CalvinWilkinson added high-priority High Priority 🔬research Research collection / investigation labels Jan 10, 2024
@CalvinWilkinson CalvinWilkinson self-assigned this Jan 10, 2024
@github-project-automation github-project-automation bot moved this to ⚪Not Set in KD-Team Jan 10, 2024
@kselena kselena added the preview Done while in preview label Jan 22, 2024
@CalvinWilkinson CalvinWilkinson moved this from ⚪Not Set to 🏗️In Development in KD-Team Jan 18, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
high-priority High Priority preview Done while in preview 🔬research Research collection / investigation
Projects
Status: 🏗️In Development
Development

No branches or pull requests

2 participants