Partager via

Helpful Tracing Routines

  • Article

Last time we looked at conditional compilation, and how using it with HDiSim could aid with interactive debugging of runtime exceptions. But as useful as interactive debugging is, there are three major cases where it is impractical or impossible:

  1. When the bug is timing related, and using a debugger masks the bug; or
  2. Reproducing the bug requires running a large amount of code it's impractical or laborious to step through by hand; or
  3. You're trying to track down an issue on a real player (which you can't debug on).

In these cases, it is very useful to have some robust tracing primitives built in to your code to give you a trace (or log) of everything that the player is doing up until the time the bug occurs. I already posted a while back on red box debugging, and how that relates to printf debugging; now we're going to add some more printf-like tracing to our HDi toolkit to help diagnose issues on retail players or to trace errors through the system in critical timing sections.

The general approach is to pepper our code with calls to a trace() function that will either write the trace info to a log file, or display it on the screen, or both. Usually the trace function will be called when execution enters a new function, when an exception is handled, and at any other point in time where it is useful to know the result of a test or the value of a particular variable or property. Now, the key to any good trace log is the ability to identify the function that was active at the time a given log entry was made. Whilst it is possible to hard-code the name of the function into the trace call (for example, trace("Inside function 'foo'") ), this is problematic because any time you re-name a function (or copy-and-paste it to a new function) you need to update the function name in the script. It would be much better if you could somehow automatically get the function name...

Enter the GetFunctionName function, defined like this:

// Returns the name of a function
function GetFunctionName(func)
{
try
{
var re = /function\s+(\w+)/;
var s = re.exec(func.toString())[1];

    // Based on naming convention of 'object_FunctionName'
if (s.indexOf("_") >= 0)
return s.substring(s.indexOf("_"));

    return s;
}
catch(ex) { ; }

  return "AnonymousOrUnknownFunction";
}

Given a Function object as its only argument, this function will return the name of the function (or the string "AnonymousOrUnknownFunction" if the function name is not available – for example, you pass in a function expression or a native method). It does this by creating a Regular Expression re that looks for the word "function" followed by some whitespace \s+ and then a word (\w+) . If the word is found, it is "captured" (because it is in parentheses) and returned by the expression re.exec(...)[1] . The toString call inside of exec simply converts the Function object into an implementation-defined representation of the function body, but ECMA 262 defines that at a minimum this contains the function name (ie, it is a FunctionDeclaration).

OK, that's kind of useful, but how do you get the right Function object to pass to the GetFunctionName function? Good question. The answer is that you use the arguments object, and in particular the callee property; it holds a reference to the function being called. Neato, eh?

I want to take a quick detour here to say that I personally think that relying on the arguments object as a way of passing parameters to a function is a bad programming practice and should be avoided for normal development; I won't bore you with all the details, but basically it makes your code harder to read (and thus harder to understand) if all the expected parameters aren't immediately obvious from the function's declaration. Nevertheless, the arguments object is great for tracing, and so we shall use it for this.

So while we're on the subject of the arguments object, it's also worth noting that it's a great way to trace the arguments passed to a function in a generic way (again, avoiding the copy-and-paste problem, or having to keep up with added or removed parameters). To do this, we'll write another function (and a little helper) that can be used to generate a string holding the value of all the arguments passed to a function. It looks like this:

// Returns a string representing the arguments list of a function
function GetArgumentsString(args)
{
  var s = "(";
  var first = true;

  for (var i = 0; i < args.length; i++)
  {
    if (first != true)
      s += ", ";

    first = false;

    var arg = args[i];
    s += ObjectToString(arg);
  }

  s += ")";
  return s;
}

// Returns a string representation of an object;
function ObjectToString(obj)
{
  try
  {
    if (typeof(obj) == "function")
      return "function " + GetFunctionName(obj);

    if (typeof(obj) == "string")
      return "\"" + obj + "\"";

    return String(obj);
  } 
  catch(ex)
  {
    return "[native Object]";
  }
}

Together these two functions will take an arguments object and return a string that contains all their values, including special handling for functions and native (host) objects. Now we can build a simple function that is used to trace function entry like this:

// Global to define whether to do tracing or not;
// Tracing can be expensive so you might not want to do it on a released title
var _DO_TRACE = true;

// Trace function name and argument list
function TraceFunctionEntry(args)
{
  // Bail immediately if tracing is not desired
  if (_DO_TRACE != true)
    return;

  var name = GetFunctionName(args.callee);
  var argString = GetArgumentsString(args);
  TraceString(name + argString);
}

And we can use the TraceFunctionEntry function like this:

function MyFunction(a, b, c)
{
  TraceFunctionEntry(arguments);

  // Do some actual work...
}

Now we just need to define the TraceString function; but that's the easy part ;-)

// Global startup code to open the diagnostics file, if necessary.
if (_DO_TRACE)
{
  try
  {
    Diagnostics.listeners.add("file");
    Diagnostics.trace.autoFlush = true;
  } catch (ex) { }
}

// Function to trace a message to the diagnostics log and, if available,
// an on-screen input.
function TraceString(msg)
{
  if (_DO_TRACE != true)
    return;

  // Write out the message to the diagnostics log
  try
  {
    Diagnostics.trace.writeLine(msg, "Trace", 1);
  } catch (ex) { }

  // Try to add the message to an <input> named 'trace', if one exists
  try
  {
    var node = document.trace;
    if (node != null && node.nodeName == "input")
      node.state.value = node.state.value + " | " + msg;

  } catch (ex) { }
}

And there you have it! I have attached a sample project that includes a couple of other helpful tracing aids (one for errors, one for informational tracing). As usual, you need to copy a file named font.ttf into the ADV_OBJ folder in order for it to work (I use the "Kooteny" sample font from the HDiSim download).

 

TracingBlog.zip

Comments

  • Anonymous
    December 07, 2007
    The comment has been removed
  • Anonymous
    December 07, 2007
    The comment has been removed
  • Anonymous
    December 13, 2007
    It's finally here! The Xbox 360 HD DVD Emulator went live today, enabling content authors to test their