profiler.cpp 23 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727
  1. //-----------------------------------------------------------------------------
  2. // Copyright (c) 2012 GarageGames, LLC
  3. //
  4. // Permission is hereby granted, free of charge, to any person obtaining a copy
  5. // of this software and associated documentation files (the "Software"), to
  6. // deal in the Software without restriction, including without limitation the
  7. // rights to use, copy, modify, merge, publish, distribute, sublicense, and/or
  8. // sell copies of the Software, and to permit persons to whom the Software is
  9. // furnished to do so, subject to the following conditions:
  10. //
  11. // The above copyright notice and this permission notice shall be included in
  12. // all copies or substantial portions of the Software.
  13. //
  14. // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
  15. // IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
  16. // FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
  17. // AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
  18. // LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
  19. // FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
  20. // IN THE SOFTWARE.
  21. //-----------------------------------------------------------------------------
  22. #include "platform/platform.h"
  23. #if defined(TORQUE_OS_WIN)
  24. #include<Windows.h> // for SetThreadAffinityMask, QueryPerformanceCounter, QueryPerformanceFrequency
  25. #elif defined(TORQUE_OS_MAC)
  26. #include <mach/mach_time.h> // for mach_absolute_time, mach_timebase_info
  27. #endif
  28. #include "core/stream/fileStream.h"
  29. #include "core/frameAllocator.h"
  30. #include "core/strings/stringFunctions.h"
  31. #include "core/stringTable.h"
  32. #include "platform/profiler.h"
  33. #include "platform/threads/thread.h"
  34. #include "console/engineAPI.h"
  35. #ifdef TORQUE_ENABLE_PROFILER
  36. ProfilerRootData *ProfilerRootData::sRootList = NULL;
  37. Profiler *gProfiler = NULL;
  38. // Uncomment the following line to enable a debugging aid for mismatched profiler blocks.
  39. //#define TORQUE_PROFILER_DEBUG
  40. // Machinery to record the stack of node names, as a debugging aid to find
  41. // mismatched PROFILE_START and PROFILE_END blocks. We profile from the
  42. // beginning to catch profile block errors that occur when torque is starting up.
  43. #ifdef TORQUE_PROFILER_DEBUG
  44. Vector<StringTableEntry> gProfilerNodeStack;
  45. #define TORQUE_PROFILE_AT_ENGINE_START true
  46. #define PROFILER_DEBUG_PUSH_NODE( nodename ) \
  47. gProfilerNodeStack.push_back( nodename );
  48. #define PROFILER_DEBUG_POP_NODE() \
  49. gProfilerNodeStack.pop_back();
  50. #else
  51. #define TORQUE_PROFILE_AT_ENGINE_START false
  52. #define PROFILER_DEBUG_PUSH_NODE( nodename ) ;
  53. #define PROFILER_DEBUG_POP_NODE() ;
  54. #endif
  55. #if defined(TORQUE_OS_WIN)
  56. static bool sQueryPerformanceInit = false;
  57. static U64 sQueryPerformanceFrequency = 0;
  58. // platform specific get hires times...
  59. void startHighResolutionTimer(U64 &time)
  60. {
  61. QueryPerformanceCounter((LARGE_INTEGER*)&time);
  62. }
  63. F64 endHighResolutionTimer(U64 time)
  64. {
  65. if (!sQueryPerformanceInit)
  66. {
  67. sQueryPerformanceInit = true;
  68. QueryPerformanceFrequency((LARGE_INTEGER*)&sQueryPerformanceFrequency);
  69. }
  70. U64 current;
  71. QueryPerformanceCounter((LARGE_INTEGER*)&current);
  72. return ((1000.0 * static_cast<F64>(current-time)) / static_cast<F64>(sQueryPerformanceFrequency));
  73. }
  74. #elif defined(TORQUE_OS_MAC)
  75. void startHighResolutionTimer(U64 &time) {
  76. time = mach_absolute_time();
  77. }
  78. F64 endHighResolutionTimer(U64 time) {
  79. static mach_timebase_info_data_t sTimebaseInfo = {0, 0};
  80. U64 now = mach_absolute_time();
  81. if(sTimebaseInfo.denom == 0){
  82. mach_timebase_info(&sTimebaseInfo);
  83. }
  84. // Handle the micros/nanos conversion first, because shedding a few bits is better than overflowing.
  85. F64 elapsedMicros = (static_cast<F64>(now - time) / 1000.0) * static_cast<F64>(sTimebaseInfo.numer) / static_cast<F64>(sTimebaseInfo.denom);
  86. return elapsedMicros; // Just truncate, and hope we didn't overflow
  87. }
  88. #else
  89. void startHighResolutionTimer(U64 &time)
  90. {
  91. time = (U64)Platform::getRealMilliseconds();
  92. }
  93. F64 endHighResolutionTimer(U64 time)
  94. {
  95. return (F64)Platform::getRealMilliseconds() - time;
  96. }
  97. #endif
  98. Profiler::Profiler()
  99. {
  100. mMaxStackDepth = MaxStackDepth;
  101. mCurrentHash = 0;
  102. mCurrentProfilerData = (ProfilerData *) malloc(sizeof(ProfilerData));
  103. mCurrentProfilerData->mRoot = NULL;
  104. mCurrentProfilerData->mNextForRoot = NULL;
  105. mCurrentProfilerData->mNextProfilerData = NULL;
  106. mCurrentProfilerData->mNextHash = NULL;
  107. mCurrentProfilerData->mParent = NULL;
  108. mCurrentProfilerData->mNextSibling = NULL;
  109. mCurrentProfilerData->mFirstChild = NULL;
  110. mCurrentProfilerData->mLastSeenProfiler = NULL;
  111. mCurrentProfilerData->mHash = 0;
  112. mCurrentProfilerData->mSubDepth = 0;
  113. mCurrentProfilerData->mInvokeCount = 0;
  114. mCurrentProfilerData->mTotalTime = 0;
  115. mCurrentProfilerData->mSubTime = 0;
  116. #ifdef TORQUE_ENABLE_PROFILE_PATH
  117. mCurrentProfilerData->mPath = "";
  118. #endif
  119. mRootProfilerData = mCurrentProfilerData;
  120. for(U32 i = 0; i < ProfilerData::HashTableSize; i++)
  121. mCurrentProfilerData->mChildHash[i] = 0;
  122. mProfileList = NULL;
  123. mEnabled = TORQUE_PROFILE_AT_ENGINE_START;
  124. mNextEnable = TORQUE_PROFILE_AT_ENGINE_START;
  125. mStackDepth = 0;
  126. gProfiler = this;
  127. mDumpToConsole = false;
  128. mDumpToFile = false;
  129. mDumpFileName[0] = '\0';
  130. }
  131. Profiler::~Profiler()
  132. {
  133. reset();
  134. free(mRootProfilerData);
  135. gProfiler = NULL;
  136. }
  137. void Profiler::reset()
  138. {
  139. mEnabled = false; // in case we're in a profiler call.
  140. ProfilerData * head = mProfileList;
  141. ProfilerData * curr = head;
  142. while ( curr )
  143. {
  144. head = curr->mNextProfilerData;
  145. free( curr );
  146. if ( head )
  147. curr = head;
  148. else
  149. curr = NULL;
  150. }
  151. mProfileList = NULL;
  152. for(ProfilerRootData *walk = ProfilerRootData::sRootList; walk; walk = walk->mNextRoot)
  153. {
  154. walk->mFirstProfilerData = 0;
  155. walk->mTotalTime = 0;
  156. walk->mSubTime = 0;
  157. walk->mTotalInvokeCount = 0;
  158. }
  159. mCurrentProfilerData = mRootProfilerData;
  160. mCurrentProfilerData->mNextForRoot = 0;
  161. mCurrentProfilerData->mFirstChild = 0;
  162. for(U32 i = 0; i < ProfilerData::HashTableSize; i++)
  163. mCurrentProfilerData->mChildHash[i] = 0;
  164. mCurrentProfilerData->mInvokeCount = 0;
  165. mCurrentProfilerData->mTotalTime = 0;
  166. mCurrentProfilerData->mSubTime = 0;
  167. mCurrentProfilerData->mSubDepth = 0;
  168. mCurrentProfilerData->mLastSeenProfiler = 0;
  169. }
  170. static Profiler aProfiler; // allocate the global profiler
  171. ProfilerRootData::ProfilerRootData(const char *name)
  172. {
  173. for(ProfilerRootData *walk = sRootList; walk; walk = walk->mNextRoot)
  174. if(!String::compare(walk->mName, name))
  175. AssertFatal( false, avar( "Duplicate profile name: %s", name ) );
  176. mName = name;
  177. mNameHash = _StringTable::hashString(name);
  178. mNextRoot = sRootList;
  179. sRootList = this;
  180. mTotalTime = 0;
  181. mTotalInvokeCount = 0;
  182. mFirstProfilerData = NULL;
  183. mEnabled = true;
  184. }
  185. void Profiler::validate()
  186. {
  187. for(ProfilerRootData *walk = ProfilerRootData::sRootList; walk; walk = walk->mNextRoot)
  188. {
  189. for(ProfilerData *dp = walk->mFirstProfilerData; dp; dp = dp->mNextForRoot)
  190. {
  191. if(dp->mRoot != walk)
  192. Platform::debugBreak();
  193. // check if it's in the parent's list...
  194. ProfilerData *wk;
  195. for(wk = dp->mParent->mFirstChild; wk; wk = wk->mNextSibling)
  196. if(wk == dp)
  197. break;
  198. if(!wk)
  199. Platform::debugBreak();
  200. for(wk = dp->mParent->mChildHash[walk->mNameHash & (ProfilerData::HashTableSize - 1)] ;
  201. wk; wk = wk->mNextHash)
  202. if(wk == dp)
  203. break;
  204. if(!wk)
  205. Platform::debugBreak();
  206. }
  207. }
  208. }
  209. #ifdef TORQUE_ENABLE_PROFILE_PATH
  210. const char * Profiler::getProfilePath()
  211. {
  212. #ifdef TORQUE_MULTITHREAD
  213. // Ignore non-main-thread profiler activity.
  214. if( !ThreadManager::isMainThread() )
  215. return "[non-main thread]";
  216. #endif
  217. return (mEnabled && mCurrentProfilerData) ? mCurrentProfilerData->mPath : "na";
  218. }
  219. #endif
  220. #ifdef TORQUE_ENABLE_PROFILE_PATH
  221. const char * Profiler::constructProfilePath(ProfilerData * pd)
  222. {
  223. if (pd->mParent)
  224. {
  225. const bool saveEnable = gProfiler->mEnabled;
  226. gProfiler->mEnabled = false;
  227. const char * connector = " -> ";
  228. U32 len = dStrlen(pd->mParent->mPath);
  229. if (!len)
  230. connector = "";
  231. len += dStrlen(connector);
  232. len += dStrlen(pd->mRoot->mName);
  233. U32 mark = FrameAllocator::getWaterMark();
  234. char * buf = (char*)FrameAllocator::alloc(len+1);
  235. dStrcpy(buf,pd->mParent->mPath,len+1);
  236. dStrcat(buf,connector,len+1);
  237. dStrcat(buf,pd->mRoot->mName,len+1);
  238. const char * ret = StringTable->insert(buf);
  239. FrameAllocator::setWaterMark(mark);
  240. gProfiler->mEnabled = saveEnable;
  241. return ret;
  242. }
  243. return "root";
  244. }
  245. #endif
  246. void Profiler::hashPush(ProfilerRootData *root)
  247. {
  248. #ifdef TORQUE_MULTITHREAD
  249. // Ignore non-main-thread profiler activity.
  250. if( !ThreadManager::isMainThread() )
  251. return;
  252. #endif
  253. mStackDepth++;
  254. PROFILER_DEBUG_PUSH_NODE(root->mName);
  255. AssertFatal(mStackDepth <= mMaxStackDepth,
  256. "Stack overflow in profiler. You may have mismatched PROFILE_START and PROFILE_ENDs");
  257. if(!mEnabled)
  258. return;
  259. ProfilerData *nextProfiler = NULL;
  260. if(!root->mEnabled || mCurrentProfilerData->mRoot == root)
  261. {
  262. mCurrentProfilerData->mSubDepth++;
  263. return;
  264. }
  265. if(mCurrentProfilerData->mLastSeenProfiler &&
  266. mCurrentProfilerData->mLastSeenProfiler->mRoot == root)
  267. nextProfiler = mCurrentProfilerData->mLastSeenProfiler;
  268. if(!nextProfiler)
  269. {
  270. // first see if it's in the hash table...
  271. U32 index = root->mNameHash & (ProfilerData::HashTableSize - 1);
  272. nextProfiler = mCurrentProfilerData->mChildHash[index];
  273. while(nextProfiler)
  274. {
  275. if(nextProfiler->mRoot == root)
  276. break;
  277. nextProfiler = nextProfiler->mNextHash;
  278. }
  279. if(!nextProfiler)
  280. {
  281. nextProfiler = (ProfilerData *) malloc(sizeof(ProfilerData));
  282. for(U32 i = 0; i < ProfilerData::HashTableSize; i++)
  283. nextProfiler->mChildHash[i] = 0;
  284. nextProfiler->mRoot = root;
  285. nextProfiler->mNextForRoot = root->mFirstProfilerData;
  286. root->mFirstProfilerData = nextProfiler;
  287. nextProfiler->mNextProfilerData = mProfileList;
  288. mProfileList = nextProfiler;
  289. nextProfiler->mNextHash = mCurrentProfilerData->mChildHash[index];
  290. mCurrentProfilerData->mChildHash[index] = nextProfiler;
  291. nextProfiler->mParent = mCurrentProfilerData;
  292. nextProfiler->mNextSibling = mCurrentProfilerData->mFirstChild;
  293. mCurrentProfilerData->mFirstChild = nextProfiler;
  294. nextProfiler->mFirstChild = NULL;
  295. nextProfiler->mLastSeenProfiler = NULL;
  296. nextProfiler->mHash = root->mNameHash;
  297. nextProfiler->mInvokeCount = 0;
  298. nextProfiler->mTotalTime = 0;
  299. nextProfiler->mSubTime = 0;
  300. nextProfiler->mSubDepth = 0;
  301. #ifdef TORQUE_ENABLE_PROFILE_PATH
  302. nextProfiler->mPath = constructProfilePath(nextProfiler);
  303. #endif
  304. }
  305. }
  306. root->mTotalInvokeCount++;
  307. nextProfiler->mInvokeCount++;
  308. startHighResolutionTimer(nextProfiler->mStartTime);
  309. mCurrentProfilerData->mLastSeenProfiler = nextProfiler;
  310. mCurrentProfilerData = nextProfiler;
  311. }
  312. void Profiler::enable(bool enabled)
  313. {
  314. mNextEnable = enabled;
  315. }
  316. void Profiler::dumpToConsole()
  317. {
  318. mDumpToConsole = true;
  319. mDumpToFile = false;
  320. mDumpFileName[0] = '\0';
  321. }
  322. void Profiler::dumpToFile(const char* fileName)
  323. {
  324. AssertFatal(dStrlen(fileName) < DumpFileNameLength, "Error, dump filename too long");
  325. mDumpToFile = true;
  326. mDumpToConsole = false;
  327. dStrcpy(mDumpFileName, fileName, DumpFileNameLength);
  328. }
  329. void Profiler::hashPop(ProfilerRootData *expected)
  330. {
  331. #ifdef TORQUE_MULTITHREAD
  332. // Ignore non-main-thread profiler activity.
  333. if( !ThreadManager::isMainThread() )
  334. return;
  335. #endif
  336. mStackDepth--;
  337. PROFILER_DEBUG_POP_NODE();
  338. AssertFatal(mStackDepth >= 0, "Stack underflow in profiler. You may have mismatched PROFILE_START and PROFILE_ENDs");
  339. if(mEnabled)
  340. {
  341. if(mCurrentProfilerData->mSubDepth)
  342. {
  343. mCurrentProfilerData->mSubDepth--;
  344. return;
  345. }
  346. if(expected)
  347. {
  348. AssertISV(expected == mCurrentProfilerData->mRoot, "Profiler::hashPop - didn't get expected ProfilerRoot!");
  349. }
  350. F64 fElapsed = endHighResolutionTimer(mCurrentProfilerData->mStartTime);
  351. mCurrentProfilerData->mTotalTime += fElapsed;
  352. mCurrentProfilerData->mParent->mSubTime += fElapsed; // mark it in the parent as well...
  353. mCurrentProfilerData->mRoot->mTotalTime += fElapsed;
  354. if(mCurrentProfilerData->mParent->mRoot)
  355. mCurrentProfilerData->mParent->mRoot->mSubTime += fElapsed; // mark it in the parent as well...
  356. mCurrentProfilerData = mCurrentProfilerData->mParent;
  357. }
  358. if(mStackDepth == 0)
  359. {
  360. // apply the next enable...
  361. if(mDumpToConsole || mDumpToFile)
  362. {
  363. dump();
  364. startHighResolutionTimer(mCurrentProfilerData->mStartTime);
  365. }
  366. if(!mEnabled && mNextEnable)
  367. startHighResolutionTimer(mCurrentProfilerData->mStartTime);
  368. #if defined(TORQUE_OS_WIN)
  369. // The high performance counters under win32 are unreliable when running on multiple
  370. // processors. When the profiler is enabled, we restrict Torque to a single processor.
  371. if(mNextEnable != mEnabled)
  372. {
  373. if(mNextEnable)
  374. {
  375. Con::warnf("Warning: forcing the Torque profiler thread to run only on cpu 1.");
  376. SetThreadAffinityMask(GetCurrentThread(), 1);
  377. }
  378. else
  379. {
  380. Con::warnf("Warning: the Torque profiler thread may now run on any cpu.");
  381. DWORD_PTR procMask;
  382. DWORD_PTR sysMask;
  383. GetProcessAffinityMask( GetCurrentProcess(), &procMask, &sysMask);
  384. SetThreadAffinityMask( GetCurrentThread(), procMask);
  385. }
  386. }
  387. #endif
  388. mEnabled = mNextEnable;
  389. }
  390. }
  391. static S32 QSORT_CALLBACK rootDataCompare(const void *s1, const void *s2)
  392. {
  393. const ProfilerRootData *r1 = *((ProfilerRootData **) s1);
  394. const ProfilerRootData *r2 = *((ProfilerRootData **) s2);
  395. if((r2->mTotalTime - r2->mSubTime) > (r1->mTotalTime - r1->mSubTime))
  396. return 1;
  397. return -1;
  398. }
  399. static void profilerDataDumpRecurse(ProfilerData *data, char *buffer, U32 bufferLen, F64 totalTime)
  400. {
  401. // dump out this one:
  402. Con::printf("%7.3f %7.3f %8d %s%s",
  403. 100 * data->mTotalTime / totalTime,
  404. 100 * (data->mTotalTime - data->mSubTime) / totalTime,
  405. data->mInvokeCount,
  406. buffer,
  407. data->mRoot ? data->mRoot->mName : "ROOT" );
  408. data->mTotalTime = 0;
  409. data->mSubTime = 0;
  410. data->mInvokeCount = 0;
  411. buffer[bufferLen] = ' ';
  412. buffer[bufferLen+1] = ' ';
  413. buffer[bufferLen+2] = 0;
  414. // sort data's children...
  415. ProfilerData *list = NULL;
  416. while(data->mFirstChild)
  417. {
  418. ProfilerData *ins = data->mFirstChild;
  419. data->mFirstChild = ins->mNextSibling;
  420. ProfilerData **walk = &list;
  421. while(*walk && (*walk)->mTotalTime > ins->mTotalTime)
  422. walk = &(*walk)->mNextSibling;
  423. ins->mNextSibling = *walk;
  424. *walk = ins;
  425. }
  426. data->mFirstChild = list;
  427. while(list)
  428. {
  429. if(list->mInvokeCount)
  430. profilerDataDumpRecurse(list, buffer, bufferLen + 2, totalTime);
  431. list = list->mNextSibling;
  432. }
  433. buffer[bufferLen] = 0;
  434. }
  435. static void profilerDataDumpRecurseFile(ProfilerData *data, char *buffer, U32 bufferLen, F64 totalTime, FileStream& fws)
  436. {
  437. char pbuffer[256];
  438. dSprintf(pbuffer, 255, "%7.3f %7.3f %8d %s%s\n",
  439. 100 * data->mTotalTime / totalTime,
  440. 100 * (data->mTotalTime - data->mSubTime) / totalTime,
  441. data->mInvokeCount,
  442. buffer,
  443. data->mRoot ? data->mRoot->mName : "ROOT" );
  444. fws.write(dStrlen(pbuffer), pbuffer);
  445. data->mTotalTime = 0;
  446. data->mSubTime = 0;
  447. data->mInvokeCount = 0;
  448. buffer[bufferLen] = ' ';
  449. buffer[bufferLen+1] = ' ';
  450. buffer[bufferLen+2] = 0;
  451. // sort data's children...
  452. ProfilerData *list = NULL;
  453. while(data->mFirstChild)
  454. {
  455. ProfilerData *ins = data->mFirstChild;
  456. data->mFirstChild = ins->mNextSibling;
  457. ProfilerData **walk = &list;
  458. while(*walk && (*walk)->mTotalTime > ins->mTotalTime)
  459. walk = &(*walk)->mNextSibling;
  460. ins->mNextSibling = *walk;
  461. *walk = ins;
  462. }
  463. data->mFirstChild = list;
  464. while(list)
  465. {
  466. if(list->mInvokeCount)
  467. profilerDataDumpRecurseFile(list, buffer, bufferLen + 2, totalTime, fws);
  468. list = list->mNextSibling;
  469. }
  470. buffer[bufferLen] = 0;
  471. }
  472. void Profiler::dump()
  473. {
  474. bool enableSave = mEnabled;
  475. mEnabled = false;
  476. mStackDepth++;
  477. // may have some profiled calls... gotta turn em off.
  478. Vector<ProfilerRootData *> rootVector;
  479. F64 totalTime = 0;
  480. for(ProfilerRootData *walk = ProfilerRootData::sRootList; walk; walk = walk->mNextRoot)
  481. {
  482. totalTime += walk->mTotalTime - walk->mSubTime;
  483. rootVector.push_back(walk);
  484. }
  485. dQsort((void *) &rootVector[0], rootVector.size(), sizeof(ProfilerRootData *), rootDataCompare);
  486. if (mDumpToConsole == true)
  487. {
  488. Con::printf("Profiler Data Dump:");
  489. Con::printf("Ordered by non-sub total time -");
  490. Con::printf("%%NSTime %% Time Invoke # Name");
  491. for(U32 i = 0; i < rootVector.size(); i++)
  492. {
  493. Con::printf("%7.3f %7.3f %8d %s",
  494. 100 * (rootVector[i]->mTotalTime - rootVector[i]->mSubTime) / totalTime,
  495. 100 * rootVector[i]->mTotalTime / totalTime,
  496. rootVector[i]->mTotalInvokeCount,
  497. rootVector[i]->mName);
  498. rootVector[i]->mTotalInvokeCount = 0;
  499. rootVector[i]->mTotalTime = 0;
  500. rootVector[i]->mSubTime = 0;
  501. }
  502. Con::printf("");
  503. Con::printf("Ordered by stack trace total time -");
  504. Con::printf("%% Time %% NSTime Invoke # Name");
  505. mCurrentProfilerData->mTotalTime = endHighResolutionTimer(mCurrentProfilerData->mStartTime);
  506. char depthBuffer[MaxStackDepth * 2 + 1];
  507. depthBuffer[0] = 0;
  508. profilerDataDumpRecurse(mCurrentProfilerData, depthBuffer, 0, totalTime);
  509. mEnabled = enableSave;
  510. mStackDepth--;
  511. }
  512. else if (mDumpToFile == true && mDumpFileName[0] != '\0')
  513. {
  514. FileStream fws;
  515. bool success = fws.open(mDumpFileName, Torque::FS::File::Write);
  516. AssertFatal(success, "Cannot write profile dump to specified file!");
  517. char buffer[1024];
  518. dStrcpy(buffer, "Profiler Data Dump:\n", 1024);
  519. fws.write(dStrlen(buffer), buffer);
  520. dStrcpy(buffer, "Ordered by non-sub total time -\n", 1024);
  521. fws.write(dStrlen(buffer), buffer);
  522. dStrcpy(buffer, "%%NSTime %% Time Invoke # Name\n", 1024);
  523. fws.write(dStrlen(buffer), buffer);
  524. for(U32 i = 0; i < rootVector.size(); i++)
  525. {
  526. dSprintf(buffer, 1023, "%7.3f %7.3f %8d %s\n",
  527. 100 * (rootVector[i]->mTotalTime - rootVector[i]->mSubTime) / totalTime,
  528. 100 * rootVector[i]->mTotalTime / totalTime,
  529. rootVector[i]->mTotalInvokeCount,
  530. rootVector[i]->mName);
  531. fws.write(dStrlen(buffer), buffer);
  532. rootVector[i]->mTotalInvokeCount = 0;
  533. rootVector[i]->mTotalTime = 0;
  534. rootVector[i]->mSubTime = 0;
  535. }
  536. dStrcpy(buffer, "\nOrdered by non-sub total time -\n", 1024);
  537. fws.write(dStrlen(buffer), buffer);
  538. dStrcpy(buffer, "%%NSTime %% Time Invoke # Name\n", 1024);
  539. fws.write(dStrlen(buffer), buffer);
  540. mCurrentProfilerData->mTotalTime = endHighResolutionTimer(mCurrentProfilerData->mStartTime);
  541. char depthBuffer[MaxStackDepth * 2 + 1];
  542. depthBuffer[0] = 0;
  543. profilerDataDumpRecurseFile(mCurrentProfilerData, depthBuffer, 0, totalTime, fws);
  544. mEnabled = enableSave;
  545. mStackDepth--;
  546. fws.close();
  547. }
  548. mDumpToConsole = false;
  549. mDumpToFile = false;
  550. mDumpFileName[0] = '\0';
  551. }
  552. void Profiler::enableMarker(const char *marker, bool enable)
  553. {
  554. reset();
  555. U32 markerLen = dStrlen(marker);
  556. if(markerLen == 0)
  557. return;
  558. bool sn = marker[markerLen - 1] == '*';
  559. for(ProfilerRootData *data = ProfilerRootData::sRootList; data; data = data->mNextRoot)
  560. {
  561. if(sn)
  562. {
  563. if(!dStrncmp(marker, data->mName, markerLen - 1))
  564. data->mEnabled = enable;
  565. }
  566. else
  567. {
  568. if(!String::compare(marker, data->mName))
  569. data->mEnabled = enable;
  570. }
  571. }
  572. }
  573. //=============================================================================
  574. // Console Functions.
  575. //=============================================================================
  576. // MARK: ---- Console Functions ----
  577. //-----------------------------------------------------------------------------
  578. DefineEngineFunction( profilerMarkerEnable, void, ( const char* markerName, bool enable ), ( true ),
  579. "@brief Enable or disable a specific profile.\n\n"
  580. "@param enable Optional paramater to enable or disable the profile.\n"
  581. "@param markerName Name of a specific marker to enable or disable.\n"
  582. "@note Calling this function will first call profilerReset(), clearing all data from profiler. "
  583. "All profile markers are enabled by default.\n\n"
  584. "@ingroup Debugging")
  585. {
  586. if( gProfiler )
  587. gProfiler->enableMarker( markerName, enable );
  588. }
  589. //-----------------------------------------------------------------------------
  590. DefineEngineFunction( profilerEnable, void, ( bool enable ),,
  591. "@brief Enables or disables the profiler.\n\n"
  592. "Data is only gathered while the profiler is enabled.\n\n"
  593. "@note Profiler is not available in shipping builds.\n"
  594. "T3D has predefined profiling areas surrounded by markers, "
  595. "but you may need to define additional markers (in C++) around areas you wish to profile,"
  596. " by using the PROFILE_START( markerName ); and PROFILE_END(); macros.\n\n"
  597. "@ingroup Debugging\n" )
  598. {
  599. if(gProfiler)
  600. gProfiler->enable(enable);
  601. }
  602. DefineEngineFunction(profilerDump, void, (),,
  603. "@brief Dumps current profiling stats to the console window.\n\n"
  604. "@note Markers disabled with profilerMarkerEnable() will be skipped over. "
  605. "If the profiler is currently running, it will be disabled.\n"
  606. "@ingroup Debugging")
  607. {
  608. if(gProfiler)
  609. gProfiler->dumpToConsole();
  610. }
  611. DefineEngineFunction( profilerDumpToFile, void, ( const char* fileName ),,
  612. "@brief Dumps current profiling stats to a file.\n\n"
  613. "@note If the profiler is currently running, it will be disabled.\n"
  614. "@param fileName Name and path of file to save profiling stats to. Must use forward slashes (/). "
  615. "Will attempt to create the file if it does not already exist.\n"
  616. "@tsexample\n"
  617. "profilerDumpToFile( \"C:/Torque/log1.txt\" );\n"
  618. "@endtsexample\n\n"
  619. "@ingroup Debugging" )
  620. {
  621. if(gProfiler)
  622. gProfiler->dumpToFile(fileName);
  623. }
  624. DefineEngineFunction( profilerReset, void, (),,
  625. "@brief Resets the profiler, clearing it of all its data.\n\n"
  626. "If the profiler is currently running, it will first be disabled. "
  627. "All markers will retain their current enabled/disabled status.\n\n"
  628. "@ingroup Debugging" )
  629. {
  630. if(gProfiler)
  631. gProfiler->reset();
  632. }
  633. #endif