A test to check about logging performance

LogPerformanceSpec.groovy

package com.spidasoftware.interchange.util

import groovy.util.logging.Log4j
import org.apache.log4j.Logger
import spock.lang.Specification

/**
 * Created by toverly on 6/27/14.
 */
class LogPerformanceSpec extends Specification {

    def final log = Logger.getLogger(LogPerformanceSpec.class)

    def expando
    def callCount

    def runs = 10000

    def setup() {
        expando = new Expando()
        expando.slow = {
            Thread.sleep(1)
            callCount++
        }
    }


    def "logging just a string should not call method in string"() {
        when:
            callCount = 0
            def begin = System.currentTimeMillis()
            for (i in 1..runs) {
                log.debug("Just a plain string")
            }
            def end = System.currentTimeMillis()
        then:
            println("Time consumed string: ${(end - begin) / 1000} s")
            end - begin < 1000
            callCount == 0
    }

    def "with a GString should not call method if not logged"() {
        when:
            callCount = 0
            def begin = System.currentTimeMillis()
            for (i in 1..runs) {
                log.debug "String in with method ${expando.slow()}"
            }
            def end = System.currentTimeMillis()
        then:
            println("Time consumed gstring: ${(end - begin) / 1000} s")
            end - begin < 1000
            callCount == 0
    }


    def "with if should not call method in string"() {
        when:
            callCount = 0
            def begin = System.currentTimeMillis()
            for (i in 1..runs) {
                if (log.isDebugEnabled()) {
                    log.debug "String in with method ${expando.slow()}"
                }
            }
            def end = System.currentTimeMillis()
        then:
            println("Time consumed if gstring: ${(end - begin) / 1000} s")
            end - begin < 1000
            callCount == 0
    }

    def "with closure should not call method in string"() {
        when:
            log.metaClass.debug = { Closure c ->
                if (delegate.debugEnabled) {
                    delegate.debug c.call().toString()
                }
            }
            callCount = 0
            def begin = System.currentTimeMillis()
            for (i in 1..runs) {
                log.debug { "String in with method closure ${expando.slow()}" }
            }
            def end = System.currentTimeMillis()
        then:
            println("Time consumed closure: ${(end - begin) / 1000} s")
            end - begin < 1000
            callCount == 0
    }
}