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;
};

@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.

good job and thanks for sharing. 

i change 

uint32_t ThreadID;
to
std::thread::id threadID;   // linux: unsigned long int (depend on compile setting 64bit or 32bit)

i found this original event trace in old school
https://github.com/mainroach/sandbox/tree/master/chrome-event-trace

Just a note here!
Instrumentor::Get().EndSession(); kills the running timer instance before it can write to profiler.
Calling timer.Stop() before ending the session makes it return safely. This is especially helpful for profiling int main().

I made a similar utility in Rust here:
https://gist.github.com/OverShifted/5e2829a85d40cf5bc531e7a2505ca970

@TheCherno I really like the awesome content that you are creating and I would also like to use it in my code as well. Under which license is this Instrumentor.h? By default it is proprietary (git default). Could you maybe make it BSD or MIT? Thanks a lot.

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);