Tracear tiempos de ejecución con AOP

En ocasiones las aplicaciones que desarrollamos deben realizar pruebas de rendimiento para determinar cómo responden y detectar los posibles errores que podemos llegar a tener en un entorno estresado. Muy común entre estas pruebas de rendimiento es que se nos pida el estudio de los tiempos de acceso a base de datos y el tiempo que nuestros métodos requieren para devolver los datos que se les pide para lo que solemos vernos obligados a introducir código en todos nuestros métodos.

Generar un log con el tiempo que un método tarda en ejecutarse es muy simple. Tan sólo necesitamos un par de líneas de código:

    public List<User> getAllUsers() throws DaoException {

        Date d = new Date();

        List<User> users= null;

        try {

           // code

           log.debug("method time: " + (new Date().getTime() - d.getTime()) + " ms");

           return users;

        } catch (Exception e) {

            log.error("Error al insertar un organismo - " + e.toString());

            throw new DaoException(e, "error getting users...");
        }
    }

Sin embargo, ¿qué sucede si tenemos un centenar de métodos para el acceso a base de datos? ¿Debemos ir uno a uno introduciendo esas líneas de código? Fácil pero laborioso.

Para simplificarnos la vida y evitar el copy/paste utilizaremos AOP en colaboración con Spring. Con AOP podremos logar los tiempos de todos de cada uno de nuestros métodos sin necesidad de ir método a método copiando y pegando las líneas de código anteriores.

Lo primero que necesitamos es importar las librerías necesarias para ello (nos centraremos sólo en las librerías AOP dejando a un lado el resto de librerías, tales como las librerías de Spring)

<!-- AOP -->
<dependency>
    <groupId>cglib</groupId>
    <artifactId>cglib-nodep</artifactId>
    <version>2.2.2</version>
</dependency>
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjrt</artifactId>
    <version>1.6.12</version>
</dependency>
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjweaver</artifactId>
    <version>1.6.12</version>
</dependency>

Seguidamente, creaemos nuestros aspecto y un "advice" de tipo "around" que será el que calcule el tiempo de ejecución de nuestros métodos:

package es.whatabout.service.db.aop;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;
import org.springframework.util.StopWatch;

@Aspect
@Component
public class Performance {

    private final Log log = LogFactory.getLog(Performance.class);

    /**
     * http://tomasjurman.blogspot.com.es/2010/01/spring-aop-with-annotation.html
     * 
     * @param joinPoint
     * @return object
     * @throws Throwable
     */

    @Around("execution(* es.whatabout.dao.*.* (..))")
    public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {

        StopWatch clock = new StopWatch("performance_dao");

        try {

            clock.start();

            log.debug("Comenzando metodo: " + joinPoint.getSignature().getName());

            return joinPoint.proceed();

        } finally {

            clock.stop();

            log.debug("Consumo: " + clock.prettyPrint());
        }

    }
}

No olvidemos declarar nuestra clase como un Aspecto y un Componente. Destacar también, en en la declaración del punto de corte hemos indicado que queremos que el advice se ejecute para todas las clases y métodos (*.*) del paquete es.whatabout.dao sean cuales sean cuales sean su parámetros ( (...) ) o retorno (*)

Por último, sólo queda configurar Spring correctamente de la siguiente forma:

    <sws:annotation-driven />

    <aop:aspectj-autoproxy proxy-target-class="true" />

    <!-- enable component scanning (beware that this does not enable mapper scanning!) -->
    <context:component-scan base-package="es.whatabout.*" />

    <!-- enable autowire -->
    <context:annotation-config />

Limpio y rápido. Si además, mañana queremos eliminar por completo cualquier log sobre tiempos, sólo debemos cambiar la configuración.