utility: Added Tracer for collecting time measurements

* define TRACING_ENABLED in utility/tracing.h to enable tracing * invoke TraceEvent by writing TRACE() at start of function or scope * provide an event name with TRACE("name") * press SPACE to show collected traces history and report with accumulated times
2016-06-16 12:03:34 +02:00
parent 6b31a43f75
commit 9560cc4ea6
14 changed files with 401 additions and 9 deletions
@@ -13,21 +13,21 @@
 	{ \
 		LogManager::getInstance()->logInfo(__str__, __FILE__, __FUNCTION__, __LINE__); \
 	} \
-	while(0) \
+	while(0)

 #define LOG_WARNING(__str__) \
 	do \
 	{ \
 		LogManager::getInstance()->logWarning(__str__, __FILE__, __FUNCTION__, __LINE__); \
 	} \
-	while(0) \
+	while(0)

 #define LOG_ERROR(__str__) \
 	do \
 	{ \
 		LogManager::getInstance()->logError(__str__, __FILE__, __FUNCTION__, __LINE__); \
 	} \
-	while(0) \
+	while(0)

 #define LOG_INFO_STREAM(__s__) \
 	do \
@@ -36,7 +36,7 @@
 		__ss__ __s__; \
 		LogManager::getInstance()->logInfo(__ss__.str(), __FILE__, __FUNCTION__, __LINE__); \
 	} \
-	while(0) \
+	while(0)

 #define LOG_WARNING_STREAM(__s__) \
 	do \
@@ -45,7 +45,7 @@
 		__ss__ __s__; \
 		LogManager::getInstance()->logWarning(__ss__.str(), __FILE__, __FUNCTION__, __LINE__); \
 	} \
-	while(0) \
+	while(0)

 #define LOG_ERROR_STREAM(__s__) \
 	do \
@@ -54,7 +54,7 @@
 		__ss__ __s__; \
 		LogManager::getInstance()->logError(__ss__.str(), __FILE__, __FUNCTION__, __LINE__); \
 	} \
-	while(0) \
+	while(0)

 #define LOG_INFO_STREAM_BARE(__s__) \
 	do \
@@ -63,6 +63,6 @@
 		__ss__ __s__; \
 		LogManager::getInstance()->logInfo(__ss__.str(), "", "", 0); \
 	} \
-	while(0) \
+	while(0)

 #endif // LOGGING_H
@@ -0,0 +1,183 @@
+#include "utility/tracing.h"
+
+#include "utility/utility.h"
+
+std::shared_ptr<Tracer> Tracer::s_instance;
+Id Tracer::s_nextTraceId = 0;
+
+Tracer* Tracer::getInstance()
+{
+	if (!s_instance)
+	{
+		s_instance = std::shared_ptr<Tracer>(new Tracer());
+	}
+
+	return s_instance.get();
+}
+
+TraceEvent* Tracer::startEvent(const std::string& eventName)
+{
+	std::lock_guard<std::mutex> lock(m_mutex);
+
+	std::thread::id id = std::this_thread::get_id();
+	std::shared_ptr<TraceEvent> event =
+		std::make_shared<TraceEvent>(eventName, s_nextTraceId++, m_startedEvents[id].size());
+
+	m_events[id].push_back(event);
+	m_startedEvents[id].push(event.get());
+
+	return event.get();
+}
+
+void Tracer::finishEvent(TraceEvent* event)
+{
+	std::lock_guard<std::mutex> lock(m_mutex);
+
+	std::thread::id id = std::this_thread::get_id();
+	m_startedEvents[id].pop();
+}
+
+void Tracer::printTraces()
+{
+	std::lock_guard<std::mutex> lock(m_mutex);
+
+	size_t unfinishEvents = 0;
+	for (auto p : m_startedEvents)
+	{
+		unfinishEvents += p.second.size();
+	}
+
+	if (unfinishEvents > 0)
+	{
+		std::cout << "TRACING: Trace events are still running." << std::endl;
+		return;
+	}
+	else if (!m_events.size())
+	{
+		std::cout << "TRACING: No trace events collected." << std::endl;
+		return;
+	}
+
+
+	std::cout << "TRACING\n--------------------------\n" << std::endl;
+
+	std::cout << "HISTORY:\n\n";
+	std::cout << "    time                 name                     function";
+	std::cout << "                                          location\n";
+	std::cout << "-----------------------------------------------------------------";
+	std::cout << "------------------------------------------------------------\n";
+
+	for (auto p : m_events)
+	{
+		std::cout << "thread: " << p.first << std::endl;
+
+		for (const std::shared_ptr<TraceEvent> event : p.second)
+		{
+			std::cout.width(8 + 2 * event->depth);
+			std::cout << std::right << std::setprecision(3) << std::fixed << event->time;
+
+			std::cout.width(17 - 2 * event->depth);
+			std::cout << " ";
+
+			std::cout.width(25);
+			std::cout << std::left << event->eventName;
+
+			std::cout.width(50);
+			std::cout << (event->functionName + "()") << event->locationName << std::endl;
+		}
+
+		std::cout << std::endl;
+	}
+
+	std::cout << "\nREPORT:\n\n";
+	std::cout << "    time      count      name                     function";
+	std::cout << "                                          location\n";
+	std::cout << "-----------------------------------------------------------------";
+	std::cout << "------------------------------------------------------------\n";
+
+	struct AccumulatedTraceEvent
+	{
+		TraceEvent* event;
+		size_t count;
+		float time;
+	};
+
+	std::map<std::string, AccumulatedTraceEvent> accumulatedEvents;
+
+	for (auto p : m_events)
+	{
+		for (const std::shared_ptr<TraceEvent> event : p.second)
+		{
+			std::string name = event->eventName + event->functionName + event->locationName;
+
+			std::pair<std::map<std::string, AccumulatedTraceEvent>::iterator, bool> p =
+				accumulatedEvents.emplace(name, AccumulatedTraceEvent());
+
+			AccumulatedTraceEvent* acc = &p.first->second;
+			if (p.second)
+			{
+				acc->event = event.get();
+				acc->time = event->time;
+				acc->count = 1;
+			}
+			else
+			{
+				acc->time += event->time;
+				acc->count++;
+			}
+		}
+	}
+
+	std::multiset<AccumulatedTraceEvent,
+			std::function<bool (const AccumulatedTraceEvent&, const AccumulatedTraceEvent&)>> sortedEvents(
+		[](const AccumulatedTraceEvent& a, const AccumulatedTraceEvent& b)
+		{
+			return a.time > b.time;
+		}
+	);
+
+	for (const std::pair<std::string, AccumulatedTraceEvent> p : accumulatedEvents)
+	{
+		sortedEvents.insert(p.second);
+	}
+
+	for (const AccumulatedTraceEvent& acc : sortedEvents)
+	{
+		std::cout.width(8);
+		std::cout << std::right << std::setprecision(3) << std::fixed << acc.time;
+
+		std::cout.width(10);
+		std::cout << acc.count << "       ";
+
+		std::cout.width(25);
+		std::cout << std::left << acc.event->eventName;
+
+		std::cout.width(50);
+		std::cout << (acc.event->functionName + "()") << acc.event->locationName << std::endl;
+	}
+
+	std::cout << std::endl;
+
+	m_events.clear();
+}
+
+Tracer::Tracer()
+{
+}
+
+
+ScopedTrace::ScopedTrace(
+	const std::string& eventName, const std::string& fileName, int lineNumber, const std::string& functionName)
+{
+	m_event = Tracer::getInstance()->startEvent(eventName);
+	m_event->functionName = functionName;
+	m_event->locationName = FilePath(fileName).fileName() + ":" + std::to_string(lineNumber);
+
+	m_timePoint = utility::durationStart();
+}
+
+ScopedTrace::~ScopedTrace()
+{
+	m_event->time = utility::duration(m_timePoint);
+	Tracer::getInstance()->finishEvent(m_event);
+}
@@ -0,0 +1,82 @@
+#ifndef TRACING_H
+#define TRACING_H
+
+#include <stack>
+#include <thread>
+
+#include "utility/TimePoint.h"
+#include "utility/types.h"
+
+struct TraceEvent
+{
+public:
+	TraceEvent(const std::string& eventName, Id id, size_t depth)
+		: eventName(eventName)
+		, id(id)
+		, depth(depth)
+		, time(0.0f)
+	{
+	}
+
+	const std::string eventName;
+	const Id id;
+	const size_t depth;
+
+	std::string functionName;
+	std::string locationName;
+
+	float time;
+};
+
+
+class Tracer
+{
+public:
+	static Tracer* getInstance();
+
+	TraceEvent* startEvent(const std::string& eventName);
+	void finishEvent(TraceEvent* event);
+
+	void printTraces();
+
+private:
+	static std::shared_ptr<Tracer> s_instance;
+	static Id s_nextTraceId;
+
+	Tracer();
+	Tracer(const Tracer&);
+	void operator=(const Tracer&);
+
+	std::map<std::thread::id, std::vector<std::shared_ptr<TraceEvent>>> m_events;
+	std::map<std::thread::id, std::stack<TraceEvent*>> m_startedEvents;
+
+	std::mutex m_mutex;
+};
+
+
+class ScopedTrace
+{
+public:
+	ScopedTrace(const std::string& eventName, const std::string& fileName, int lineNumber, const std::string& functionName);
+	~ScopedTrace();
+
+private:
+	TraceEvent* m_event;
+	TimePoint m_timePoint;
+};
+
+
+// #define TRACING_ENABLED
+
+#ifdef TRACING_ENABLED
+	#define TRACE(__name__) \
+		ScopedTrace __trace__(std::string(__name__), __FILE__, __LINE__, __FUNCTION__)
+
+	#define PRINT_TRACES() \
+		Tracer::getInstance()->printTraces()
+#else
+	#define TRACE(__name__)
+	#define PRINT_TRACES()
+#endif
+
+#endif // TRACING_H