Ever have a bright idea and think to yourself “oh, man, this is going to be so much faster”? Well, I do often, and often I find out that I’m a dummy. But that’s OK! We need to learn. So how do you find out your bright idea is as bright as a black hole? Diagnostics. The tool I tend to use most is simply the Stopwatch provided by the System.Diagnostics namespace. It’s pretty simple and provides that much-needed insight to the age-old question: “Is this method better than that method”. In this article I’ll take you through a couple of methods that are commonly frowned upon because they are slow with some simple usage examples of the Stopwatch, then I’ll show you how to make a more generalized diagnostics tool that’s more flexible and is good for your toolbox (I call it the DiagnosticsRecorder). Let’s begin!Simple Usage of Stopwatch
We’re often told that such and such method is slow and should be avoided at all costs. Two common ones are using Vector magnitudes vs. square magnitudes and repeated calls to Unity’s GetComponent() method. Let’s start off by testing the difference between Vector3.magnitude vs. Vector3.sqrMagnitude. Place your bets now on which will be faster and what the time difference is!
First simply create a MonoBehaviour derived script with just an empty Start() method. Then pop in the following method.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 |
// Make sure to use this in your namespace declarations using System.Diagnostics; // This is needed because System.Diagnostics also contains a Debug class using Debug = UnityEngine.Debug; // We'll need a lot of iterations to get any result for this. public int iterations = 1000000; void TestMagnitude() { // Fill up an array of vectors to test on. Vector3[] testVectors = new Vector3[iterations]; for (int i = 0; i < iterations; i++) { testVectors[i] = new Vector3( Random.Range(-100, 100), Random.Range(-100, 100), Random.Range(-100, 100)); } // Instantiate a new stopwatch Stopwatch stopwatch = new Stopwatch(); // Set up our value outside of the for loop just in case there's any // performance hit from declaring it inside the loop. float value; // Test sqrMagnitude on our test vectors stopwatch.Start(); for (int i = 0; i < iterations; i++) { value = testVectors[i].sqrMagnitude; } stopwatch.Stop(); // "Save" the total test time in a variable to output later. double sqrMagnitudeTime = stopwatch.ElapsedMilliseconds; // Make sure to reset/clear the stopwatch befor using it again. stopwatch.Reset(); // Test magnitude on our test vectors stopwatch.Start(); for (int i = 0; i < iterations; i++) { value = testVectors[i].magnitude; } stopwatch.Stop(); double magnitudeTime = stopwatch.ElapsedMilliseconds; stopwatch.Reset(); // Output the test results to the console. Debug.LogFormat( "Magnitude test results:\n" + "total sqrMagnitude time: {0:G}ms\n" + "average sqrMagnitude time: {1:G}ms\n" + "total magnitude time: {2:G}ms\n" + "average magnitude time: {3:G}ms\n", sqrMagnitudeTime, (sqrMagnitudeTime / iterations), magnitudeTime, (magnitudeTime / iterations) ); } |
The code should be self-explanatory. Basically we just set up a bunch of random Vector3s and record the time it takes to do a bunch of iterations of sqrMagnitude and magnitude. Now for the results! On my system (AMD 8350 CPU and Unity 5.3.4) the results are:
Magnitude test results:
total sqrMagnitude time: 14ms
average sqrMagnitude time: 1.4E-05ms
total magnitude time: 35ms
average magnitude time: 3.5E-05ms
So, as expected, magnitude calls are much slower than sqrMagnitude, approximately 3 times slower. However, this is 1 million iterations! In conclusion, although magnitude is definitely slower than square magnitude, you’d have to call it over 70,000 times to see an impact of 1ms. Though I’ll probably still suggest usage of square magnitude, the difference is not as big as what people make of it. Let’s check something else.
Another commonly frowned upon method call is gameObject.GetComponent<T>(). This is considered quite slow and we’re often told avoid doing this in methods that are called frequently, like Update(). But how slow is it exactly? Place the following code into your testing script to find out.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 |
void TestGetComponent() { Stopwatch stopwatch = Stopwatch.StartNew(); for (int i = 0; i < iterations; i++) { Camera.main.GetComponent<AudioListener>().enabled = true; } double getComponentTime = stopwatch.ElapsedMilliseconds; stopwatch.Reset(); stopwatch.Start(); AudioListener al = null; for (int i = 0; i < iterations; i++) { if (i == 0) al = Camera.main.GetComponent<AudioListener>(); if (al != null) al.enabled = true; } double getComponentOnce = stopwatch.ElapsedMilliseconds; stopwatch.Reset(); Debug.LogFormat( "GetComponent test results:\n" + "total GetComponent time: {0:G}ms\n" + "average GetComponent time: {1:G}ms\n" + "total single GetComponent time: {2:G}ms\n" + "average single GetComponent time: {3:G}ms\n", getComponentTime, (getComponentTime / iterations), getComponentOnce, (getComponentOnce / iterations) ); } |
The above code is basically the same concept as the magnitude test method, but here I’m calling GetComponent. Not only do I call GetComponent, but I do a a trivial setting (enable = true) just to make the call relevant. In the comparison test I only call GetComponent once then perform the setting of enable = true on that component repeatedly. The results are as follows:
GetComponent test results:
total GetComponent time: 211ms
average GetComponent time: 0.000211ms
total single GetComponent time: 60ms
average single GetComponent time: 6E-05ms
As we would expect, calling GetComponent is indeed pretty slow. Like our comparison of sqrMagnitude and magnitude, GetComponent also seems to be about 3x slower than a single call to GetComponent . What’s a bit unexpected is how slow the loop with the single call to GetComponent is. After some more testing I found that about 50% of the time spent in the second loop is due to the conditional if(al != null). Wow! That’s sort of huge and leads to an important lesson: The results are only as good as the test. So in my test method, there is a flaw that skews the results. However, I usually check if a GameObject or component is null before accessing it to prevent those lovely null reference exception errors. Maybe I should be doing try-catches instead? It’s another test for another day. In conclusion: GetComponent is pretty slow, don’t use it in Update methods and cache it whenever possible. How slow? It’ll take about 17,000 calls per frame to see a 1ms impact. But when we’re trying to get over 60fps we only get 16ms to spend per frame, so beware!
As you can see, Stopwatch is extremely useful in testing out your ideas on how to optimize your code. However, imagine the pain of setting this up for 15 methods over 100 classes. Ouch! So let’s explore a simpler and more valuable class for diagnostics.
DiagnosticsRecorder Class
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 |
using UnityEngine; using System.Collections; using NG.Diagnostics; public class TestsWithDr : MonoBehaviour { public int iterations = 1000000; private DiagnosticRecorder dr = new DiagnosticRecorder(); void Start() { StartCoroutine(TestRoutine()); } IEnumerator TestRoutine() { // Switch between the two tests // and do a WaitforEndOFrame so as to not lock up Unity for too long. for (int i = 0; i < 10; i++) { if (i % 2 == 0) TestMagnitude(); else TestGetComponent(); yield return new WaitForEndOfFrame(); } // Call our results. Debug.Log(dr.ToString()); } void TestMagnitude() { // fill up an array of vectors to test on Vector3[] testVectors = new Vector3[iterations]; for (int i = 0; i < iterations; i++) { testVectors[i] = new Vector3( Random.Range(-100, 100), Random.Range(-100, 100), Random.Range(-100, 100)); } // Set up our value outside of the for loop just in case there's any // performance hit from declaring it inside the loop. float value; // Test sqrMagnitude on our test vectors dr.StartTimer("Square Magnitude"); for (int i = 0; i < iterations; i++) { value = testVectors[i].sqrMagnitude; } dr.StopTimer("Square Magnitude"); // Test magnitude on our test vectors dr.StartTimer("Test Magnitude"); for (int i = 0; i < iterations; i++) { value = testVectors[i].magnitude; } dr.StopTimer("Test Magnitude"); } void TestGetComponent() { dr.StartTimer("GetComponent repeat"); for (int i = 0; i < iterations; i++) { Camera.main.GetComponent<AudioListener>().enabled = true; } dr.StopTimer("GetComponent repeat"); dr.StartTimer("GetComponent once"); AudioListener al = null; for (int i = 0; i < iterations; i++) { if (i == 0) al = Camera.main.GetComponent<AudioListener>(); al.enabled = true; } dr.StopTimer("GetComponent once"); } } |
Timers (ms)
Square Magnitude
Last: 17 Min: 14 Max: 17 Avg: 14.8 Total: 74
Test Magnitude
Last: 36 Min: 36 Max: 37 Avg: 36.2 Total: 181
GetComponent repeat
Last: 196 Min: 190 Max: 196 Avg: 192.4 Total: 962
GetComponent once
Last: 27 Min: 26 Max: 27 Avg: 26.8 Total: 134
As you can see they are mostly the same as the original tests, with some variance of course. But so much less code setup to run the timers and get the results.
Your challenge, should you accept it, is to show us some results for method calls that are commonly frowned upon. Are for loops actually faster than for each? Are string comparisons slower than int comparisons? Try out your ideas for optimizing your code and share what you find out.
As always, thanks for reading!
Stopwatch image courtesy of Designed by Freepik
