Make Profiler able to report number of calls per second

diff --git a/source/debug/profiler.cpp b/source/debug/profiler.cpp
index 6cce271983022302a6a3820acf20e049d02d7143..38681ed9fd2d5103c685d567a88690600cda36a8 100644 (file)
--- 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 5ec8f3f1fcafa5dae8ebe4508a5b02abaeb7e1f3..ad0653c0697f566b31f356974733293277d6e63b 100644 (file)
--- 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();