Writing a simple profiler

[caption id="attachment_197" align="alignleft" width="300" caption="Photo by MNSC"][/caption]

Before doing any kind of optimisation it is important to find out where your program is spending its time. A lot of people have wasted a lot of time and written lots of unnecessary code because they thought they knew where to optimise. If you find out your program is spend 80% of it's time going disk I/O (input and output) and only 20% of its time doing calculations then halving the time it spends doing calculations will only improve the overall speed on the program by 10%. On the other hand, a 25% improvement of the speed of the I/O code will reduce the running time by 20%.
A profiler is a program, or code inside your program, that measures how long sections of code take to execute. External profilers hook into your code as it is running, internal ones, generally, need the hooks adding by hand.
Writing your own simple profiler is easy and allows you to quickly find out where your code is spending its time. In this post we'll show you how.

As we are trying to be as language agnostic as possible we'll create the design in pseudo-code assuming that you are using a object oriented language but the same basic idea can be transferred to any language.

First lets look at how the profiler is used. It's got a very simple interface: two methods called Start and End and a method, Results, to get the results.

For example:

function doStuff()
{
Profiler.Start("doStuff");

... code goes here ...

Profiler.End("doStuff");
}

doStuff();
doStuff();
doStuff();

... rest of the program ...

string output = Profiler.Results();
print(output);

Output:
doStuff,3,134

The results are: the name passed into the profiler, the number of times the name was used and the total time (in milliseconds) that was spent between the calls to Start and End.

Design

The Profiler class needs to visible from all the code that will want to use it. It could be a static class, a globally accessible variable or a Singleton.
For simplicity we're going to make our Profiler class static.
The Profiler class uses a dictionary to store a list of Names and ProfilerItem classes (which stores the current count, total time and a list of currently active timers - more on this later). Every time Start(name) is called it looks to see if the name is already in the list. If it is, then the current time is stored in the ProfilerItem. If the name isn't in the list a new one is created, add to the list and then the start time is saved.
When End(name) is called the name is looked up in the dictionary (and an exception is thrown if it can't be found) and then End is called on the ProfilerItem (again an exception is thrown if there are no active timers), this increases the count by one and adds the difference in time to the total time.
ProfilerItem stores a stack of start times so that Start(name) can be called multiple times before End(name). This happens if any of your code is recursive (ie calls itself). We're using a Stack data structure as it is easy to add items (Push) and then get the last added item (Pop) which is exactly what we want as the first time you call End it'll match with the last time you call Start.

Result just loops through all the entries in the dictionary and creates a comma separated list of name, count and total time on each line.
A possible extension is to check whether there are any running timers and throw an exception or print a warning.

The Code

Below is the pseudo-code for the Profiler class.

NB. This code shouldn't be used in a multi-threaded environment as it isn't thread safe. You'll have to make some modifications, or rewrite it completely, before it is thread safe.

static class Profiler
{
    private class ProfilerItem
    {
        private int m_count;
        private int m_totalTime; //using an int as GetCurrentTime returns milliseconds
        private Stack m_currentTimers;

        public ProfilerItem()
        {
               m_count = 0;
               m_totalTime = 0.0;
               m_currentTimers = new Stack();
         }

         public int Count()
         {
               return m_count;
         }

         public int TotalTime()
         {
               return m_totalTime;
         }

         public void AddTime(int time)
         {
               m_count++;
               m_totalTime += time;
         }

         public void Start()
         {
               m_currentTimers.Push(GetCurrentTime());
         }

         public void End()
         {
               if(m_currentTimers.Length == 0)
               {
                       throw new Exception("No currently active timer");
               }

               int startTime = m_currentTimers.Pop();
               AddTime(GetCurrentTime() - startTime);
         }
    }

    private static Dictionary m_Items = new Dictionary();

    public static void Start(string name)
    {
         ProfilerItem item = m_Items.Get(name);
         if(item == null)
         {
               item = new ProfilerItem();
               m_Items.Add(name, item);
         }               

         item.Start();
    }

    public static void End(string name)
    {
         ProfilerItem item = m_Items.Get(name);
         if(item == null)
         {
               throw new Exception("Can't find name '" + name +
                                            "'. Have you called End before Start?");
         }

         item.End();
    }

    public static string Results()
    {
         string result = "";
         foreach(Pair item in m_Items)
         {
               result += item.Key + ","
                         + item.Value.Count() + ","
                         + item.Value.TotalTime() + "\n";
         }
         return result;
    }
};

Conclusion

Knowing where your code is actually spending its time is vitally because without it you can't know which parts to optimise. This simple profiler will help you focus your optimisation efforts in the correct places.