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.
