Skip to content

Commit

Permalink
Instrumentation fixes (TheCherno#179)
Browse files Browse the repository at this point in the history
- Added mutex to Instrumentor to avoid jumbled output if profiling multiple threads.
- Ensure that new a BeginSession() will cleanly end any previously existing session.
- Removed std::hash<> hack on ThreadId.
  • Loading branch information
0xworks authored and LovelySanta committed Jan 12, 2020
1 parent a15917c commit 3531a50
Show file tree
Hide file tree
Showing 4 changed files with 60 additions and 35 deletions.
92 changes: 60 additions & 32 deletions Hazel/src/Hazel/Debug/Instrumentor.h
Original file line number Diff line number Diff line change
@@ -1,18 +1,17 @@
#pragma once

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

#include <string>
#include <thread>

namespace Hazel {
struct ProfileResult
{
std::string Name;
long long Start, End;
uint32_t ThreadID;
std::thread::id ThreadID;
};

struct InstrumentationSession
Expand All @@ -23,55 +22,79 @@ namespace Hazel {
class Instrumentor
{
private:
std::mutex m_Mutex;
InstrumentationSession* m_CurrentSession;
std::ofstream m_OutputStream;
int m_ProfileCount;
public:
Instrumentor()
: m_CurrentSession(nullptr), m_ProfileCount(0)
: m_CurrentSession(nullptr)
{
}

void BeginSession(const std::string& name, const std::string& filepath = "results.json")
{
std::lock_guard lock(m_Mutex);
if (m_CurrentSession) {
// If there is already a current session, then close it before beginning new one.
// Subsequent profiling output meant for the original session will end up in the
// newly opened session instead. That's better than having badly formatted
// profiling output.
if (Log::GetCoreLogger()) { // Edge case: BeginSession() might be before Log::Init()
HZ_CORE_ERROR("Instrumentor::BeginSession('{0}') when session '{1}' already open.", name, m_CurrentSession->Name);
}
InternalEndSession();
}
m_OutputStream.open(filepath);
WriteHeader();
m_CurrentSession = new InstrumentationSession{ name };
if (m_OutputStream.is_open()) {
m_CurrentSession = new InstrumentationSession({name});
WriteHeader();
} else {
if (Log::GetCoreLogger()) { // Edge case: BeginSession() might be before Log::Init()
HZ_CORE_ERROR("Instrumentor could not open results file '{0}'.", filepath);
}
}
}

void EndSession()
{
WriteFooter();
m_OutputStream.close();
delete m_CurrentSession;
m_CurrentSession = nullptr;
m_ProfileCount = 0;
std::lock_guard lock(m_Mutex);
InternalEndSession();
}

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

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 << "}";
json << ",{";
json << "\"cat\":\"function\",";
json << "\"dur\":" << (result.End - result.Start) << ',';
json << "\"name\":\"" << name << "\",";
json << "\"ph\":\"X\",";
json << "\"pid\":0,";
json << "\"tid\":" << result.ThreadID << ",";
json << "\"ts\":" << result.Start;
json << "}";

std::lock_guard lock(m_Mutex);
if (m_CurrentSession) {
m_OutputStream << json.str();
m_OutputStream.flush();
}
}

m_OutputStream.flush();
static Instrumentor& Get() {
static Instrumentor instance;
return instance;
}

private:

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

Expand All @@ -81,11 +104,17 @@ namespace Hazel {
m_OutputStream.flush();
}

static Instrumentor& Get()
{
static Instrumentor instance;
return instance;
// Note: you must already own lock on m_Mutex before
// calling InternalEndSession()
void InternalEndSession() {
if (m_CurrentSession) {
WriteFooter();
m_OutputStream.close();
delete m_CurrentSession;
m_CurrentSession = nullptr;
}
}

};

class InstrumentationTimer
Expand All @@ -110,8 +139,7 @@ namespace Hazel {
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 });
Instrumentor::Get().WriteProfile({ m_Name, start, end, std::this_thread::get_id()});

m_Stopped = true;
}
Expand Down
1 change: 0 additions & 1 deletion Sandbox/HazelProfile-Runtime.json

This file was deleted.

1 change: 0 additions & 1 deletion Sandbox/HazelProfile-Shutdown.json

This file was deleted.

1 change: 0 additions & 1 deletion Sandbox/HazelProfile-Startup.json

This file was deleted.

0 comments on commit 3531a50

Please sign in to comment.