Code Optimization in Unity : Part 2

“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 = "\n\nTaking 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 = "\n\n";
			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 \n";

			// 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 += "\n";
				
			// 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 += "\n";

				// 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!

About these ads

23 Responses to “Code Optimization in Unity : Part 2”

  1. Thank you very much for these optimization articles. Such a great resource for someone like me who is coding outside my comfort zone. (^_^)

  2. When using Unity Pro, have you considered using Unity’s built-in function Profiler.BeginSample() and Profiler.EndSample() which basically does the same thing, but integrated with the Profiler? (And conditionally compiled away in non-development builds so it has zero overhead.)

    http://unity3d.com/support/documentation/ScriptReference/Profiler.BeginSample.html

    I know your solution works for non-Pro too, but the BeginSample / EndSample is worth knowing for those who do have access to Pro. :)

  3. Your Blog is amazing. Thank you for all of the great articles. Your recent topics on optimization have been especially relevant to me.

    I am currently near completion on my first IOS game. I would love to use your profiler, as the game runs slow on older generation IOS devices.

    Unfortunately, I can not get the profiler working. My game is written in JavaScript and I have made sure to place the scripts in the proper compilation order, as you stated. When the CodeProfiler.cs script compiles first, I receive 59 syntax errors starting with “Unexpected symbol “&” in class, struct or interface member declaration. The rest of the errors read about the same.

    I am sure that I am making a simple mistake, but I am out of ideas. This is my first time using C#.

    Any insight you could give me would be greatly appreciated. Thank you in advance. I am looking forward to part three of your optimization articles.

    • Apologies! At some point since I published the post the quote characters (and some other symbols) seem to have been converted to their HTML Entity codes (which look like this: " ).

      Not sure how this happened, but I’ve fixed it now. Let me know if you have any other problems using it!

      • Thanks a lot. Your fix got rid of all of those errors. I’m still getting one last CS0246 error (“The type or namespace name `Dictionary’ could not be found. Are you missing a using directive or an assembly reference?”).

        I am trying to learn what that means online. Seems like I have to move a .dll file around or something.

        Thanks again. I can’t be far off now!

  4. That suggests you haven’t included the line: “using System.Collections.Generic;” at the top of your script.

    • I’m sure it’s something simple like that, but not that exactly. I’ve spent a few hours trying different suggestions from online research, but no luck. Thanks anyway.

      • This was a formatting problem when pasting the script into wordpress, it seems it removed the dictionary type definitions (which are inside angle brackets). I have updated the post!

  5. Simurr Says:

    Got the same error Justin did. had to change line 27

    static Dictionary recordings = new Dictionary();

    to

    static Dictionary recordings = new Dictionary();

    to get it to compile. haven’t tested it yet, but it compiled.

    • Simurr Says:

      hrmm… had my code eaten in formatting

      static Dictionary recordings = new Dictionary();
      
    • Simurr Says:

      let me try again…

      static Dictionary>string, ProfilerRecording< recordings = new Dictionary>string, ProfilerRecording<();

      if that didn’t get across, > is greater than, < is less than

      perhaps that is what was supposed to be in the code and it was also eaten by WordPress?

    • Simurr Says:

      good grief

      static Dictionary<string, ProfilerRecording> recordings = new Dictionary<string, ProfilerRecording>();

  6. Yup you guys are right, somewhere along the way the formatting had removed the parts of the code inside angle brackets, presumably because it looks like html tags. I’ve added them back in. Sorry for the confusion!

  7. Note to self: It’s not enough to test my code before pasting into a post, I must then copy it back out and test again to make sure nothing got formatted away!

  8. Great post! Having a good way to measure your performance is a key part of optimizing, but one many people miss!

  9. Wow! thanks for sharing great post! :D Im looking forward to your next post… static Dictionary recordings does this needs to be cleared from the memory? sorry im new to c#, and I’m actually confuse if the allocated variables need to be release from the memory of its automatically release by the GC.

    I been coding obj-c so I was so cautious in memory management, but in c# I’m lost.

  10. The first part is great, it explains things well, I was kinda expecting something in the second part like how to properly use the unity’s profiler and also will all the figures how do you tell which parts is the most critical ones and what is the exceptable execution time for a function, etc…. the second part is like jumping right into the timing, thought that you didnt have enough time to elaborate on it, hope that you would create another post that explains it more clearly how to do optimizations in unity, I’ve done a research and did not get much results in my search to better understand the optimization process.

    (this one IMO is most helpful anyway)
    Cheers,
    J

  11. Thank you! I Had now idea that Time.realtimeSinceStartup worked like that.
    I’m making an editor window for it:

    Now just need to get sorting put in it.

  12. I’ve just gotten a tweaked version of your CodeProfiler working:

    It’s a singleton that creates its own GameObject when CodeProfiler.Begin(“blah”) is first called. It uses Stopwatch to check elapsed time (didn’t even know about Stopwatch until I read your article), and uses a StringBuilder instead of string concatenation. It also uses a Stack to keep track of Begin() End() pairs, so the End() call doesn’t need the id of the timer.

    Ironically, it includes its own premature optimizations. You can optionally use a coroutine instead of the Update function. This appears to be about 1/10000 of a second faster.

    One issue I’ve seen is that if code executes in under 1 millisecond the record’s totalMilliseconds will be 0. But if code is executing in under 1 millisecond you probably shouldn’t be profiling it anyway.

  13. [...] avez la version indie et vous aimeriez bien avoir le Profiler. Qu’à celà ne tienne, Robotduck vous propose sa solution multiplateforme qui vous affichera les performances de tous vos [...]

  14. [...] avez la version indie et vous aimeriez bien avoir le Profiler. Qu’à celà ne tienne, Robotduck vous propose sa solution multiplateforme qui vous affichera les performances de tous vos [...]

  15. Just what I was looking for – even DateTime.Now.Ticks or Time.realtimeSinceStartup would have done me, since I know this exists in other languages but couldn’t find it for Unity until I read your post – but I’m definitely using your class :)

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 42 other followers

%d bloggers like this: