Performance Messungen mit Spring AOP

Intro

Tjaja… die Performance. Wie oft kommt eine Situation vor, dass man gerne wissen möchte welche Methodenausführung wie lange dauert. Es gibt da natürlich tolle Hilfsmittel wie XRebel von zeroturnaround, jedoch habe ich mich oft für einfachere Möglichkeiten interessiert.

Eine - wie ich finde - sehr schicke und schlichte Art der Performance Messung lässt mit mittels AOP realisieren. Dabei sieht das Ziel genau so aus, dass wir eine beliebige Methode mit einer Annotation versehen können und daraufhin im Log Performance-Messungen zu dieser Methode lesen können.

Setup

Wie immer habe ich ein Github-Projekt angelegt, was du dir anschauen kannst wenn dir die Ausführung hier nicht reichen sollte oder du lieber direkt aus Code lernst.

Zunächst einmal ist das Beispiel-Projekt mal wieder ein Spring-Boot-Projekt. Damit die Applikation nicht gleich terminiert und man von außen ein paar Aktionen ausführen kann, habe ich noch den Web-Starter hinzugefügt, so dass wir - zusammen mit AOP - am Ende zu der folgenden pom.xml kommen.

<parent>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-parent</artifactId>
  <version>1.3.2.RELEASE</version>
  <relativePath/>
</parent>

<!-- ... -->

<dependencies>
  <dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter</artifactId>
  </dependency>
  <dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
  </dependency>
  <dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
  </dependency>
</dependencies>
   

Annotation zum Markieren von zu loggenden Entries

Als nächstes legen wir eine Annotation an, um Methoden zu annotieren, für die wir am Ende im Log genaue Laufzeitinformationen erhalten wollen. Eine solche Annotation kann wie folgt aussehen:

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Measure {

  /**
   * The name of the action.
   * @return
   */
  String action();
}

Das Markieren von zu loggenden Laufzeitinformationen

Das soeben angelegte Interface können wir jetzt benutzen um unsere Methoden zu annotieren. Hier zum Beispiel eine Methode aus einem BeerService (wie gesagt, zu finden in meinem Github-Projekt).

@Measure(action = "drinking")
public void drink() throws InterruptedException {
  LOG.info("skål");
  Thread.sleep(new Random().longs(1, 2).findFirst().getAsLong());
}

In der Methode wird zunächst ein skål im Log ausgegeben und danach 1-2 Sekunden lang gewartet. Die interessante Stelle ist allerdings die Annotation der Methode. Wir sagen hier, dass Messungen aufgezeichnet werden sollen mit der Action drinking. Diese Action soll später wieder im Log auftauchen.

Die Logging-Komponente

Spring bietet uns die Möglichkeit nicht nur die klassischen Spring-Annotations zu nutzen um eine Bean zu erzeugen oder an anderer Stelle zu injizieren oder in den Lifecycle aufzunehmen - nein. Vielmehr gibt es uns mit dem Paket spring-boot-starter-aop auch Möglichkeiten AOP-Funktionalität mit einfachen Annotations in unser Projekt zu ziehen. Zunächst einmal kannst du dir einen Überblick verschaffen, bevor ich auf die Details eingehe.

@Component
@Aspect
public class LogMeasurementFilter {

  /**
   * Aspect4j method which will be executed around other methods which are annotated with {@link Measure}.
   *
   * @param joinPoint the join point with the method execution.
   * @return the result of the method execution.
   * @throws Throwable
   */
  @Around("@annotation(Measure)")
  public Object logMeasurement(ProceedingJoinPoint joinPoint) throws Throwable {
    // determines the annotated action.
    MethodSignature signature = (MethodSignature) joinPoint.getSignature();
    Method method = signature.getMethod();
    Measure annotation = method.getAnnotation(Measure.class);
    String measurementAction = annotation.action();

    // starts time measurement.
    StopWatch stopWatch = new StopWatch();
    stopWatch.start();
    Logger logger = LoggerFactory.getLogger(joinPoint.getTarget().getClass());
    logger.info(measurementAction + " started.");

    try {
      // execute the original method.
      return joinPoint.proceed();

    } finally {
      // stops execution measurement and log the data.
      stopWatch.stop();
      MDC.put("executionTime", stopWatch.getTotalTimeMillis());
      logger.info(measurementAction + " completed.");
      MDC.remove("executionTime");
    }
  }
}

Zunächst einmal erzeugen wir eine ganz normale Spring-Component. Dies passiert in Zeile 1. Daraufhin sagen mir mittels der @Aspect-Annotation, dass diese Komponente AOP-Funktionalität bereitstellt. Ab diesem Zeitpunkt können wir Aspekte wie Pointcut, Around, AfterThrowing, … nutzen.

In Zeile 12 und 13 nutzen wir einen solchen Aspekt, in dem wir eine Methode formulieren, die als einziges Argument einen JoinPoint erhält und die mittels @Around annotiert ist. In der Annotation setzen wir das Ziel, nämlich dass diese Methode für alle mit Measure annotierten Methoden ausgeführt werden soll. Und zwar wird die Methode logMeasurement aufgerufen, bevor die mittels Measure annotierte Methode aufgerufen wurde. Den Aufruf der Zielmethode müssen wir händisch in Zeile 28 durchführen.

Die anderen Zeilen sind relativ selbsterklärend. In den Zeilen 15-18 wird der Wert der Annotation ausgelesen. In den Zeilen 21-24 wird für die Zielklasse ein Logger instanziiert und für mehr Transparenz geloggt, dass jetzt die Ausführung einer annotierten Methode beginnt. In den Zeilen 32-35 wird die Laufzeit für die Action geloggt.

Fazit

Wird jetzt die Methode drink() aufgerufen taucht folgendes im Log auf (Vorrausgesetzt der MDC wird dort ausgegeben):

de.chclaus.examples.BeerService          : drinking started. |
de.chclaus.examples.BeerService          : skål |
de.chclaus.examples.BeerService          : drinking completed. | executionTime=2

Damit haben wir ganz schick eine Annotation eingeführt, mit der wir gezielte Methodenmessungen durchfüren können ohne einen großen Haufen Aufwand zu betreiben.

Cheers!