From 4798e6e5eac917b6225a1295fa5b118d88345237 Mon Sep 17 00:00:00 2001
From: Mikko Rasa <tdb@tdb.fi>
Date: Sun, 16 Sep 2012 23:36:53 +0300
Subject: [PATCH] Make Profiler able to report number of calls per second

---
 source/debug/profiler.cpp | 30 ++++++++++++++++++++++++++----
 source/debug/profiler.h   | 12 +++++++++++-
 2 files changed, 37 insertions(+), 5 deletions(-)

diff --git a/source/debug/profiler.cpp b/source/debug/profiler.cpp
index 6cce271..38681ed 100644
--- a/source/debug/profiler.cpp
+++ b/source/debug/profiler.cpp
@@ -25,8 +25,9 @@ void Profiler::set_period(unsigned p)
 		if(p==0)
 			si.history.clear();
 		else
-			si.history.assign(period, Time::zero);
+			si.history.assign(period, CallInfo());
 		si.hist_pos = 0;
+		si.hist_full = false;
 	}
 }
 
@@ -52,6 +53,7 @@ void Profiler::record(const ProfilingScope &scope)
 	if(i==scopes.end())
 	{
 		i = scopes.insert(map<string, ScopeInfo>::value_type(scope.get_name(), ScopeInfo())).first;
+		i->second.first_call = scope.get_entry_time();
 		i->second.history.resize(period);
 	}
 
@@ -63,13 +65,31 @@ void Profiler::record(const ProfilingScope &scope)
 	si.self_time += scope.get_time_spent()-scope.get_child_time();
 	if(period)
 	{
-		si.avg_time += scope.get_time_spent()/period-si.history[si.hist_pos]/period;
-		si.history[si.hist_pos++] = scope.get_time_spent();
+		si.avg_time += scope.get_time_spent()/period-si.history[si.hist_pos].duration/period;
+
+		CallInfo &ci = si.history[si.hist_pos];
+		Time::TimeStamp old_entry = ci.entry_time;
+		ci.entry_time = scope.get_entry_time();
+		ci.duration = scope.get_time_spent();
+
+		++si.hist_pos;
 		if(si.hist_pos>=period)
 			si.hist_pos -= period;
+
+		if(si.hist_full)
+			si.calls_per_sec = period*Time::sec/(scope.get_entry_time()-old_entry);
+		else if(si.hist_pos>1)
+			si.calls_per_sec = (si.hist_pos-1)*Time::sec/(scope.get_entry_time()-si.history.front().entry_time);
+
+		if(si.hist_pos==0)
+			si.hist_full = true;
 	}
 	else
+	{
 		si.avg_time = si.total_time/si.calls;
+		if(si.calls>1)
+			si.calls_per_sec = (si.calls-1)*Time::sec/(scope.get_entry_time()-si.first_call);
+	}
 }
 
 const Profiler::ScopeInfo &Profiler::get_scope(const string &sn) const
@@ -80,7 +100,9 @@ const Profiler::ScopeInfo &Profiler::get_scope(const string &sn) const
 
 Profiler::ScopeInfo::ScopeInfo():
 	calls(0),
-	hist_pos(0)
+	calls_per_sec(0),
+	hist_pos(0),
+	hist_full(false)
 { }
 
 } // namespace Debug
diff --git a/source/debug/profiler.h b/source/debug/profiler.h
index 5ec8f3f..ad0653c 100644
--- a/source/debug/profiler.h
+++ b/source/debug/profiler.h
@@ -5,6 +5,7 @@
 #include <string>
 #include <vector>
 #include <msp/time/timedelta.h>
+#include <msp/time/timestamp.h>
 
 namespace Msp {
 namespace Debug {
@@ -25,14 +26,23 @@ Profiler for each thread.
 class Profiler
 {
 public:
+	struct CallInfo
+	{
+		Msp::Time::TimeStamp entry_time;
+		Msp::Time::TimeDelta duration;
+	};
+
 	struct ScopeInfo
 	{
+		Time::TimeStamp first_call;
 		unsigned calls;
 		Time::TimeDelta total_time;
 		Time::TimeDelta self_time;
 		Time::TimeDelta avg_time;
-		std::vector<Time::TimeDelta> history;
+		float calls_per_sec;
+		std::vector<CallInfo> history;
 		unsigned hist_pos;
+		bool hist_full;
 		std::map<std::string, unsigned> called_from;
 
 		ScopeInfo();
-- 
2.43.0