Fix for not writing logs, added profiling to a bunch of common lib stuff.

eqperf/eqp_profiler.cpp

@@ -1,4 +1,5 @@
 #include "eqp_profiler.h"
+#include "eqp_profile_timer.h"
 #include <iostream>
 #include <thread>
 #include <mutex>
@@ -51,6 +52,8 @@ std::string EQP::CPU::ST::Profiler::EventStarted(const char *func, const char *n
 		current_ = t;
 	}
 
+	current_->GetCount()++;
+	current_->SetStarted(GetCurrentTimer());
 	return identifier_;
 }
 
@@ -58,8 +61,9 @@ void EQP::CPU::ST::Profiler::EventFinished(uint64_t time, std::string ident) {
 	if(ident.compare(identifier_) != 0) {
 		return;
 	}
+	
+	current_->SetStarted(0);
 	current_->GetTime() += time;
-	current_->GetCount()++;
 	current_ = current_->GetParent();
 }
 
@@ -87,6 +91,9 @@ void EQP::CPU::ST::Profiler::Dump(std::ostream &stream, int num) {
 		sorted_vec.push_back(n);
 
 		total += iter.second->GetTime();
+		if(iter.second->GetStarted() > 0) {
+			total += GetCurrentTimer() - iter.second->GetStarted();
+		}
 	}
 
 	std::sort(sorted_vec.begin(), sorted_vec.end(), 
@@ -158,6 +165,8 @@ std::string EQP::CPU::MT::Profiler::EventStarted(const char *func, const char *n
 		ti->current_ = t;
 	}
 
+	ti->current_->GetCount()++;
+	ti->current_->SetStarted(GetCurrentTimer());
 	return imp_->identifier_;
 }
 
@@ -176,8 +185,8 @@ void EQP::CPU::MT::Profiler::EventFinished(uint64_t time, std::string ident) {
 		ti = ti_search->second;
 	}
 
+	ti->current_->SetStarted(0);
 	ti->current_->GetTime() += time;
-	ti->current_->GetCount()++;
 	ti->current_ = ti->current_->GetParent();
 }
 
@@ -205,6 +214,9 @@ void EQP::CPU::MT::Profiler::Dump(std::ostream &stream, int num) {
 			sorted_vec.push_back(n);
 
 			total += t_iter.second->GetTime();
+			if(t_iter.second->GetStarted() > 0) {
+				total += GetCurrentTimer() - t_iter.second->GetStarted();
+			}
 		}
 		
 		std::sort(sorted_vec.begin(), sorted_vec.end(), 

eqperf/eqp_profiler.h

@@ -17,7 +17,7 @@
 #define _eqp_dump(strm, count) EQP::CPU::ST::GetProfiler().Dump(strm, count)
 #define _eqp_dump_file(name) char time_str[128]; \
 	time_t result = time(nullptr); \
-	strftime(time_str, sizeof(time_str), "%Y_%m_%d_%H:%M:%S", localtime(&result)); \
+	strftime(time_str, sizeof(time_str), "%Y_%m_%d_%H_%M_%S", localtime(&result)); \
 	std::string prof_name = "./profile/"; \
 	prof_name += name; \
 	prof_name += "_"; \
@@ -32,7 +32,18 @@
 #define _eqpn(x) EQP::CPU::MT::Event eqp_comb(eq_perf_event_, __LINE__) (__PRETTY_FUNCTION__, x);
 #define _eqp_clear() EQP::CPU::MT::GetProfiler().Clear()
 #define _eqp_dump(strm, count) EQP::CPU::MT::GetProfiler().Dump(strm, count)
-#define _eqp_dump_file() 
+#define _eqp_dump_file(name) char time_str[128]; \
+	time_t result = time(nullptr); \
+	strftime(time_str, sizeof(time_str), "%Y_%m_%d_%H_%M_%S", localtime(&result)); \
+	std::string prof_name = "./profile/"; \
+	prof_name += name; \
+	prof_name += "_"; \
+	prof_name += time_str; \
+	prof_name += ".log"; \
+	std::ofstream profile_out(prof_name, std::ofstream::out); \
+	if(profile_out.good()) { \
+		_eqp_dump(profile_out, 10); \
+	}
 #endif
 
 namespace EQP

eqperf/eqp_profiler_node.cpp

@@ -1,4 +1,5 @@
 #include "eqp_profiler_node.h"
+#include "eqp_profile_timer.h"
 #include <iostream>
 #include <iomanip>
 #include <algorithm>
@@ -6,6 +7,7 @@
 EQP::CPU::ProfilerNode::ProfilerNode() {
 	count_ = 0;
 	time_ = 0;
+	started_ = 0;
 	parent_ = nullptr;;
 }
 
@@ -18,12 +20,17 @@ EQP::CPU::ProfilerNode::~ProfilerNode() {
 void EQP::CPU::ProfilerNode::Dump(std::ostream &stream, const std::string &func, uint64_t total_time, int node_level, int num) {
 
 	if(node_level >= 1) {
-		stream << std::setw(node_level * 2) << " ";
+		stream << std::setw(node_level * 4) << " ";
 	}
 
-	double m_cycles = time_ / 1000.0;
+	double m_cycles = static_cast<double>(time_);
+	if(started_) {
+		m_cycles += GetCurrentTimer() - started_;
+	}
+
+	double percentage = m_cycles * 100 / static_cast<double>(total_time);
+	m_cycles = m_cycles / 1000.0;
 	double m_avg_cycles = m_cycles / count_;
-	double percentage = time_ * 100 / static_cast<double>(total_time);
 
 	std::streamsize p = stream.precision();
 

eqperf/eqp_profiler_node.h

@@ -19,6 +19,9 @@ namespace EQP
 
 			inline void SetTime(uint64_t t) { time_ = t; }
 			inline uint64_t& GetTime() { return time_; }
+			
+			inline void SetStarted(uint64_t t) { started_ = t; }
+			inline uint64_t& GetStarted() { return started_; }
 
 			inline void SetParent(ProfilerNode *p) { parent_ = p; }
 			inline ProfilerNode* GetParent() { return parent_; }
@@ -29,6 +32,7 @@ namespace EQP
 		private:
 			uint64_t count_;
 			uint64_t time_;
+			uint64_t started_;
 			ProfilerNode *parent_;
 			std::unordered_map<std::string, ProfilerNode*> nodes_;
 		};