Profiler.cpp

00001 /***************************************************************************
00002  *                                                                         *
00003  *   (c) Art Tevs, MPI Informatik Saarbruecken                             *
00004  *       mailto: <tevs@mpi-sb.mpg.de>                                      *
00005  *                                                                         *
00006  *   This program is free software; you can redistribute it and/or modify  *
00007  *   it under the terms of the GNU General Public License as published by  *
00008  *   the Free Software Foundation; either version 2 of the License, or     *
00009  *   (at your option) any later version.                                   *
00010  *                                                                         *
00011  ***************************************************************************/
00012 
00013 
00014 //----------------------------------------------------------------------------------
00015 // Includes
00016 //----------------------------------------------------------------------------------
00017 #include "Engine.h"
00018 #include "Profiler.h"
00019 #include "Exception.h"
00020 #include "TimeSource.h"
00021 
00022 namespace nrEngine{
00023 
00024         //--------------------------------------------------------------------
00025         Profile::Profile(const std::string& name, bool isSystemProfile) : mName(name), mSystemProfile(isSystemProfile)
00026         {
00027                 Engine::sProfiler()->beginProfile(mName, isSystemProfile);
00028         }
00029         
00030         //--------------------------------------------------------------------
00031         Profile::~Profile()
00032         {
00033                 Engine::sProfiler()->endProfile(mName, mSystemProfile);
00034         }
00035         
00036         
00037         
00038         //--------------------------------------------------------------------
00039         Profiler::Profiler(SharedPtr<TimeSource> timeSource)
00040         {
00041                 mTimeSource = timeSource;
00042                 mTotalFrameTime = 0;
00043                 mEnabled = mNewEnableState = true; // the profiler starts out as enabled
00044                 mEnableStateChangePending = false;
00045                 mEngineProfileEnabled = false;
00046         }
00047         
00048         //--------------------------------------------------------------------
00049         Profiler::~Profiler()
00050         {
00051                 // clear all our lists
00052                 mProfiles.clear();
00053                 mProfileFrame.clear();
00054                 mProfileHistoryMap.clear();
00055                 mProfileHistory.clear();
00056         }       
00057         
00058         //--------------------------------------------------------------------
00059         void Profiler::beginProfile(const std::string& profileName, bool isSystemProfile) {
00060         
00061                 // if the profiler is enabled
00062                 if (!mEnabled || (isSystemProfile && !mEngineProfileEnabled))
00063                         return;
00064         
00065                 // need a timer to profile!
00066                 NR_ASSERT (mTimeSource && "Time Source is not set!");
00067 
00068                 // empty string is reserved for the root
00069                 NR_ASSERT ((profileName != "") && ("Profile name can't be an empty string"));
00070         
00071                 // make sure this profile isn't being used more than once
00072                 /*ProfileStack::iterator iter;
00073                 for (iter = mProfiles.begin(); iter != mProfiles.end(); iter++)
00074                         if ((*iter).name == profileName)        
00075                                 break;
00076                 */
00077                                 
00078                 //NR_ASSERT ((iter == mProfiles.end()) && ("This profile name is already being used"));
00079 
00080                 // profile instance
00081                 ProfileInstance p;
00082         
00083                 // this is the root, it has no parent
00084                 if (mProfiles.empty()) {
00085         
00086                         p.parent = "";
00087         
00088                 // otherwise peek at the stack and use the top as the parent
00089                 } else {
00090         
00091                         ProfileInstance parent = mProfiles.back();
00092                         p.parent = parent.name;
00093         
00094                 }
00095                 
00096                 // some iterator variables
00097                 ProfileFrameList::iterator fIter;
00098                 ProfileHistoryList::iterator hIter;
00099         
00100                 // we check to see if this profile has been called in the frame before
00101                 for (fIter = mProfileFrame.begin(); fIter != mProfileFrame.end(); fIter++)
00102                         if ((*fIter).name == profileName)
00103                                 break;
00104                 
00105                 // if it hasn't been called before, set its position in the stack
00106                 if (fIter == mProfileFrame.end()) {
00107                         ProfileFrame f;
00108                         f.name = profileName;
00109                         f.frameTime = 0;
00110                         f.frameTotalTime = 0;
00111                         f.calls = 0;
00112                         f.hierarchicalLvl = (uint32) mProfiles.size();
00113                         mProfileFrame.push_back(f);
00114                 }
00115         
00116                 // we check to see if this profile has been called in the app before
00117                 ProfileHistoryMap::iterator histMapIter;
00118                 histMapIter = mProfileHistoryMap.find(profileName);
00119         
00120                 // if not we add a profile with just the name into the history
00121                 if (histMapIter == mProfileHistoryMap.end()) {
00122                         ProfileHistory h;
00123                         h.name = profileName;
00124                         h.numCallsThisFrame = 0;
00125                         h.totalTime = 0;
00126                         h.totalCalls = 0;
00127                         h.maxTime = 0;
00128                         h.minTime = 1;
00129                         h.hierarchicalLvl = p.hierarchicalLvl;
00130                         h.currentTime = 0;
00131                         h.realTotalTime = 0;
00132                         h.realTime = 0;
00133                         h.isSystemProfile = isSystemProfile;
00134                         
00135                         // we add this to the history
00136                         hIter = mProfileHistory.insert(mProfileHistory.end(), h);
00137         
00138                         // for quick look-ups, we'll add it to the history map as well
00139                         mProfileHistoryMap.insert(std::pair< std::string, ProfileHistoryList::iterator>(profileName, hIter));
00140                 }
00141         
00142                 // add the stats to this profile and push it on the stack
00143                 // we do this at the very end of the function to get the most
00144                 // accurate timing results
00145                 p.name = profileName;
00146                 p.isSystemProfile = isSystemProfile;
00147                 p.currTime = mTimeSource->getTime();
00148                 p.accum = 0;
00149                 p.hierarchicalLvl = (uint32) mProfiles.size();
00150                 mProfiles.push_back(p);
00151         }
00152         
00153 
00154         //--------------------------------------------------------------------
00155         void Profiler::endProfile(const std::string& profileName, bool isSystemProfile) {
00156         
00157                 // if the profiler is enabled
00158                 if (!mEnabled || (isSystemProfile && !mEngineProfileEnabled))
00159                         return;
00160                 
00161                 // need a timer to profile!
00162                 NR_ASSERT (mTimeSource && "Timer not set!");
00163         
00164                 // get the end time of this profile
00165                 // we do this as close the beginning of this function as possible
00166                 // to get more accurate timing results
00167                 float64 endTime = mTimeSource->getTime();
00168         
00169                 // empty string is reserved for designating an empty parent
00170                 NR_ASSERT ((profileName != "") && ("Profile name can't be an empty string"));
00171                 
00172                 // stack shouldnt be empty
00173                 NR_ASSERT (!mProfiles.empty() && ("You have to begin any profile before stop it"));
00174         
00175                 // get the start of this profile
00176                 ProfileInstance bProfile;
00177                 bProfile = mProfiles.back();
00178                 mProfiles.pop_back();
00179         
00180                 // calculate the elapsed time of this profile
00181                 float64 timeElapsed = endTime - bProfile.currTime;
00182         
00183                 // update parent's accumalator if it isn't the root
00184                 if (bProfile.parent != "") {
00185                         // find the parent
00186                         ProfileStack::iterator iter;
00187                         for(iter = mProfiles.begin(); iter != mProfiles.end(); iter++)  
00188                                 if ((*iter).name == bProfile.parent)
00189                                         break;
00190         
00191                         // the parent should be found 
00192                         NR_ASSERT(iter != mProfiles.end());
00193         
00194                         // add this profile's time to the parent's accumulator
00195                         (*iter).accum += timeElapsed;   
00196                 }
00197         
00198                 // we find the profile in this frame
00199                 ProfileFrameList::iterator iter;
00200                 for (iter = mProfileFrame.begin(); iter != mProfileFrame.end(); iter++)
00201                         if ((*iter).name == bProfile.name)
00202                                 break;
00203         
00204                 // we subtract the time the children profiles took from this profile
00205                 (*iter).frameTime += timeElapsed - bProfile.accum;
00206                 (*iter).frameTotalTime += timeElapsed;
00207                 (*iter).calls++;
00208         
00209                 // the stack is empty and all the profiles have been completed
00210                 // we have reached the end of the frame so process the frame statistics
00211                 if (mProfiles.empty()) {
00212         
00213                         // we know that the time elapsed of the main loop is the total time the frame took
00214                         mTotalFrameTime = timeElapsed;
00215         
00216                         // we got all the information we need, so process the profiles
00217                         // for this frame
00218                         processFrameStats();
00219         
00220                         // clear the frame stats for next frame
00221                         mProfileFrame.clear();
00222                 
00223                         // if the profiler received a request to be enabled or disabled
00224                         // we reached the end of the frame so we can safely do this
00225                         if (mEnableStateChangePending) {
00226                                 changeEnableState();
00227                         }
00228         
00229                 }
00230         
00231         }
00232         
00233         //--------------------------------------------------------------------
00234         void Profiler::processFrameStats() {
00235         
00236                 // if the profiler is enabled
00237                 if (!mEnabled)
00238                         return;
00239 
00240                 ProfileFrameList::iterator frameIter;
00241                 ProfileHistoryList::iterator historyIter;
00242         
00243                 // we set the number of times each profile was called per frame to 0
00244                 // because not all profiles are called every frame
00245                 for (historyIter = mProfileHistory.begin(); historyIter != mProfileHistory.end(); historyIter++)
00246                         (*historyIter).numCallsThisFrame = 0;
00247         
00248                 // iterate through each of the profiles processed during this frame
00249                 for (frameIter = mProfileFrame.begin(); frameIter != mProfileFrame.end(); frameIter++) {
00250         
00251                         std::string s = (*frameIter).name;
00252         
00253                         // use our map to find the appropriate profile in the history
00254                         historyIter = (*mProfileHistoryMap.find(s)).second;
00255         
00256                         // extract the frame stats
00257                         float64 frameTime = (*frameIter).frameTime;
00258                         uint32 calls = (*frameIter).calls;
00259                         uint32 lvl = (*frameIter).hierarchicalLvl;
00260         
00261                         // calculate what percentage of frame time this profile took
00262                         float32 framePercentage = static_cast<float32>(frameTime) / static_cast<float32>(mTotalFrameTime);
00263         
00264                         // update the profile stats
00265                         (*historyIter).currentTime = framePercentage;
00266                         (*historyIter).totalTime += framePercentage;
00267                         (*historyIter).totalCalls++;
00268                         (*historyIter).numCallsThisFrame = calls;
00269                         (*historyIter).hierarchicalLvl = lvl;
00270                         (*historyIter).realTime += frameTime;
00271                         (*historyIter).realTotalTime += (*frameIter).frameTotalTime;
00272                         
00273                         // if we find a new minimum for this profile, update it
00274                         if ((framePercentage) < ((*historyIter).minTime)) {     
00275                                 (*historyIter).minTime = framePercentage;
00276                         }
00277         
00278                         // if we find a new maximum for this profile, update it
00279                         if ((framePercentage) > ((*historyIter).maxTime)) {     
00280                                 (*historyIter).maxTime = framePercentage;
00281                         }
00282         
00283                 }
00284         
00285         }
00286 
00287         //-----------------------------------------------------------------------
00288         void Profiler::setEnable(bool enable)
00289         {
00290 
00291                 // check whenever we get new state
00292                 if (mEnabled != enable){
00293                         mEnableStateChangePending = true;
00294                         mNewEnableState = enable;               
00295                 }
00296                 
00297         }
00298         
00299         //-----------------------------------------------------------------------
00300         void Profiler::reset() {
00301         
00302                 ProfileHistoryList::iterator iter;
00303                 for (iter = mProfileHistory.begin(); iter != mProfileHistory.end(); iter++) {
00304                         (*iter).currentTime = (*iter).maxTime = (*iter).totalTime = 0;
00305                         (*iter).numCallsThisFrame = (*iter).totalCalls = 0;
00306                         (*iter).minTime = 1;    
00307                 }
00308         
00309         }
00310 
00311         //--------------------------------------------------------------------
00312         void Profiler::logResults(Log::LogTarget lt){
00313 
00314                 // if the profiler is enabled
00315                 if (!mEnabled)
00316                         return;
00317                 
00318                 // sort the history so we get profiles that need more time on the top
00319                 mProfileHistory.sort();
00320                                 
00321                 ProfileHistoryList::iterator iter;
00322         
00323                 NR_Log(lt,  "--------------------------------------Profiler Results------------------------------");
00324                 NR_Log(lt,  "| Name                        | Avg(\%) | Max(\%) | Min(\%) | Time sec     |  Calls   |");
00325                 NR_Log(lt,  "------------------------------------------------------------------------------------");
00326 
00327                 // log system results
00328                 NR_Log(lt,  "| System Profiles                                                                  |");
00329                 for (iter = mProfileHistory.begin(); iter != mProfileHistory.end(); iter++)
00330                 {
00331                         // only for system profiles
00332                         if (iter->isSystemProfile){
00333                                 // create an indent that represents the hierarchical order of the profile
00334                                 std::string indent = "   ";
00335                                 //for (uint32 i = 0; i < (*iter).hierarchicalLvl; i++)
00336                                 //      indent = indent + " --";
00337                                 indent += (*iter).name;
00338                                 indent.resize(27, ' ');
00339         
00340                                 logLine(indent.c_str(), iter->minTime, iter->maxTime, iter->realTime, iter->totalTime, iter->totalCalls);
00341                         }
00342                 }
00343                 
00344                 // log application results
00345                 NR_Log(lt,  "|----------------------------------------------------------------------------------|");
00346                 NR_Log(lt,  "| Application Profiles                                                             |");
00347                 for (iter = mProfileHistory.begin(); iter != mProfileHistory.end(); iter++)
00348                 {
00349                         // only for application profiles
00350                         if (!iter->isSystemProfile){
00351                                 // create an indent that represents the hierarchical order of the profile
00352                                 std::string indent = "   ";
00353                                 //for (uint32 i = 0; i < (*iter).hierarchicalLvl; i++)
00354                                 //      indent = indent + " --";
00355                                 indent += (*iter).name;
00356                                 indent.resize(27, ' ');
00357         
00358                                 logLine(indent.c_str(), iter->minTime, iter->maxTime, iter->realTime, iter->totalTime, iter->totalCalls);
00359                         }
00360                 }
00361         
00362                 NR_Log(lt,  "|                                                                                  |");
00363                 NR_Log(lt,  "------------------------------------------------------------------------------------");
00364 
00365         }
00366 
00367         //-----------------------------------------------------------------------
00368         void Profiler::logLine(const char* name, float32 min, float32 max, float32 frameTime, float32 totalTime, uint32 totalCalls)
00369         {
00370                 // create some strings containing the statistics
00371                 char avg[32];
00372                 sprintf(avg, "%2.2f", (totalTime / totalCalls) * 100.0f);
00373 
00374                 char smin[32];
00375                 sprintf(smin, "%2.2f", min * 100.0f);
00376 
00377                 char smax[32];
00378                 sprintf(smax, "%2.2f", max * 100.0f);
00379 
00380                 char tim[32];
00381                 sprintf(tim, "%4.6f", frameTime);
00382 
00383                 char cls[32];
00384                 sprintf(cls, "%d", totalCalls);
00385 
00386                 char ttm[32];
00387                 sprintf(ttm, "%4.6f", totalTime);
00388                 
00389                 NR_Log(Log::LOG_APP, "| %s |  %-6s|  %-6s|  %-6s| %-13s| %-9s|", name, avg, smax, smin, tim, cls);
00390         }
00391         
00392 
00393         //-----------------------------------------------------------------------
00394         void Profiler::changeEnableState() {    
00395                 mEnabled = mNewEnableState;
00396                 mEnableStateChangePending = false;
00397         }
00398 
00399         
00400         //-----------------------------------------------------------------------
00401         bool Profiler::ProfileHistory::operator <(const Profiler::ProfileHistory& p)
00402         {
00403                 float my_avg = totalTime / totalCalls;
00404                 float it_avg = p.totalTime / p.totalCalls;
00405                 return (it_avg < my_avg);
00406         }
00407 
00408 }; // end namespace
00409 

Generated on Wed Sep 12 23:19:42 2007 for nrEngine by  doxygen 1.5.1