nel/src/misc/hierarchical_timer.cpp

   1 // NeL - MMORPG Framework <http://dev.ryzom.com/projects/nel/>
   2 // Copyright (C) 2010  Winch Gate Property Limited
   3 //
   4 // This program is free software: you can redistribute it and/or modify
   5 // it under the terms of the GNU Affero General Public License as
   6 // published by the Free Software Foundation, either version 3 of the
   7 // License, or (at your option) any later version.
   8 //
   9 // This program is distributed in the hope that it will be useful,
  10 // but WITHOUT ANY WARRANTY; without even the implied warranty of
  11 // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  12 // GNU Affero General Public License for more details.
  13 //
  14 // You should have received a copy of the GNU Affero General Public License
  15 // along with this program.  If not, see <http://www.gnu.org/licenses/>.
  16
  17 #include "stdmisc.h"
  18
  19 #include "nel/misc/hierarchical_timer.h"
  20 #include "nel/misc/common.h"
  21 #include "nel/misc/debug.h"
  22 #include "nel/misc/command.h"
  23 #include "nel/misc/system_info.h"
  24
  25 #ifdef NL_CPU_INTEL
  26 #include "nel/misc/time_nl.h"
  27 #endif
  28
  29 #ifdef DEBUG_NEW
  30         #define new DEBUG_NEW
  31 #endif
  32
  33 namespace NLMISC
  34 {
  35
  36 bool   CSimpleClock::_InitDone = false;
  37 uint64 CSimpleClock::_StartStopNumTicks = 0;
  38
  39
  40 // root node for all execution paths
  41 CHTimer::CNode  CHTimer::_RootNode;
  42 CHTimer::CNode *CHTimer::_CurrNode = &_RootNode;
  43 CSimpleClock    CHTimer::_PreambuleClock;
  44 CHTimer                 CHTimer::_RootTimer("root", true);
  45 bool                    CHTimer::_Benching = false;
  46 bool                    CHTimer::_BenchStartedOnce = false;
  47 double                  CHTimer::_MsPerTick;
  48 bool                    CHTimer::_WantStandardDeviation = false;
  49 CHTimer            *CHTimer::_CurrTimer = &_RootTimer;
  50 sint64                  CHTimer::_AfterStopEstimateTime= 0;
  51 bool                    CHTimer::_AfterStopEstimateTimeDone= false;
  52
  53
  54
  55
  56
  57
  58
  59 //=================================================================
  60 void CSimpleClock::init()
  61 {
  62         if (_InitDone) return;
  63         const uint numSamples = 10000;
  64
  65         CSimpleClock observedClock;
  66         CSimpleClock measuringClock;
  67
  68         measuringClock.start();
  69         for(uint l = 0; l < numSamples; ++l)
  70         {
  71                 observedClock.start();
  72                 observedClock.stop();
  73         }
  74         measuringClock.stop();
  75
  76         _StartStopNumTicks = (measuringClock.getNumTicks() >> 1) / numSamples;
  77         _InitDone = true;
  78 }
  79
  80
  81
  82 //=================================================================
  83 /** Do simple statistics on a list of values (mean value, standard deviation)
  84   */
  85 /*static void PerformStatistics(const std::vector<double> &values, double &standardDeviation)
  86 {
  87         nlassert(!values.empty());
  88         double total = 0;
  89         double variance = 0;
  90         uint k;
  91         for(k = 0; k < values.size(); ++k)
  92         {
  93                 total += (double) values[k];
  94         }
  95         meanValue = total / values.size();
  96         if (values.size() <= 1)
  97         {
  98                 standardDeviation = 0.f;
  99                 return;
 100         }
 101         for(k = 0; k < values.size(); ++k)
 102         {
 103                 variance += NLMISC::sqr((values[k] - meanValue));
 104         }
 105         standardDeviation = ::sqrt(variance / values.size() - 1);
 106 }*/
 107
 108
 109
 110 //=================================================================
 111 CHTimer::CNode::~CNode()
 112 {
 113         releaseSons();
 114         for(uint k = 0; k < Sons.size(); ++k)
 115                 delete Sons[k];
 116 }
 117
 118 //=================================================================
 119 void CHTimer::CNode::releaseSons()
 120 {
 121         for(uint k = 0; k < Sons.size(); ++k)
 122                 delete Sons[k];
 123         Sons.clear();
 124 }
 125
 126 //=================================================================
 127 void CHTimer::CNode::displayPath(CLog *log) const
 128 {
 129         std::string path;
 130         getPath(path);
 131         log->displayRawNL(("HTIMER: " + path).c_str());
 132 }
 133
 134 //=================================================================
 135 void CHTimer::CNode::getPath(std::string &path) const
 136 {
 137         path.clear();
 138         const CNode *currNode = this;
 139         do
 140         {
 141                 path = path.empty() ? currNode->Owner->getName()
 142                         : currNode->Owner->getName() + std::string("::") + path;
 143                 currNode = currNode->Parent;
 144         }
 145         while (currNode);
 146 }
 147
 148
 149 //=================================================================
 150 uint CHTimer::CNode::getNumNodes() const
 151 {
 152         uint sum = 1;
 153         for(uint k = 0; k < Sons.size(); ++k)
 154         {
 155                 sum += Sons[k]->getNumNodes();
 156         }
 157         return sum;
 158 }
 159
 160
 161 //=================================================================
 162 void CHTimer::walkTreeToCurrent()
 163 {
 164         if (_IsRoot) return;
 165         bool found = false;
 166         for(uint k = 0; k < _CurrNode->Sons.size(); ++k)
 167         {
 168                 if (_CurrNode->Sons[k]->Owner == this)
 169                 {
 170                         _CurrNode = _CurrNode->Sons[k];
 171                         found = true;
 172                         break;
 173                 }
 174         }
 175         if (!found)
 176         {
 177                 // no node for this execution path : create a new one
 178                 _CurrNode->Sons.push_back(new CNode(this, _CurrNode));
 179                 _CurrNode->Sons.back()->Parent = _CurrNode;
 180                 _CurrNode = _CurrNode->Sons.back();
 181         }
 182 }
 183
 184
 185
 186 //=================================================================
 187 void    CHTimer::estimateAfterStopTime()
 188 {
 189         if(_AfterStopEstimateTimeDone)
 190                 return;
 191         const uint numSamples = 1000;
 192
 193         // Do as in startBench, reset and init
 194         clear();
 195
 196         {
 197 #ifdef NL_CPU_INTEL
 198                 double freq = (double) CSystemInfo::getProcessorFrequency(false);
 199                 _MsPerTick = 1000 / (double) freq;
 200 #else
 201                 _MsPerTick = CTime::ticksToSecond(1000);
 202 #endif
 203                 CSimpleClock::init();
 204         }
 205
 206         // start
 207         _Benching = true;
 208         _BenchStartedOnce = true;
 209         _RootNode.Owner = &_RootTimer;
 210         _WantStandardDeviation = false;
 211         _RootTimer.before();
 212
 213         for(uint i=0;i<numSamples;i++)
 214         {
 215                 static NLMISC::CHTimer          estimateSampleTimer("sampleTimer");
 216                 estimateSampleTimer.before();
 217                 estimateSampleTimer.after();
 218         }
 219
 220         _RootTimer.after();
 221         _Benching = false;
 222
 223         // Then the After Stop time is the rootTimer time / numSamples
 224         _AfterStopEstimateTime= (_RootNode.TotalTime-_RootNode.SonsTotalTime) / numSamples;
 225
 226         _AfterStopEstimateTimeDone= true;
 227
 228         // must re-clear.
 229         clear();
 230 }
 231
 232
 233 //=================================================================
 234 void    CHTimer::startBench(bool wantStandardDeviation /*= false*/, bool quick, bool reset)
 235 {
 236         nlassert(!_Benching);
 237
 238         // if not done, estimate the AfterStopTime
 239         estimateAfterStopTime();
 240
 241         if(reset)
 242                 clear();
 243
 244         if(reset)
 245         {
 246 #ifdef NL_CPU_INTEL
 247                 double freq = (double) CSystemInfo::getProcessorFrequency(quick);
 248                 _MsPerTick = 1000 / (double) freq;
 249 #else
 250                 _MsPerTick = CTime::ticksToSecond(1000);
 251 #endif
 252                 CSimpleClock::init();
 253         }
 254
 255         // if reset needed, clearup all
 256         if (reset)
 257                 clearSessionStats();
 258
 259         // clear current for session
 260         clearSessionCurrent();
 261
 262         // Launch
 263         _Benching = true;
 264         _BenchStartedOnce = true;
 265         _RootNode.Owner = &_RootTimer;
 266         _WantStandardDeviation = wantStandardDeviation;
 267         _RootTimer.before();
 268 }
 269
 270 //=================================================================
 271 void    CHTimer::endBench()
 272 {
 273         if (!_Benching)
 274                 return;
 275
 276         if (_CurrNode == &_RootNode)
 277         {
 278                 _RootTimer.after();
 279         }
 280         else
 281         {
 282                 nlwarning("HTIMER: Stopping the bench inside a benched functions !");
 283         }
 284         _Benching = false;
 285
 286         // spread session stats if root node is greater
 287         updateSessionStats();
 288 }
 289
 290 //=================================================================
 291 void    CHTimer::display(CLog *log, TSortCriterion criterion, bool displayInline /*= true*/, bool displayEx)
 292 {
 293         CSimpleClock    benchClock;
 294         benchClock.start();
 295         if(!_BenchStartedOnce) // should have done at least one bench
 296         {
 297                 benchClock.stop();
 298                 _CurrNode->SonsPreambule += benchClock.getNumTicks();
 299                 return;
 300         }
 301         log->displayNL("HTIMER: =========================================================================");
 302         log->displayRawNL("HTIMER: Bench cumuled results");
 303         typedef std::map<CHTimer *, TNodeVect> TNodeMap;
 304         TNodeMap nodeMap;
 305         TNodeVect nodeLeft;
 306         nodeLeft.push_back(&_RootNode);
 307
 308         /// 1 ) walk the tree to build the node map (well, in a not very optimal way..)
 309         while (!nodeLeft.empty())
 310         {
 311                 CNode *currNode = nodeLeft.back();
 312                 nodeMap[currNode->Owner].push_back(currNode);
 313                 nodeLeft.pop_back();
 314                 nodeLeft.insert(nodeLeft.end(), currNode->Sons.begin(), currNode->Sons.end());
 315         }
 316
 317         // 2 ) build statistics
 318         typedef std::vector<CTimerStat> TTimerStatVect;
 319         typedef std::vector<CTimerStat *> TTimerStatPtrVect;
 320         TTimerStatVect          stats(nodeMap.size());
 321         TTimerStatPtrVect       statsPtr(stats.size());
 322         //
 323         uint k = 0;
 324         for(TNodeMap::iterator it = nodeMap.begin(); it != nodeMap.end(); ++it)
 325         {
 326                 statsPtr[k] = &stats[k];
 327                 stats[k].Timer = it->first;
 328                 stats[k].buildFromNodes(&(it->second[0]), (uint)it->second.size(), _MsPerTick);
 329                 ++k;
 330         }
 331
 332         // 3 ) sort statistics
 333         if (criterion != NoSort)
 334         {
 335                 CStatSorter sorter(criterion);
 336                 std::sort(statsPtr.begin(), statsPtr.end(), sorter);
 337         }
 338
 339         // 4 ) get root total time.
 340         CStats  rootStats;
 341         rootStats.buildFromNode( &_RootNode, _MsPerTick);
 342
 343         // 5 ) display statistics
 344         uint maxNodeLength = 0;
 345         std::string format;
 346         if (displayInline)
 347         {
 348                 for(TTimerStatPtrVect::iterator statIt = statsPtr.begin(); statIt != statsPtr.end(); ++statIt)
 349                 {
 350                         maxNodeLength = std::max(maxNodeLength, (uint)strlen((*statIt)->Timer->_Name));
 351                 }
 352                 format = "HTIMER: %-" + NLMISC::toString(maxNodeLength + 1) + "s %s";
 353         }
 354         std::string statsInline;
 355
 356         log->displayRawNL(format.c_str(), "", " |      total |      local |       visits |  loc%/ glb% | sessn max |       min |       max |      mean");
 357
 358         for(TTimerStatPtrVect::iterator statIt = statsPtr.begin(); statIt != statsPtr.end(); ++statIt)
 359         {
 360                 if (!displayInline)
 361                 {
 362                         log->displayRawNL("HTIMER: =================================");
 363                         log->displayRawNL("HTIMER: Node %s", (*statIt)->Timer->_Name);
 364                         (*statIt)->display(log, displayEx, _WantStandardDeviation);
 365                 }
 366                 else
 367                 {
 368                         (*statIt)->getStats(statsInline, displayEx, rootStats.TotalTime, _WantStandardDeviation);
 369                         char out[4096];
 370                         NLMISC::smprintf(out, 2048, format.c_str(), (*statIt)->Timer->_Name, statsInline.c_str());
 371                         log->displayRawNL(out);
 372                 }
 373         }
 374         benchClock.stop();
 375         _CurrNode->SonsPreambule += benchClock.getNumTicks();
 376 }
 377
 378 //================================================================================================
 379 void            CHTimer::displayByExecutionPath(CLog *log, TSortCriterion criterion, bool displayInline, bool alignPaths, bool displayEx)
 380 {
 381         CSimpleClock    benchClock;
 382         benchClock.start();
 383         log->displayRawNL("HTIMER: =========================================================================");
 384         log->displayRawNL("HTIMER: Bench by execution path");
 385         nlassert(_BenchStartedOnce); // should have done at least one bench
 386         //
 387         typedef std::vector<CNodeStat>   TNodeStatVect;
 388         typedef std::vector<CNodeStat *> TNodeStatPtrVect;
 389
 390         TNodeStatVect nodeStats;
 391         nodeStats.reserve(_RootNode.getNumNodes());
 392         TNodeVect nodeLeft;
 393         nodeLeft.push_back(&_RootNode);
 394         /// 1 ) walk the tree to build the node map (well, in a not very optimal way..)
 395         while (!nodeLeft.empty())
 396         {
 397                 CNode *currNode = nodeLeft.back();
 398
 399                 nodeStats.push_back(CNodeStat());
 400                 nodeStats.back().buildFromNode(currNode, _MsPerTick);
 401                 nodeStats.back().Node = currNode;
 402
 403                 nodeLeft.pop_back();
 404                 nodeLeft.insert(nodeLeft.end(), currNode->Sons.begin(), currNode->Sons.end());
 405
 406         }
 407
 408         /// 2 ) sort statistics
 409         // create a pointer list
 410         TNodeStatPtrVect nodeStatsPtrs(nodeStats.size());
 411         for(uint k = 0; k < nodeStats.size(); ++k)
 412         {
 413                 nodeStatsPtrs[k] = &nodeStats[k];
 414         }
 415
 416         // 3 ) sort statistics
 417         if (criterion != NoSort)
 418         {
 419                 CStatSorter sorter(criterion);
 420                 std::sort(nodeStatsPtrs.begin(), nodeStatsPtrs.end(), sorter);
 421         }
 422
 423         // 4 ) get root total time.
 424         CStats  rootStats;
 425         rootStats.buildFromNode(&_RootNode, _MsPerTick);
 426
 427         // 5 ) display statistics
 428         std::string statsInline;
 429         std::string nodePath;
 430
 431         std::string format;
 432         if (displayInline)
 433         {
 434                 if (alignPaths)
 435                 {
 436                         uint maxSize = 0;
 437                         std::string np;
 438                         for(TNodeStatPtrVect::iterator it = nodeStatsPtrs.begin(); it != nodeStatsPtrs.end(); ++it)
 439                         {
 440                                 (*it)->Node->getPath(np);
 441                                 maxSize = std::max(maxSize, (uint)np.size());
 442                         }
 443                         format = "HTIMER: %-" + NLMISC::toString(maxSize) +"s %s";
 444                 }
 445                 else
 446                 {
 447                         format = "HTIMER: %s %s";
 448                 }
 449         }
 450
 451         log->displayRawNL(format.c_str(), "", " |      total |      local |       visits |  loc%/ glb% | sessn max |       min |       max |      mean");
 452
 453         for(TNodeStatPtrVect::iterator it = nodeStatsPtrs.begin(); it != nodeStatsPtrs.end(); ++it)
 454         {
 455                 if (!displayInline)
 456                 {
 457                         log->displayRawNL("HTIMER: =================================");
 458                         (*it)->Node->displayPath(log);
 459                         (*it)->display(log, displayEx, _WantStandardDeviation);
 460                 }
 461                 else
 462                 {
 463                         (*it)->getStats(statsInline, displayEx, rootStats.TotalTime, _WantStandardDeviation);
 464                         (*it)->Node->getPath(nodePath);
 465
 466                         char out[2048];
 467                         NLMISC::smprintf(out, 2048, format.c_str(), nodePath.c_str(), statsInline.c_str());
 468                         log->displayRawNL(out);
 469                 }
 470         }
 471         benchClock.stop();
 472         _CurrNode->SonsPreambule += benchClock.getNumTicks();
 473 }
 474
 475 //=================================================================
 476 /*static*/ void CHTimer::displayHierarchical(CLog *log, bool displayEx /*=true*/,uint labelNumChar /*=32*/, uint indentationStep /*= 2*/)
 477 {
 478         CSimpleClock    benchClock;
 479         benchClock.start();
 480         log->displayNL("HTIMER: =========================================================================");
 481         log->displayRawNL("HTIMER: Hierarchical display of bench");
 482         nlassert(_BenchStartedOnce); // should have done at least one bench
 483         typedef std::map<CHTimer *, TNodeVect> TNodeMap;
 484         TNodeMap nodeMap;
 485         TNodeVect nodeLeft;
 486         nodeLeft.push_back(&_RootNode);
 487         /// 1 ) walk the execution tree to build the node map (well, in a not very optimal way..)
 488         while (!nodeLeft.empty())
 489         {
 490                 CNode *currNode = nodeLeft.back();
 491                 nodeMap[currNode->Owner].push_back(currNode);
 492                 nodeLeft.pop_back();
 493                 nodeLeft.insert(nodeLeft.end(), currNode->Sons.begin(), currNode->Sons.end());
 494
 495         }
 496         log->displayRawNL("HTIMER: %*s |      total |      local |       visits |  loc%%/ glb%% | sessn max |       min |       max |      mean", labelNumChar, "");
 497
 498         /// 2 ) get root total time.
 499         CStats  rootStats;
 500         rootStats.buildFromNode(&_RootNode, _MsPerTick);
 501
 502         /// 3 ) walk the timers tree and display infos (cumulate infos of nodes of each execution path)
 503         CStats  currNodeStats;
 504         std::vector<uint> sonsIndex;
 505         uint depth = 0;
 506         CHTimer *currTimer = &_RootTimer;
 507         sonsIndex.push_back(0);
 508         bool displayStat = true;
 509         std::string resultName;
 510         std::string resultStats;
 511         while (!sonsIndex.empty())
 512         {
 513                 if (displayStat)
 514                 {
 515                         resultName.resize(labelNumChar);
 516                         std::fill(resultName.begin(), resultName.end(), '.');
 517                         uint startIndex = depth * indentationStep;
 518                         uint endIndex = std::min(startIndex + (uint)::strlen(currTimer->_Name), labelNumChar);
 519                         if ((sint) (endIndex - startIndex) >= 1)
 520                         {
 521                                 std::copy(currTimer->_Name, currTimer->_Name + (endIndex - startIndex), resultName.begin() + startIndex);
 522                         }
 523                         TNodeVect &execNodes = nodeMap[currTimer];
 524                         if (!execNodes.empty())
 525                         {
 526                                 currNodeStats.buildFromNodes(&execNodes[0], (uint)execNodes.size(), _MsPerTick);
 527                                 currNodeStats.getStats(resultStats, displayEx, rootStats.TotalTime, _WantStandardDeviation);
 528                                 log->displayRawNL("HTIMER: %s", (resultName + resultStats).c_str());
 529                         }
 530                 }
 531                 if (sonsIndex.back() == currTimer->_Sons.size())
 532                 {
 533                         sonsIndex.pop_back();
 534                         currTimer = currTimer->_Parent;
 535                         displayStat = false;
 536                         -- depth;
 537                 }
 538                 else
 539                 {
 540                         currTimer = currTimer->_Sons[sonsIndex.back()];
 541                         ++ sonsIndex.back();
 542                         sonsIndex.push_back(0);
 543                         displayStat = true;
 544                         ++ depth;
 545                 }
 546         }
 547         benchClock.stop();
 548         _CurrNode->SonsPreambule += benchClock.getNumTicks();
 549 }
 550
 551
 552 //=================================================================
 553 /*static*/ void         CHTimer::displayHierarchicalByExecutionPath(CLog *log, bool displayEx, uint labelNumChar, uint indentationStep)
 554 {
 555         displayHierarchicalByExecutionPathSorted(log, NoSort, displayEx, labelNumChar, indentationStep);
 556 }
 557
 558
 559 //=================================================================
 560 /*static*/ void         CHTimer::displayHierarchicalByExecutionPathSorted(CLog *log, TSortCriterion criterion, bool displayEx, uint labelNumChar, uint indentationStep)
 561 {
 562
 563         CSimpleClock    benchClock;
 564         benchClock.start();
 565         nlassert(_BenchStartedOnce); // should have done at least one bench
 566
 567         // get root total time.
 568         CStats  rootStats;
 569         rootStats.buildFromNode(&_RootNode, _MsPerTick);
 570
 571
 572         // display header.
 573         CLog::TDisplayInfo      dummyDspInfo;
 574         log->displayRawNL("HTIMER: =========================================================================");
 575         log->displayRawNL("HTIMER: Hierarchical display of bench by execution path");
 576         log->displayRawNL("HTIMER: %*s |      total |      local |       visits |  loc%%/ glb%% | sessn max |       min |       max |      mean", labelNumChar, "");
 577
 578
 579         // use list because vector of vector is bad.
 580         std::list< CExamStackEntry >    examStack;
 581
 582         // Add the root to the stack.
 583         examStack.push_back( CExamStackEntry( &_RootNode ) );
 584         CStats          currNodeStats;
 585         std::string resultName;
 586         std::string resultStats;
 587
 588         while (!examStack.empty())
 589         {
 590                 CNode                           *node = examStack.back().Node;
 591                 std::vector<CNode*>     &children= examStack.back().Children;
 592                 uint                            child = examStack.back().CurrentChild;
 593
 594                 // If child 0, then must first build children info and display me.
 595                 if (child == 0)
 596                 {
 597                         // Build Sons Infos.
 598                         // ==============
 599
 600                         // resize array
 601                         children.resize(node->Sons.size());
 602
 603                         // If no sort, easy.
 604                         if(criterion == NoSort)
 605                         {
 606                                 children= node->Sons;
 607                         }
 608                         // else, Sort them with criterion.
 609                         else
 610                         {
 611                                 std::vector<CNodeStat>          stats;
 612                                 std::vector<CNodeStat *>        ptrStats;
 613                                 stats.resize(children.size());
 614                                 ptrStats.resize(children.size());
 615
 616                                 // build stats.
 617                                 uint    i;
 618                                 for(i=0; i<children.size(); i++)
 619                                 {
 620                                         CNode   *childNode= node->Sons[i];
 621                                         stats[i].buildFromNode(childNode, _MsPerTick);
 622                                         stats[i].Node = childNode;
 623                                         ptrStats[i]= &stats[i];
 624                                 }
 625
 626                                 // sort.
 627                                 CStatSorter     sorter;
 628                                 sorter.Criterion= criterion;
 629                                 std::sort(ptrStats.begin(), ptrStats.end(), sorter);
 630
 631                                 // fill children.
 632                                 for(i=0; i<children.size(); i++)
 633                                 {
 634                                         children[i]= ptrStats[i]->Node;
 635                                 }
 636                         }
 637
 638
 639                         // Display our infos
 640                         // ==============
 641                         // build the indented node name.
 642                         resultName.resize(labelNumChar);
 643                         std::fill(resultName.begin(), resultName.end(), '.');
 644                         uint startIndex = (uint)(examStack.size()-1) * indentationStep;
 645                         uint endIndex = std::min(startIndex + (uint)::strlen(node->Owner->_Name), labelNumChar);
 646                         if ((sint) (endIndex - startIndex) >= 1)
 647                         {
 648                                 std::copy(node->Owner->_Name, node->Owner->_Name + (endIndex - startIndex), resultName.begin() + startIndex);
 649                         }
 650
 651                         // build the stats string.
 652                         currNodeStats.buildFromNode(node, _MsPerTick);
 653                         currNodeStats.getStats(resultStats, displayEx, rootStats.TotalTime, _WantStandardDeviation);
 654
 655                         // display
 656                         log->displayRawNL("HTIMER: %s", (resultName + resultStats).c_str());
 657                 }
 658
 659                 // End of sons?? stop.
 660                 if (child >= children.size())
 661                 {
 662                         examStack.pop_back();
 663                         continue;
 664                 }
 665
 666                 // next son.
 667                 ++(examStack.back().CurrentChild);
 668
 669                 // process the current son.
 670                 examStack.push_back( CExamStackEntry( children[child] ) );
 671         }
 672
 673         //
 674         benchClock.stop();
 675         _CurrNode->SonsPreambule += benchClock.getNumTicks();
 676 }
 677
 678 //=================================================================
 679 /*static*/ void         CHTimer::displaySummary(CLog *log, TSortCriterion criterion, bool displayEx, uint labelNumChar, uint indentationStep, uint maxDepth)
 680 {
 681
 682         CSimpleClock    benchClock;
 683         benchClock.start();
 684         nlassert(_BenchStartedOnce); // should have done at least one bench
 685
 686         // get root total time.
 687         CStats  rootStats;
 688         rootStats.buildFromNode(&_RootNode, _MsPerTick);
 689
 690
 691         // display header.
 692         CLog::TDisplayInfo      dummyDspInfo;
 693         log->displayRawNL("HTIMER: =========================================================================");
 694         log->displayRawNL("HTIMER: Hierarchical display of bench by execution path");
 695         log->displayRawNL("HTIMER: %*s |      total |      local |       visits |  loc%%/ glb%% | sessn max |       min |       max |      mean", labelNumChar, "");
 696
 697
 698         // use list because vector of vector is bad.
 699         std::list< CExamStackEntry >    examStack;
 700
 701         // Add the root to the stack.
 702         examStack.push_back( CExamStackEntry( &_RootNode ) );
 703         CStats          currNodeStats;
 704         std::string resultName;
 705         std::string resultStats;
 706
 707         while (!examStack.empty())
 708         {
 709                 CNode                           *node = examStack.back().Node;
 710                 std::vector<CNode*>     &children= examStack.back().Children;
 711                 uint                            child = examStack.back().CurrentChild;
 712                 uint                            depth = examStack.back().Depth;
 713
 714                 // If child 0, then must first build children info and display me.
 715                 if (child == 0)
 716                 {
 717                         // Build Sons Infos.
 718                         // ==============
 719
 720                         // resize array
 721                         children.resize(node->Sons.size());
 722
 723                         // If no sort, easy.
 724                         if(criterion == NoSort)
 725                         {
 726                                 children= node->Sons;
 727                         }
 728                         // else, Sort them with criterion.
 729                         else
 730                         {
 731                                 std::vector<CNodeStat>          stats;
 732                                 std::vector<CNodeStat *>        ptrStats;
 733                                 stats.resize(children.size());
 734                                 ptrStats.resize(children.size());
 735
 736                                 // build stats.
 737                                 uint    i;
 738                                 for(i=0; i<children.size(); i++)
 739                                 {
 740                                         CNode   *childNode= node->Sons[i];
 741                                         stats[i].buildFromNode(childNode, _MsPerTick);
 742                                         stats[i].Node = childNode;
 743                                         ptrStats[i]= &stats[i];
 744                                 }
 745
 746                                 // sort.
 747                                 CStatSorter     sorter;
 748                                 sorter.Criterion= criterion;
 749                                 std::sort(ptrStats.begin(), ptrStats.end(), sorter);
 750
 751                                 // fill children.
 752                                 for(i=0; i<children.size(); i++)
 753                                 {
 754                                         children[i]= ptrStats[i]->Node;
 755                                 }
 756                         }
 757
 758
 759                         // Display our infos
 760                         // ==============
 761                         // build the indented node name.
 762                         resultName.resize(labelNumChar);
 763                         std::fill(resultName.begin(), resultName.end(), '.');
 764                         uint startIndex = (uint)(examStack.size()-1) * indentationStep;
 765                         uint endIndex = std::min(startIndex + (uint)::strlen(node->Owner->_Name), labelNumChar);
 766                         if ((sint) (endIndex - startIndex) >= 1)
 767                         {
 768                                 std::copy(node->Owner->_Name, node->Owner->_Name + (endIndex - startIndex), resultName.begin() + startIndex);
 769                         }
 770
 771                         // build the stats string.
 772                         currNodeStats.buildFromNode(node, _MsPerTick);
 773                         currNodeStats.getStats(resultStats, displayEx, rootStats.TotalTime, _WantStandardDeviation);
 774
 775                         // display
 776                         log->displayRawNL("HTIMER: %s", (resultName + resultStats).c_str());
 777                 }
 778
 779                 // End of sons?? stop.
 780                 if (child >= children.size())
 781                 {
 782                         examStack.pop_back();
 783                         continue;
 784                 }
 785
 786                 // next son.
 787                 ++(examStack.back().CurrentChild);
 788
 789                 // process the current son.
 790                 if (depth+1 < maxDepth)
 791                         examStack.push_back( CExamStackEntry( children[child], depth+1 ) );
 792         }
 793
 794         //
 795         benchClock.stop();
 796         _CurrNode->SonsPreambule += benchClock.getNumTicks();
 797 }
 798
 799 //=================================================================
 800 void    CHTimer::clear()
 801 {
 802         // should not be benching !
 803         nlassert(_CurrNode == &_RootNode);
 804         _RootNode.releaseSons();
 805         _CurrNode = &_RootNode;
 806         _RootNode.reset();
 807 }
 808
 809 //=================================================================
 810 void CHTimer::CStats::buildFromNode(CNode *node, double msPerTick)
 811 {
 812         buildFromNodes(&node, 1, msPerTick);
 813 }
 814
 815 //=================================================================
 816 void CHTimer::CStats::buildFromNodes(CNode **nodes, uint numNodes, double msPerTick)
 817 {
 818         TotalTime = 0;
 819         TotalTimeWithoutSons = 0;
 820         NumVisits = 0;
 821
 822         uint64 minTime = (uint64) -1;
 823         uint64 maxTime = 0;
 824         uint64 sessionMaxTime = 0;
 825
 826         uint k, l;
 827         for(k = 0; k < numNodes; ++k)
 828         {
 829                 TotalTime += nodes[k]->TotalTime * msPerTick;
 830                 TotalTimeWithoutSons += (nodes[k]->TotalTime -  nodes[k]->LastSonsTotalTime) * msPerTick;
 831                 NumVisits += nodes[k]->NumVisits;
 832                 minTime = std::min(minTime, nodes[k]->MinTime);
 833                 maxTime = std::max(maxTime, nodes[k]->MaxTime);
 834                 sessionMaxTime = std::max(sessionMaxTime, nodes[k]->SessionMax);
 835         }
 836         if (minTime == (uint64) -1)
 837         {
 838                 minTime = 0;
 839         }
 840         MinTime  = minTime * msPerTick;
 841         MaxTime  = maxTime * msPerTick;
 842         SessionMaxTime = sessionMaxTime * msPerTick;
 843
 844         if (NumVisits > 0)
 845                 MeanTime = TotalTime / NumVisits;
 846         else
 847                 MeanTime = 0.0;
 848
 849         // compute standard deviation
 850         double varianceSum = 0;
 851         uint   numMeasures = 0;
 852         for(k = 0; k < numNodes; ++k)
 853         {
 854                 numMeasures += (uint)nodes[k]->Measures.size();
 855                 for(l = 0; l < nodes[k]->Measures.size(); ++l)
 856                 {
 857                         varianceSum += NLMISC::sqr(nodes[k]->Measures[l] - MeanTime);
 858                 }
 859         }
 860         TimeStandardDeviation = numMeasures == 0 ? 0
 861                                                                                          : ::sqrt(varianceSum / (numMeasures +1));
 862 }
 863
 864 //=================================================================
 865 void CHTimer::CStats::display(CLog *log, bool displayEx, bool wantStandardDeviation /* = false*/)
 866 {
 867         log->displayRawNL("HTIMER: Total time                = %.3f ms", (float) TotalTime);
 868         log->displayRawNL("HTIMER: Total time without sons   = %.3f ms", (float) TotalTimeWithoutSons);
 869         log->displayRawNL(("HTIMER: Num visits                = " + NLMISC::toString(NumVisits)).c_str());
 870         if (displayEx)
 871         {
 872                         log->displayRawNL("HTIMER: Min time                  = %.3f ms", (float) MinTime);
 873                         log->displayRawNL("HTIMER: Max time                  = %.3f ms", (float) MaxTime);
 874                         log->displayRawNL("HTIMER: Mean time                 = %.3f ms", (float) MeanTime);
 875                         if (wantStandardDeviation)
 876                         {
 877                         log->displayRawNL("HTIMER: Standard deviation        = %.3f ms", (float) TimeStandardDeviation);
 878                         }
 879                         log->displayRawNL("HTIMER: Session Max time          = %.3f ms", (float) SessionMaxTime);
 880                         //log->displayRawNL("Time standard deviation    = %.3f ms", (float) TimeStandardDeviation);
 881         }
 882 }
 883
 884
 885 //=================================================================
 886 void CHTimer::CStats::getStats(std::string &dest, bool statEx, double rootTotalTime, bool wantStandardDeviation /*= false*/)
 887 {
 888         char buf[1024];
 889         if (!wantStandardDeviation)
 890         {
 891                 if (!statEx)
 892                 {
 893                         NLMISC::smprintf(buf, 1024, " | %10.3f | %10.3f | %12s ", (float) TotalTime, (float) TotalTimeWithoutSons, toString(NumVisits).c_str());
 894                 }
 895                 else
 896                 {
 897                         NLMISC::smprintf(buf, 1024, " | %10.3f | %10.3f | %12s | %5.1f/%5.1f | %9.3f | %9.3f | %9.3f | %9.3f",
 898                                           (float) TotalTime, (float) TotalTimeWithoutSons, toString(NumVisits).c_str(),
 899                                           float(100*TotalTimeWithoutSons/rootTotalTime), float(100*TotalTime/rootTotalTime),
 900                                           (float) SessionMaxTime,
 901                                           (float) MinTime, (float) MaxTime, (float) MeanTime
 902                                          );
 903                 }
 904         }
 905         else
 906         {
 907                 if (!statEx)
 908                 {
 909                         NLMISC::smprintf(buf, 1024, " | %10.3f | %10.3f | %12s | std deviation %9.3f", (float) TotalTime, (float) TotalTimeWithoutSons, toString(NumVisits).c_str(), (float) TimeStandardDeviation);
 910                 }
 911                 else
 912                 {
 913                         NLMISC::smprintf(buf, 1024, " | %10.3f | %10.3f | %12s | %5.1f/%5.1f | %9.3f | %9.3f | %9.3f | %9.3f | std deviation %9.3f",
 914                                                           (float) TotalTime, (float) TotalTimeWithoutSons, toString(NumVisits).c_str(),
 915                                                           float(100*TotalTimeWithoutSons/rootTotalTime), float(100*TotalTime/rootTotalTime),
 916                                                           (float) SessionMaxTime,
 917                                                           (float) MinTime, (float) MaxTime, (float) MeanTime,
 918                                                           (float) TimeStandardDeviation
 919                                                         );
 920                 }
 921         }
 922         dest = buf;
 923 }
 924
 925
 926 //=================================================================
 927 bool CHTimer::CStatSorter::operator()(const CHTimer::CStats *lhs, const CHTimer::CStats *rhs)
 928 {
 929         switch(Criterion)
 930         {
 931                 case CHTimer::TotalTime:                                return lhs->TotalTime >= rhs->TotalTime;
 932                 case CHTimer::TotalTimeWithoutSons:             return lhs->TotalTimeWithoutSons >= rhs->TotalTimeWithoutSons;
 933                 case CHTimer::MeanTime:                                 return lhs->MeanTime >= rhs->MeanTime;
 934                 case CHTimer::NumVisits:                                return lhs->NumVisits >= rhs->NumVisits;
 935                 case CHTimer::MaxTime:                                  return lhs->MaxTime >= rhs->MaxTime;
 936                 case CHTimer::MinTime:                                  return lhs->MinTime < rhs->MinTime;
 937                 case CHTimer::MaxSession:                               return lhs->SessionMaxTime > rhs->SessionMaxTime;
 938                 default:
 939                         nlassert(0); // not a valid criterion
 940                 break;
 941         }
 942         return false;
 943 }
 944
 945
 946 //===============================================
 947 void    CHTimer::doBefore()
 948 {
 949         _PreambuleClock.start();
 950         walkTreeToCurrent();
 951         ++ _CurrNode->NumVisits;
 952         _CurrNode->SonsPreambule = 0;
 953         if (!_Parent && _CurrTimer != this)
 954         {
 955                 _Parent = _CurrTimer;
 956                 // register as a son of the parent
 957                 _Parent->_Sons.push_back(this);
 958         }
 959         _CurrTimer = this;
 960         _PreambuleClock.stop();
 961         if (_CurrNode->Parent)
 962         {
 963                 _CurrNode->Parent->SonsPreambule += _PreambuleClock.getNumTicks();
 964         }
 965         _CurrNode->Clock.start();
 966 }
 967
 968 //===============================================
 969 void    CHTimer::doAfter(bool displayAfter)
 970 {
 971         _CurrNode->Clock.stop();
 972         _PreambuleClock.start();
 973         /* Remove my Son preambule, and remove only ONE StartStop
 974                 It is because between the start and the end, only ONE rdtsc time is counted:
 975         */
 976         sint64 numTicks = _CurrNode->Clock.getNumTicks()  - _CurrNode->SonsPreambule - (CSimpleClock::getStartStopNumTicks());
 977         // Case where the SonPreambule is overestimated,
 978         numTicks= std::max((sint64)0, numTicks);
 979         // In case where the SonPreambule is overestimated, the TotalTime must not be < of the SonTime
 980         if(_CurrNode->TotalTime + numTicks < _CurrNode->SonsTotalTime)
 981                 numTicks= _CurrNode->SonsTotalTime - _CurrNode->TotalTime;
 982
 983         _CurrNode->TotalTime += numTicks;
 984         _CurrNode->MinTime = std::min(_CurrNode->MinTime, (uint64)numTicks);
 985         _CurrNode->MaxTime = std::max(_CurrNode->MaxTime, (uint64)numTicks);
 986         _CurrNode->LastSonsTotalTime = _CurrNode->SonsTotalTime;
 987
 988         _CurrNode->SessionCurrent += (uint64)numTicks;
 989
 990         if (displayAfter)
 991         {
 992                 nlinfo("HTIMER: %s %.3fms loop number %d", _Name, numTicks * _MsPerTick, _CurrNode->NumVisits);
 993         }
 994         //
 995         if (_WantStandardDeviation)
 996         {
 997                 _CurrNode->Measures.push_back(numTicks * _MsPerTick);
 998         }
 999         //
1000         if (_Parent)
1001         {
1002                 _CurrTimer = _Parent;
1003         }
1004         //
1005         if (_CurrNode->Parent)
1006         {
1007                 CNode   *curNode= _CurrNode;
1008                 CNode   *parent= _CurrNode->Parent;
1009                 parent->SonsTotalTime += numTicks;
1010                 _PreambuleClock.stop();
1011                 /*
1012                         The SonPreambule of my parent is
1013                                 + my BeforePreambule (counted in doBefore)
1014                                 + my Afterpreambule (see below)
1015                                 + my Sons Preambule
1016                                 + some constant time due to the Start/Stop of the _CurrNode->Clock, the 2* Start/Stop
1017                                         of the PreabmuleClock, the function call time of doBefore and doAfter
1018                 */
1019                 parent->SonsPreambule += _PreambuleClock.getNumTicks() + curNode->SonsPreambule + _AfterStopEstimateTime;
1020                 // walk to parent
1021                 _CurrNode= parent;
1022         }
1023         else
1024         {
1025                 _PreambuleClock.stop();
1026         }
1027 }
1028
1029
1030
1031
1032 /*
1033  * Clears SessionMax current stats (only current value)
1034  */
1035 void    CHTimer::clearSessionCurrent()
1036 {
1037         _RootNode.resetSessionCurrent();
1038 }
1039
1040 /*
1041  * Clears all SessionMax stats (max and current values)
1042  */
1043 void    CHTimer::clearSessionStats()
1044 {
1045         _RootNode.resetSessionStats();
1046 }
1047
1048 /*
1049  * Update session stats
1050  */
1051 void    CHTimer::updateSessionStats()
1052 {
1053         if (_RootNode.SessionCurrent > _RootNode.SessionMax)
1054                 _RootNode.spreadSession();
1055 }
1056
1057
1058
1059
1060 //
1061 // Commands
1062 //
1063
1064 #define CASE_DISPLAYMEASURES(crit, alternative) \
1065         if (args[0] == #crit || depth == alternative)   \
1066         {       \
1067                 CHTimer::TSortCriterion criterion = CHTimer::crit;      \
1068                 if (hasDepth && depth != alternative)   \
1069                         CHTimer::displaySummary(&log, criterion, true, 64, 2, depth);   \
1070                 else    \
1071                         CHTimer::display(&log, criterion);      \
1072         }       \
1073         else
1074
1075 NLMISC_CATEGORISED_COMMAND(nel,displayMeasures, "display hierarchical timer", "[TotalTime(=-2)|NoSort(=-3)|TotalTimeWithoutSons(=-4)|MeanTime(=-5)|NumVisits(=-6)|MaxTime(=-7)|MinTime(=-8)|MaxSession(=-9)] [depth]")
1076 {
1077         if (args.size() < 1)
1078         {
1079                 CHTimer::display(&log);
1080                 CHTimer::displayHierarchicalByExecutionPathSorted (&log, CHTimer::TotalTime, true, 64);
1081                 return true;
1082         }
1083
1084         sint    depth = 0;
1085         bool    hasDepth = (fromString(args[0], depth) || (args.size() > 1 && fromString(args[1], depth)));
1086
1087         CASE_DISPLAYMEASURES(NoSort, -3)
1088         CASE_DISPLAYMEASURES(TotalTime, -2)
1089         CASE_DISPLAYMEASURES(TotalTimeWithoutSons, -4)
1090         CASE_DISPLAYMEASURES(MeanTime, -5)
1091         CASE_DISPLAYMEASURES(NumVisits, -6)
1092         CASE_DISPLAYMEASURES(MaxTime, -7)
1093         CASE_DISPLAYMEASURES(MinTime, -8)
1094         CASE_DISPLAYMEASURES(MaxSession, -9)
1095         {
1096                 if (hasDepth)
1097                         CHTimer::displaySummary(&log, CHTimer::TotalTime, true, 64, 2, depth);
1098                 else
1099                         CHTimer::display(&log, CHTimer::TotalTime);
1100         }
1101
1102         return true;
1103 }
1104
1105 } // NLMISC
1106