“By measurement to knowledge”

So, in part 1 we saw a few examples of the output from the Profiler window in Unity Pro. If you have Pro, this built-in profiler can be incredibly useful in determining whether your code is taking up a significant amount of time, and if so, which scripts and functions in particular are responsible. There are also other professional code profilers available for other development environments, such as Red Gate’s “ANTS” which will literally give you a speed recording for every line of code in your project. These types of tools are invaluable if you have the budget for them, but many don’t have access to such tools, particularly beginners and budding indie developers. However, all is not lost – it’s actually possible to measure the speed of your own code within the code itself.

In a nutshell, you can achieve this by simply recording the time before and after the code is executed. In practice there are a few more hurdles involved in getting sensible and useful recordings which I will talk through over the course of this post, however this is the fundamental concept – so the first thing you need to know is how to record time.

I’m aware that my previous post attracted the attention of some non-Unity readers, I will try to make as much of this post relevant to all languages as possible, however it will remain largely Unity-centric!

Unity provides you with the Time class for dealing with time, and pretty much all languages have the equivalent of a “current time” system property. In regular C# (in or outside of Unity) you can use DateTime.Now.Ticks, and in Flash’s Actionscript, there’s getTimer(). The concepts from here on are fairly simple so you should be able to adapt them to any language of your choice.

Before we get started though, it’s important to know one thing about your time variable before you use it – whether it can return a changing value when called multiple times during the execution of a function. In Unity, the most commonly used time properties, “Time.deltaTime” and “Time.time” do not update over the duration of a function. Instead, they only get a new value each frame, and they keep that value until the entire frame has completed. Because of this, they are useless for profiling code within a function!

For example, if we wanted to measure the contents of our Player’s “Update()” function, we might try something like this, where we record the time before and after the contents of the Update() function, and compare the difference:

void Update() { float startTime = Time.time; // (Some code here which you want to measure) float endTime = Time.time; float timeElapsed = (endTime-startTime); }

With the above example, startTime and endTime will always have the same value, because Unity’s Time.time does not change while the function is being executed – which is obviously no use at all because the measured time difference would always equal zero! Instead however, you can use the lesser-known property on the same class: Time.realtimeSinceStartup. This is very useful because not only does it update during the course of a function running, but it is also not affected by your current timescale setting, so it won’t be affected if you’re using slow-motion or other time-stretching effects in your game. If you’re working in something other than Unity 3D, make sure your time function has this important feature!

So to make a measurement, we record the realtimeSinceStartup value before and after the code, and simply subtract the latter from the former like this:

void Update() { float startTime = Time.realtimeSinceStartup; // (Some code here which you want to measure) float endTime = Time.realtimeSinceStartup; float timeElapsed = (endTime-startTime); }

Now any single timing of the same code is likely to fluctuate a certain amount, and the smaller the timescale that you’re trying to measure, the larger the fluctuations will be in comparison. Depending on what you’re measuring, this amount of time elapsed may be very very small – even down to hundredths of a millisecond or less – so to get a sensible reading it’s best to record the same action lots of times and average the result.

One way to do this would be to simply use a tight “for” or “while” loop which repeats the enclosed code a few thousand times. This is fine if you want to quickly test a certain section of code in isolation but it’s not so useful when trying to profile your game while it’s being played in a normal way (eg, baddies moving, bullets flying around, etc). So, to expand on the example that I’ve started building above, to accumulate and average the recordings of our Update function over a larger time period, we could do something like this, which records the time taken to perform the function 500 times (once per frame), and then outputs the result to Unity’s console window:

int numRecordings = 500; // number of recordings to make float timeRecorded = 0; // total accumulated time int recordingNum = 0; // current recording number void Update() { float startTime = Time.realtimeSinceStartup; // (the code here that you want to measure) float endTime = Time.realtimeSinceStartup; // this section now accumulates the time, and // computes the average once we hit the required // number of recordings: float timeElapsed = (endTime-startTime); recordingNum++; timeRecorded += timeElapsed; if (recordingNum == numRecordings) { // calculate and display the average time float averageTime = timeRecorded/numRecordings; Debug.Log("Avg Time: "+averageTime+" seconds"); // and finally, reset & repeat: recordingNum = 0; timeRecording = 0; } }

Now we’re getting somewhere. With this in place, we can get a good idea of the time taken to execute any block of code that we might care about. Note that it doesn’t have to be your Update function that is measured. You might be interested in, for example, how long it’s taking a particular single line your Instantiate function to execute. In this case, you could put the “startTime” and “endTime” recordings either side of this single line, like this:

float startTime = Time.realtimeSinceStartup; Instantiate(enemyPrefab, pos, rot); float endTime = Time.realtimeSinceStartup;

The main problem with the method above is that while it works, it would be impractical, messy and confusing to duplicate all this code to each and every Update function, and to every other part of your program that you want to measure in your project. Aren’t you thinking it would be so much better if we could encapsulate the system used here into a simple friendly portable class? So am I!

The next example does just this. It’s a class I have written called “CodeProfiler” which is designed to be placed on an empty GameObject in your scene. For those working in a different engine and unfamiliar with Unity’s conventions, this basically means that the class will be automatically instantiated, and it receives Start() and Update() events automatically from the Unity engine while playing. The reason it requires these events is so that it can accumulate and average the overall frame rate which is then used as a comparison with your own chosen measurements. It has two public functions, “Begin” and “End” which you can call at the beginning and end of any particular code you want to profile. These functions are static, which means you can call them directly just by using the class name as a prefix – so there is no need to find references to the profiler GameObject or script instance.

The full code for the CodeProfiler class is included at the bottom of this post, but first I’m going to explain how to use it and how it works. The script is written in C#, but you can call it from both C# scripts and scripts written in Unity’s Javascript if you place it the appropriate folder.

In order to differentiate between the various parts of code that you want to measure, you pass an ID to these Begin and End functions – which is nothing more complex than a name, as a string parameter. You are essentially just picking a label to name each different reading that is taking place in your code. For example, if – in your game – you wanted to measure the speed of each your Player’s, Enemy’s and Bullet’s update functions, you could add the Begin and End functions in your code like this:

// Player Script: void Update() { CodeProfiler.Begin("Player:Update"); // (The rest of your Player update code here) CodeProfiler.End("Player:Update"); }

// Enemy Script: void Update() { CodeProfiler.Begin("Enemy:Update"); // (The rest of your Enemy update code here) CodeProfiler.End("Enemy:Update"); }

// Bullet Script: void Update() { CodeProfiler.Begin("Bullet:Update"); // (The rest of your Bullet update code here) CodeProfiler.End("Bullet:Update"); }

So you can see in the above examples, I’ve picked the labels “Player:Update”, “Enemy:Update”, and “Bullet:Update” for my 3 entries in the code profiler. I’ve chosen a convention of “ClassName:FunctionName” but you could use whatever you like as long as each entry is unique. Now all that remains to do is to make sure that my CodeProfiler script is actually placed on an empty gameobject in the scene, and hit Play in the Unity editor.

The CodeProfiler updates its results every 5 seconds (the results are the average of the readings over those five seconds), and they look like this:

Avg frame time: 19.6ms, 51 fps Total MS/frame Calls/frame MS/call Label 0.467% 0.092ms 1.000 0.0933ms Player:Update 6.429% 1.260ms 6.000 0.2101ms Enemy:Update 4.036% 0.791ms 16.480 0.0480ms Bullet:Update

The first line gives you the average time elapsed per frame, and the corresponding “frames per second” that this results in. This includes everything – rendering, physics, scripts, etc.

Underneath are your individual readings for each “ID” that you used when measuring your code. In this example, the three IDs I mentioned earlier are present. Each entry has the following figures:

“Total” shows the percentage time taken of the whole frame time.

“MS/Frame” shows the amount of milliseconds spent on this task per frame. This is the sum if there were multiple calls (for example if multiple enemies all recorded their Update times under the same ID).

“Calls/Frame” tells you the average number of times this reading was measured per frame. In my example, for the player it’s 1. For the Enemy, it’s 6, because there were 6 enemies present during the test all recording their time against the same ID. For the Bullets it’s the same situation, but this time it’s not a whole number, because the number of bullets present varied over the duration of the 5 seconds measured, but it averaged about 16.

And finally, “MS/call” tells you how long each individual call took, on average. This is basically MS/Frame divided by Calls/frame.

These statistics give you some means to assess what impact your scripts are having in terms of your game’s overall performance. A game that is having performance trouble might come out looking something like this:

Avg frame time: 110.1ms, 9.1 fps Total MS/frame Calls/fra MS/call Label 0.285% 0.314ms 5.500 0.0570ms Player:FixedUpdate 79.270% 87.275ms 107.022 0.8155ms Bullet:Update 0.004% 0.004ms 1.000 0.0045ms Level:Update 5.604% 6.170ms 56.283 0.1096ms Enemy:FixedUpdate 0.900% 0.991ms 2.413 0.4107ms Enemy:FireBullet

Uh-oh – there are serious problems here: the game is running at around nine frames per second. My CodeProfiler doesn’t measure the time taken for physics and rendering, but it does measure the total frame time, and we can see from the results that the bullet’s Update function is by far dominating the total time taken per frame. The bullet’s update function is also being called many times – an average of 107 bullets per frame, each having its Update function called every frame, for this particular 5 second time-slice. This wouldn’t be so bad if their individual execution time was very fast (which it should be, for a bullet!), however an average of 0.8155ms per call is a long time, so there is clearly something wrong within that function which – when multiplied by every active bullet – causes a huge slowdown.

You might also notice at the bottom of the list that I added an entry for “Enemy:FireBullet”, which is a sub-section of the enemy’s code which is responsible for instantiating and calculating the trajectory for each individual bullet, to see whether that was the problem. I did that by simply adding another call to CodeProfiler.Begin() and CodeProfiler.End() around just that section of code, and choosing the label “Enemy:FireBullet”. The results show that approximately 2.4 bullets were fired per frame, but the code for this only totalled 0.9% of the frame time, so this clearly isn’t the cause of the poor framerate.

So from this example we can clearly see the problem lies within the bullet’s Update function, and it’s not the instantiation of the bullet. If this was your project, you could narrow it down further by adding Begin() and End() calls around smaller parts within the offending code until you can identify what exactly is the major time-consumer in there. It’s very common for for the most time to be taken up by very few or even a single element of your code.

If all your code readings add up to a small portion of the total frame time, but your game is still running slowly, you know the major costs are elsewhere – i.e. graphics and/or physics.

How does the CodeProfiler work? Basically it uses a type of collection called a “Dictionary” to store multiple recordings. A dictionary is a bit like an array, however it stores key/value pairs rather than a simple list of values. (Read more about Dictionaries and other types of arrays and collections in Unity here). The “key” is the string ID that you choose, and the “value” is an instance of the accompanying class “ProfileRecording”. This ProfileRecording class contains just a few variables and functions which allow it to act as a simple stopwatch. The CodeProfiler class creates a new ProfileRecording instance each time it encounters an ID which isn’t yet present in the dictionary, and adds the instance to the dictionary under the given ID. The CodeProfiler uses Unity’s OnGUI functions to display the text on-screen each frame, and each time the “nextOutputTime” is reached, the results are calculated and the text displayed is updated.

When you call the Begin and End function function with an ID, the CodeProfiler looks up the ProfileRecording associated with that ID in the dictionary, and calls the corresponding Start or Stop function on it. Each individial ProfileRecording instance in the dictionary keeps track of how much time it has accumulated. The ProfileRecording class has a Reset function to allow it to begin a fresh recording when required, and also generates an error if the Start and Stop functions are called out-of-order.

(I’m aware that .Net actually provides a “Stopwatch” class with much of the same functionality, however I included this simple custom class instead for the sake of learning and clarity so you can see exactly how this is being achieved, and how the concepts progress onwards from the simpler examples above. Out of curiosity I tested the script using .Net’s Stopwatch class in place of my own, and happily it came out with near-identical results!)

Without further ado, here’s the CodeProfiler class:

using UnityEngine; using System.Collections.Generic; // Simple code profiler class for Unity projects // @robotduck 2011 // // usage: place on an empty gameobject in your scene // then insert calls to CodeProfiler.Begin(id) and // CodeProfiler.End(id) around the section you want to profile // // "id" should be string, unique to each code portion that you're timing // for example, in your enemy update function, you might have: // // function Update { // CodeProfiler.Begin("Enemy:Update"); // <the rest of your enemy update code here> // CodeProfiler.End("Enemy:Update"); // } // // the Begin id and the End id must match exactly. public class CodeProfiler : MonoBehaviour { float startTime = 0; float nextOutputTime = 5; int numFrames = 0; static Dictionary<string, ProfilerRecording> recordings = new Dictionary<string, ProfilerRecording>(); string displayText; Rect displayRect = new Rect(10,10,460,300); void Awake() { startTime = Time.time; displayText = "



Taking initial readings..."; } void OnGUI() { GUI.Box(displayRect,"Code Profiler"); GUI.Label(displayRect, displayText); } public static void Begin(string id) { // create a new recording if not present in the list if (!recordings.ContainsKey(id)) { recordings[id] = new ProfilerRecording(id); } recordings[id].Start(); } public static void End(string id) { recordings[id].Stop(); } void Update() { numFrames++; if (Time.time > nextOutputTime) { // time to display the results // column width for text display int colWidth = 10; // the overall frame time and frames per second: displayText = "



"; float totalMS = (Time.time-startTime)*1000; float avgMS = (totalMS/numFrames); float fps = (1000/(totalMS/numFrames)); displayText += "Avg frame time: "; displayText += avgMS.ToString("0.#")+"ms, "; displayText += fps.ToString("0.#")+" fps

"; // the column titles for the individual recordings: displayText += "Total".PadRight(colWidth); displayText += "MS/frame".PadRight(colWidth); displayText += "Calls/fra".PadRight(colWidth); displayText += "MS/call".PadRight(colWidth); displayText += "Label"; displayText += "

"; // now we loop through each individual recording foreach(var entry in recordings) { // Each "entry" is a key-value pair where the string ID // is the key, and the recording instance is the value: ProfilerRecording recording = entry.Value; // calculate the statistics for this recording: float recordedMS = (recording.Seconds * 1000); float percent = (recordedMS*100) / totalMS; float msPerFrame = recordedMS / numFrames; float msPerCall = recordedMS / recording.Count; float timesPerFrame = recording.Count / (float)numFrames; // add the stats to the display text displayText += (percent.ToString("0.000")+"%").PadRight(colWidth); displayText += (msPerFrame.ToString("0.000")+"ms").PadRight(colWidth); displayText += (timesPerFrame.ToString("0.000")).PadRight(colWidth); displayText += (msPerCall.ToString("0.0000")+"ms").PadRight(colWidth); displayText += (recording.id); displayText += "

"; // and reset the recording recording.Reset(); } Debug.Log(displayText); // reset & schedule the next time to display results: numFrames = 0; startTime = Time.time; nextOutputTime = Time.time + 5; } } } // this is the ProfileRecording class which is simply included // directly after the CodeProfiler class in the same file. // The ProfileRecording class is basically for "internal use // only" - you don't need to place it on a gameobject or interact // with it in any way yourself, it's purely used by the // CodeProfiler to do its job. class ProfilerRecording { // this class accumulates time for a single recording int count = 0; float startTime = 0; float accumulatedTime = 0; bool started = false; public string id; public ProfilerRecording(string id) { this.id = id; } public void Start() { if (started) { BalanceError(); } count++; started = true; startTime = Time.realtimeSinceStartup; // done last } public void Stop() { float endTime = Time.realtimeSinceStartup; // done first if (!started) { BalanceError(); } started = false; float elapsedTime = (endTime-startTime); accumulatedTime += elapsedTime; } public void Reset() { accumulatedTime = 0; count = 0; started = false; } void BalanceError() { // this lets you know if you've accidentally // used the begin/end functions out of order Debug.LogError("ProfilerRecording start/stops not balanced for '"+id+"'"); } public float Seconds { get { return accumulatedTime; } } public int Count { get { return count; } } }

Of course this is a simple script and could be vastly improved on. It has significant shortcomings, and does not do a number of things which perhaps it should, such as:

– Sort the results into any particular order

– Deduct the average time taken for an “empty reading”

– Give similar results to Unity Pro’s profiler *

– Graph the results.

– Make you a much-needed cup of tea.

I’ll leave these as an excercise for the reader. May I recommend starting with the last item first.

* Unity’s profiler seems to assign larger times to function calls than those recorded by simply checking the time at the beginning and end of a function – I’m guessing this is because it includes other things such as the time taken for the Unity engine to actually invoke the function (which is done via Reflection for MonoBehaviour events like Update).

In part 3 of this series, I’ll be examining the performance of various common code structures and techniques in Unity and shedding light on some faster alternatives, as well as exposing the “voodoo” optimisation techniques that some of us use just-in-case, but which actually provide little or no benefit!