Over a million developers have joined DZone.

Ratpacked: Log Request Duration

Need to set up a RequestLogger? Here's a great example of accomplishing that feat in Groovy.

Discover 50 of the latest mobile performance statistics with the Ultimate Guide to Digital Experience Monitoring, brought to you in partnership with Catchpoint.

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.

Is your APM strategy broken? This ebook explores the latest in Gartner research to help you learn how to close the end-user experience gap in APM, brought to you in partnership with Catchpoint.

Topics:
performance ,logging ,ratpack ,groovy

Published at DZone with permission of Hubert Klein Ikkink, DZone MVB. See the original article here.

Opinions expressed by DZone contributors are their own.

The best of DZone straight to your inbox.

SEE AN EXAMPLE
Please provide a valid email address.

Thanks for subscribing!

Awesome! Check your inbox to verify your email so you can start receiving the latest in tech news and resources.
Subscribe

{{ parent.title || parent.header.title}}

{{ parent.tldr }}

{{ parent.urlSource.name }}