Java Method Logging with AOP and Annotations
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:
public class Foo {
@Loggable
public int power(int x, int p) {
return Math.pow(x, p);
}
}
This is what I see in log4j output:
[INFO] com.example.Foo #power(2, 10): 1024 in 12μs
[INFO] com.example.Foo #power(3, 3): 27 in 4μs
Nice, isn't it? Now, let's see how it works.
Annotation with Runtime Retention
Annotations is 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.
For example, @Override
is of the first type (its retention type is SOURCE
), while @Test
from JUnit is of the second type (retention type is RUNTIME
). @Loggable
— the one I'm using in the script above — is an annotation of the second type, from jcabi-aspects. It stays with the bytecode in the.class
file after compilation.
Again, it is important to understand that even though method 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)
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 power()
, measure its execution time and send this information to slf4j.
We want that interceptor to understand our @Loggable
annotation 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 thatcross-cuts the code at certain join points and applies an around advice that implements the desired functionality.
AspectJ
Let's see what these magic words mean. But, first, let's see how jcabi-aspectsimplements them using AspectJ (it's a simplified example, full code you can find in MethodLogger.java
):
@Aspect
public class MethodLogger {
@Around("execution(* *(..)) && @annotation(Loggable)")
public Object around(ProceedingJoinPoint point) {
long start = System.currentTimeMillis();
Object result = point.proceed();
Logger.info(
"#%s(%s): %s in %[msec]s",
MethodSignature.class.cast(point.getSignature()).getMethod().getName(),
point.getArgs(),
result,
System.currentTimeMillis() - start
);
return result;
}
}
This is an aspect with a single around advice around()
inside. The aspect is annotated with @Aspect
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.
Annotation @Around
has one parameter, which — in this case — says that the advice should be applied to a method if:
-
its visibility modifier is
*
(public
,protected
orprivate
); -
its name is name
*
(any name); -
its arguments are
..
(any arguments); and -
it is annotated with
@Loggable
When a call to an annotated method is to be intercepted, method around()
executes before executing the actual method. When a call to methodpower()
is to be intercepted, method around()
receives an instance of class ProceedingJoinPoint
and must return an object, which will be used as a result of method power()
.
In order to call the original method, power()
, the advice has to callproceed()
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 Foo.class
and MethodLogger.class
; it gives back three — modified Foo.class
, Foo$AjcClosure1.class
and unmodified MethodLogger.class
.
In order to understand which advices should be applied to which methods, AspectJ weaver is using annotations from .class
files. Also, it usesreflection to browse all classes on classpath. It analyzes which methods satisfy the conditions from the @Around
annotation. Of course, it finds our method power()
.
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:
public class Foo {
private final MethodLogger logger;
@Loggable
public int power(int x, int p) {
return this.logger.around(point);
}
private int power_aroundBody(int x, int p) {
return Math.pow(x, p);
}
}
AspectJ weaver moves our original functionality to a new method,power_aroundBody()
, and redirects all power()
calls to the aspect classMethodLogger
.
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 power()
:
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
jcabi-aspects is a JAR library that contains Loggable
annotation andMethodLogger
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):
<project>
<dependencies>
<dependency>
<groupId>com.jcabi</groupId>
<artifactId>jcabi-aspects</artifactId>
</dependency>
<dependency>
<groupId>org.aspectj</groupId>
<artifactId>aspectjrt</artifactId>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>com.jcabi</groupId>
<artifactId>jcabi-maven-plugin</artifactId>
<executions>
<execution>
<goals>
<goal>ajc</goal>
</goals>
</execution>
</executions>
</plugin>
</plugins>
</build>
</project>
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 usejcabi-maven-plugin.
That's it. Now you can use @com.jcabi.aspects.Loggable
annotation and your methods will be logged through slf4j.
If something doesn't work as explained, don't hesitate to submit a Github issue.
Related Posts
You may also find these posts interesting:
相关文章
- 深入java面向对象五:Java的内存管理
- Java实现 LeetCode 725 分隔链表(暴力)
- Java实现 LeetCode 572 另一个树的子树(遍历树)
- Java实现字母去重
- Java实现 洛谷 P1426 小鱼会有危险吗
- java实现第四届蓝桥杯买不到的数目
- 【JAVA秒会技术之秒杀面试官】秒杀Java面试官——集合篇(一)
- Java 多线程编程(2-异步中包含同步)
- 【JAVA】Java 异常中e的getMessage()和toString()方法的异同
- 【JAVA】毕向东Java基础视频教程-笔记
- [Linux] Install java and add JAVA_HOME, PATH
- 面向切面编程AOP[四](java AnnotationAwareAspectJAutoProxyCreator与ioc的联系)
- JAVA中反射的实现过程和作用分别是什么?
- Spring读源码系列之AOP--08--aop执行完整源码流程之自动代理创建器导入的两种方式
- Aitit aop之道 艾龙著 需要整合zop资料包东西 第1章 AOP的产生 1.1 软件开发方法的演进 1.2 AOP产生的前奏——把系统看做一批关注点
- android工程java项目如何转kotlin
- How to improve Java's I/O performance( 提升 java i/o 性能)
- 1小时学会通过Java Swing Design设计java图形化
- 【java】Java 枚举(enum)如何使用以及原理
- 【Java】java中javaSE与javaEE的区别
- Java中static作用及用法详解
- 一文详解java线程池 详解Java线程池的七个参数 详解池化技术 java如何选择核心线程数 详解Java线程池的拒绝策略
- Java基础(9)-基础语法
- 【java】Java 中泛型的实现原理
- 【java】Java 继承
- 【java】Java 集合框架
- 基于JAVA实现的WEB端UI自动化 - WebDriver框架篇 - 框架设计小结
- Java中的ThreadLocal详解