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

@davechurchill I think that TheCherrno's method for singletons is better. Your method could return a nullptr(or at least, that's my guessing).

No, it couldn't ever return null since the object is guaranteed to exist

@tobanteAudio @davechurchill thanks guys, updated.

So I changed line 126 to use auto on my implementation and then I get a warning on the following line. Might be something I did different or system dependent but I get a warning on gcc narrowing conversion of ‘ThreadID’ from ‘long unsigned int’ to ‘uint32_t {aka unsigned int}’. Ended up switching the struct to use a uint64_t. Don't know if it makes sense to change it on this or not, but figured I'd share.

@TheCherno Probably wouldn't have learned c++ nearly as well without your videos. My c++ teacher at uni isn't the best. Thanks for making a bunch of great videos!

Hi, thanks for the code!
question, is this thread safe? Isn't a lock needed in WriteProfile? or I'm missing something?

great project btw!

Thanks for the great YouTube series on C++ coding!
I updated your Instrumentation.h file to be thread-safe with a std::mutex + lock_guard.
Also made a small main.cpp and Makefile (linux) to have complete example. Always nice to just download and run make ...

Code exist in the "maronsson" fork of your code. code

Best regards,
/Mattias

First of all thanks again @TheCherno for showing this video. I really loved the Instrumentor class and have been using it ever since watching. Due to it being so useful, I have analyzed it a bit and I have a few more questions and suggestions for the design and implementation. I figured that since you also enjoy using it you'd be open to the feedback.

1. What is the point of the InstrumentationSession / name?

The name doesn't appear to actually be used anywhere (the session data structure is never actually read anywhere other than to delete it), nor is there support for multiple running 'sessions' in parallel, so I assume it's just there so you can begin a new session with a new file name if you want to. I think it's much cleaner to just have this name stored as a string rather than another struct which makes it a little more confusing.

2. Why did you allocate the InstrumentationSession on the heap with new?

Not only would a non-heap allocated string have worked, but you've introduced a bug here where if someone starts a 2nd session without ending the first one, you leave a dangling pointer to the first InstrumentationSession which can now never be deleted. If you had simple stored the name as a string you'd be fine. If you do NEED this to be heap allocated for some reason, you need to check if m_CurrentSession is null in BeginSession() and delete it if it isn't, in order to fix the dangling pointer.

3. Why no destructor for Instrumentor?

The destructor could call EndSession() just to make sure the file gets cleaned up if someone forgot to end it manually. This would go nicely with the flow of InstrumentationTimer which does this sort of thing with the stopped check

4. Constructor of Instrumentor should be private

The standard practice for C++ singletons should be to make the constructor of the Singleton class private, so that you can ONLY access it via the Get() function

5. Use of initializer list in Instrumentor constructor

I think that the preferred modern C++ usage is: "If the member variables can be given default values on the line of declaration, then that is preferred to giving them their default values in the initializer list". This way the default variables are visible on the line that they are declared which is much cleaner and intuitive to the user.

6. Don't manually call flush on the output stream

If you manually flush like you're doing now, you're doing a disk write every single profile, which is extremely expensive. Just delete the line to manually flush and let the internal output buffer do its thing like it was intended to. This will result in far less i/o calls.

7. Consistent member variable declaration location

In Instrumentor and InstrumentationTimer you've declared the private variables in different places. One at the top of the class and the other at the bottom of the class. Might be cleaner to put them in the same spot for both classes.

8. InstrumentationTimer should internally store a ProfileResult object

Store a ProfileResult object inside InstrumentationTimer as a member variable to hold the name, start, end, and threadID. This way when you go to call Instrumentor::Get().WriteProfile you can simply pass in the member variable as a reference, rather than constructing the ProfileResult on the fly, which will save you a constructor/copy.

Here is my implementation so far with all of these changes:
https://pastebin.com/qw5Neq4U

Please don't take these suggestions as criticism! I only ever comment on code that's great that I actually plan on using. Keep up the great work, looking forward to your new videos

In addition to @davechurchill: On MSys/MinGW std::chrono::steady_clock may be needed instead of high_resolution_clock. See msys2/MINGW-packages#5086 (comment).

The design of threadID as uint32_t is flawed, e.g i have typedef unsigned __int64 uintptr_t and this varies from implementation to implementation, as the hash does. Just use std::thread::id threadID.

BTW. Nice work, @TheCherno and @davechurchill :)

P.S: For those who are allergic to chrome: QT Creator, Analyze ⇒ Chrome Trace Format Viewer ⇒ Load JSON File

The constructor of InstrumentationTimer should be explicit as it has only one argument.

What is the significance of creating InstrumentationSession * m_CurrentSession in class Instrumentor?

Hi, I have a suggestion. We can make this implementation thread-safe by adding locks in "void WriteProfile(const ProfileResult& result)"

Hello all

Did you guys happen to have this issue ? Sometimes, when I try to profile a function that calls another profiled function, it may happen that both functions have the exact same starting point (field "ts" in the result.json). This causes the tracing tool to not render the graph correctly.

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

Great tool btw, very useful :)

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