The point is missed

Museum of public mistakes and unfinished projects

Posts Tagged ‘timing

Loggingtools in Scala

with 20 comments

UPDATE: As John pointed out in the comments the trait did not really work as expected. I updated it with the code I actually have in my project. How I ended up posting a different thing on my blog I don’t know but it sort of has to be me :). This code is tested with slf4j-api-1.5.0. I think some newer version makes it possible to do this without the temporary objects involved in the form of arrays. I will look into that later.

My pet-project is becoming more and more Scalafied and I’m starting to wonder why I ever thought it was important that I should be able to use it from java-applications. Given my detachment from Java some mental barriers are falling and I am adding new strategies to my active toolbox. Today I created some simple traits that I thought would be worth exploring in a blog.

Here we go, logging with slf4j is something I’ve done a lot. I found myself sprinkling a lot of this around in my code:

import org.slf4j.{Logger, LoggerFactory}
class SomeClass {
   private val log = LoggerFactory.getLogger(getClass)
   def aMethodThatLogs  {
      log.debug("This is a value: {}", 4711)

Nothing new (unless you never saw slf4j before in which case you should check it out now wether you program in Scala or Java. The code so far is not dependent on scala other than syntax-wise.)

What I keep forgetting about

Scala has traits, it’s easy to forget that traits are more than just interfaces. Over the years I’ve gotten pretty used to not being able to add any generic functionality other than via composition or inheritance.

Thinking out of the java-box I created this little trait:

import org.slf4j.{Logger, LoggerFactory}

trait Log {
 private val log = LoggerFactory.getLogger(getClass)

 def trace(message:String, values:Any*) = 
 def trace(message:String, error:Throwable) = log.trace(message, error)
 def trace(message:String, error:Throwable, values:Any*) = 
     log.trace(message, error,[Object]).toArray)

 def debug(message:String, values:Any*) = 
 def debug(message:String, error:Throwable) = log.debug(message, error)
 def debug(message:String, error:Throwable, values:Any*) = 
     log.debug(message, error,[Object]).toArray)

 def info(message:String, values:Any*) =,[Object]).toArray)
 def info(message:String, error:Throwable) =, error)
 def info(message:String, error:Throwable, values:Any*) =, error,[Object]).toArray)

 def warn(message:String, values:Any*) = 
 def warn(message:String, error:Throwable) = log.warn(message, error)
 def warn(message:String, error:Throwable, values:Any*) = 
     log.warn(message, error,[Object]).toArray)

 def error(message:String, values:Any*) = 
 def error(message:String, error:Throwable) = log.error(message, error)
 def error(message:String, error:Throwable, values:Any*) = 
     log.error(message, error,[Object]).toArray)

Using it is now a matter of:

import johlrogge.Logging
class SomeClass extends Object with Logging {
   def aMethodThatLogs  {
      debug("This is a value: {}", 4711)

It’s not a huge difference but I kind of like the with Logging and the lack of boilerplate code in the class-body.
I also like that I can drop the log. part of the logging.

Traits are on the menu

Of course this my wetted my appetite for traits. And it didn’t take long before an opportunity arose. How often have you written code like this in java:

long startTime = System.currentTimeMillis();
AValue value = doSomethingTimeConsuming(parameter);
log.debug("SomethingTimeConsuming took {}ms to complete", System.currentTimeMillis()-startTime);
return value;

I was about to repeat the process in Scala when I thought: function… pass by name… and then… TRAIT!

To make a long story short: Enter Timing:

trait Timing {
  def time[T, R](f: => T, res:(T, Long) => R):R = {
    val startTime = System.currentTimeMillis
    res(f, System.currentTimeMillis - startTime)

How this beast came to be:

  1. I realized that the timing-code in the java-example could measure anything given that anything given that anything was executable. And thats what pass by name is for.
  2. I realized that sometimes you want to have the timed value, sometimes you want to log it as a side effect. So, a second pass by name function made sense. The res-function that takes the timing-value and does whatever it likes with it.
  3. You may want to return the timervalue, the result of the timed function, both or something completely different. So I made the result type generic and different from the result-type of the timed function.

How to use it:

import johlrogge.Logging
class SomeClass extends Object with Logging
                               with Timing {
   def aMethodThatTimesAndReturns =  {
              debugMs("The timeConsumingMethod generated {} in {}ms", _:SomeValue, _))

   def debugMs[T](message:String, result:T, spent:Long):T = {
    debug(message, result, spent)

   def timeConsumingMethod(interval:Int):SomeValue =  {
       new SomeValue

Pretty neat. Of course you can compose all kinds of pre-packaged res-methods. The point is that time becomes reusable and you don’t have to log. You could for instance update and return a data-set for a graph that you’re plotting somewhere else in your code. We have abstracted away timing.

Just so you know

If I would mind that anyone cut and pasted the code I wrote in this post and even make money from it (like thats going to happen) I wouldn’t post it on the net. I hope that the code is useful and/or inspires someone in some way. So use it however you want and have fun!


Written by johlrogge

June 27, 2009 at 5:20 pm

Posted in scala

Tagged with , ,