Interception

This document gives us an overview over the method call interception mechanism that is provided by Cerny.js. Method call interception allows us to call a function before and after the actual invocation of a function. This way we can easily profile the execution time or log actual parameters and the return value. Unlike inline logging statements, interception does not clog our code, and, additionally, it can be turned on and off on demand. Interception even opens up a possibility for type checking.

Configuring interception

The list of active interceptors is held in the array CERNY.Configuration.Interception.active. We have to fill this array in the CERNY.configure function in the cerny.conf.js script.

CERNY.configure = function() { var interceptors = CERNY.Configuration.Interception.active; interceptors.push(CERNY.Interceptors.LogIndenter); interceptors.push(CERNY.Interceptors.Tracer); // interceptors.push(CERNY.Interceptors.TypeChecker); // interceptors.push(CERNY.Interceptors.ContractChecker); interceptors.push(CERNY.Interceptors.Profiler); }

In this case, three interceptors that come with Cerny.js are pushed onto the interceptors array. They will be wrapped around the next function that is attached to an object by means of Cerny.js provides, which we will learn about soon. More basic interceptors, e.g LogIndenter, are pushed first, so that the later interceptors can benefit from their effect. In the case of LogIndenter this results in the correct indentation of the profiling and tracing statements in the log output.

Installing interception on existing code

Let's say, we have existing JavaScript code and we encounter performance issues. After being granted immunity, one of our programmers admits that it might be the object Snail, which is causing the problem. Knowing this, we add the following line after Snail is defined and turn up the log level of Snail to TRACE.

CERNY.intercept(Snail);

Looking at the log output, we learn how long the method calls to Slow actually take.

Wed Jan 17 2007 18:39:40 GMT+0100 (CET), TRACE: start | OURAPP.snail.move Wed Jan 17 2007 18:39:40 GMT+0100 (CET), TRACE: start | OURAPP.snail.slime Wed Jan 17 2007 18:39:40 GMT+0100 (CET), TRACE: stop: 600 ms | OURAPP.snail.slime Wed Jan 17 2007 18:39:40 GMT+0100 (CET), TRACE: stop: 800 ms | OURAPP.snail.move

We notice that Snail is spending 800 ms in move, of which 600 ms are spent in a call to slime. Now we know where the performance issues come from, because all Snails do in our application is move.

CERNY.intercept takes optional arguments which can be used to specify the names of the functions to intercept, either by a string or a regular expression. If there is no other parameter than the object, like in the above example, all methods that are attached directly to the object (hasOwnProperty) are prepared for interception. This does not entail methods of the prototype, which must be prepared for interception separately. Here is an example how to do that, also illustrating the use of optional arguments.

CERNY.intercept(Snail.prototype, /^get.*/, /^set.*/, "giveBirth");

If the object of interception has a logger stored in the member logger, the Interceptors will log to that logger. If there is no logger attached to the object, the logger will be of category NONE. For this reason, it is recommended that the NONE category is always set to TRACE in the configuration file, so that no log statements go missing.

Creating a customized interceptor

An interceptor is an object which has a before and after method. Let's have a look at the Profiler which comes with Cerny.js.

CERNY.Interceptors.Profiler = { before: function(call) { call.logger.trace("start"); call.start = new Date(); }, after: function(call) { call.logger.trace("stop: " + (new Date().getTime() - call.start.getTime()) + " ms"); } }

Both methods of the interceptor have a parameter call, in which an object specific to the function call is passed. It can be used to transfer information across the actual function call (and all later interceptors). In the example above, we notice that the current time is stored in the property start in the call object. Furthermore, the call object comes with a logger ready for use.

API Documentation for version