Aug 11

Profiling Javascript functions

Tilt has reached a point in which profiling is mandatory. Execution time is virtually impossible to compute correctly in Javascript, but the bottlenecks can still be successfully spotted by counting the function calls and computing the total execution time. Moreover, intercepting function calls can be tricky, but easy once everything is handled properly. If a parent object and the function name are available, using closures we can retain the original function. The whole idea is to overwrite that function to handle before/during/after method calls, and, once this is done, we can record the number of calls, the total time necessary to execute a function and other useful information.

A tricky issue can appear when an overwritten function needs to return a value. In this case, the afterCall still needs to be executed after the function returns. The try/finally clause does just this, it ensures the execution of the afterCall function even after the original function has returned a value.

Using an array of profiles, retaining information about all the functions, variables like longestTime or averageTime can easily be updated. Other issues may appear when handling the “this” object, which can differ from the function parent object. To fix this, the handy .call() hack does the trick.

Probably the most annoying hack needed to be done is passing parameters from the overwritten function to the original child function. Since most of the times the overwritten function has one or more arguments, simply passing the arguments property inside the function isn’t enough. We need to construct the parameters directly, separated by commas, just like a normal call would be executed. Although discouraged, eval() works pretty well in this case, and even with every possible function call profiled in Tilt, no performance drop was observed. Be careful though, and use this hack only with code you trust. Update: a much better way of handling this scenario is to just use method.apply(object, args); to handle passing parameters from one function to another. The code was updated to reflect this change. Never, ever use eval!

Once everything is finished, logging can be done by sorting all the recorded function calls, timing and other information by a key. With Tilt, the most useful data was received when sorting by the total time necessary for a function to be executed. However, this is easily changeable to suit other scenarios.

Because some functions inside objects can be duplicated when creating object via var foo = new MyObject(), that is, when they are declared inside the constructor function and not the object prototype, we need to check for duplicates and recalculate the number of calls, longest time, total time, average time for these situations. Replace the Tilt.Console.log call with your favorite logging method, like console.log or something similar.

Intercepting functions in an object is very easy. Inside the constructor function, call the intercept method:

See the Tilt.Renderer constructor for an example. Certain functions from an object can be specified to be logged, instead of all the child functions. If you’re not using objects, pass window as the parent object for specific named functions, in which case the call would be intercept(null, “window”, “myFunc”). See the intercept function documentation from Tilt.Profiler for more information.