2
\$\begingroup\$

I am working with a little project intended to allow applications to benefit from aspect oriented programming. The first aspect is logging, which is already working. However I want this code to be more performatic and cleaner.

Whole project

The basic goals is to annotate methods - private/public static or instance - with and Custom annotation @LoggableObjects. This annotation has options to define level of log - how much information to log (only args values, profiling information).

Since it uses reflection in many steps, I am afraid I might have missed something. I would appreciate if anyone reviewed my code.

This code processes the annotations and instruments the methods. How can the method aroundObjects be better executed? Is this a valid idea?

package org.greentea.aspect.log;

import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.regex.Matcher;
import java.util.regex.Pattern;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.greentea.aspect.log.annotation.LoggableObject;

/**
 * LoggableObjects are either Methods or Constructors that migh be logged <br>
 * The information logged is the method signature, its arguments and execution
 * time
 * 
 * The level of verbosity, and information might be configurable through the use
 * of the annotation @LoggableObjet
 * 
 * @author Filipe Gonzaga Miranda
 */
@Aspect
public class LoggableObjects {

    PluggableLogger pluggableLogger;

    public static ConcurrentMap<Class<? extends PluggableLogger>, PluggableLogger> cachedLoggers = new ConcurrentHashMap<>();

    static{
        cachedLoggers.putIfAbsent(DefaultPluggableLoggerIfNotInjected.class, new DefaultPluggableLoggerIfNotInjected());
    }

    /**
     * Captures the Annotations {@link LoggableObjects}
     * 
     * And applies the logic to decide how to log the information based on the
     * LogModes
     * 
     * @param proJoinPoint
     * @return
     * @throws Throwable
     */
    @Around("execution(* *(..)) && @annotation(LoggableObject)")
    public Object aroundObjects(ProceedingJoinPoint proJoinPoint)
            throws Throwable {
        Signature methodSignature = proJoinPoint.getSignature();
        String declaringClass = methodSignature.getDeclaringTypeName();
        String methodName = methodSignature.getName();
        Object[] args = proJoinPoint.getArgs();

        LoggableObject loggObject = getLoggableObjectAnnt(args, methodSignature);

        if (loggObject.disable()) {
            return proJoinPoint.proceed();
        }

        Class<? extends PluggableLogger> clazzPluggLogg = loggObject.pluggableLoggerClass();

        if(clazzPluggLogg != DefaultPluggableLoggerIfNotInjected.class){
            if(cachedLoggers.containsKey(clazzPluggLogg)){
                pluggableLogger = cachedLoggers.get(clazzPluggLogg);
            }else{
                pluggableLogger = clazzPluggLogg.newInstance();
                cachedLoggers.putIfAbsent(clazzPluggLogg, pluggableLogger);
            }
        }else{
            pluggableLogger = cachedLoggers.get(clazzPluggLogg);
        }

        LoggableObject.LogModes[] logModes = loggObject.logMode();

        boolean profileMode = false;
        boolean argsMode = false;
        boolean methodMode = false;

        logModesLoop: for (int i = 0; i < logModes.length; i++) {
            switch (logModes[i]) {
            case ALL:
                profileMode = true;
                argsMode = true;
                methodMode = true;
                break logModesLoop;
            case PROFILE:
                profileMode = true;
                break;
            case METHOD_NAME:
                methodMode = true;
                break;
            case ARGS:
                argsMode = true;
                break;
            default:
                throw new AssertionError("Operation not supported. "
                        + logModes[i].name());
            }
        }

        PluggableLogger logger = pluggableLogger;

        // getting modifiers
        if (methodMode || argsMode) {
            logger.logInfo(String.format(
                    "Entering execution of method %s, of class %s", methodName,
                    declaringClass));
        }


        if (argsMode && args.length > 0) {
            logger.logInfo(String.format("Arguments of method %s are: %s",
                    methodName, java.util.Arrays.toString(args)));
        }

        Object returnObject;
        try {
            long startNanoTime = System.nanoTime();
            returnObject = proJoinPoint.proceed();
            long execTime = System.nanoTime() - startNanoTime;
            if (profileMode) {
                logger.logInfo(String.format(
                        "Finished execution of %s in %s nanoTime", methodName,
                        execTime));
            }
        } catch (Exception e) {
            logger.logError("\nException in the method " + methodName
                    + " of class: " + methodSignature.getDeclaringTypeName());
            if (!loggObject.exceptionOnlyToExceptions()) {
                throw e;
            }
            logger.logWarning("Exception " + e + " supressed. Setting returning value to null...");

            returnObject = null;
        }
        return returnObject;
    }

    @SuppressWarnings("unchecked")
    private LoggableObject getLoggableObjectAnnt(Object[] args, Signature methodSignature) throws Exception{
        int loadedClasses = 0;
        Class<?> clazzTypes[] = new Class[args.length];
        for (int i = 0; i < args.length; i++) {
            Class<?> clazz = null;
            if (args[i] == null) {
                String completeSignature = methodSignature.toLongString();

                Pattern p = Pattern
                        .compile("[\\w+.-]+([a-zA-Z_$][a-zA-Z\\d_$]*\\.)*[a-zA-Z_$][a-zA-Z\\d_$]*");

                Matcher m = p.matcher(completeSignature);

                m.find();
                m.find();
                m.find();
                int pos = 0;
                while(pos < loadedClasses){
                    m.find();
                    pos++;
                }
                m.find();
                String clazzName = m.group();
                clazz = Class.forName(clazzName);
                loadedClasses++;
            }else{
                clazz = args[i].getClass();
                loadedClasses++;
            }
            clazzTypes[i] = clazz;
        }


        return methodSignature.getDeclaringType()
                .getDeclaredMethod(methodSignature.getName(), clazzTypes)
                .getAnnotation(LoggableObject.class);

    }

    /**
     * Default implementation of {@link PluggableLogger} using
     * {@link java.util.logging.Logger} internally to Log msgs
     * @author Filipe Gonzaga Miranda
     */
    public static class DefaultPluggableLoggerIfNotInjected implements PluggableLogger{

        @Override
        public void logInfo(String msg) {
            Logger logger = Logger.getLogger("greentea.logger");
            logger.log(Level.INFO, msg);
        }

        @Override
        public void logError(String msg) {
            Logger logger = Logger.getLogger("greentea.logger");
            logger.log(Level.SEVERE, msg);
        }

        @Override
        public void logWarning(String msg) {
            Logger logger = Logger.getLogger("greentea.logger");            
            logger.log(Level.WARNING, msg);
        }

        @Override
        public PluggableLogger getForCache() {
            return this;
        }

        @Override
        public String toString() {
            return "DefaultPluggableLoggerIfNotInjected - It has a java.util.logging.Logger";
        }
    }

}
\$\endgroup\$
1
\$\begingroup\$

I know little about AspectJ, but have a number of more basic points to call out in your code.

Hygiene

  • cachedLoggers should be private static final and not public static. Do you really want anyone to be able to replace your instance?
  • PluggableLogger pluggableLogger is an instance field, but it should be in the method only (perhaps just called logger). As things are at the moment, you risk a race condition when the method is called concurrently.... you could be overwriting the logger part-way through one call, with another call.
  • throws Throwable .... really? you should always narrow your exceptions down more than that.
  • throw new AssertionError(...) ... really? Why not just an IllegalArgumentException?

Performance

  • The Pattern.compile(...) should be a private-static-final field. The patterns are thread-safe, and designed to be reused.
  • Instead of a ConcurrentMap I would consider a thread-local HashMap. This would require benchmarking to resolve, but, it could be significantly better at memory management, especially when there's only the default plugin used.
  • You can do the isDisabled check before getting the declaring class, and method name
  • You jump through hoops getting the clazzPluggLogg ..:

    Class<? extends PluggableLogger> clazzPluggLogg = loggObject.pluggableLoggerClass();
    
    if(clazzPluggLogg != DefaultPluggableLoggerIfNotInjected.class){
        if(cachedLoggers.containsKey(clazzPluggLogg)){
            pluggableLogger = cachedLoggers.get(clazzPluggLogg);
        }else{
            pluggableLogger = clazzPluggLogg.newInstance();
            cachedLoggers.putIfAbsent(clazzPluggLogg, pluggableLogger);
        }
    }else{
        pluggableLogger = cachedLoggers.get(clazzPluggLogg);
    }
    

    this can be done instead as:

    Class<? extends PluggableLogger> clazzPluggLogg = loggObject.pluggableLoggerClass();
    pluggableLogger = cachedLoggers.computeIfAbsent(clazzPluggLogg, k -> k.newInstance());
    

    The above will lock the map only once, not multiple times.

| improve this answer | |
\$\endgroup\$
  • \$\begingroup\$ Excellent Review, I will be applying this to my project, about the AssertionError, I read this idiom in "Effective Java", I thought it was the better, but you say it is simplier to use IllegalArgumentException, I think you re right, because, it is a more well known exception. Again, thanks! \$\endgroup\$ – Filipe Miranda Jun 8 '15 at 13:42

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.