source: nrEngine/src/Profiler.cpp @ 30

Revision 30, 13.2 KB checked in by art, 12 years ago (diff)

::std wurde durch std ueberall ersetzt!

Line 
1/***************************************************************************
2 *                                                                         *
3 *   (c) Art Tevs, MPI Informatik Saarbruecken                             *
4 *       mailto: <tevs@mpi-sb.mpg.de>                                      *
5 *                                                                         *
6 *   This program is free software; you can redistribute it and/or modify  *
7 *   it under the terms of the GNU General Public License as published by  *
8 *   the Free Software Foundation; either version 2 of the License, or     *
9 *   (at your option) any later version.                                   *
10 *                                                                         *
11 ***************************************************************************/
12
13
14//----------------------------------------------------------------------------------
15// Includes
16//----------------------------------------------------------------------------------
17#include "Engine.h"
18#include "Profiler.h"
19#include "Exception.h"
20#include "TimeSource.h"
21
22namespace nrEngine{
23
24        //--------------------------------------------------------------------
25        Profile::Profile(const std::string& name, bool isSystemProfile) : mName(name), mSystemProfile(isSystemProfile)
26        {
27                Engine::sProfiler()->beginProfile(mName, isSystemProfile);
28        }
29       
30        //--------------------------------------------------------------------
31        Profile::~Profile()
32        {
33                Engine::sProfiler()->endProfile(mName, mSystemProfile);
34        }
35       
36       
37       
38        //--------------------------------------------------------------------
39        Profiler::Profiler(SharedPtr<TimeSource> timeSource)
40        {
41                mTimeSource = timeSource;
42                mTotalFrameTime = 0;
43                mEnabled = mNewEnableState = true; // the profiler starts out as enabled
44                mEnableStateChangePending = false;
45                mEngineProfileEnabled = false;
46        }
47       
48        //--------------------------------------------------------------------
49        Profiler::~Profiler()
50        {
51                // clear all our lists
52                mProfiles.clear();
53                mProfileFrame.clear();
54                mProfileHistoryMap.clear();
55                mProfileHistory.clear();
56        }       
57       
58        //--------------------------------------------------------------------
59        void Profiler::beginProfile(const std::string& profileName, bool isSystemProfile) {
60       
61                // if the profiler is enabled
62                if (!mEnabled || (isSystemProfile && !mEngineProfileEnabled))
63                        return;
64       
65                // need a timer to profile!
66                NR_ASSERT (mTimeSource && "Time Source is not set!");
67
68                // empty string is reserved for the root
69                NR_ASSERT ((profileName != "") && ("Profile name can't be an empty string"));
70       
71                // make sure this profile isn't being used more than once
72                /*ProfileStack::iterator iter;
73                for (iter = mProfiles.begin(); iter != mProfiles.end(); iter++)
74                        if ((*iter).name == profileName)       
75                                break;
76                */
77                               
78                //NR_ASSERT ((iter == mProfiles.end()) && ("This profile name is already being used"));
79
80                // profile instance
81                ProfileInstance p;
82       
83                // this is the root, it has no parent
84                if (mProfiles.empty()) {
85       
86                        p.parent = "";
87       
88                // otherwise peek at the stack and use the top as the parent
89                } else {
90       
91                        ProfileInstance parent = mProfiles.back();
92                        p.parent = parent.name;
93       
94                }
95               
96                // some iterator variables
97                ProfileFrameList::iterator fIter;
98                ProfileHistoryList::iterator hIter;
99       
100                // we check to see if this profile has been called in the frame before
101                for (fIter = mProfileFrame.begin(); fIter != mProfileFrame.end(); fIter++)
102                        if ((*fIter).name == profileName)
103                                break;
104               
105                // if it hasn't been called before, set its position in the stack
106                if (fIter == mProfileFrame.end()) {
107                        ProfileFrame f;
108                        f.name = profileName;
109                        f.frameTime = 0;
110                        f.frameTotalTime = 0;
111                        f.calls = 0;
112                        f.hierarchicalLvl = (uint32) mProfiles.size();
113                        mProfileFrame.push_back(f);
114                }
115       
116                // we check to see if this profile has been called in the app before
117                ProfileHistoryMap::iterator histMapIter;
118                histMapIter = mProfileHistoryMap.find(profileName);
119       
120                // if not we add a profile with just the name into the history
121                if (histMapIter == mProfileHistoryMap.end()) {
122                        ProfileHistory h;
123                        h.name = profileName;
124                        h.numCallsThisFrame = 0;
125                        h.totalTime = 0;
126                        h.totalCalls = 0;
127                        h.maxTime = 0;
128                        h.minTime = 1;
129                        h.hierarchicalLvl = p.hierarchicalLvl;
130                        h.currentTime = 0;
131                        h.realTotalTime = 0;
132                        h.realTime = 0;
133                        h.isSystemProfile = isSystemProfile;
134                       
135                        // we add this to the history
136                        hIter = mProfileHistory.insert(mProfileHistory.end(), h);
137       
138                        // for quick look-ups, we'll add it to the history map as well
139                        mProfileHistoryMap.insert(std::pair< std::string, ProfileHistoryList::iterator>(profileName, hIter));
140                }
141       
142                // add the stats to this profile and push it on the stack
143                // we do this at the very end of the function to get the most
144                // accurate timing results
145                p.name = profileName;
146                p.isSystemProfile = isSystemProfile;
147                p.currTime = mTimeSource->getTime();
148                p.accum = 0;
149                p.hierarchicalLvl = (uint32) mProfiles.size();
150                mProfiles.push_back(p);
151        }
152       
153
154        //--------------------------------------------------------------------
155        void Profiler::endProfile(const std::string& profileName, bool isSystemProfile) {
156       
157                // if the profiler is enabled
158                if (!mEnabled || (isSystemProfile && !mEngineProfileEnabled))
159                        return;
160               
161                // need a timer to profile!
162                NR_ASSERT (mTimeSource && "Timer not set!");
163       
164                // get the end time of this profile
165                // we do this as close the beginning of this function as possible
166                // to get more accurate timing results
167                float64 endTime = mTimeSource->getTime();
168       
169                // empty string is reserved for designating an empty parent
170                NR_ASSERT ((profileName != "") && ("Profile name can't be an empty string"));
171               
172                // stack shouldnt be empty
173                NR_ASSERT (!mProfiles.empty() && ("You have to begin any profile before stop it"));
174       
175                // get the start of this profile
176                ProfileInstance bProfile;
177                bProfile = mProfiles.back();
178                mProfiles.pop_back();
179       
180                // calculate the elapsed time of this profile
181                float64 timeElapsed = endTime - bProfile.currTime;
182       
183                // update parent's accumalator if it isn't the root
184                if (bProfile.parent != "") {
185                        // find the parent
186                        ProfileStack::iterator iter;
187                        for(iter = mProfiles.begin(); iter != mProfiles.end(); iter++) 
188                                if ((*iter).name == bProfile.parent)
189                                        break;
190       
191                        // the parent should be found
192                        NR_ASSERT(iter != mProfiles.end());
193       
194                        // add this profile's time to the parent's accumulator
195                        (*iter).accum += timeElapsed;   
196                }
197       
198                // we find the profile in this frame
199                ProfileFrameList::iterator iter;
200                for (iter = mProfileFrame.begin(); iter != mProfileFrame.end(); iter++)
201                        if ((*iter).name == bProfile.name)
202                                break;
203       
204                // we subtract the time the children profiles took from this profile
205                (*iter).frameTime += timeElapsed - bProfile.accum;
206                (*iter).frameTotalTime += timeElapsed;
207                (*iter).calls++;
208       
209                // the stack is empty and all the profiles have been completed
210                // we have reached the end of the frame so process the frame statistics
211                if (mProfiles.empty()) {
212       
213                        // we know that the time elapsed of the main loop is the total time the frame took
214                        mTotalFrameTime = timeElapsed;
215       
216                        // we got all the information we need, so process the profiles
217                        // for this frame
218                        processFrameStats();
219       
220                        // clear the frame stats for next frame
221                        mProfileFrame.clear();
222               
223                        // if the profiler received a request to be enabled or disabled
224                        // we reached the end of the frame so we can safely do this
225                        if (mEnableStateChangePending) {
226                                changeEnableState();
227                        }
228       
229                }
230       
231        }
232       
233        //--------------------------------------------------------------------
234        void Profiler::processFrameStats() {
235       
236                // if the profiler is enabled
237                if (!mEnabled)
238                        return;
239
240                ProfileFrameList::iterator frameIter;
241                ProfileHistoryList::iterator historyIter;
242       
243                // we set the number of times each profile was called per frame to 0
244                // because not all profiles are called every frame
245                for (historyIter = mProfileHistory.begin(); historyIter != mProfileHistory.end(); historyIter++)
246                        (*historyIter).numCallsThisFrame = 0;
247       
248                // iterate through each of the profiles processed during this frame
249                for (frameIter = mProfileFrame.begin(); frameIter != mProfileFrame.end(); frameIter++) {
250       
251                        std::string s = (*frameIter).name;
252       
253                        // use our map to find the appropriate profile in the history
254                        historyIter = (*mProfileHistoryMap.find(s)).second;
255       
256                        // extract the frame stats
257                        float64 frameTime = (*frameIter).frameTime;
258                        uint32 calls = (*frameIter).calls;
259                        uint32 lvl = (*frameIter).hierarchicalLvl;
260       
261                        // calculate what percentage of frame time this profile took
262                        float32 framePercentage = static_cast<float32>(frameTime) / static_cast<float32>(mTotalFrameTime);
263       
264                        // update the profile stats
265                        (*historyIter).currentTime = framePercentage;
266                        (*historyIter).totalTime += framePercentage;
267                        (*historyIter).totalCalls++;
268                        (*historyIter).numCallsThisFrame = calls;
269                        (*historyIter).hierarchicalLvl = lvl;
270                        (*historyIter).realTime += frameTime;
271                        (*historyIter).realTotalTime += (*frameIter).frameTotalTime;
272                       
273                        // if we find a new minimum for this profile, update it
274                        if ((framePercentage) < ((*historyIter).minTime)) {     
275                                (*historyIter).minTime = framePercentage;
276                        }
277       
278                        // if we find a new maximum for this profile, update it
279                        if ((framePercentage) > ((*historyIter).maxTime)) {     
280                                (*historyIter).maxTime = framePercentage;
281                        }
282       
283                }
284       
285        }
286
287        //-----------------------------------------------------------------------
288        void Profiler::setEnable(bool enable)
289        {
290
291                // check whenever we get new state
292                if (mEnabled != enable){
293                        mEnableStateChangePending = true;
294                        mNewEnableState = enable;               
295                }
296               
297        }
298       
299        //-----------------------------------------------------------------------
300        void Profiler::reset() {
301       
302                ProfileHistoryList::iterator iter;
303                for (iter = mProfileHistory.begin(); iter != mProfileHistory.end(); iter++) {
304                        (*iter).currentTime = (*iter).maxTime = (*iter).totalTime = 0;
305                        (*iter).numCallsThisFrame = (*iter).totalCalls = 0;
306                        (*iter).minTime = 1;   
307                }
308       
309        }
310
311        //--------------------------------------------------------------------
312        void Profiler::logResults(Log::LogTarget lt){
313
314                // if the profiler is enabled
315                if (!mEnabled)
316                        return;
317               
318                // sort the history so we get profiles that need more time on the top
319                mProfileHistory.sort();
320                               
321                ProfileHistoryList::iterator iter;
322       
323                NR_Log(lt,  "--------------------------------------Profiler Results------------------------------");
324                NR_Log(lt,  "| Name                        | Avg(\%) | Max(\%) | Min(\%) | Time sec     |  Calls   |");
325                NR_Log(lt,  "------------------------------------------------------------------------------------");
326
327                // log system results
328                NR_Log(lt,  "| System Profiles                                                                  |");
329                for (iter = mProfileHistory.begin(); iter != mProfileHistory.end(); iter++)
330                {
331                        // only for system profiles
332                        if (iter->isSystemProfile){
333                                // create an indent that represents the hierarchical order of the profile
334                                std::string indent = "   ";
335                                //for (uint32 i = 0; i < (*iter).hierarchicalLvl; i++)
336                                //      indent = indent + " --";
337                                indent += (*iter).name;
338                                indent.resize(27, ' ');
339       
340                                logLine(indent.c_str(), iter->minTime, iter->maxTime, iter->realTime, iter->totalTime, iter->totalCalls);
341                        }
342                }
343               
344                // log application results
345                NR_Log(lt,  "|----------------------------------------------------------------------------------|");
346                NR_Log(lt,  "| Application Profiles                                                             |");
347                for (iter = mProfileHistory.begin(); iter != mProfileHistory.end(); iter++)
348                {
349                        // only for application profiles
350                        if (!iter->isSystemProfile){
351                                // create an indent that represents the hierarchical order of the profile
352                                std::string indent = "   ";
353                                //for (uint32 i = 0; i < (*iter).hierarchicalLvl; i++)
354                                //      indent = indent + " --";
355                                indent += (*iter).name;
356                                indent.resize(27, ' ');
357       
358                                logLine(indent.c_str(), iter->minTime, iter->maxTime, iter->realTime, iter->totalTime, iter->totalCalls);
359                        }
360                }
361       
362                NR_Log(lt,  "|                                                                                  |");
363                NR_Log(lt,  "------------------------------------------------------------------------------------");
364
365        }
366
367        //-----------------------------------------------------------------------
368        void Profiler::logLine(const char* name, float32 min, float32 max, float32 frameTime, float32 totalTime, uint32 totalCalls)
369        {
370                // create some strings containing the statistics
371                char avg[32];
372                sprintf(avg, "%2.2f", (totalTime / totalCalls) * 100.0f);
373
374                char smin[32];
375                sprintf(smin, "%2.2f", min * 100.0f);
376
377                char smax[32];
378                sprintf(smax, "%2.2f", max * 100.0f);
379
380                char tim[32];
381                sprintf(tim, "%4.6f", frameTime);
382
383                char cls[32];
384                sprintf(cls, "%d", totalCalls);
385
386                char ttm[32];
387                sprintf(ttm, "%4.6f", totalTime);
388               
389                NR_Log(Log::LOG_APP, "| %s |  %-6s|  %-6s|  %-6s| %-13s| %-9s|", name, avg, smax, smin, tim, cls);
390        }
391       
392
393        //-----------------------------------------------------------------------
394        void Profiler::changeEnableState() {   
395                mEnabled = mNewEnableState;
396                mEnableStateChangePending = false;
397        }
398
399       
400        //-----------------------------------------------------------------------
401        bool Profiler::ProfileHistory::operator <(const Profiler::ProfileHistory& p)
402        {
403                float my_avg = totalTime / totalCalls;
404                float it_avg = p.totalTime / p.totalCalls;
405                return (it_avg < my_avg);
406        }
407
408}; // end namespace
409
Note: See TracBrowser for help on using the repository browser.