Code to track execution time for each function in a class

Question

Problem Statement

I want to be able to look at log files and figure out where the bottlenecks are in the code in an easy/visual way rather than trying to do the math every time I make some improvements. I want to be able to use a single instance of this throughout the target class rather than creating a new instance in every function within it. Hope that helps to clear some of the confusion.

Class Description

The ExecTimeLogger class has a simple interface of Start(), Stop() and Summary() and it stores that information in a map keyed off of a token and the function name

#include <string>
#include <iostream>
#include <sstream>
#include <iomanip>
#include <chrono>
#include <map>
#include <atomic>
#include <Logger.h>

/*
Utility class which provides logging the function execution times and summarizing the results of all executed functions within a class
*/
class ExecTimeLogger
{
private:
std::map <std::string, ExecTimeData> _execMap;
std::atomic<int> _sectionNumber;
int const INSTANCE_TOKEN = 0;
std::string const INSTANCE_NAME = "Entire Instance";
Logger* _logger;

std::string GetKeyName(int token, std::string sectionName)
{
    auto keyName = std::to_string(token) + "_" + sectionName;
    return keyName;
}

void LogMessage(std::string message)
{
    if (_logger != nullptr)
    {
        _logger->printMessage("\n");
        _logger->printMessage(message.c_str());
    }
    else
        std::cout << message.c_str();
}

public:
/*
Instantiates the ExecTimeLogger class with an optional pointer to logger
If a logger is not provided, it logs everything to the console
*/
ExecTimeLogger(Logger* logger = nullptr)
{
    _sectionNumber = INSTANCE_TOKEN;
    this->Start(INSTANCE_NAME);
    this->_logger = logger;
}
~ExecTimeLogger()
{
    delete _logger;
    this->_logger = nullptr;
}

/*
Stops the timer for the given section name
*/
int Start(std::string sectionName)
{
    ExecTimeData newSection;
    newSection.SectionName = sectionName;
    newSection.TokenID = _sectionNumber++;
    newSection.SectionStartTime = std::chrono::high_resolution_clock::now();

    auto keyName = GetKeyName(newSection.TokenID, sectionName);

    if (_execMap.count(sectionName) == 0)
    {
        _execMap.insert(std::make_pair(keyName, newSection));
    }
    else
    {
        _execMap[keyName] = newSection;
    }

    return newSection.TokenID;
}

/*
Stops the timer for the given section name and token combination
*/
void Stop(std::string sectionName, int tokenID)
{
    auto keyName = GetKeyName(tokenID, sectionName);

    if (_execMap.count(keyName) == 0)
    {
        LogMessage(sectionName + " or " + std::to_string(tokenID) + " does not exist.\n");
        return;
    }

    _execMap[keyName].SectionStopTime = std::chrono::high_resolution_clock::now();
    std::stringstream summaryBuf;
    summaryBuf << _execMap[keyName].TokenID << ") " << _execMap[keyName].SectionName.c_str() << " = " << _execMap[keyName].Elapsed() << "(ms)" << std::endl;
    LogMessage(summaryBuf.str());
}

/*
Prints the execution time summary either to the logger if available or to the console
*/
void LogSummary()
{
    this->Stop(INSTANCE_NAME, 0);
    std::stringstream summaryBuf;
    summaryBuf << "---------------------------------------------------------------------------------------\n";
    summaryBuf << "------------------------------------Execution Times------------------------------------\n";
    summaryBuf << "---------------------------------------------------------------------------------------\n";
    summaryBuf
        << std::setw(10)
        << "Token"
        << std::setw(20)
        << "Section Name"
        << std::setw(21)
        << "Exec. Time (ms)"
        << std::setw(14)
        << "% of total"
        << std::setw(22)
        << "Impact"
        << std::endl;
    summaryBuf << "---------------------------------------------------------------------------------------\n";

    auto instanceElapsed = _execMap[GetKeyName(INSTANCE_TOKEN, INSTANCE_NAME)].Elapsed();
    long long totalExec = 0;

    for (auto const& record : _execMap)
    {
        auto currentRecord = record.second;

        // Don't print the full binary time
        if (currentRecord.TokenID == INSTANCE_TOKEN)
            continue;

        auto currentRecordElapsed = currentRecord.Elapsed();
        if (currentRecordElapsed > 0)
            totalExec += currentRecordElapsed;

        auto percentage = ((float)currentRecordElapsed / instanceElapsed) * 100.00;

        int impact = percentage / 5;
        std::string impactStr = "";

        if (currentRecordElapsed < 0)
            impactStr = "NA";
        else
        {
            for (size_t i = 0; i <= impact; i++)
            {
                impactStr += "*";
            }
        }

        summaryBuf
            << std::fixed
            << std::setprecision(2)
            << std::setw(9)
            << std::to_string(currentRecord.TokenID)
            << ")"
            << std::setw(20)
            << currentRecord.SectionName
            << std::setw(21)
            << currentRecordElapsed
            << std::setw(14)
            << ((float)currentRecordElapsed / instanceElapsed) * 100.00
            << std::setw(22)
            << impactStr
            << std::endl;
    }

    summaryBuf << "---------------------------------------------------------------------------------------\n";
    summaryBuf << "Total Execution Time of the Instance\t\t= " << std::to_string(instanceElapsed) << "(ms)\n";
    summaryBuf << "Total Execution Time of all the functions\t= " << std::to_string(totalExec) << "(ms)\n";
    summaryBuf << std::fixed << std::setprecision(2)
        << "% execution time of all the functions\t\t= " << (((float)totalExec / instanceElapsed) * 100.00) << "%\n";
    summaryBuf << "---------------------------------------------------------------------------------------\n";

    LogMessage(summaryBuf.str());
}
};

This is the class which holds the data:

/*
Class which holds the execution time data
*/
class ExecTimeData
{
public:
int TokenID;
std::string SectionName;
std::chrono::high_resolution_clock::time_point SectionStartTime;
std::chrono::high_resolution_clock::time_point SectionStopTime;

/*
Returns the total number of milliseconds that've elapsed to execute the section
*/
long long Elapsed()
{
    // The clock was never stopped
    if (SectionStopTime.time_since_epoch().count() == 0)
        return -1;

    long long  elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(SectionStopTime - SectionStartTime).count();
    return elapsed;
}
};

And, here is an example use case:

class ClassToBeBenchmarked
{
private:
    ExecTimeLogger* exec;

    void PrivateFunctionOne()
    {
        auto token = exec->Start(__FUNCTION__);
        std::this_thread::sleep_for(std::chrono::milliseconds(500));
        exec->Stop(__FUNCTION__, token);

        return;
    }
    void PrivateFunctionTwo()
    {
        auto token = exec->Start(__FUNCTION__);
        std::this_thread::sleep_for(std::chrono::milliseconds(700));
        exec->Stop(__FUNCTION__, token);

        return;
    }
public:
    ClassToBeBenchmarked() 
    {
        exec = new ExecTimeLogger();
    }
    ~ClassToBeBenchmarked()
    {
        exec->LogSummary();
    }
    void PublicEntryFunction() 
    {
        auto token = exec->Start(__FUNCTION__);
        std::this_thread::sleep_for(std::chrono::milliseconds(2000));
        PrivateFunctionOne();
        PrivateFunctionTwo();
        exec->Stop(__FUNCTION__, token);
        return;
    }
};

int main()
{
    ClassToBeBenchmarked bench;
    bench.PublicEntryFunction();
    return 0;

}

One thing that I'm not a fan of here is to have to put

auto token = exec.Start(__FUNCTION__);

and

exec.Stop(__FUNCTION__, token);

in every function.

Please suggest if there is a clever way to handle that, otherwise general code improvement comments are appreciated. Thanks!

Sample Output:

2) ClassToBeBenchmarked::PrivateFunctionOne = 500(ms)
3) ClassToBeBenchmarked::PrivateFunctionTwo = 701(ms)
1) ClassToBeBenchmarked::PublicEntryFunction = 3224(ms)
0) Entire Instance = 3233(ms)
322437244425----------------------------------------------------------------------------------------------------------------
------------------------------------------------Execution Times-------------------------------------------------
----------------------------------------------------------------------------------------------------------------
     Token                                 Section Name      Exec. Time (ms)    % of total                Impact
----------------------------------------------------------------------------------------------------------------
        1)    ClassToBeBenchmarked::PublicEntryFunction                 3224         99.72  ********************
        2)     ClassToBeBenchmarked::PrivateFunctionOne                  500         15.47                  ****
        3)     ClassToBeBenchmarked::PrivateFunctionTwo                  701         21.68                 *****
----------------------------------------------------------------------------------------------------------------
Total Execution Time of the Instance            = 3233(ms)
Total Execution Time of all the functions       = 4425(ms)
% execution time of all the functions           = 136.87%
----------------------------------------------------------------------------------------------------------------

Answer 1

If you return an object from Start, you could arrange for its destructor to stop the timer. That RAII style instantly reduces the intrusiveness of the instrumentation by half (and saves you having to think about all the return points of the functions - which might be as exceptions, remember).

Other points of review:

• We have std::clog, which is to be preferred to std::cout for these informational messages.
• Don't clutter members with unnecessary this-> - it's only necessary if you have name shadowing in effect, which you don't.

• Prefer initializer lists in your constructors, rather than assignment:

  ExecTimeLogger(Logger* logger = nullptr)
     : _sectionNumber{INSTANCE_TOKEN},
       _logger{logger}
  {
      Start(INSTANCE_NAME);
  }
  

• There's no point assigning to members in the destructor - they will all be out of scope when it finishes.

• Prefer not to own objects by raw pointers - Modern C++ uses smart pointers to manage ownership.

Answer 2

Easy to use correctly, hard to use incorrectly

People who read my reviews probably got fed up with my suggestions about usability, but this one looks easy to fix. Current correct usage:

1. Start timer where I want

2. Stop timer where I want (do I want to?)

What I (personally) would expect:

1. Start timer where I want and let destructor handle it

Fix

Implement something like std::lock_guard:

template <typename Timer>
requires /*if you have extremely new compiler, check for lockability*/
class timer_guard {
    Timer& instance;
public:
    timer_guard(Timer& instance, std::string_view function_name):
           instance(instance)
    {
        instance.start(function_name);
    }

    ~timer_guard() {
        instance.stop();
    }
}

Code Review:

Use aggregate initialization if types don't repeat often

ExecTimeData newSection;
newSection.SectionName = sectionName;
newSection.TokenID = _sectionNumber++;
newSection.SectionStartTime = std::chrono::high_resolution_clock::now();

This piece could use aggregate initialization:

ExecTimeData newSection{/*values...*/};

Use better library for string formatting

I didn't count exactly, but it looks like 20-25 lines just for the output. And they don't look pretty.

Use const std::string& or std::string_view for read-only view into string

Although not equivalent, before C++17 const reference is the only way to go.

Use default values

In the log summary, it looks like using something along the lines of std::ostream& os = std::cout would be better, as it makes it harder to use incorrectly.

Don't perform lossy conversions unless required

std::chrono::duration_cast<std::chrono::milliseconds>

It is better to give user default resolution and let them choose in other cases. Performing lossy conversions is like throwing away part of the data.

Consider reading more about problem that the code solves

Microbenchmarks are usually guarded by some mechanism which makes the start and end execution points observable (e.g. puts the timed code in sort of a barrier). Benchmarks of more sophisticated functionality usually don't care about such nuances. Benchmarks are often comparative, e.g. one solution/implementation is compared to other(s). Algorithms that process some data are usually fed with varying sizes and distributions. Some benchmarks might want better timing resolution, e.g. std::nanoseconds. There are plethora of other usage contexts.