nevrax.org : docs

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 
+
hierarchical_timer.cpp
