musingstudio

I recently needed to profile some C++ code that was taking longer than expected to run. The code was running on a machine without a profiler, so I wrote a handy Timer class that dumps nested timings of each method. You can initialize it to write either to a file or to std::cout if the machine has a console.

I originally thought of this as a ‘Poor Man’s Profiler’, but having used it there are real benefits to taking the trouble to instrument your own code – you can use the file dumps to swiftly compare performance between code changes; you can print out performance statistics and take along to meetings.

#include <iostream>
#include <chrono>
class TimerOutput
{
  public:
    TimerOutput( const std::string file_path = "" ) :
      file_path_( file_path )
    {
      if ( !file_path_.empty() )
      {
        file_.open( file_path_ );
      }
    }

    std::ostream& Stream()
    {
      if (file_path_.empty() )
        return std::cout;
      else
        return file_;
    }

private:
    std::string file_path_;
    std::ofstream file_;
};

class Timer
{
public:
    Timer( const std::string& description ) :
      description_(description),
      start_(std::chrono::system_clock::now())
    {
        applyIndent();
        timer_output_->Stream() << "Start " << description_.c_str() << "\n";
        ++indent;
    }

    ~Timer()
    {
        --indent;
        const std::chrono::time_point<std::chrono::system_clock> finish = std::chrono::system_clock::now();
        auto milliseconds = std::chrono::duration_cast<std::chrono::milliseconds>(finish - start_).count();

        applyIndent();
        timer_output_->Stream() << "Finished " << description_.c_str()
            << ", took " << milliseconds << " (ms)" << "\n";
}

private:
    void applyIndent() const
    {
        for ( size_t i = 0; i < indent; ++i )
        {
            timer_output_->Stream() << "--";
        }
    }

    static size_t indent;
    static TimerOutput* timer_output_;
    std::string description_;
    const std::chrono::time_point<std::chrono::system_clock> start_;
};

#define INITIALIZE_PROFILING_TO_CONSOLE() \
  TimerOutput timer_output; \
  size_t Timer::indent = 0; \
  TimerOutput* Timer::timer_output_ = &timer_output;

#define INITIALIZE_PROFILING_TO_FILE( path ) \
  TimerOutput timer_output( path ); \
  size_t Timer::indent = 0; \
  TimerOutput* Timer::timer_output_ = &timer_output;

#define TIME( description, f ) \
  { \
    Timer profiler( description ); \
    f; \
  }

The obvious limitation of my solution is that it uses a class static to achieve the levels of nesting, so it won’t work on multi-threaded code – but it was great for my purposes. Here’s some sample code that shows it in action:

#include "stdafx.h"

#include <thread>
#include <fstream>

#include "..\MusingStudio\Profiler.h"

//INITIALIZE_PROFILING_TO_CONSOLE()
INITIALIZE_PROFILING_TO_FILE( "c:/temp/timings.txt" )

void method2()
{
  TIME( "method2",
    std::chrono::milliseconds short_wait( 5 );
    std::this_thread::sleep_for( short_wait );
  )
}

void method1()
{
 TIME( "method1",
  TIME( "loop",
    for ( int i = 0; i &lt; 5; ++i )
    {
        method2();
    }
  )

  TIME( "expensive algorithm",
    std::chrono::milliseconds wait( 100 );
    std::this_thread::sleep_for( wait );
  )
 )
}

void method3()
{
  TIME( "method3",
    std::chrono::milliseconds long_wait( 500 );
    std::this_thread::sleep_for( long_wait );
  )
}

int main(int argc, char* argv[])
{
  TIME( "main",
    method1();
    method3();
  )

  return 0;
}

Here’s the output from the sample code: