JavaScript tracing

Usually when I'm trying to diagnose a problem with some piece of code, I'll reach for a debugger. A debugger is a great tool to use if you want to watch your code as it's executing, to see where it goes, what it touches, etc. But sometimes, using a debugger is inappropriate. For example, timing problems in your code can be difficult-to-impossible to diagnose with a debugger, because the act of debugging changes the timing (the observer effect).

In these cases, I reach for a tracer. What's a tracer? A tracer is a debugger, of sorts, that shows you what functions are being executed, and produces some kind of hierarchical log of the function execution when you are "done". Here's an example of a tracer log:

ElementsPanel.reset() ➊
   ElementsPanel.rootDOMNode() ➋
      ElementsTreeOutline.rootDOMNode() ➌
   ElementsPanel.focusedDOMNode() ➍
      ElementsTreeOutline.focusedDOMNode()
         ElementsTreeOutline.revealAndSelectNode()
   ElementsPanel.searchCanceled()
Panel.searchCanceled()

In this example, the function ElementsPanel.reset() ➊ calls the function ElementsPanel.rootDOMNode() ➋ which calls ElementsTreeOutline.rootDOMNode() ➌. After the call to ElementsTreeOutline.rootDOMNode() returns, ElementsPanel.rootDOMNode() then calls ElementsPanel.focusedDOMNode() ➍. And so on.

You could instrument your code by hand, using printf() or whatever, but that's tedious. Let the computer do the work for you.

In a previous life, as a Java developer, I've written at least two Java tracers using the Java^TM Debug Interface (JDI). Once you figure out how to use JDI, it's straight-forward to write single-purpose debugging clients like a tracer.

In my current life, I'm a JavaScript developer. There is nothing like the JDI for JavaScript. Yet. Bummer. But all hope is not lost. Turns out it's fairly straight-forward to write a tracer for JavaScript "classes". Here's one: function-tracer.js. And here's how I used it in a real-life situation.

I'm currently looking at a bug which smelled to me like it had a timing issue. I knew the suspect classes, so I just traced all of them, using the following bit of code added to my HTML:

<script src="function-tracer.js"></script>

<script>
FunctionTracer.logFunction = function(message) { WebInspector.log(message); };

FunctionTracer.traceFunctionsInObject(WebInspector.View.prototype, "View.");
FunctionTracer.traceFunctionsInObject(WebInspector.Panel.prototype, "Panel.");
FunctionTracer.traceFunctionsInObject(WebInspector.ElementsTreeOutline.prototype, "ElementsTreeOutline.");
FunctionTracer.traceFunctionsInObject(WebInspector.ElementsTreeElement.prototype, "ElementsTreeElement.");
FunctionTracer.traceFunctionsInObject(WebInspector.ElementsPanel.prototype,       "ElementsPanel.");
</script>

What's going on here:

• Add the function-tracer code via the <script src=> element.

• Add a custom logging function which writes to a logger that my application uses (WebInspector.log)

• Instrument the suspect classes (WebInspector.View, etc)

"Instrument"ing a class means that when an "instance" method in the class runs (a function in the class's prototype), it will get logged by my logger. The tracing output sample above was copied straight from my logger. I'll let you figure out how it actually works.

The code I posted handles new age ECMAScript 5 getter/setter accessors, which the code I'm debugging is using. I think I've provided enough checking in the code that it will work if you're running on some crusty old ECMAScript 3-ish engine.

In the end, I believe I found the issue with the bug in question, by comparing a "successful" run of the code with a "failure" run. But what's really the most fun thing of all with a tracer, is to see how bloaty your code is. In this case, I not only found a problem in the code, I could see that it was re-running some of the same code, over and over, probably for no good reason. But that's another bug.