RequestPerformanceContext.java

package ...util.perf;

import lombok.NonNull;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.Logger;
import org.springframework.beans.factory.annotation.*;
import org.springframework.context.ApplicationContext;
import org.springframework.context.annotation.*;
import org.springframework.util.StopWatch;

import java.util.Optional;

import static ...isProduction;
import static java.lang.Thread.currentThread;
import static java.util.Optional.*;
import static org.slf4j.helpers.MessageFormatter.arrayFormat;
import static org.springframework.context.annotation.ScopedProxyMode.TARGET_CLASS;
import static org.springframework.web.context.WebApplicationContext.SCOPE_REQUEST;
import static org.springframework.web.context.request.RequestContextHolder.getRequestAttributes;

/**
 * The intended usage is to (manually) create an instance of this class wherever we want to time (or otherwise profile)
 * the execution of a section of code throughout the handling of a web request (as opposed to having it injected). The
 * information gathered is local to each request handling thread and multiple code sections, in different method calls
 * within the same thread can thus be timed and logged under the same report through this mechanism.
 * <p/>
 * If the current thread is not a request handling one (e.g., flows, scheduled jobs, etc.), calls to the
 * methods of this class have no effect.
 *
 * @author <a href="mailto:octavian.nita@gmail.com">Octavian Nita</a>
 * @version $Id$
 */
@Slf4j
@Configurable(preConstruction = true)
public class RequestPerformanceContext {

    @Autowired
    private ApplicationContext context;

    /**
     * A request-scoped (or thread-local) {@link StopWatch}. Should be non-{@code null} if the current thread is
     * handling a web request and timing various sections within the request handling thread is allowed.
     */
    private StopWatch requestStopWatch;

    public RequestPerformanceContext() {

        // Try to obtain a request-specific stopwatch, if available and allowed:
        requestStopWatch = isProduction() || notInRequestProcessing() ? null : context
            .getBean(RequestPerformanceContextConfig.REQUEST_STOPWATCH, StopWatch.class);

        if (requestStopWatch != null) {
            p("Acquired request-specific stopwatch {}", requestStopWatch);
        } else {
            p("Not a request-handling thread or no request-specific stopwatches are available");
        }
    }

    public RequestPerformanceContext start(Class<?> klass, String methodName) {
        return start(taskName(klass, methodName));
    }

    public RequestPerformanceContext start(Object object, String methodName) {
        return start(taskName(object, methodName));
    }

    public RequestPerformanceContext start(@NonNull String taskName) {
        if (requestStopWatch != null) {

            if (requestStopWatch.isRunning()) {
                p("Stopping request-specific stopwatch before starting task {}...", taskName);
                requestStopWatch.stop();
            }
            requestStopWatch.start(taskName);

        }
        return this;
    }

    public RequestPerformanceContext stop() {
        if (requestStopWatch != null) {

            if (requestStopWatch.isRunning()) {
                requestStopWatch.stop();
            }

        }
        return this;
    }

    public RequestPerformanceContext report() { return report(null); }

    public RequestPerformanceContext report(Logger log) {
        if (requestStopWatch != null) {

            (log == null ? RequestPerformanceContext.log : log).info(requestStopWatch.prettyPrint());

        }
        return this;
    }

    public static boolean inRequestProcessing() { return getRequestAttributes() != null; }

    public static boolean notInRequestProcessing() { return getRequestAttributes() == null; }

    public static Optional<RequestPerformanceContext> startTimed(Class<?> klass, String methodName) {
        return inRequestProcessing() ? of(new RequestPerformanceContext().start(klass, methodName)) : empty();
    }

    public static Optional<RequestPerformanceContext> startTimed(Object object, String methodName) {
        return inRequestProcessing() ? of(new RequestPerformanceContext().start(object, methodName)) : empty();
    }

    public static Optional<RequestPerformanceContext> startTimed(@NonNull String taskName) {
        return inRequestProcessing() ? of(new RequestPerformanceContext().start(taskName)) : empty();
    }

    public static Optional<RequestPerformanceContext> stopTimed() {
        return inRequestProcessing() ? of(new RequestPerformanceContext().stop()) : empty();
    }

    public static Optional<RequestPerformanceContext> reportPerf() {
        return inRequestProcessing() ? of(new RequestPerformanceContext().report()) : empty();
    }

    public static Optional<RequestPerformanceContext> reportPerf(Logger log) {
        return inRequestProcessing() ? of(new RequestPerformanceContext().report(log)) : empty();
    }

    public static Optional<RequestPerformanceContext> stopTimedAndReport() {
        return inRequestProcessing() ? of(new RequestPerformanceContext().stop().report()) : empty();
    }

    public static Optional<RequestPerformanceContext> stopTimedAndReport(Logger log) {
        return inRequestProcessing() ? of(new RequestPerformanceContext().stop().report(log)) : empty();
    }

    @Configuration
    static class RequestPerformanceContextConfig {

        static final String REQUEST_STOPWATCH = "requestStopWatch";

        @Bean(name = REQUEST_STOPWATCH)
        @Scope(value = SCOPE_REQUEST, proxyMode = TARGET_CLASS)
        StopWatch requestStopWatch() { return new StopWatch(REQUEST_STOPWATCH); }
    }

    private void p(String fmt, Object... args) {
        if (log.isDebugEnabled()) {
            final Thread currentThread = currentThread();
            log.debug(">>> PERF (thread #" + currentThread.getId() + ": " + currentThread.getName() + " >>> " +
                      arrayFormat(fmt, args).getMessage());
        }
    }

    @NonNull
    private static String taskName(Object objectOrClass, String methodName) {
        String taskName = "";

        if (objectOrClass != null) {
            taskName =
                ((objectOrClass instanceof Class) ? (Class<?>) objectOrClass : objectOrClass.getClass()).getName();
        }

        if (methodName != null) {
            taskName += "::" + methodName;
        }

        return taskName.isEmpty() ? "N/A" : taskName;
    }
}