The Profiler is just one tool at our disposal. Sometimes, we may want to perform customized profiling and logging of our code. Maybe we're not confident that the Unity Profiler is giving us the right answer, maybe we consider its overhead cost too great, or maybe we just like having complete control of every single aspect of our application. Whatever our motivations, knowing some techniques to perform an independent analysis of our code is a useful skill to have. It's unlikely we'll only be working with Unity for the entirety of our game development careers, after all.
Profiling tools are generally very complex, so it's unlikely we would be able to generate a comparable solution on our own within a reasonable time frame. When it comes to testing CPU usage, all we should really need is an accurate timing system, a fast, low-cost way of logging that information, and some piece of code to test against. It just so happens that the .NET library (or, technically, the Mono framework) comes with a Stopwatch class under the System.Diagnostics namespace. We can stop and start a Stopwatch object at any time, and we can easily acquire a measure of how much time has passed since the Stopwatch was started.
Unfortunately, this class is not perfectly accurate; it is accurate only to milliseconds, or tenths of a millisecond, at best. Counting high-precision real time with a CPU clock can be a surprisingly difficult task when we start to get into it; so, in order to avoid a detailed discussion of the topic, we should try to find a way for the Stopwatch class to satisfy our needs.
If precision is important, then one effective way to increase it is by running the same test multiple times. Assuming that the test code block is both easily repeatable and not exceptionally long, we should be able to run thousands, or even millions of tests within a reasonable time frame and then divide the total elapsed time by the number of tests we just performed to get a more accurate time for a single test.
Before we get obsessed with the topic of high precision, we should first ask ourselves if we even need it. Most games expect to run at 30 FPS or 60 FPS, which means that they only have around 33 milliseconds or 16 milliseconds, respectively, to compute everything for the entire frame. So, hypothetically, if we need to bring only the performance of a particular code block under ten milliseconds, then repeating the test thousands of times to get microsecond precision is too many orders of magnitude away from the target to be worthwhile.
The following is a class definition for a custom timer that uses a Stopwatch to count time for a given number of tests:
using System;
using System.Diagnostics;
public class CustomTimer : IDisposable {
private string _timerName;
private int _numTests;
private Stopwatch _watch;
// give the timer a name, and a count of the
// number of tests we're running
public CustomTimer(string timerName, int numTests) {
_timerName = timerName;
_numTests = numTests;
if (_numTests <= 0) {
_numTests = 1;
}
_watch = Stopwatch.StartNew();
}
// automatically called when the 'using()' block ends
public void Dispose() {
_watch.Stop();
float ms = _watch.ElapsedMilliseconds;
UnityEngine.Debug.Log(string.Format("{0} finished: {1:0.00} " +
"milliseconds total, {2:0.000000} milliseconds per-test " +
"for {3} tests", _timerName, ms, ms / _numTests, _numTests));
}
}
Adding an underscore before member variable names is a common and useful way of distinguishing a class' member variables (also known as fields) from a method's arguments and local variables.
The following is an example of the CustomTimer class usage:
const int numTests = 1000;
using (new CustomTimer("My Test", numTests)) {
for(int i = 0; i < numTests; ++i) {
TestFunction();
}
} // the timer's Dispose() method is automatically called here
There are three things to note when using this approach. Firstly, we are only making an average of multiple method invocations. If processing time varies enormously between invocations, then that will not be well represented in the final average.
Secondly, if memory access is common, then repeatedly requesting the same blocks of memory will result in an artificially higher cache hit rate (where the CPU can find data in memory very quickly because it's accessed the same region recently), which will bring the average time down when compared to a typical invocation.
Thirdly, the effects of Just-In-Time (JIT) compilation will be effectively hidden for similarly artificial reasons, as it only affects the first invocation of the method. JIT compilation is a .NET feature that will be covered in more detail in Chapter 8, Masterful Memory Management.
The using block is typically used to safely ensure that unmanaged resources are properly destroyed when they go out of scope. When the using block ends, it will automatically invoke the object's Dispose() method to handle any cleanup operations. In order to achieve this, the object must implement the IDisposable interface, which forces it to define the Dispose() method.
However, the same language feature can be used to create a distinct code block, which creates a short-term object, which then automatically processes something useful when the code block ends, which is how it is being used in the preceding code block.
Note that the using block should not be confused with the using statement, which is used at the start of a script file to pull in additional namespaces. It's extremely ironic that the keyword for managing namespaces in C# has a naming conflict with another keyword.
As a result, the using block and the CustomTimer class give us a clean way of wrapping our test code in a way that makes it obvious when and where it is being used.
Another concern to worry about is application warm-up time. Unity has a significant startup cost when a Scene begins, given the amount of data that needs to be loaded from disk, the initialization of complex subsystems, such as the Physics and Rendering Systems, and the number of calls to various Awake() and Start() callbacks that need to be resolved before anything else can happen. This early overhead might only last a second, but that can have a significant effect on the results of our testing if the code is also executed during this early initialization period. This makes it crucial that if we want an accurate test, then any runtime testing should begin only after the application has reached a steady state.
Ideally, we would be able to execute the target code block in its own Scene after its initialization has completed. This is not always possible, so as a backup plan, we could wrap the target code block in an Input.GetKeyDown() check in order to assume control over when it is invoked. For example, the following code will execute our test method only when the spacebar is pressed:
if (Input.GetKeyDown(KeyCode.Space)) {
const int numTests = 1000;
using (new CustomTimer("Controlled Test", numTests)) {
for(int i = 0; i < numTests; ++i) {
TestFunction();
}
}
}
As mentioned previously, Unity's Console window logging mechanism is prohibitively expensive. As a result, we should try not to use these logging methods in the middle of a profiling test (or during gameplay, for that matter). If we find ourselves absolutely needing detailed profiling data that prints out lots of individual messages (such as performing a timing test on a loop to figure out which iteration is costing more time than the rest), then it would be wiser to cache the logging data and print it all out at the end, as the CustomTimer class does. This will reduce runtime overhead, at the cost of some memory consumption. The alternative is that many milliseconds are lost to printing each Debug.Log() message in the middle of the test, which pollutes the results.
The CustomTimer class also makes use of string.Format(). This will be covered in more detail in Chapter 8, Masterful Memory Management, but the short explanation is that this method is used because generating custom string object using the + operator (for example, code such as Debug.Log("Test: " + output);) can result in a surprisingly large amount of memory allocations, which attracts the attention of the Garbage Collector. Doing otherwise would conflict with our goal of achieving accurate timing and analysis and should be avoided.
