detect slow script functions: setExecDurationWarnThreshhold()

new torqueScript diagnostic tool: setExecDurationWarnThreshhold().

this resource implements a new torqueScript function, setExecDurationWarnThreshhold(),
which will print a warning when any script codeblock takes "a long time" to execute.
i believe there is no performance overhead for this monitoring.

first, here are some examples for motivation:

==>function hardSleep(%ms) { %a = getRealTime(); %b = %a; while (mSubS32(%b, %a) < %ms) { %b = getRealTime(); } }
==>function foo(%ms) { hardSleep(%ms); }
==>setExecDurationWarnThreshhold(1500);
==>foo(1500);
slow codeblock -  1500ms -    hardSleep()
slow codeblock -  1500ms -   foo()
slow codeblock -  1500ms -  ConsoleEntry::eval()

here's a more real-world example from a particularly slow call from some code,
with the threshhold set to 50ms. (this is a debug build, sort of artificially slow)
you can pretty immediately see that ClosetTabs::tabSelected() might be worth looking at:

==>setExecDurationWarnThreshhold(50);
==>toggleClosetGui();
slow codeblock -    63ms -         Closet::skuListHasCategory()
slow codeblock -   343ms -         Closet::skuListHasCategory()
slow codeblock -   672ms -        ClosetItemPopup::update()
slow codeblock -   937ms -       ClosetThumbnails::setDrawers()
slow codeblock -   937ms -      ClosetItemsFrame::update()
slow codeblock -   984ms -     ClosetMyOutfitsFrame::hangerSelected()
slow codeblock -  6656ms -    ClosetTabs::tabSelected()
slow codeblock -  6671ms -   TabControl::selectTabAtIndex()
slow codeblock -  6671ms -  TabControl::selectTabWithName()
slow codeblock -  7125ms - (no namespace)::toggleClosetGui()

and here's the modifications to a TGE 1.3.5 codebase.
all the modification are here, but familiarity with C++ and the Torque source code is assumed.

caveat: i'm seeing that my codebase is actually a bit different than a stock TGE 1.4 codebase,
so i've adapted to what i think should work, but have not actually tested this exact changeset.


consoleInternal.h
in the class ExprEvalState, after bool traceOn;, add:

U32  execDurationWarnThreshhold;

consoleInternal.cc
in the class ExprEvalState, after traceOn = false;, add:

execDurationWarnThreshhold = 0;

consoleFunctions.cc
after the console function "trace" ( search for ConsoleFunction(trace ), add this console function:

ConsoleFunction(setExecDurationWarnThreshhold, void, 2, 2, "setExecDurationWarnThreshhold(U32 ms)")
{
   gEvalState.execDurationWarnThreshhold = dAtoi(argv[1]);
}

ConsoleFunction(getExecDurationWarnThreshhold, S32, 1, 1, "getExecDurationWarnThreshhold()")
{
   return gEvalState.execDurationWarnThreshhold;
}

compiledEval.cc, in the method CodeBlock::exec()
up near the top along with the declaration of curStringTable, add:

U32     timeStart = 0;

just before gEvalState.pushFrame(thisFunctionName, thisNamespace);, insert:

if (gEvalState.execDurationWarnThreshhold > 0)
      {
         timeStart = Platform::getRealMilliseconds();
      }

down just below execFinished:, add:

if (argv != NULL && timeStart != 0 && gEvalState.execDurationWarnThreshhold > 0)
      {
         U32 timeFinish = Platform::getRealMilliseconds();
         U32 timeDelta  = timeFinish - timeStart;
         if (timeDelta >= gEvalState.execDurationWarnThreshhold)
         {
            const char* ns = (thisNamespace    != NULL && thisNamespace->mName != NULL) ? thisNamespace->mName : ""                 ;
            const char* sp = (thisNamespace    != NULL && thisNamespace->mName != NULL) ? "::"                 : ""                 ;
            const char* fn = (thisFunctionName != NULL                                    ) ? thisFunctionName : "(no functionName)";
            Con::warnf("slow codeblock - %5dms - %-*s%s%s%s()", timeDelta, gEvalState.stack.size() - 1, "", ns, sp, fn);
         }
      }

.. and that should do it.