160919、使用AOP与注解记录Java日志

有些时候，我想要把每个运行过的方法接收到的参数、返回值和执行时间等信息记录（通过slf4j 和 log4j）下来。在AspectJ、jcabi-aspects和Java注解的帮助下我实现了这个想法。

public class Foo {

  @Loggable

  public int power(int x, int p) {

    return Math.pow(x, p);

  }

}

在log4j中可以看到以下输出：

[INFO] com.example.Foo #power(2, 10): 1024 in 12μs

[INFO] com.example.Foo #power(3, 3): 27 in 4μs

看上去很酷对吧？接下来我们来看看它是如何工作的。

注解

注解是Java 6中采用的一种技术（译注：其实Java 5就有注解了）。它是一种不会影响程序运行的元编程指令，我们可以用它来对一些指定的元素（方法、类或者变量）进行标记。换句话说，注解就是代码中可以看到的标记。一些注解只在编译阶段可见——它们不存在于编译好的.class文件中，另外一些注解在编译后仍然可见。

例如，@Override是第一种类型（它的保留类型是SOURCE），而JUnit的@Test是第二种类型（保留类型是RUNTIME），@Loggable——我在上面使用过的是第二种注解，包含在jcabi-aspects中，在编译后会留在.class文件中。

值得注意的是，上文的power()方法即便被注解并且编译，也不会发送任何内容到slf4j。仅仅是一种用来提醒相关软件“请记录我的执行过程”的标记， 理解这一点很重要。

AOP

AOP（面向切面编程）是一种可以在对源代码不作明显改动的情况下向其加入可执行块的技术。在上面的示例中，我们不想在实现类中记录方法的执行，而是用其他类去拦截power()方法的每次调用，测量执行时间并把这些信息发送给slf4j。

我想要使拦截类能识别@Loggable注解并且记录下power()方法的每次调用，当然它也应该能拦截其他方法。

这个想法与AOP的出发点很符合——避免在多个类中重复实现一些共同的功能。

日志是Java主要功能的一个补充。我们不想往代码中加入繁杂的日志指令，这样会导致代码可读性降低，所以我们想在别的地方偷偷地记录日志。

从AOP的角度来看，我们的解决方案是新建一个指定切入点和环绕通知的切面以实现预期的功能。

AspectJ

接下来，让我们来看看这些神奇的注解。首先，让我们来了解jcabi-aspects是如何用AspectJ来实现注解的。下面是一个简单例子，你可以在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;

  }

}

这个切面（aspect）里有一个around()通知，切面用@Aspect注解，通知用@Around注解， 上面提到过这些注解仅仅是在.class文件中做了标记，这些标记在运行时能提供一些信息给那些对它们感兴趣对象。

@Around注解有一个参数，如果该方法

1. 可见性是 * （public、protected或private）；

2. 名字是 * （任何名字都可以）；

3. 参数是 .. （任何参数都可以）；

5. 注解为@Loggable

那么通知就会应用到该方法。

当注解方法被调用的时就会被拦截，around()通知会在被拦截方法之前执行，其中 @Around 类型的通知需要一个 ProceedingJoinPoint 类的实例作为参数，之后返回一个对象给power()方法。

为了调用power()方法，通知需要调用join point对象的proceed()方法。

接下来编译并把它加入环境变量，让我们的主文件Foo.class能够调用它。目前为止一切顺利，我们还需要最后一步——把通知运转起来。

二进制切面织入

切面织入（aspect waving）就是将切面应用到目标对象从而创建一个新的代理对象的过程。切面织入将一些代码插入原代码，AspectJ就是这么做的。我们给它两个二进制Java类Foo.class 和 MethodLogger.class; 它返回三个类——修改过的Foo.class、Foo$AjcClosure1.class和未修改的MethodLogger.class。

为了理解如何将不同的通知应用于对应的哪个方法，AspectJ织入在.class文件中使用了注解，并使用反射来浏览环境变量中的所有类。它分析@Around注解中的哪个方法满足条件。power()就在此时被发现了。

上述操作需要分为两步。首先，我们把.java文件编译。然后AspectJ对编译后的文件进行织入/修改，织入后的Foo类看起来像下面这样：

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织入把我们原来的功能移到新方法power_aroundBody()中，并把所有的power()调用重定向到切面类MethodLogger。

下图是每次调用power()的过程：

图中那一小块绿色就是原方法power()。

如你所见，切面织入过程把类和切面等联系起来了。如果没有织入，它们仅仅是一堆编译好的二进制代码和注解。

jcabi-aspects

jcabi-aspects是一个含有Loggable注解和MethodLogger切面的JAR库，它还有其它注解和切面。你不必自己实现切面，只要在环境变量加入一些依赖并为切面织入配置好jcabi-maven-plugin。可以到Maven Central获取最新版本。

<project>

  <depenencies>

    <dependency>

      <dependency>

        <groupId>com.jcabi</groupId>

        <artifactId>jcabi-aspects</artifactId>

      </dependency>

      <dependency>

        <groupId>org.aspectj</groupId>

        <artifactId>aspectjrt</artifactId>

      </dependency>

    </dependency>

  </depenencies>

  <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>

由于织入过程比较复杂，我用Maven插件和ajc goal做了一个便捷的织入。你也可以直接用AspectJ，不过我还是推荐你使用jcabi-maven-plugin。

好了，现在你可以用@com.jcabi.aspects.Loggable 注解你的方法执行过程将会通过slf4j记录下来。