Profiling with Stopwatch

Originally posted to Shawn Hargreaves Blog on MSDN, Tuesday, July 7, 2009

A while back I was doing some performance investigation on a Zune game. It was CPU bound, and Remote Performance Monitor said garbage collection was not a significant problem, so I knew this must be a good ole "too much code taking too long to run" CPU performance issue. That meant a sampling profiler was my tool of choice.

Luckily, I had a Windows version of the game, so I fired up the VSTS profiler and recorded a couple of minutes of gameplay. Because I was running a Zune game on a fast PC, I saw 90% of CPU spent in the Game.Tick method, which was just sitting there waiting until it was time for the next frame. That wasn't very interesting, but when I dug into the remaining 10% (which would account for 100% of CPU on the slower Zune device) I easily identified the slowest couple of methods. Task complete.

And then my conscience caught up with me. How can I be sure the things that are slow on Windows are also the reason this game runs too slowly on Zune? They are highly likely to be the same, but I didn't want to risk giving a report back to the game developer, only for it to turn out the Zune bottleneck was somewhere else entirely!

There are no CPU profilers for Xbox or Zune, so the only way to find out was to instrument my code. I started by adding this timer class:

    class Profiler
    {
        public static List<Profiler> AllProfilers = new List<Profiler>();

        string name;
        double elapsedTime;
        Stopwatch stopwatch;
        
        public Profiler(string name)
        {
            this.name = name;
            AllProfilers.Add(this);
        }

        public void Start()
        {
            stopwatch = Stopwatch.StartNew();
        }

        public void Stop()
        {
            elapsedTime += stopwatch.Elapsed.TotalSeconds;
        }

        public void Print(double totalTime)
        {
            Trace.WriteLine(string.Format("{0}: {1:F2}%", name, elapsedTime * 100 / totalTime));
            elapsedTime = 0;
        }
    }

I also added this component, which prints profiler data to the Visual Studio output window every 5 seconds:

    class ProfilerComponent : GameComponent
    {
        double totalTime;

        public ProfilerComponent(Game game)
            : base(game)
        { }

        public override void Update(GameTime gameTime)
        {
            totalTime += gameTime.ElapsedGameTime.TotalSeconds;

            if (totalTime >= 5)
            {
                foreach (Profiler profiler in Profiler.AllProfilers)
                    profiler.Print(totalTime);

                Trace.WriteLine(string.Empty);
                totalTime = 0;
            }
        }
    }

To use this system, add a ProfilerComponent in your Game constructor:

    Components.Add(new ProfilerComponent(this));

You can then create a separate Profiler instance for each thing you are interested in timing. For instance I added these fields to my Game class:

    static Profiler updateProfiler = new Profiler("Update");
    static Profiler drawProfiler = new Profiler("Draw");

Call Profiler.Start and Profiler.End before and after the code you want to measure, and Bob's your uncle.

It was a pain having to remember to call the End method, though, especially when there were multiple return statements or exceptions that could be thrown from the code I was measuring. So I added this helper:

    struct ProfileMarker : IDisposable
    {
        public ProfileMarker(Profiler profiler)
        {
            this.profiler = profiler;
            profiler.Start();
        }

        public void Dispose()
        {
            profiler.Stop();
        }

        Profiler profiler;
    }

It is used like so:

    protected override void Draw(GameTime gameTime)
    {
        using (new ProfileMarker(drawProfiler))
        {
            GraphicsDevice.Clear(Color.CornflowerBlue);

            // TODO: Add your drawing code here

            base.Draw(gameTime);
        }
    }

Armed with this infrastructure, it was but the work of a moment to confirm that yes indeed, the Zune game was spending 60% of CPU in the same place indicated by my earlier Windows profiling.

So why bother profiling on Windows at all, if I was going to check the results using Stopwatch no matter what?

To save time.

Stopwatch profiling is a blunt tool. It tells how long the code inside each ProfileMarker block takes to run, but this is only useful if you somehow know or guess which pieces of code to wrap these markers around. Identifying performance hotspots by trial and error or binary search is laborious and not my idea of fun. It is much quicker if I can go in already armed with ideas about where to look.

You can think of the Windows profiler as circumstantial evidence ("I saw someone who looked like him hanging around before the robbery"), while using Stopwatch on Xbox or Zune is the equivalent of a finding the stolen goods stashed in his basement. You need the latter to secure a conviction, but you also need the former to know which basement to look in!