Sometimes, I want to log (through slf4j and log4j) every execution of a method, seeing what arguments it receives, what it returns and how much time every execution takes. This is how I'm doing it, with help of AspectJ, jcabi-aspects and Java 6 annotations:
This is what I see in log4j output:
Nice, isn't it? Now, let's see how it works.
Annotation with Runtime Retention
a technique introduced in Java 6. It is a meta-programming
instrument that doesn't change the way code works, but gives
marks to certain elements (methods, classes or variables).
In other words, annotations are just markers attached to the code
that can be seen and read. Some annotations are designed to be
seen at compile time only — they don't exist in
.class files after
compilation. Others remain visible after compilation and can
be accessed in runtime.
@Override is of
the first type (its retention type is
@Test from JUnit is of the second type (retention type is
the one I'm using in the script above — is an annotation of the second type,
It stays with the byte-code in the
.class file after compilation.
Again, it is important to understand that even though
power() is annotated and compiled, it doesn't
send anything to slf4j so far. It just contains
a marker saying "please, log my execution".
Aspect Oriented Programming (AOP)
is a useful technique that enables adding executable blocks
to the source code without explicitly changing it. In our example,
we don't want to log method execution inside the class. Instead,
we want some other class to intercept every call to method
measure its execution time and send this information to slf4j.
We want that interceptor to understand our
and log every call to that specific method
power(). And, of course,
the same interceptor should be used for other methods where
we'll place the same annotation in the future.
This case perfectly fits the original intent of AOP — to avoid re-implementation of some common behavior in multiple classes.
Logging is a supplementary feature to our main functionality, and we don't want to pollute our code with multiple logging instructions. Instead, we want logging to happen behind the scenes.
In terms of AOP, our solution can be explained as creating an aspect that cross-cuts the code at certain join points and applies an around advice that implements the desired functionality.
This is an aspect with a single around advice
around() inside. The aspect is annotated with
and advice is annotated with
@Around. As discussed above,
these annotations are just markers in
.class files. They don't do
anything except provide some meta-information to those w
ho are interested in runtime.
@Around has one parameter, which — in this case —
says that the advice should be applied to a method if:
its visibility modifier is
its name is name
its arguments are
..(any arguments); and
it is annotated with
When a call to an annotated method is to be intercepted,
around() executes before executing the actual method.
When a call to method
power() is to be intercepted, method
receives an instance of class
ProceedingJoinPoint and must return an
object, which will be used as a result of method
In order to call the original method,
power(), the advice has
proceed() of the join point object.
We compile this aspect and make it available in classpath
together with our main file
Foo.class. So far so good,
but we need to take one last step in order to put
our aspect into action — we should apply our advice.
Binary Aspect Weaving
Aspect weaving is the name of the advice applying process.
Aspect weaver modifies original code by injecting calls to aspects.
AspectJ does exactly that. We give it two binary Java classes
MethodLogger.class; it gives back three — modified
Foo$AjcClosure1.class and unmodified
In order to understand which advice should be applied to which methods,
AspectJ weaver is using annotations from
Also, it uses reflection
to browse all classes on classpath. It analyzes which methods satisfy
the conditions from the
Of course, it finds our method
So, there are two steps. First, we compile our
.java files using
javac and get two files. Then, AspectJ weaves/modifies them and
creates its own extra class. Our
Foo class looks something
like this after weaving:
AspectJ weaver moves our original functionality to a new method,
power_aroundBody(), and redirects all
to the aspect class
Instead of one method
power() in class
Foo now we have
four classes working together. From now on,
this is what happens behind the scenes on every call to
Original functionality of method
power() is indicated
by the small green lifeline on the diagram.
As you see, the aspect weaving process connects together classes and aspects, transferring calls between them through join points. Without weaving, both classes and aspects are just compiled Java binaries with attached annotations.
jcabi-aspects is a JAR library
Loggable annotation and
aspect (btw, there are many more
aspects and annotations). You don't need to write your own
aspect for method logging. Just add a few dependencies to
your classpath and configure jcabi-maven-plugin
for aspect weaving
(get their latest versions in Maven Central):
Since this weaving procedure takes a lot of configuration effort,
I created a convenient Maven plugin with an
ajc goal, which does
the entire aspect weaving job. You can use AspectJ directly, but
I recommend that you use jcabi-maven-plugin.
That's it. Now you can use
annotation and your methods will be logged through slf4j.
If something doesn't work as explained, don't hesitate to submit a GitHub issue.