Basic Instrumentation Profiler

Instrumentor.h

//
// Basic instrumentation profiler by Cherno

// Usage: include this header file somewhere in your code (eg. precompiled header), and then use like:
//
// Instrumentor::Get().BeginSession("Session Name");        // Begin session 
// {
//     InstrumentationTimer timer("Profiled Scope Name");   // Place code like this in scopes you'd like to include in profiling
//     // Code
// }
// Instrumentor::Get().EndSession();                        // End Session
//
// You will probably want to macro-fy this, to switch on/off easily and use things like __FUNCSIG__ for the profile name.
//
#pragma once

#include <string>
#include <chrono>
#include <algorithm>
#include <fstream>

#include <thread>

struct ProfileResult
{
    std::string Name;
    long long Start, End;
    uint32_t ThreadID;
};

struct InstrumentationSession
{
    std::string Name;
};

class Instrumentor
{
private:
    InstrumentationSession* m_CurrentSession;
    std::ofstream m_OutputStream;
    int m_ProfileCount;
public:
    Instrumentor()
        : m_CurrentSession(nullptr), m_ProfileCount(0)
    {
    }

    void BeginSession(const std::string& name, const std::string& filepath = "results.json")
    {
        m_OutputStream.open(filepath);
        WriteHeader();
        m_CurrentSession = new InstrumentationSession{ name };
    }

    void EndSession()
    {
        WriteFooter();
        m_OutputStream.close();
        delete m_CurrentSession;
        m_CurrentSession = nullptr;
        m_ProfileCount = 0;
    }

    void WriteProfile(const ProfileResult& result)
    {
        if (m_ProfileCount++ > 0)
            m_OutputStream << ",";

        std::string name = result.Name;
        std::replace(name.begin(), name.end(), '"', '\'');

        m_OutputStream << "{";
        m_OutputStream << "\"cat\":\"function\",";
        m_OutputStream << "\"dur\":" << (result.End - result.Start) << ',';
        m_OutputStream << "\"name\":\"" << name << "\",";
        m_OutputStream << "\"ph\":\"X\",";
        m_OutputStream << "\"pid\":0,";
        m_OutputStream << "\"tid\":" << result.ThreadID << ",";
        m_OutputStream << "\"ts\":" << result.Start;
        m_OutputStream << "}";

        m_OutputStream.flush();
    }

    void WriteHeader()
    {
        m_OutputStream << "{\"otherData\": {},\"traceEvents\":[";
        m_OutputStream.flush();
    }

    void WriteFooter()
    {
        m_OutputStream << "]}";
        m_OutputStream.flush();
    }

    static Instrumentor& Get()
    {
        static Instrumentor instance;
        return instance;
    }
};

class InstrumentationTimer
{
public:
    InstrumentationTimer(const char* name)
        : m_Name(name), m_Stopped(false)
    {
        m_StartTimepoint = std::chrono::high_resolution_clock::now();
    }

    ~InstrumentationTimer()
    {
        if (!m_Stopped)
            Stop();
    }

    void Stop()
    {
        auto endTimepoint = std::chrono::high_resolution_clock::now();

        long long start = std::chrono::time_point_cast<std::chrono::microseconds>(m_StartTimepoint).time_since_epoch().count();
        long long end = std::chrono::time_point_cast<std::chrono::microseconds>(endTimepoint).time_since_epoch().count();

        uint32_t threadID = std::hash<std::thread::id>{}(std::this_thread::get_id());
        Instrumentor::Get().WriteProfile({ m_Name, start, end, threadID });

        m_Stopped = true;
    }
private:
    const char* m_Name;
    std::chrono::time_point<std::chrono::high_resolution_clock> m_StartTimepoint;
    bool m_Stopped;
};

I don't know why, but when I added this header in my C++ project, the output result.json file contains only the json below:

{"otherData": {},"traceEvents":[]}

I tried both implementations: Cherno original code and @davechurchill version.

Could you please help me why is this happening?

My mistake! I have to set the pre-processor flag!
Now all is working good! Thanks!

This is really great discussion here. I have two comments regarding your video, not the scripts here, since you got rid of macros.

1. For PROFILE_SCOPE macro, using timer##LINE(name), this might not work out exactly as wished, due to that LINE is an integer, you might need to stringify it before concatenating to a string.
   #define COMBINE_HELPER(X,Y) X##Y
   #define COMBINE(X,Y) COMBINE_HELPER(X,Y)
   #define PROFILE_SCOPE_AUX(name) myprofiler::InstrumentationTimer COMBINE(timer,LINE)(name);

2. If you are going to use macros, it might be a good idea to put ";" behind it, so in main code, you can use either PROFILE_SCOPE_AUX with or without ";".

Please do feel free to correct me if I am wrong here.

@l3ch4tno1r

A quick fix is to use nanoseconds instead fo microseconds, so it is accurate enough to avoid that, but there is a side effect : the time scale in the tracing tool will not be correct...

Im having a similar issue to yourself, but unfotunately converting std::chrono::microseconds to std::chrono::nanoseconds in the cast does not solve the problem.

you can add a function(>1 microsecond) in InstrumentationTimer constructor to avoid this

I actually got a question. Typically we got too many functions, which we may have several projects. If the sub-functions happen to be in a separate shared library project other than my main project. This will print anything of this subfunction, other than the ones in current project.

Any suggestions on this?

Is there a way to have the InstrumentationTimer nullify when used in a constexpr context? Some functions maybe declared as constexpr, which can't be profiled and I get that, but are used more often as non-constexpr functions and I would like to profile those.

@AbduEhab Maybe std::is_constant_evaluated() in C++20 can help

Is dur a valid field? I looked at the format docs (linked below) and cannot find it.
https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU

@AbduEhab Maybe std::is_constant_evaluated() in C++20 can help

That was exactly what I was looking for, thanks! Should be trivial to change the macros to accommodate it.

Is dur a valid field? I looked at the format docs (linked below) and cannot find it. https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU

It is a valid field for the "Complete Events".
https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit#heading=h.lpfof2aylapb

This is not bad, but could be better. I recently put together a small repo which does a similar thing. https://github.com/sirgru/SimpleCppProfiler

In this code the data is put on the output_stream when the timer goes out of scope. Won't this skew the results if there are Multiple Timers running, that is, a function being timed calls another Function being timed , In this the Time to write is also considered

I needed to add one mutex in WriteProfile function to stop different threads writing to .json in the same time.
I added this line at the begging of WriteProfile function:
std::lock_guard<std::mutex> lock(Mutex);