profiler.cpp 24 KB

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