Ratpacked: Log Request Duration

In a previous post we learned how to log request information in common log or NCSA format. But we can also provide our own implementation of a RequestLogger to log for example the time spent in processing a request. One of the easiest ways to do this is by using the RequestLogger.of method. We can provide a lambda expression or closure for this method with an argument type RequestOutcome. The RequestOutcome class has properties to access the request and sent response objects. And it also contains a Duration object which has the duration of the time spent for the total request (all handlers in the chain). This doesn't include the necessary time to send the request to the client.

import ratpack.handling.RequestLogger

import static ratpack.groovy.Groovy.ratpack

ratpack {

    handlers {

        // Here we use the of method to implement
        // custom request logging.
        all(RequestLogger.of { outcome ->

            // Only log when logger is enabled.
            if (RequestLogger.LOGGER.infoEnabled) {

                // Log how long the request handling took.
                RequestLogger.LOGGER.info(
                        'Request for {} took {}.{} seconds.',
                        outcome.request.uri,
                        outcome.duration.seconds,
                        outcome.duration.nano)
            }
        })

        get {
            render 'Ratpack rules!'
        }

    }

}

Instead of using the RequestLogger.of method we can write our own implementation of the RequestLogger interface. We only have to override the log method that has the argument type RequestOutcome. Let's rewrite our previous example and use a new class RequestDurationLogger:

// File: src/main/groovy/com/mrhaki/ratpack/request/logging/RequestDurationLogger.groovy
package com.mrhaki.ratpack.request.logging

import groovy.transform.CompileStatic
import groovy.util.logging.Slf4j
import ratpack.handling.RequestLogger
import ratpack.handling.RequestOutcome

/**
 * Custom implementation of the {@link RequestLogger} to
 * log how much time is spent on processing a request.
 * The time spent doesn't include the time spent in
 * transportation from and to the client.
 */
@Slf4j(value = 'logger', category = 'ratpack.request.duration')
@CompileStatic
class RequestDurationLogger implements RequestLogger {

    /**
     * Log the duration in seconds spent on processing a request.
     *
     * @param outcome Information about the request and send response, including duration
     */
    @Override
    void log(final RequestOutcome outcome) throws Exception {
        // Only log when logger is enabled.
        if (logger.infoEnabled) {
            // Log how long the request handling took.
            logger.info(
                    'Request for {} took {}.{} seconds.',
                    outcome.request.uri,
                    outcome.duration.seconds,
                    outcome.duration.nano)
        }
    }
}

In the Groovy DSL of our Ratpack application we now use our new class:

import com.mrhaki.ratpack.request.logging.RequestDurationLogger

import static ratpack.groovy.Groovy.ratpack

ratpack {

    handlers {

        // Here we use our RequestLogger implementation.
        all(new RequestDurationLogger())

        get {
            render 'Ratpack rules!'
        }

    }

}

When we look at some sample logging output we see how much time is spent to handle a request:

[ratpack-compute-5-8] INFO ratpack.request.duration - Request for / took 0.1000000 seconds.

Written with Ratpack 1.0.0.