00001
00007
00008
00009
00010
00011
00012
00013
00014
00015
00016
00017
00018
00019
00020
00021
00022
00023
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
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
00090
00091
00092
00093
00094
00095
00096
00097
00098
00099
00100
00101
00102
00103
00104
00105
00106
00107
00108
00109
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
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;
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 , 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 , bool displayEx)
00285 {
00286 CSimpleClock benchClock;
00287 benchClock.start();
00288 if(!_BenchStartedOnce)
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
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
00325 if (criterion != NoSort)
00326 {
00327 CStatSorter sorter(criterion);
00328 std::sort(statsPtr.begin(), statsPtr.end(), sorter);
00329 }
00330
00331
00332 CStats rootStats;
00333 rootStats.buildFromNode( &_RootNode, _MsPerTick);
00334
00335
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);
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
00402 TNodeStatPtrVect nodeStatsPtrs(nodeStats.size());
00403 for(uint k = 0; k < nodeStats.size(); ++k)
00404 {
00405 nodeStatsPtrs[k] = &nodeStats[k];
00406 }
00407
00408
00409 if (criterion != NoSort)
00410 {
00411 CStatSorter sorter(criterion);
00412 std::sort(nodeStatsPtrs.begin(), nodeStatsPtrs.end(), sorter);
00413 }
00414
00415
00416 CStats rootStats;
00417 rootStats.buildFromNode(&_RootNode, _MsPerTick);
00418
00419
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 void CHTimer::displayHierarchical(CLog *log, bool displayEx ,uint labelNumChar , uint indentationStep )
00469 {
00470 CSimpleClock benchClock;
00471 benchClock.start();
00472 log->displayNL("HTIMER: =========================================================================");
00473 log->displayRawNL("HTIMER: Hierarchical display of bench");
00474 nlassert(_BenchStartedOnce);
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 void CHTimer::displayHierarchicalByExecutionPath(CLog *log, bool displayEx, uint labelNumChar, uint indentationStep)
00543 {
00544 displayHierarchicalByExecutionPathSorted(log, NoSort, displayEx, labelNumChar, indentationStep);
00545 }
00546
00547
00548
00549 void CHTimer::displayHierarchicalByExecutionPathSorted(CLog *log, TSortCriterion criterion, bool displayEx, uint labelNumChar, uint indentationStep)
00550 {
00551
00552 CSimpleClock benchClock;
00553 benchClock.start();
00554 nlassert(_BenchStartedOnce);
00555
00556
00557 CStats rootStats;
00558 rootStats.buildFromNode(&_RootNode, _MsPerTick);
00559
00560
00561
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
00569 std::list< CExamStackEntry > examStack;
00570
00571
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
00584 if (child == 0)
00585 {
00586
00587
00588
00589
00590 children.resize(node->Sons.size());
00591
00592
00593 if(criterion == NoSort)
00594 {
00595 children= node->Sons;
00596 }
00597
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
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
00616 CStatSorter sorter;
00617 sorter.Criterion= criterion;
00618 std::sort(ptrStats.begin(), ptrStats.end(), sorter);
00619
00620
00621 for(i=0; i<children.size(); i++)
00622 {
00623 children[i]= ptrStats[i]->Node;
00624 }
00625 }
00626
00627
00628
00629
00630
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
00641 currNodeStats.buildFromNode(node, _MsPerTick);
00642 currNodeStats.getStats(resultStats, displayEx, rootStats.TotalTime, _WantStandardDeviation);
00643
00644
00645 log->displayRawNL("HTIMER: %s", (resultName + resultStats).c_str());
00646 }
00647
00648
00649 if (child >= children.size())
00650 {
00651 examStack.pop_back();
00652 continue;
00653 }
00654
00655
00656 ++(examStack.back().CurrentChild);
00657
00658
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
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
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 )
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
00741 }
00742 }
00743
00744
00745
00746 void CHTimer::CStats::getStats(std::string &dest, bool statEx, double rootTotalTime, bool wantStandardDeviation )
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);
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
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 )
00828 {
00829 if (!_Benching) return;
00830 _CurrNode->Clock.stop();
00831 _PreambuleClock.start();
00832
00833
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 }
00871