00001
00002
00003
00004
00005
00006
00007
00008
00009
00010
00011
00012
00013
00014
00015
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;
00044 mEnableStateChangePending = false;
00045 mEngineProfileEnabled = false;
00046 }
00047
00048
00049 Profiler::~Profiler()
00050 {
00051
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
00062 if (!mEnabled || (isSystemProfile && !mEngineProfileEnabled))
00063 return;
00064
00065
00066 NR_ASSERT (mTimeSource && "Time Source is not set!");
00067
00068
00069 NR_ASSERT ((profileName != "") && ("Profile name can't be an empty string"));
00070
00071
00072
00073
00074
00075
00076
00077
00078
00079
00080
00081 ProfileInstance p;
00082
00083
00084 if (mProfiles.empty()) {
00085
00086 p.parent = "";
00087
00088
00089 } else {
00090
00091 ProfileInstance parent = mProfiles.back();
00092 p.parent = parent.name;
00093
00094 }
00095
00096
00097 ProfileFrameList::iterator fIter;
00098 ProfileHistoryList::iterator hIter;
00099
00100
00101 for (fIter = mProfileFrame.begin(); fIter != mProfileFrame.end(); fIter++)
00102 if ((*fIter).name == profileName)
00103 break;
00104
00105
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
00117 ProfileHistoryMap::iterator histMapIter;
00118 histMapIter = mProfileHistoryMap.find(profileName);
00119
00120
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
00136 hIter = mProfileHistory.insert(mProfileHistory.end(), h);
00137
00138
00139 mProfileHistoryMap.insert(std::pair< std::string, ProfileHistoryList::iterator>(profileName, hIter));
00140 }
00141
00142
00143
00144
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
00158 if (!mEnabled || (isSystemProfile && !mEngineProfileEnabled))
00159 return;
00160
00161
00162 NR_ASSERT (mTimeSource && "Timer not set!");
00163
00164
00165
00166
00167 float64 endTime = mTimeSource->getTime();
00168
00169
00170 NR_ASSERT ((profileName != "") && ("Profile name can't be an empty string"));
00171
00172
00173 NR_ASSERT (!mProfiles.empty() && ("You have to begin any profile before stop it"));
00174
00175
00176 ProfileInstance bProfile;
00177 bProfile = mProfiles.back();
00178 mProfiles.pop_back();
00179
00180
00181 float64 timeElapsed = endTime - bProfile.currTime;
00182
00183
00184 if (bProfile.parent != "") {
00185
00186 ProfileStack::iterator iter;
00187 for(iter = mProfiles.begin(); iter != mProfiles.end(); iter++)
00188 if ((*iter).name == bProfile.parent)
00189 break;
00190
00191
00192 NR_ASSERT(iter != mProfiles.end());
00193
00194
00195 (*iter).accum += timeElapsed;
00196 }
00197
00198
00199 ProfileFrameList::iterator iter;
00200 for (iter = mProfileFrame.begin(); iter != mProfileFrame.end(); iter++)
00201 if ((*iter).name == bProfile.name)
00202 break;
00203
00204
00205 (*iter).frameTime += timeElapsed - bProfile.accum;
00206 (*iter).frameTotalTime += timeElapsed;
00207 (*iter).calls++;
00208
00209
00210
00211 if (mProfiles.empty()) {
00212
00213
00214 mTotalFrameTime = timeElapsed;
00215
00216
00217
00218 processFrameStats();
00219
00220
00221 mProfileFrame.clear();
00222
00223
00224
00225 if (mEnableStateChangePending) {
00226 changeEnableState();
00227 }
00228
00229 }
00230
00231 }
00232
00233
00234 void Profiler::processFrameStats() {
00235
00236
00237 if (!mEnabled)
00238 return;
00239
00240 ProfileFrameList::iterator frameIter;
00241 ProfileHistoryList::iterator historyIter;
00242
00243
00244
00245 for (historyIter = mProfileHistory.begin(); historyIter != mProfileHistory.end(); historyIter++)
00246 (*historyIter).numCallsThisFrame = 0;
00247
00248
00249 for (frameIter = mProfileFrame.begin(); frameIter != mProfileFrame.end(); frameIter++) {
00250
00251 std::string s = (*frameIter).name;
00252
00253
00254 historyIter = (*mProfileHistoryMap.find(s)).second;
00255
00256
00257 float64 frameTime = (*frameIter).frameTime;
00258 uint32 calls = (*frameIter).calls;
00259 uint32 lvl = (*frameIter).hierarchicalLvl;
00260
00261
00262 float32 framePercentage = static_cast<float32>(frameTime) / static_cast<float32>(mTotalFrameTime);
00263
00264
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
00274 if ((framePercentage) < ((*historyIter).minTime)) {
00275 (*historyIter).minTime = framePercentage;
00276 }
00277
00278
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
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
00315 if (!mEnabled)
00316 return;
00317
00318
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
00328 NR_Log(lt, "| System Profiles |");
00329 for (iter = mProfileHistory.begin(); iter != mProfileHistory.end(); iter++)
00330 {
00331
00332 if (iter->isSystemProfile){
00333
00334 std::string indent = " ";
00335
00336
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
00345 NR_Log(lt, "|----------------------------------------------------------------------------------|");
00346 NR_Log(lt, "| Application Profiles |");
00347 for (iter = mProfileHistory.begin(); iter != mProfileHistory.end(); iter++)
00348 {
00349
00350 if (!iter->isSystemProfile){
00351
00352 std::string indent = " ";
00353
00354
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
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 };
00409