Profiling using byte buddy or some library

Question

I am trying to build a Query Logging Profiler which calculates the execution time of every query and also log if query takes more time. Using AspectJ it is taking more time as compared to Wrapper. So I would like to use byte buddy or some other library if there is a scope for performance improvement.

Here is my current implementaion using AspectJ.

@Aspect
public class QueryLoggerProfiler {
    private static final Logger LOGGER = Logger.getLogger(QueryLoggerProfiler.class.getName());

    public static final String QUERY_LOGGING_POINTCUT = "execution(* com.abc.PreparedStatement.execute*(..))";

    @
    Pointcut(QUERY_LOGGING_POINTCUT)
    private void queryPointcut() {}

    @
    Around("queryPointcut()")
    public Object profile(ProceedingJoinPoint joinPoint) throws Throwable {

        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
        Method method = signature.getMethod();

        long start = System.currentTimeMillis();
        Object output = joinPoint.proceed();
        long elapsedTime = System.currentTimeMillis() - start;
        if (elapsedTime >= 5) {
            LOGGER.info(">>>>>>>>>>>>>>>>>>>... Going to call the method ... " + method.getName());
            LOGGER.info(">>>>>>>>>>>>>>>>>>>... With parameter ... " + method.getParameters());
            LOGGER.info(">>>>>>>>>>>>>>>>>>>... Method execution time: " + elapsedTime + " milliseconds.");
        }
        return output;
    }
}

Is there any way to log as well as there is no performance bottle-neck?

Answer 1

Actually I code like below.

public static void premain(String agentArgument, Instrumentation instrumentation) {
    System.out.println(">>>>>>>>>>>>>>>>>> Entered premain");
    try {
        new AgentBuilder.Default()
                .type(ElementMatchers.nameStartsWith("com.mycomp.hikari.LoggingPreparedStatement"))
                .transform((builder, typeDescription, classLoader) -> builder
                        .method(ElementMatchers.any())
                        .intercept(MethodDelegation.to(new Interceptor())))
                .installOn(instrumentation);
    } catch (RuntimeException e) {
        System.out.println(">>>>>>>>>>>>>>>>>> Exception instrumenting code : " + e);
        e.printStackTrace();
    }
}

And then class Interceptor as....

public class Interceptor {
@RuntimeType
public Object intercept(@SuperCall Callable<?> callable, @AllArguments Object[] allArguments, @Origin Method method, @Origin Class clazz) throws Exception {
    long startTime = System.currentTimeMillis();
    Object response;
    try {
        response = callable.call();
    } catch (Exception e) {
        System.out.println(">>>>>>>>>>>>>>>>>>>> .... Exception occurred in method call: " + methodName(clazz, method, allArguments) + " Exception = " + e);
        throw e;
    } finally {
        long elapsedTime = System.currentTimeMillis() - startTime;
        if (elapsedTime > 3)
        System.out.println(">>>>>>>>>>>>>>>>>>>> .... Method " + methodName(clazz, method, allArguments) + " completed in " + elapsedTime + " milliseconds");
    }
    return response;
}

private String methodName(Class clazz, Method method, Object[] allArguments) {
    StringBuilder builder = new StringBuilder();
    builder.append(clazz.getName());
    builder.append(".");
    builder.append(method.getName());
    builder.append("(");
    for (int i = 0; i < method.getParameters().length; i++) {

        builder.append(method.getParameters()[i].getName());
        if (allArguments != null) {
            Object arg = allArguments[i];
            builder.append("=");
            builder.append(arg != null ? arg.toString() : "null");
        }

        if (i < method.getParameters().length - 1) {
            builder.append(", ");
        }
    }
    builder.append(")");
    return builder.toString();
  }
}