{"id":7,"date":"2016-10-05T19:18:00","date_gmt":"2016-10-05T23:18:00","guid":{"rendered":""},"modified":"2018-12-18T09:07:16","modified_gmt":"2018-12-18T14:07:16","slug":"diagnostics","status":"publish","type":"post","link":"https:\/\/naplandgames.com\/blog\/2016\/10\/05\/diagnostics\/","title":{"rendered":"Diagnostics"},"content":{"rendered":"
\"Unity3DEver 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 <\/span>provided by the System.Diagnostics<\/span> 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<\/span>). Let’s begin!<\/div>\n

Simple Usage of Stopwatch<\/h3>\n

We’re often told that such and such method is slow and should be avoided at all costs. Two common ones are using Vector <\/span>magnitudes vs. square magnitudes and repeated calls to Unity’s GetComponent()<\/span> method. Let’s start off by testing the difference between Vector3.magnitude<\/span> vs.<\/span> Vector3.sqrMagnitude<\/span>. Place your bets now on which will be faster and what the time difference is!<\/p>\n

First simply create a MonoBehaviour <\/span>derived script with just an empty Start()<\/span> method. Then pop in the following method.<\/p>\n

\/\/ Make sure to use this in your namespace declarations\r\nusing System.Diagnostics;\r\n\/\/ This is needed because System.Diagnostics also contains a Debug class\r\nusing Debug = UnityEngine.Debug;\r\n \r\n\/\/ We'll need a lot of iterations to get any result for this.\r\npublic int iterations = 1000000;\r\n \r\nvoid TestMagnitude()\r\n{\r\n    \/\/ Fill up an array of vectors to test on.\r\n    Vector3[] testVectors = new Vector3[iterations];\r\n    for (int i = 0; i < iterations; i++)\r\n    {\r\n        testVectors[i] =\r\n            new Vector3(\r\n                Random.Range(-100, 100),\r\n                Random.Range(-100, 100),\r\n                Random.Range(-100, 100));\r\n    }\r\n \r\n    \/\/ Instantiate a new stopwatch\r\n    Stopwatch stopwatch = new Stopwatch();\r\n \r\n    \/\/ Set up our value outside of the for loop just in case there's any\r\n    \/\/ performance hit from declaring it inside the loop.\r\n    float value;\r\n \r\n    \/\/ Test sqrMagnitude on our test vectors\r\n    stopwatch.Start();\r\n    for (int i = 0; i < iterations; i++)\r\n    {\r\n        value = testVectors[i].sqrMagnitude;\r\n    }\r\n    stopwatch.Stop();\r\n \r\n    \/\/ \"Save\" the total test time in a variable to output later.\r\n    double sqrMagnitudeTime = stopwatch.ElapsedMilliseconds;\r\n    \/\/ Make sure to reset\/clear the stopwatch befor using it again.\r\n    stopwatch.Reset();\r\n \r\n    \/\/ Test magnitude on our test vectors\r\n    stopwatch.Start();\r\n    for (int i = 0; i < iterations; i++)\r\n    {\r\n        value = testVectors[i].magnitude;\r\n    }\r\n    stopwatch.Stop();\r\n \r\n    double magnitudeTime = stopwatch.ElapsedMilliseconds;\r\n    stopwatch.Reset();\r\n \r\n    \/\/ Output the test results to the console.\r\n    Debug.LogFormat(\r\n        \"Magnitude test results:\\n\" +\r\n        \"total sqrMagnitude time: {0:G}ms\\n\" +\r\n        \"average sqrMagnitude time: {1:G}ms\\n\" +\r\n        \"total magnitude time: {2:G}ms\\n\" +\r\n        \"average magnitude time: {3:G}ms\\n\",\r\n        sqrMagnitudeTime,\r\n        (sqrMagnitudeTime \/ iterations),\r\n        magnitudeTime,\r\n        (magnitudeTime \/ iterations)\r\n        );\r\n}<\/pre>\n
 <\/p>\n
The code should be self-explanatory. Basically we just set up a bunch of random Vector3<\/span>s 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:
\nMagnitude test results:<\/span>
\ntotal sqrMagnitude time: 14ms<\/span>
\naverage sqrMagnitude time: 1.4E-05ms<\/span>
\ntotal magnitude time: 35ms<\/span>
\naverage magnitude time: 3.5E-05ms<\/span><\/p>\n
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.<\/p>\n
Another commonly frowned upon method call is gameObject.GetComponent<T>()<\/span>. This is considered quite slow and we’re often told avoid doing this in methods that are called frequently, like Update()<\/span>. But how slow is it exactly? Place the following code into your testing script to find out.<\/p>\n
void TestGetComponent()\r\n{\r\n    Stopwatch stopwatch = Stopwatch.StartNew();\r\n       \r\n    for (int i = 0; i < iterations; i++)\r\n    {\r\n        Camera.main.GetComponent<AudioListener>().enabled = true;\r\n    }\r\n       \r\n    double getComponentTime = stopwatch.ElapsedMilliseconds;\r\n    stopwatch.Reset();\r\n \r\n    stopwatch.Start();\r\n    AudioListener al = null;\r\n    for (int i = 0; i < iterations; i++)\r\n    {\r\n        if (i == 0)\r\n            al = Camera.main.GetComponent<AudioListener>();\r\n \r\n        if (al != null)\r\n            al.enabled = true;\r\n    }\r\n    double getComponentOnce = stopwatch.ElapsedMilliseconds;\r\n    stopwatch.Reset();\r\n \r\n    Debug.LogFormat(\r\n        \"GetComponent test results:\\n\" +\r\n        \"total GetComponent time: {0:G}ms\\n\" +\r\n        \"average GetComponent time: {1:G}ms\\n\" +\r\n        \"total single GetComponent time: {2:G}ms\\n\" +\r\n        \"average single GetComponent time: {3:G}ms\\n\",\r\n        getComponentTime,\r\n        (getComponentTime \/ iterations),\r\n        getComponentOnce,\r\n        (getComponentOnce \/ iterations)\r\n        );\r\n}<\/pre>\n
 <\/p>\n
The above code is basically the same concept as the magnitude test method, but here I’m calling\u00a0GetComponent<\/span>. Not only do I call\u00a0GetComponent<\/span>, but I do a a trivial setting (enable = true) just to make the call relevant. In the comparison test I only call\u00a0GetComponent<\/span>\u00a0once then perform the setting of enable = true on that component repeatedly. The results are as follows:
\nGetComponent test results:<\/span>
\ntotal GetComponent time: 211ms<\/span>
\naverage GetComponent time: 0.000211ms<\/span>
\ntotal single GetComponent time: 60ms<\/span>
\naverage single GetComponent time: 6E-05ms<\/span><\/p>\n
As we would expect, calling\u00a0GetComponent\u00a0<\/span>is indeed pretty slow. Like our comparison of sqrMagnitude and magnitude,\u00a0GetComponent\u00a0<\/span>also seems to be about 3x slower than a single call to\u00a0GetComponent\u00a0<\/span>. What’s a bit unexpected is how slow the loop with the single call to\u00a0GetComponent\u00a0<\/span>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 <\/span>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!<\/p>\n
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.<\/p>\n
DiagnosticsRecorder Class<\/h3>\n
The DiagnosticsRecorder<\/span> class was made to ease my pain of checking the performance of multiple methods in a class. It also provides more valuable statistics such as min, max, and average. I also find myself in need of a simple counter class to tell me how often calls to a particular section of code are happening. So I added in a counter recorder that works similarly to the stopwatch recorder. One caveat though – these classes do have a cost! The\u00a0DiagnosticsRecorder<\/span>\u00a0class makes use of Dictionaries and key lookups (Dictionary.ContainsKey()<\/span>) which can be slow if the dictionary is large. So best to be cautious of how many diagnostics to run in a single instance of\u00a0DiagnosticsRecorder<\/span>. Also, remember to keep in mind that tests are best as relative comparisons. So look for your slow points in comparison to other tests.<\/div>\n
<\/div>\n
On to the code! I’m not going to embed the entire code here, but instead simply provide a link to each of the three classes.<\/div>\n
DiagnosticsRecorder.cs<\/a><\/div>\n
StopwatchRecorder.cs<\/a><\/div>\n
Counter.cs<\/a><\/div>\n
<\/div>\n
The\u00a0DiagnosticsRecorder<\/span>\u00a0class requires both StopwatchRecorder<\/span> and\u00a0Counter<\/span>, but the other two can stand on their own. The code is documented so it should be pretty self-explanatory, but I’ll talk a bit about the classes and how to use them.<\/div>\n
<\/div>\n
The\u00a0StopwatchRecorder<\/span>\u00a0and Counter<\/span> record times and counts respectively. They record these into lists so that they can be summed easily later when you want the test results. If the list overflows then the sums are stored in another list. So you can run these for quite a while without issue.<\/div>\n
<\/div>\n
DiagnosticsRecorder<\/span>\u00a0allows us to name our\u00a0StopwatchRecorders<\/span>\u00a0and\u00a0Counters<\/span>\u00a0so that we have a compact way of recording a bunch of tests and outputting the results.<\/div>\n
<\/div>\n
Let’s take a look at how to use them. Below is the complete code for the two tests we ran earlier, but making use of the\u00a0DiagnosticsRecorder<\/span>\u00a0instead.<\/div>\n
<\/div>\n
using UnityEngine;\r\nusing System.Collections;\r\nusing NG.Diagnostics;\r\npublic class TestsWithDr : MonoBehaviour\r\n{\r\n    public int iterations = 1000000;\r\n    private DiagnosticRecorder dr = new DiagnosticRecorder();\r\n \r\n    void Start()\r\n    {\r\n        StartCoroutine(TestRoutine());\r\n    }\r\n \r\n    IEnumerator TestRoutine()\r\n    {\r\n        \/\/ Switch between the two tests\r\n        \/\/ and do a WaitforEndOFrame so as to not lock up Unity for too long.\r\n        for (int i = 0; i < 10; i++)\r\n        {\r\n            if (i % 2 == 0)\r\n                TestMagnitude();\r\n            else\r\n                TestGetComponent();\r\n \r\n            yield return new WaitForEndOfFrame();\r\n        }\r\n \r\n        \/\/ Call our results.\r\n        Debug.Log(dr.ToString());\r\n    }\r\n \r\n \r\n    void TestMagnitude()\r\n    {\r\n        \/\/ fill up an array of vectors to test on\r\n        Vector3[] testVectors = new Vector3[iterations];\r\n        for (int i = 0; i < iterations; i++)\r\n        {\r\n            testVectors[i] =\r\n                new Vector3(\r\n                    Random.Range(-100, 100),\r\n                    Random.Range(-100, 100),\r\n                    Random.Range(-100, 100));\r\n        }\r\n \r\n        \/\/ Set up our value outside of the for loop just in case there's any\r\n        \/\/ performance hit from declaring it inside the loop.\r\n        float value;\r\n \r\n        \/\/ Test sqrMagnitude on our test vectors\r\n        dr.StartTimer(\"Square Magnitude\");\r\n        for (int i = 0; i < iterations; i++)\r\n        {\r\n            value = testVectors[i].sqrMagnitude;\r\n        }\r\n        dr.StopTimer(\"Square Magnitude\");\r\n \r\n        \/\/ Test magnitude on our test vectors\r\n        dr.StartTimer(\"Test Magnitude\");\r\n        for (int i = 0; i < iterations; i++)\r\n        {\r\n            value = testVectors[i].magnitude;\r\n        }\r\n        dr.StopTimer(\"Test Magnitude\");\r\n    }\r\n \r\n    void TestGetComponent()\r\n    {\r\n        dr.StartTimer(\"GetComponent repeat\");\r\n        for (int i = 0; i < iterations; i++)\r\n        {\r\n            Camera.main.GetComponent<AudioListener>().enabled = true;\r\n        }\r\n        dr.StopTimer(\"GetComponent repeat\");\r\n \r\n        dr.StartTimer(\"GetComponent once\");\r\n        AudioListener al = null;\r\n        for (int i = 0; i < iterations; i++)\r\n        {\r\n            if (i == 0)\r\n                al = Camera.main.GetComponent<AudioListener>();\r\n \r\n            al.enabled = true;\r\n        }\r\n        dr.StopTimer(\"GetComponent once\");\r\n    }\r\n \r\n}\r\n<\/pre>\n
 <\/p>\n
As you may see, the setup per test is a lot more compact and calling the results is a single method call instead of the need to set up string.formats for every test. I run through all of the tests 5 times each to give a nice average instead of a one-off because averages are much more representative. The results I got are as follows:
\nTimers (ms)<\/span>
\nSquare Magnitude<\/span>
\nLast: 17 \u00a0 \u00a0Min: 14 \u00a0 \u00a0Max: 17 \u00a0 \u00a0Avg: 14.8 \u00a0 \u00a0Total: 74<\/span>
\nTest Magnitude<\/span>
\nLast: 36 \u00a0 \u00a0Min: 36 \u00a0 \u00a0Max: 37 \u00a0 \u00a0Avg: 36.2 \u00a0 \u00a0Total: 181<\/span>
\nGetComponent repeat<\/span>
\nLast: 196 \u00a0 \u00a0Min: 190 \u00a0 \u00a0Max: 196 \u00a0 \u00a0Avg: 192.4 \u00a0 \u00a0Total: 962<\/span>
\nGetComponent once<\/span>
\nLast: 27 \u00a0 \u00a0Min: 26 \u00a0 \u00a0Max: 27 \u00a0 \u00a0Avg: 26.8 \u00a0 \u00a0Total: 134<\/span><\/div>\n
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.<\/p>\n
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.<\/p>\n
As always, thanks for reading!<\/p>\n
Stopwatch image courtesy of Designed by Freepik<\/a><\/p>\n
<\/div>\n
<\/path><\/svg><\/i> \"Loading\"<\/p>\n
<\/div>\n","protected":false},"excerpt":{"rendered":"
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…<\/p>\n
Continue readingDiagnostics<\/span><\/a><\/div>\n
<\/div>\n
<\/path><\/svg><\/i> \"Loading\"<\/p>\n
<\/div>\n","protected":false},"author":1,"featured_media":53,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[4],"tags":[9,11,12,10,8,13,7,14],"a3_pvc":{"activated":true,"total_views":35719,"today_views":0},"_links":{"self":[{"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/posts\/7"}],"collection":[{"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/comments?post=7"}],"version-history":[{"count":12,"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/posts\/7\/revisions"}],"predecessor-version":[{"id":320,"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/posts\/7\/revisions\/320"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/media\/53"}],"wp:attachment":[{"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/media?parent=7"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/categories?post=7"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/naplandgames.com\/blog\/wp-json\/wp\/v2\/tags?post=7"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}