Wednesday, January 12, 2011

Self-diagnosing code

Been a long time since I wrote a blog post - so here's a short one, about how you can make your ExtendScript code help you diagnose issues, and how to do it without killing the execution speed.
First of all, a fairly long intro about how I make my code self-diagnosing. I'll be skimping on the details - it's all part of my intro, and I'll get to the real point I want to make later.
When writing code, I nearly always routinely add all kinds of logging to the code. For example, every single function I make gets a little 'intro' and a little, er... 'extro' ;-) ?
function blah(var param) 
{
  ... body ...
  return retVal;
}
becomes
function blah(var param)
{
  if (kTracing) 
  {
     LogEntry("blah, param = " + param);
  }


  ... body ...


  if (kTracing) 
  {
     LogExit("blah);
  }
  return retVal;
}
kTracing is a constant that I define somewhere near the top of the script - e.g.
const kTracing = false;
LogEntry and LogExit are two functions I wrote that append their string parameter to a log file. 
I won't elaborate on those - they're very simple. In my case they're part of a larger set of 'standard' routines I use in all my scripts - I also have LogError, LogWarning, LogNote...and these all append their information to the same log file, and can be suppressed by modifying a constant kLogLevel. Writing those for yourself is left as an exercise. 
Secondly, I religiously test pre-conditions: things that should be true are verified and re-verified. I like using the do-while (false) 'non-loop' construct for bailing out quickly when preconditions are incorrect.
function DoSomethingWithCharacter(c)
{
  do // This is not a loop!
  {

    if (c == null)
    {
     LogError("DoSomethingWithCharacter: c == null");
     break;
    }


    if (! (c instanceof Character)) 
    {
     LogError("DoSomethingWithCharacter: c is not a Character");
     break;
    }


... body of the function ...


  }
  while (false); // This is not a loop! 
}
Not sure whether this is actually any faster than try/catch/throw constructs in ExtendScript, but I do know that in a number of environments like C and C++, try/catch comes with a performance penalty, and might not be available for various complex reasons - whereas I expect do-while(false) to be relatively cheap. 
I do use both constructs - I tend to use try/catch/throw more for really catastrophic issues, or as a workaround for InDesign issues (e.g. testing for 'dead' object references) whereas do-while(false) is used for 'controlled failure'. 
The code above is self-diagnosing: it spits out error messages into my log file every time something is not quite right, and in my experience, the error messages are more 'pin-point' precise than what you'd get with try/catch; with try/catch I often find myself struggling a bit to find the actual location of the error.
Release versions of my scripts will typically have their log level set to zero (which means calls to LogError and friends amount to almost 'do-nothing', apart from a little overhead). When things go wrong, I modify a few constants (kLogLevel, kTracing) at the top of the script, let it do its thing, and often know what the issue is very soon thereafter.
Writing this kind of code takes a bit of extra effort - but it always pays back for itself the first time I get the first hairy bug to diagnose. It's not always possible to use the ExtendScript Toolkit for a debugging session for various reasons, and having the proper testing and logging code ready-to-go is often a life saver.
Now, that's the intro - now onto the real issue I wanted to discuss.
Adding logging code to all my functions comes at a performance penalty: especially 'deep' routines that are called from within loops are often called thousands or millions of times, and even when kTracing is set to false,  this could still incur some overhead.
Now, here's a trick I often use: I use my trusty text editor (BBEdit) to make my logging code disappear and reappear as needed. Here's how it goes: I dress up all my intro and 'extro' code as follows:
...

  /*TRACEIN*/if (kTrace)
  {
    LogEntry("AdjustStory");
  }/*TRACEOUT*/
...
When the code is ready for a production environment, I do a global search-and-replace and replace
/*TRACEIN*/
with
/*TRACEIN*-/
and also (even though it is not necessary, but I am obsessive compulsive about this, so I need to do it to keep things 'even') 
/*TRACEOUT*/ 
is replaced with
/-*TRACEOUT*/
As a result, my tracing code now becomes:
...
  /*TRACEIN*-/if (kTrace)
  {
    LogEntry("AdjustStory");
  }/-*TRACEOUT*/
...
If you look closely, you'll see the whole construct is now a 3-line comment, which will almost certainly be less costly in performance. I can only guess how the ExtendScript engine works, but I suspect that the only cost will be a tiny bit of time when the script is parsed, and there would be no additional cost during repeated execution of the function.
Furthermore, my scripts often are packaged up as .spln files (using Active Page Item Developer), and this automatically strips out all comments when creating a release version of an .spln - so when using this for .spln development, the entry/exit logging code is guaranteed to be completely gone.
When an issue arises, I simply perform the reverse search-and-replace, and re-enable my disabled logging code.
There's lot of additional things you can do with logging - I've only scratched the surface here. For example, sometimes I use an XML format for output of the logging - and the extra effort to do that is rewarded by the fact that I can use an XML editor or XML browser to selectively hide and show whole sections of the log. Anyway, depending on feedback, I might do another post some time later on a few more of these techniques.