# Home    # nevrax.com   
Nevrax
Nevrax.org
#News
#Mailing-list
#Documentation
#CVS
#Bugs
#License
Docs
 
Documentation  
Main Page   Namespace List   Class Hierarchy   Alphabetical List   Compound List   File List   Namespace Members   Compound Members   File Members   Related Pages   Search  

hierarchical_timer.cpp

Go to the documentation of this file.
00001 
00007 /* Copyright, 2000, 2001 Nevrax Ltd.
00008  *
00009  * This file is part of NEVRAX NeL Network Services.
00010  * NEVRAX NeL Network Services is free software; you can redistribute it and/or modify
00011  * it under the terms of the GNU General Public License as published by
00012  * the Free Software Foundation; either version 2, or (at your option)
00013  * any later version.
00014 
00015  * NEVRAX NeL Network Services is distributed in the hope that it will be useful, but
00016  * WITHOUT ANY WARRANTY; without even the implied warranty of
00017  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
00018  * General Public License for more details.
00019 
00020  * You should have received a copy of the GNU General Public License
00021  * along with NEVRAX NeL Network Services; see the file COPYING. If not, write to the
00022  * Free Software Foundation, Inc., 59 Temple Place - Suite 330, Boston,
00023  * MA 02111-1307, USA.
00024  */
00025 
00026 #include "stdmisc.h"
00027 
00028 #include "nel/misc/hierarchical_timer.h"
00029 #include "nel/misc/common.h"
00030 #include "nel/misc/debug.h"
00031 
00032 #ifdef NL_CPU_INTEL
00033 #include "nel/misc/time_nl.h"
00034 #endif
00035 
00036 #include <map>
00037 
00038 namespace NLMISC
00039 {
00040 
00041      
00042 bool   CSimpleClock::_InitDone = false;
00043 uint64 CSimpleClock::_StartStopNumTicks = 0;
00044 
00045 
00046 // root node for all execution paths
00047 CHTimer::CNode  CHTimer::_RootNode;
00048 CHTimer::CNode *CHTimer::_CurrNode = &_RootNode;
00049 CSimpleClock    CHTimer::_PreambuleClock;
00050 CHTimer                 CHTimer::_RootTimer("root", true);
00051 bool                    CHTimer::_Benching = false;
00052 bool                    CHTimer::_BenchStartedOnce = false;
00053 double                  CHTimer::_MsPerTick;
00054 bool                    CHTimer::_WantStandardDeviation = false;
00055 CHTimer            *CHTimer::_CurrTimer = &_RootTimer;
00056 
00057 
00058 
00059 
00060 
00061 
00062 
00063 //=================================================================
00064 void CSimpleClock::init()
00065 {       
00066         if (_InitDone) return;
00067         const uint numSamples = 10000;
00068 
00069         CSimpleClock observedClock;
00070         CSimpleClock measuringClock;
00071         
00072         measuringClock.start();
00073         for(uint l = 0; l < numSamples; ++l)
00074         {               
00075                 observedClock.start();
00076                 observedClock.stop();
00077         }
00078         measuringClock.stop();
00079 
00080         _StartStopNumTicks = (measuringClock.getNumTicks() >> 1) / numSamples;  
00081         _InitDone = true;
00082 }
00083 
00084 
00085 
00086 //=================================================================
00089 /*static void PerformStatistics(const std::vector<double> &values, double &standardDeviation)
00090 {
00091         nlassert(!values.empty());
00092         double total = 0;       
00093         double variance = 0;
00094         uint k;
00095         for(k = 0; k < values.size(); ++k)
00096         {
00097                 total += (double) values[k];            
00098         }
00099         meanValue = total / values.size();
00100         if (values.size() <= 1)
00101         {
00102                 standardDeviation = 0.f;
00103                 return;
00104         }
00105         for(k = 0; k < values.size(); ++k)
00106         {
00107                 variance += NLMISC::sqr((values[k] - meanValue));
00108         }
00109         standardDeviation = ::sqrt(variance / values.size() - 1);
00110 }*/
00111 
00112 
00113 
00114 //=================================================================
00115 CHTimer::CNode::~CNode()
00116 {
00117         releaseSons();
00118         for(uint k = 0; k < Sons.size(); ++k)
00119                 delete Sons[k];
00120 }
00121 
00122 //=================================================================
00123 void CHTimer::CNode::releaseSons()
00124 {
00125         for(uint k = 0; k < Sons.size(); ++k)
00126                 delete Sons[k];
00127         Sons.clear();
00128 }
00129 
00130 //=================================================================
00131 void CHTimer::CNode::displayPath(CLog *log) const
00132 {
00133         std::string path;
00134         getPath(path);
00135         log->displayRawNL(("HTIMER: " + path).c_str());
00136 }
00137 
00138 //=================================================================
00139 void CHTimer::CNode::getPath(std::string &path) const
00140 {
00141         path.clear();
00142         const CNode *currNode = this;
00143         do
00144         {
00145                 path = path.empty() ? currNode->Owner->getName() 
00146                         : currNode->Owner->getName() + std::string("::") + path;
00147                 currNode = currNode->Parent;
00148         }
00149         while (currNode);
00150 }
00151 
00152 
00153 //=================================================================
00154 uint CHTimer::CNode::getNumNodes() const
00155 {
00156         uint sum = 1;
00157         for(uint k = 0; k < Sons.size(); ++k)
00158         {
00159                 sum += Sons[k]->getNumNodes();
00160         }
00161         return sum;
00162 }
00163 
00164 
00165 //=================================================================
00166 void CHTimer::walkTreeToCurrent()
00167 {
00168         if (_IsRoot) return;    
00169         bool found = false;
00170         for(uint k = 0; k < _CurrNode->Sons.size(); ++k)
00171         {
00172                 if (_CurrNode->Sons[k]->Owner == this)
00173                 {
00174                         _CurrNode = _CurrNode->Sons[k];
00175                         found = true;
00176                         break;
00177                 }
00178         }
00179         if (!found)
00180         {
00181                 // no node for this execution path : create a new one
00182                 _CurrNode->Sons.push_back(new CNode(this, _CurrNode));
00183                 _CurrNode->Sons.back()->Parent = _CurrNode;
00184                 _CurrNode = _CurrNode->Sons.back();
00185         }
00186 }
00187 
00188 #ifdef  NL_CPU_INTEL
00189 //=================================================================
00190 uint64 CHTimer::getProcessorFrequency(bool quick)
00191 {
00192         static uint64 freq;
00193         static bool freqComputed = false;       
00194         if (freqComputed) return freq;
00195 
00196         if (!quick)
00197         {
00198                 TTicks bestNumTicks   = 0;
00199                 uint64 bestNumCycles;
00200                 uint64 numCycles;
00201                 const uint numSamples = 5;
00202                 const uint numLoops   = 50000000;
00203 
00204                 volatile uint k; // prevent optimisation for the loop
00205                 volatile dummy = 0;
00206                 for(uint l = 0; l < numSamples; ++l)
00207                 {       
00208                         TTicks startTick = NLMISC::CTime::getPerformanceTime();
00209                         uint64 startCycle = rdtsc();
00210                         uint dummy = 0;
00211                         for(k = 0; k < numLoops; ++k)
00212                         {               
00213                                 ++ dummy;
00214                         }               
00215                         numCycles = rdtsc() - startCycle;
00216                         TTicks numTicks = NLMISC::CTime::getPerformanceTime() - startTick;
00217                         if (numTicks > bestNumTicks)
00218                         {               
00219                                 bestNumTicks  = numTicks;
00220                                 bestNumCycles = numCycles;
00221                         }
00222                 }
00223                 freq = (uint64) ((double) bestNumCycles * 1 / CTime::ticksToSecond(bestNumTicks));
00224         }
00225         else
00226         {
00227                 TTicks timeBefore = NLMISC::CTime::getPerformanceTime();
00228                 uint64 tickBefore = rdtsc();
00229                 nlSleep (100);
00230                 TTicks timeAfter = NLMISC::CTime::getPerformanceTime();
00231                 TTicks tickAfter = rdtsc();
00232 
00233                 double timeDelta = CTime::ticksToSecond(timeAfter - timeBefore);
00234                 TTicks tickDelta = tickAfter - tickBefore;
00235 
00236                 freq = (uint64) ((double)tickDelta / timeDelta);
00237         }
00238 
00239         nlinfo ("HTIMER: Processor frequency is %.0f MHz", (float)freq/1000000.0);
00240         freqComputed = true;
00241         return freq;
00242 }
00243 #endif
00244 
00245 
00246 //=================================================================
00247 void    CHTimer::startBench(bool wantStandardDeviation /*= false*/, bool quick)
00248 {
00249         nlassert(!_Benching)
00250         clear();
00251         _Benching = true;
00252         _BenchStartedOnce = true;
00253         _RootNode.Owner = &_RootTimer;
00254 #       ifdef NL_CPU_INTEL
00255                 double freq = (double) getProcessorFrequency(quick);
00256                 _MsPerTick = 1000 / (double) freq;
00257 #       else
00258                 _MsPerTick = CTime::ticksToSecond(1000);
00259 #       endif
00260         CSimpleClock::init();
00261         _RootNode.Owner = &_RootTimer;
00262         _WantStandardDeviation = wantStandardDeviation;
00263         _RootTimer.before();
00264 }
00265 
00266 //=================================================================
00267 void    CHTimer::endBench()
00268 {
00269         if (!_Benching)
00270                 return;
00271 
00272         if (_CurrNode == &_RootNode)
00273         {
00274                 _RootTimer.after();
00275         }
00276         else
00277         {
00278                 nlwarning("FEHTIMER> Stopping the bench inside a benched functions !");
00279         }
00280         _Benching = false;
00281 }
00282 
00283 //=================================================================
00284 void    CHTimer::display(CLog *log, TSortCriterion criterion, bool displayInline /*= true*/, bool displayEx)
00285 {       
00286         CSimpleClock    benchClock;
00287         benchClock.start();
00288         if(!_BenchStartedOnce) // should have done at least one bench   
00289         {
00290                 benchClock.stop();
00291                 _CurrNode->SonsPreambule += benchClock.getNumTicks();
00292                 return;
00293         }
00294         log->displayNL("HTIMER: =========================================================================");
00295         log->displayRawNL("HTIMER: Bench cumuled results");
00296         typedef std::map<CHTimer *, TNodeVect> TNodeMap;
00297         TNodeMap nodeMap;
00298         TNodeVect nodeLeft;     
00299         nodeLeft.push_back(&_RootNode);
00301         while (!nodeLeft.empty())
00302         {       
00303                 CNode *currNode = nodeLeft.back();
00304                 nodeMap[currNode->Owner].push_back(currNode);
00305                 nodeLeft.pop_back();
00306                 nodeLeft.insert(nodeLeft.end(), currNode->Sons.begin(), currNode->Sons.end());
00307 
00308         }
00309         //      
00310         // 2 ) build statistics 
00311         typedef std::vector<CTimerStat> TTimerStatVect;
00312         typedef std::vector<CTimerStat *> TTimerStatPtrVect;
00313         TTimerStatVect          stats(nodeMap.size());
00314         TTimerStatPtrVect       statsPtr(stats.size());
00315         //
00316         uint k = 0;
00317         for(TNodeMap::iterator it = nodeMap.begin(); it != nodeMap.end(); ++it)
00318         {
00319                 statsPtr[k] = &stats[k];
00320                 stats[k].Timer = it->first;
00321                 stats[k].buildFromNodes(&(it->second[0]), it->second.size(), _MsPerTick);
00322                 ++k;
00323         }
00324         // 3 ) sort statistics
00325         if (criterion != NoSort)
00326         {
00327                 CStatSorter sorter(criterion);
00328                 std::sort(statsPtr.begin(), statsPtr.end(), sorter);            
00329         }
00330 
00331         // 4 ) get root total time.
00332         CStats  rootStats;
00333         rootStats.buildFromNode( &_RootNode, _MsPerTick);
00334 
00335         // 5 ) display statistics
00336         uint maxNodeLenght = 0;
00337         std::string format;
00338         if (displayInline)
00339         {
00340                 for(TTimerStatPtrVect::iterator statIt = statsPtr.begin(); statIt != statsPtr.end(); ++statIt)
00341                 {
00342                         maxNodeLenght = std::max(maxNodeLenght, strlen((*statIt)->Timer->_Name));
00343                 }
00344                 format = "HTIMER: %-" + NLMISC::toString(maxNodeLenght + 1) + "s %s";
00345         }
00346         std::string statsInline;
00347 
00348         log->displayRawNL(format.c_str(), "", " |      total |      local |       visits |  loc%/ glb% |       min |       max |      mean");
00349 
00350         for(TTimerStatPtrVect::iterator statIt = statsPtr.begin(); statIt != statsPtr.end(); ++statIt)
00351         {
00352                 if (!displayInline)
00353                 {               
00354                         log->displayRawNL("HTIMER: =================================");
00355                         log->displayRawNL("HTIMER: Node %s", (*statIt)->Timer->_Name);          
00356                         (*statIt)->display(log, displayEx, _WantStandardDeviation);
00357                 }
00358                 else
00359                 {
00360                         (*statIt)->getStats(statsInline, displayEx, rootStats.TotalTime, _WantStandardDeviation);
00361                         char out[4096];
00362                         NLMISC::smprintf(out, 2048, format.c_str(), (*statIt)->Timer->_Name, statsInline.c_str());
00363                         log->displayRawNL(out);                                 
00364                 }
00365         }       
00366         benchClock.stop();
00367         _CurrNode->SonsPreambule += benchClock.getNumTicks();
00368 }
00369 
00370 //================================================================================================
00371 void            CHTimer::displayByExecutionPath(CLog *log, TSortCriterion criterion, bool displayInline, bool alignPaths, bool displayEx)
00372 {       
00373         CSimpleClock    benchClock;
00374         benchClock.start();
00375         log->displayRawNL("HTIMER: =========================================================================");
00376         log->displayRawNL("HTIMER: Bench by execution path");
00377         nlassert(_BenchStartedOnce); // should have done at least one bench     
00378         //
00379         typedef std::vector<CNodeStat>   TNodeStatVect;
00380         typedef std::vector<CNodeStat *> TNodeStatPtrVect;
00381 
00382         TNodeStatVect nodeStats;
00383         nodeStats.reserve(_RootNode.getNumNodes());
00384         TNodeVect nodeLeft;     
00385         nodeLeft.push_back(&_RootNode);
00387         while (!nodeLeft.empty())
00388         {       
00389                 CNode *currNode = nodeLeft.back();
00390                 
00391                 nodeStats.push_back(CNodeStat());
00392                 nodeStats.back().buildFromNode(currNode, _MsPerTick);
00393                 nodeStats.back().Node = currNode;
00394 
00395                 nodeLeft.pop_back();
00396                 nodeLeft.insert(nodeLeft.end(), currNode->Sons.begin(), currNode->Sons.end());
00397 
00398         }
00399 
00401         // create a pointer list
00402         TNodeStatPtrVect nodeStatsPtrs(nodeStats.size());
00403         for(uint k = 0; k < nodeStats.size(); ++k)
00404         {
00405                 nodeStatsPtrs[k] = &nodeStats[k];
00406         }
00407 
00408         // 3 ) sort statistics
00409         if (criterion != NoSort)
00410         {
00411                 CStatSorter sorter(criterion);
00412                 std::sort(nodeStatsPtrs.begin(), nodeStatsPtrs.end(), sorter);
00413         }
00414 
00415         // 4 ) get root total time.
00416         CStats  rootStats;
00417         rootStats.buildFromNode(&_RootNode, _MsPerTick);
00418 
00419         // 5 ) display statistics
00420         std::string statsInline;
00421         std::string nodePath;
00422 
00423         std::string format;
00424         if (displayInline)
00425         {
00426                 if (alignPaths)
00427                 {
00428                         uint maxSize = 0;
00429                         std::string nodePath;
00430                         for(TNodeStatPtrVect::iterator it = nodeStatsPtrs.begin(); it != nodeStatsPtrs.end(); ++it)
00431                         {
00432                                 (*it)->Node->getPath(nodePath);
00433                                 maxSize = std::max(maxSize, nodePath.size());
00434                         }
00435                         format = "HTIMER: %-" + NLMISC::toString(maxSize) +"s %s";
00436                 }
00437                 else
00438                 {
00439                         format = "HTIMER: %s %s";
00440                 }
00441         }
00442 
00443         log->displayRawNL(format.c_str(), "", " |      total |      local |       visits |  loc%/ glb% |       min |       max |      mean");
00444 
00445         for(TNodeStatPtrVect::iterator it = nodeStatsPtrs.begin(); it != nodeStatsPtrs.end(); ++it)
00446         {
00447                 if (!displayInline)
00448                 {               
00449                         log->displayRawNL("HTIMER: =================================");
00450                         (*it)->Node->displayPath(log);
00451                         (*it)->display(log, displayEx, _WantStandardDeviation);
00452                 }
00453                 else
00454                 {
00455                         (*it)->getStats(statsInline, displayEx, rootStats.TotalTime, _WantStandardDeviation);
00456                         (*it)->Node->getPath(nodePath);
00457 
00458                         char out[2048];
00459                         NLMISC::smprintf(out, 2048, format.c_str(), nodePath.c_str(), statsInline.c_str());
00460                         log->displayRawNL(out);
00461                 }
00462         }
00463         benchClock.stop();
00464         _CurrNode->SonsPreambule += benchClock.getNumTicks();
00465 }
00466 
00467 //=================================================================
00468 /*static*/ void CHTimer::displayHierarchical(CLog *log, bool displayEx /*=true*/,uint labelNumChar /*=32*/, uint indentationStep /*= 2*/)
00469 {
00470         CSimpleClock    benchClock;
00471         benchClock.start();
00472         log->displayNL("HTIMER: =========================================================================");
00473         log->displayRawNL("HTIMER: Hierarchical display of bench");
00474         nlassert(_BenchStartedOnce); // should have done at least one bench
00475         typedef std::map<CHTimer *, TNodeVect> TNodeMap;
00476         TNodeMap nodeMap;
00477         TNodeVect nodeLeft;     
00478         nodeLeft.push_back(&_RootNode);
00480         while (!nodeLeft.empty())
00481         {       
00482                 CNode *currNode = nodeLeft.back();
00483                 nodeMap[currNode->Owner].push_back(currNode);
00484                 nodeLeft.pop_back();
00485                 nodeLeft.insert(nodeLeft.end(), currNode->Sons.begin(), currNode->Sons.end());
00486 
00487         }
00488         log->displayRawNL("HTIMER: %*s |      total |      local |       visits |  loc%%/ glb%% |       min |       max |      mean", labelNumChar, "");
00489 
00491         CStats  rootStats;
00492         rootStats.buildFromNode(&_RootNode, _MsPerTick);
00493 
00495         CStats  currNodeStats;
00496         std::vector<uint> sonsIndex;
00497         uint depth = 0;
00498         CHTimer *currTimer = &_RootTimer;
00499         sonsIndex.push_back(0);
00500         bool displayStat = true;
00501         std::string resultName;
00502         std::string resultStats;
00503         while (!sonsIndex.empty())
00504         {               
00505                 if (displayStat)
00506                 {
00507                         resultName.resize(labelNumChar);
00508                         std::fill(resultName.begin(), resultName.end(), '.');
00509                         uint startIndex = depth * indentationStep;
00510                         uint endIndex = std::min(startIndex + ::strlen(currTimer->_Name), labelNumChar);                        
00511                         if ((sint) (endIndex - startIndex) >= 1)
00512                         {
00513                                 std::copy(currTimer->_Name, currTimer->_Name + (endIndex - startIndex), resultName.begin() + startIndex);
00514                         }
00515                         TNodeVect &execNodes = nodeMap[currTimer];
00516                         currNodeStats.buildFromNodes(&execNodes[0], execNodes.size(), _MsPerTick);                      
00517                         currNodeStats.getStats(resultStats, displayEx, rootStats.TotalTime, _WantStandardDeviation);
00518                         log->displayRawNL("HTIMER: %s", (resultName + resultStats).c_str());
00519                 }
00520                 if (sonsIndex.back() == currTimer->_Sons.size())
00521                 {
00522                         sonsIndex.pop_back();
00523                         currTimer = currTimer->_Parent;
00524                         displayStat = false;
00525                         -- depth;
00526                 }
00527                 else
00528                 {
00529                         currTimer = currTimer->_Sons[sonsIndex.back()];
00530                         ++ sonsIndex.back();
00531                         sonsIndex.push_back(0);                 
00532                         displayStat = true;
00533                         ++ depth;
00534                 }
00535         }       
00536         benchClock.stop();
00537         _CurrNode->SonsPreambule += benchClock.getNumTicks();
00538 }
00539 
00540 
00541 //=================================================================
00542 /*static*/ void         CHTimer::displayHierarchicalByExecutionPath(CLog *log, bool displayEx, uint labelNumChar, uint indentationStep)
00543 {
00544         displayHierarchicalByExecutionPathSorted(log, NoSort, displayEx, labelNumChar, indentationStep);
00545 }
00546 
00547 
00548 //=================================================================
00549 /*static*/ void         CHTimer::displayHierarchicalByExecutionPathSorted(CLog *log, TSortCriterion criterion, bool displayEx, uint labelNumChar, uint indentationStep)
00550 {
00551 
00552         CSimpleClock    benchClock;
00553         benchClock.start();
00554         nlassert(_BenchStartedOnce); // should have done at least one bench
00555 
00556         // get root total time.
00557         CStats  rootStats;
00558         rootStats.buildFromNode(&_RootNode, _MsPerTick);
00559 
00560 
00561         // display header.
00562         TDisplayInfo    dummyDspInfo;
00563         log->displayNL("HTIMER: =========================================================================");
00564         log->displayRawNL("HTIMER: Hierarchical display of bench by execution path");
00565         log->displayRawNL("HTIMER: %*s |      total |      local |       visits |  loc%%/ glb%% |       min |       max |      mean", labelNumChar, "");
00566 
00567 
00568         // use list because vector of vector is bad.
00569         std::list< CExamStackEntry >    examStack;
00570 
00571         // Add the root to the stack.
00572         examStack.push_back( CExamStackEntry( &_RootNode ) );
00573         CStats          currNodeStats;
00574         std::string resultName;
00575         std::string resultStats;
00576 
00577         while (!examStack.empty())
00578         {
00579                 CNode                           *node = examStack.back().Node;
00580                 std::vector<CNode*>     &children= examStack.back().Children;
00581                 uint                            child = examStack.back().CurrentChild;
00582 
00583                 // If child 0, then must first build children info and display me.
00584                 if (child == 0)
00585                 {
00586                         // Build Sons Infos.
00587                         // ==============
00588                         
00589                         // resize array
00590                         children.resize(node->Sons.size());
00591 
00592                         // If no sort, easy.
00593                         if(criterion == NoSort)
00594                         {
00595                                 children= node->Sons;
00596                         }
00597                         // else, Sort them with criterion.
00598                         else
00599                         {
00600                                 std::vector<CNodeStat>          stats;
00601                                 std::vector<CNodeStat *>        ptrStats;
00602                                 stats.resize(children.size());
00603                                 ptrStats.resize(children.size());
00604 
00605                                 // build stats.
00606                                 uint    i;
00607                                 for(i=0; i<children.size(); i++)
00608                                 {
00609                                         CNode   *childNode= node->Sons[i];
00610                                         stats[i].buildFromNode(childNode, _MsPerTick);
00611                                         stats[i].Node = childNode;
00612                                         ptrStats[i]= &stats[i];
00613                                 }
00614 
00615                                 // sort.
00616                                 CStatSorter     sorter;
00617                                 sorter.Criterion= criterion;
00618                                 std::sort(ptrStats.begin(), ptrStats.end(), sorter);            
00619 
00620                                 // fill children.
00621                                 for(i=0; i<children.size(); i++)
00622                                 {
00623                                         children[i]= ptrStats[i]->Node;
00624                                 }
00625                         }
00626 
00627 
00628                         // Display our infos
00629                         // ==============
00630                         // build the indented node name.
00631                         resultName.resize(labelNumChar);
00632                         std::fill(resultName.begin(), resultName.end(), '.');
00633                         uint startIndex = (examStack.size()-1) * indentationStep;
00634                         uint endIndex = std::min(startIndex + ::strlen(node->Owner->_Name), labelNumChar);                      
00635                         if ((sint) (endIndex - startIndex) >= 1)
00636                         {
00637                                 std::copy(node->Owner->_Name, node->Owner->_Name + (endIndex - startIndex), resultName.begin() + startIndex);
00638                         }
00639 
00640                         // build the stats string.
00641                         currNodeStats.buildFromNode(node, _MsPerTick);                  
00642                         currNodeStats.getStats(resultStats, displayEx, rootStats.TotalTime, _WantStandardDeviation);
00643 
00644                         // display
00645                         log->displayRawNL("HTIMER: %s", (resultName + resultStats).c_str());
00646                 }
00647 
00648                 // End of sons?? stop.
00649                 if (child >= children.size())
00650                 {
00651                         examStack.pop_back();
00652                         continue;
00653                 }
00654 
00655                 // next son.
00656                 ++(examStack.back().CurrentChild);
00657 
00658                 // process the current son.
00659                 examStack.push_back( CExamStackEntry( children[child] ) );
00660         }
00661 
00662         //
00663         benchClock.stop();
00664         _CurrNode->SonsPreambule += benchClock.getNumTicks();
00665 }
00666 
00667 //=================================================================
00668 void    CHTimer::clear()
00669 {
00670         // should not be benching !
00671         nlassert(_CurrNode == &_RootNode)
00672         _RootNode.releaseSons();
00673         _CurrNode = &_RootNode;
00674         _RootNode.reset();      
00675 }
00676 
00677 //=================================================================
00678 void CHTimer::CStats::buildFromNode(CNode *node, double msPerTick)
00679 {
00680         buildFromNodes(&node, 1, msPerTick);
00681 }
00682 
00683 //=================================================================
00684 void CHTimer::CStats::buildFromNodes(CNode **nodes, uint numNodes, double msPerTick)
00685 {
00686         TotalTime = 0;  
00687         TotalTimeWithoutSons = 0;       
00688         NumVisits = 0;
00689         
00690         uint64 minTime = (uint64) -1;
00691         uint64 maxTime = 0;
00692         
00693         uint k, l;
00694         for(k = 0; k < numNodes; ++k)
00695         {               
00696                 TotalTime += nodes[k]->TotalTime * msPerTick;
00697                 TotalTimeWithoutSons += (nodes[k]->TotalTime -  nodes[k]->LastSonsTotalTime) * msPerTick;
00698                 NumVisits += nodes[k]->NumVisits;
00699                 minTime = std::min(minTime, nodes[k]->MinTime);
00700                 maxTime = std::max(maxTime, nodes[k]->MaxTime);                         
00701         }
00702         if (minTime == (uint64) -1) 
00703         {
00704                 minTime = 0;
00705         }
00706         MinTime  = minTime * msPerTick;
00707         MaxTime  = maxTime * msPerTick;
00708         MeanTime = TotalTime / NumVisits;
00709 
00710         // compute standard deviation
00711         double varianceSum = 0;
00712         uint   numMeasures = 0;
00713         for(k = 0; k < numNodes; ++k)
00714         {
00715                 numMeasures += nodes[k]->Measures.size();
00716                 for(l = 0; l < nodes[k]->Measures.size(); ++l)
00717                 {
00718                         varianceSum += NLMISC::sqr(nodes[k]->Measures[l] - MeanTime);
00719                 }               
00720         }
00721         TimeStandardDeviation = numMeasures == 0 ? 0
00722                                                                                          : ::sqrt(varianceSum / (numMeasures +1));
00723 }
00724 
00725 //=================================================================
00726 void CHTimer::CStats::display(CLog *log, bool displayEx, bool wantStandardDeviation /* = false*/)
00727 {
00728         log->displayRawNL("HTIMER: Total time                = %.3f ms", (float) TotalTime);
00729         log->displayRawNL("HTIMER: Total time without sons   = %.3f ms", (float) TotalTimeWithoutSons);
00730         log->displayRawNL(("HTIMER: Num visits                = " + NLMISC::toString(NumVisits)).c_str());      
00731         if (displayEx)
00732         {
00733                         log->displayRawNL("HTIMER: Min time                  = %.3f ms", (float) MinTime);
00734                         log->displayRawNL("HTIMER: Max time                  = %.3f ms", (float) MaxTime);
00735                         log->displayRawNL("HTIMER: Mean time                 = %.3f ms", (float) MeanTime);
00736                         if (wantStandardDeviation)
00737                         {
00738                         log->displayRawNL("HTIMER: Standard deviation        = %.3f ms", (float) TimeStandardDeviation);
00739                         }
00740                         //log->displayRawNL("Time standard deviation    = %.3f ms", (float) TimeStandardDeviation);
00741         }
00742 }
00743 
00744 
00745 //=================================================================
00746 void CHTimer::CStats::getStats(std::string &dest, bool statEx, double rootTotalTime, bool wantStandardDeviation /*= false*/)
00747 {
00748         char buf[1024];
00749         if (!wantStandardDeviation)
00750         {       
00751                 if (!statEx)
00752                 {       
00753                         NLMISC::smprintf(buf, 1024, " | %10.3f | %10.3f | %12s ", (float) TotalTime, (float) TotalTimeWithoutSons, toString(NumVisits).c_str());
00754                 }
00755                 else
00756                 {
00757                         NLMISC::smprintf(buf, 1024, " | %10.3f | %10.3f | %12s | %5.1f/%5.1f | %9.3f | %9.3f | %9.3f",
00758                                           (float) TotalTime, (float) TotalTimeWithoutSons, toString(NumVisits).c_str(), 
00759                                           float(100*TotalTimeWithoutSons/rootTotalTime), float(100*TotalTime/rootTotalTime), 
00760                                           (float) MinTime, (float) MaxTime, (float) MeanTime
00761                                          );
00762                 }
00763         }
00764         else
00765         {
00766                 if (!statEx)
00767                 {       
00768                         NLMISC::smprintf(buf, 1024, " | %10.3f | %10.3f | %12s | std deviation %9.3f", (float) TotalTime, (float) TotalTimeWithoutSons, toString(NumVisits).c_str(), (float) TimeStandardDeviation);
00769                 }
00770                 else
00771                 {
00772                         NLMISC::smprintf(buf, 1024, " | %10.3f | %10.3f | %12s | %5.1f/%5.1f | %9.3f | %9.3f | %9.3f | std deviation %9.3f",
00773                                                           (float) TotalTime, (float) TotalTimeWithoutSons, toString(NumVisits).c_str(), 
00774                                                           float(100*TotalTimeWithoutSons/rootTotalTime), float(100*TotalTime/rootTotalTime), 
00775                                                           (float) MinTime, (float) MaxTime, (float) MeanTime,
00776                                                           (float) TimeStandardDeviation
00777                                                         );
00778                 }
00779         }
00780         dest = buf;
00781 }
00782 
00783 
00784 //=================================================================
00785 bool CHTimer::CStatSorter::operator()(const CHTimer::CStats *lhs, const CHTimer::CStats *rhs)
00786 {
00787         switch(Criterion)
00788         {
00789                 case CHTimer::TotalTime:                                return lhs->TotalTime >= rhs->TotalTime;
00790                 case CHTimer::TotalTimeWithoutSons:             return lhs->TotalTimeWithoutSons >= rhs->TotalTimeWithoutSons;
00791                 case CHTimer::MeanTime:                                 return lhs->MeanTime >= rhs->MeanTime;
00792                 case CHTimer::NumVisits:                                return lhs->NumVisits >= rhs->NumVisits;
00793                 case CHTimer::MaxTime:                                  return lhs->MaxTime >= rhs->MaxTime;
00794                 case CHTimer::MinTime:                                  return lhs->MinTime < rhs->MinTime;     
00795                 default:
00796                         nlassert(0); // not a valid criterion
00797                 break;
00798         }
00799         return false;
00800 }
00801 
00802 
00803 //===============================================
00804 void    CHTimer::before()
00805 {       
00806         if (!_Benching) return;
00807         _PreambuleClock.start();        
00808         walkTreeToCurrent();                    
00809         ++ _CurrNode->NumVisits;
00810         _CurrNode->SonsPreambule = 0;
00811         if (!_Parent && _CurrTimer != this)
00812         {
00813                 _Parent = _CurrTimer;
00814                 // register as a son of the parent
00815                 _Parent->_Sons.push_back(this); 
00816         }
00817         _CurrTimer = this;
00818         _PreambuleClock.stop();
00819         if (_CurrNode->Parent)
00820         {       
00821                 _CurrNode->Parent->SonsPreambule += _PreambuleClock.getNumTicks();
00822         }
00823         _CurrNode->Clock.start();
00824 }
00825 
00826 //===============================================
00827 void    CHTimer::after(bool displayAfter /*= false*/)
00828 {
00829         if (!_Benching) return;
00830         _CurrNode->Clock.stop();                
00831         _PreambuleClock.start();
00832         //              
00833         //nlinfo((std::string("clock ") + _Name + std::string(" time = ") + NLMISC::toString(_CurrNode->Clock.getNumTicks())).c_str());
00834         sint64 numTicks = _CurrNode->Clock.getNumTicks()  - _CurrNode->SonsPreambule - (CSimpleClock::getStartStopNumTicks() << 1);
00835         numTicks= std::max((sint64)0, numTicks);
00836 
00837         _CurrNode->TotalTime += numTicks;               
00838         _CurrNode->MinTime = std::min(_CurrNode->MinTime, (uint64)numTicks);
00839         _CurrNode->MaxTime = std::max(_CurrNode->MaxTime, (uint64)numTicks);
00840         _CurrNode->LastSonsTotalTime = _CurrNode->SonsTotalTime;
00841 
00842         if (displayAfter)
00843         {               
00844                 nlinfo("FEHTIMER> %s %.3fms loop number %d", _Name, numTicks * _MsPerTick, _CurrNode->NumVisits);
00845         }
00846         //
00847         if (_WantStandardDeviation)
00848         {
00849                 _CurrNode->Measures.push_back(numTicks * _MsPerTick);
00850         }
00851         //
00852         if (_Parent)
00853         {
00854                 _CurrTimer = _Parent;
00855         }       
00856         //
00857         if (_CurrNode->Parent)
00858         {
00859                 _PreambuleClock.stop();
00860                 _CurrNode = _CurrNode->Parent;
00861                 _CurrNode->SonsTotalTime += numTicks;
00862                 _CurrNode->SonsPreambule += _PreambuleClock.getNumTicks();
00863         }
00864         else
00865         {
00866                 _PreambuleClock.stop();
00867         }
00868 }
00869 
00870 } // NLMISC
00871