Loggingtools in Scala « The point is missed

Loggingtools in Scala

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*) = 
     log.trace(message, values.map(_.asInstanceOf[Object]).toArray)
 def trace(message:String, error:Throwable) = log.trace(message, error)
 def trace(message:String, error:Throwable, values:Any*) =
     log.trace(message, error, values.map(_.asInstanceOf[Object]).toArray)

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

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

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

 def error(message:String, values:Any*) = 
     log.error(message, values.map(_.asInstanceOf[Object]).toArray)
 def error(message:String, error:Throwable) = log.error(message, error)
 def error(message:String, error:Throwable, values:Any*) =
     log.error(message, error, values.map(_.asInstanceOf[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:

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.
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.
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 =  {
      time(timeConsumingMethod(4711),
              debugMs("The timeConsumingMethod generated {} in {}ms", _:SomeValue, _))
   }

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

   def timeConsumingMethod(interval:Int):SomeValue =  {
       Thread.sleep(interval);
       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 logging, scala, timing

11 Responses

Subscribe to comments with RSS.

Cool, and weird because I did some similar both with logging and timing. I like your stuff better though so I will adopt it, thanks.

Channing

Channing Walton

June 27, 2009 at 7:17 pm

Reply
- Ideas are weird that way. They seem to come to a lot of people at the same time. I’m glad you liked it and you’re welcome.
  
  /J
  
  johlrogge
  
  June 27, 2009 at 7:59 pm
  
  Reply
Another thing you missed are by-name parameters. The canonical way to do logging in scala is something like

def warn(msg: => String, err: => Throwable) {
if (log.isEnabled(Level.WARN)) { // or how your logger calls it
log.warn(msg, err)
}
}

(guess the blogging platfom will eat the indentation :-))
That way possibly expensive operations needed to construct the arguments are only performed if the message is acually logged. If you only ever log constant strings, this will be sightly slower, but imagine a debug-level log statement that constructs a sting representation of the subtree rooted at the current node.

Florian

July 1, 2009 at 5:24 am

Reply
- logback/slf4j does that already:
  
  log.warn(“hello {}”, “world”)
  
  The string “hello world” will only be assembled if the log-level is at least warn.
  
  In your example you would have the anonymous functions created every time wouldn’t you? msg and err would be shortlived instances of Fn0 while if you kept msg as a string it would likely be cached due to javas flyweight string-stuff and the throwable would have been created wether you decided to log it or not.
  
  Unless I miss something your suggestion would actually create more shortlived objects than how it was before. I agree that anonymous functions would be the obvious implementation in scala though and I admit that I am not quite sure what nifty tricks scala might use to minimize the number of shortlived objects. I can’t think of any but that doesn’t mean there are none.
  
  I always look at () => “a” as I look at javas collection.iterator (or more subtly: for(String a : collection). All three would create the same amount of shortlived objects right (not counting the string)? (Iterator, Fn0)
  
  johlrogge
  
  July 1, 2009 at 6:01 am
  
  Reply
I quite the Logging trait but would like some ideas about how to use the parameterized logging messages. Everything is wrapped in a Scala array that slf4j treats as a single (Object) argument instead of a vararg or Java array.

With a message of “Message {} and {}” I get a result of:

21:04:02.495 [Thread-5] INFO bank.Account – Message Array(first, second) and {}

… this isn’t really the intent of SLF4J!

The info method “public void info(String format, Object arg)” is invoked instead of “public void info(String format, Object[] argArray)”.

How should I specify the arguments (in Scala) so that the appropriate Java method is called?

John

August 18, 2009 at 9:41 am

Reply
- Hi John,
  
  I don’t know if this is an oversight from my side or if SLF4J changed it’s API recently. I remember trying out this code (obviously) before posting it but it’s possible I stuffed it up. I think the problem is that SLF4J no longer takes vararg-parameters but allows up to two (and no more) parameters in the message. The benefit of that is that less temporary objects are created (no argument arrays). It should be straight forward to modify the logging trait. I’ll look into that tonight and update the post.
  
  I just thought I’d post these unverified and hastily put together words in hope that It will help you solve your problem.
  
  As a side note (but probably not applicable to this particular problem). To pass a scala array into a javamethod that takes varargs you suffix _* if I’m not mistaken: method(myScalaArray._*)
  
  Hope this helps
  
  johlrogge
  
  August 18, 2009 at 9:59 am
  
  Reply
  - Thanks for the reply Joakim.
    
    The syntax is:
    
    def info(message:String, values: Object*) = log.info(message, values:_*)
    
    …but this generates the scala compile error:
    
    [WARNING] Logging.scala:18: error: no `: _*’ annotation allowed here
    [WARNING] (such annotations are only allowed in arguments to *-parameters)
    [WARNING] def info(message:String, values:Object*) = log.info(message, values:_*)
    [WARNING] ^
    
    It would seem that the SLF4J “info” method that expects Object[] is not good enough for the scala compiler.
    
    I look forward to seeing what you can come up with.
    
    John
    
    John
    
    August 18, 2009 at 11:21 am
I updated the code above in the post. I don’t know how I managed to stuff it up but I did. Thanks for noticing and taking your time to let me know about it. Here is my test:

object Test extends Object with Log {
def main(args : Array[String]) : Unit = {
info(“Hello {} how are you doing this {} day”, “friend”, “lovely”);
}
}

Prints:

1 [main] INFO – Hello friend how are you doing this lovely day

johlrogge

August 18, 2009 at 7:16 pm

Reply
- That’s great. Output just as I wanted it.
  
  I assume that the array manipulation will occur whether or not the logging level is active, but the final string construction will only occur if logging is enabled.
  
  John
  
  August 19, 2009 at 10:47 am
  
  Reply
  - Yes, that’s correct. A way around that would be to pass the array construction by name as suggested in another comment. That would still construct a temporary object for a function but will be faster than the array manipulation every time.
    
    I’m looking into loosing the arrays completely with the newest version of slf4j. I hope I’ll get around to it this week but it would be straight forward. Just to do a few overloads:
    
    def info(message:String)
    def info(message:String, arg1:Object)
    def info(message:String, arg1:Object, arg2:Object)
    
    And so on. 1.5.8 has matching methods:
    void debug(String msg) Log a message at the DEBUG level. void debug(String format, Object arg) Log a message at the DEBUG level according to the specified format and argument. void debug(String format, Object[] argArray) Log a message at the DEBUG level according to the specified format and arguments. void debug(String format, Object arg1, Object arg2) Log a message at the DEBUG level according to the specified format and arguments.
    
    That would limit the number of parameters to two and require manually creating an array for more arguments than that but it’s a fair trade off IMO.
    
    johlrogge
    
    August 19, 2009 at 11:21 am
Thanks for posting this piece of code, it’s very helpful. I’m new to Scala and I wasn’t quite sure how to implement logging features in my code.

I’m looking forward to new blog articles from you.

Pedro

September 25, 2009 at 7:02 pm

Reply

	Pedro on Loggingtools in Scala
	johlrogge on More Scala and SWT
	Randin on More Scala and SWT
	Randin on More Scala and SWT
	johlrogge on Loggingtools in Scala

The point is missed