Tekkotsu Homepage
Demos
Overview
Downloads
Dev. Resources
Reference
Credits

Profiler.cc

Go to the documentation of this file.
00001 #include "Profiler.h"
00002 #include "debuget.h"
00003 #include <cmath>
00004 
00005 const float Profiler::HistCurve = 4.05f;
00006 
00007 float Profiler::buckets[Profiler::HistSize];
00008 
00009 unsigned int Profiler::infosOffset=((size_t)(&static_cast<ProfilerOfSize<1>*>(NULL)[1].infos))-((size_t)(&static_cast<ProfilerOfSize<1>*>(NULL)[1].prof));
00010 
00011 ProfilerOfSize<20> * mainProfiler=NULL;
00012 ProfilerOfSize<06> * motionProfiler=NULL;
00013 ProfilerOfSize<06> * soundProfiler=NULL;
00014 
00015 /*! Tells the profiler that this is now the active timer, so new timers will fit "under" this.\n
00016  *  Timer isn't actually started here, lets Profiler::setCurrent do that.
00017  *  @param prof profiler to report results to.  If is NULL, does nothing.
00018  *  @param id id number for this function.  See Profiler::getNewID() for what you should pass this */
00019 Profiler::Timer::Timer(unsigned int id, Profiler* prof) : _prof(prof), _id(id), _parent(-1U), _t(0L) {
00020   if(_prof!=NULL)
00021     _prof->setCurrent(*this);
00022 }
00023 
00024 Profiler::Timer::~Timer() {
00025   if(_prof!=NULL)
00026     _prof->finished(*this);
00027 }
00028 
00029 void Profiler::Timer::setID(unsigned int id, Profiler* prof) {
00030   _id=id;
00031   _prof=prof;
00032   if(_prof!=NULL)
00033     _prof->setCurrent(*this);
00034 } 
00035 
00036 Profiler::SectionInfo::SectionInfo()
00037   : totalTime(0L),lastTime(0L),totalInterval(0L),childTime(0L),execExpAvg(0),interExpAvg(0),calls(0)
00038 {
00039   name[0]='\0';
00040   for(unsigned int j=0; j<HistSize; j++)
00041     execHist[j]=interHist[j]=0;
00042 }
00043 
00044 void Profiler::SectionInfo::reset() {
00045   totalTime.Set(0L);
00046   lastTime.Set();
00047   totalInterval.Set(0L);
00048   childTime.Set(0L);
00049   execExpAvg=0;
00050   interExpAvg=0;
00051   for(unsigned int j=0; j<HistSize; j++)
00052     execHist[j]=interHist[j]=0;
00053   calls=0;
00054 }
00055 
00056 void Profiler::initBuckets() {
00057   float g=HistTime/std::pow(HistSize,HistCurve)/1000;
00058   for(unsigned int i=1; i<=HistSize; i++)
00059     buckets[i-1]=g*std::pow(i,HistCurve);
00060 }
00061 
00062 unsigned int Profiler::getNewID(const char* name) {
00063   ASSERTRETVAL(sectionsUsed<maxSections,"Too many sections registered (increase ProfilerOfSize<MaxSections>)",-1U);
00064   SectionInfo * infos=getInfos();
00065 #ifdef DEBUG
00066   for(unsigned int i=0; i<sectionsUsed; i++)
00067     ASSERTRETVAL(strncmp(infos[i].name,name,MaxSectionNameLen-1)!=0,"Already using name " << name,-1U);
00068 #endif
00069   unsigned int id=sectionsUsed++;
00070   strncpy(infos[id].name,name,MaxSectionNameLen-1);
00071   infos[id].name[MaxSectionNameLen-1]='\0'; //guarantees null-termination
00072   return id;
00073 }
00074 
00075 std::string Profiler::report() {
00076   char tmp[255];
00077   SectionInfo * infos=getInfos();
00078   sprintf(tmp,"Profiling information since: %f to %f\n",startTime.Value(),TimeET().Value());
00079   std::string ans(tmp);
00080   for(unsigned int i=0; i<sectionsUsed; i++) {
00081     sprintf(tmp,"%s:\n",infos[i].name); ans+=tmp;
00082     unsigned int calls=infos[i].calls;
00083     sprintf(tmp,"\t%d calls\n",calls); ans+=tmp;
00084     if(calls>0) {
00085       sprintf(tmp,"\t%f ms avg\n",infos[i].totalTime.Value()/calls*1000); ans+=tmp;
00086       sprintf(tmp,"\t%f ms exp.avg\n",infos[i].execExpAvg*1000); ans+=tmp;
00087       sprintf(tmp,"\t%f ms avg child time (%f%%)\n",infos[i].childTime.Value()/calls*1000,((int)(infos[i].childTime.Value()/infos[i].totalTime.Value()*1000))/10.0); ans+=tmp;
00088       sprintf(tmp,"\t%f ms avg inter (%f fps)\n",infos[i].totalInterval.Value()/calls*1000,calls/infos[i].totalInterval.Value()); ans+=tmp;
00089       sprintf(tmp,"\t%f ms exp.avg (%f fps)\n",infos[i].interExpAvg*1000,1/infos[i].interExpAvg); ans+=tmp;
00090       ans+="\tExec: ";
00091       for(unsigned int j=0; j<HistSize; j++) {
00092         sprintf(tmp,"%d ",infos[i].execHist[j]);
00093         ans+=tmp;
00094       }
00095       ans+="\n\tInter: ";
00096       for(unsigned int j=0; j<HistSize; j++) {
00097         sprintf(tmp,"%d ",infos[i].interHist[j]);
00098         ans+=tmp;
00099       }
00100       ans+="\n";
00101     }
00102   }
00103   ans+="Bucket distribution (in ms):\n\t0";
00104   for(unsigned int j=0; j<HistSize; j++) {
00105     sprintf(tmp,"<%.3g, ",buckets[j]*1000);
00106     ans+=tmp;
00107   }
00108   ans+="\n";
00109   return ans;
00110 }
00111 
00112 void Profiler::reset() {
00113   SectionInfo * infos=getInfos();
00114   for(unsigned int i=0; i<sectionsUsed; i++)
00115     infos[i].reset();
00116   startTime.Set();
00117 }
00118 
00119 Profiler::Profiler(unsigned int mx)
00120   : curSection(-1U), startTime(), gamma(.85f), maxSections(mx), sectionsUsed(0), autoInit()
00121 { }
00122 
00123 unsigned int Profiler::AutoInit::refcount=0;
00124 unsigned int Profiler::AutoInit::totalcount=0;
00125 
00126 Profiler::AutoInit::AutoInit() {
00127   if(totalcount==0)
00128     Profiler::initBuckets();
00129   totalcount++;
00130   refcount++;
00131 }
00132 
00133 Profiler::AutoInit::~AutoInit() { refcount--; }
00134 
00135 void Profiler::setCurrent(Timer& tr) {
00136   SectionInfo& info=getInfos()[tr._id];
00137   tr._parent=curSection;
00138   curSection=tr._id;
00139   info.calls++;
00140   if(info.calls>1) {
00141     TimeET diff=info.lastTime.Age();
00142     info.totalInterval+=diff;
00143     if(info.calls==2)
00144       info.interExpAvg=(float)diff.Value();
00145     else
00146       info.interExpAvg=info.interExpAvg*gamma+(float)diff.Value()*(1-gamma);
00147     if(diff.Value()*1000>HistTime)
00148       info.interHist[HistSize-1]++;
00149     else
00150       info.interHist[getBucket((float)diff.Value())]++;
00151   }
00152   tr._t.Set(); //do last so profiling code won't throw off timing results (but makes childtime's a little bloated)
00153   info.lastTime=tr._t;
00154 }
00155 
00156 void Profiler::finished(Timer& tr) {
00157   TimeET diff=tr.elapsed(); //do immediately for accuracy
00158   SectionInfo& info=getInfos()[tr._id];
00159   info.totalTime+=diff;
00160   if(tr._parent!=-1U)
00161     getInfos()[tr._parent].childTime+=diff;
00162   //  ASSERT(info.calls!=0,"calls is 0 on finished");
00163   if(info.calls==1)
00164     info.execExpAvg=(float)diff.Value();
00165   else
00166     info.execExpAvg=info.execExpAvg*gamma+(float)diff.Value()*(1-gamma);
00167   if(diff.Value()*1000>HistTime)
00168     info.execHist[HistSize-1]++;
00169   else
00170     info.execHist[getBucket((float)diff.Value())]++;
00171   //the old way:
00172   //info.execHist[mathutils::log2t((unsigned int)(((1U<<31)/HistTime*2)*diff.Value()))]++;
00173   curSection=tr._parent;
00174 }
00175 
00176 /*! @file
00177  * @brief Implements Profiler, which managers a hierarchy of timers for profiling time spent in code
00178  * @author ejt (Creator)
00179  */

Tekkotsu v5.1CVS
Generated Mon May 9 04:58:49 2016 by Doxygen 1.6.3