The point is missed

Museum of public mistakes and unfinished projects

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*) = 
     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:

  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 =  {
      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 , ,

20 Responses

Subscribe to comments with RSS.

  1. 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

    • 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

  2. 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

    • 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

      • Yeah, logback/slf4j will assemble the strings lazily, but I think the point is, what if it’s expensive to generate the strings? In that case you want call-by-name almost certainly.

        It’s certainly considered canonical to use by-name for this; if it really produces a lot of overhead, it would be interesting to know how much.

        Eric Bowman

        June 4, 2010 at 10:43 am

      • I think you’re absolutely right and I realize that I was confused about the difference between anonymous functions and call by name when I wrote this post and later the comment.
        I’ve meant to revisit this post and remedy that. Call by name, as I understand it, does not generate anonymous classes and such which would be an excellent way to solve this problem.
        I also saw that logback now changed the api so you can use up to two arguments that are not dynamic (no under the hood array creation) I don’t know if that is still usefule given call by name.

        Also, given how clever hotspot is nowadays it certainly wouldn’t make much sense to avoid that extra method-call indirection (if that is what will be genereated by the scalacompiler in the first place)

        Thanks for your comment!

        johlrogge

        June 4, 2010 at 11:27 am

      • Well, call-by-name is implemented as anonymous functions underneath (though in an opaque way). So a class is created. The question is, how much overhead is this /really/?

        Eric Bowman

        June 4, 2010 at 1:44 pm

  3. 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

    • 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

      • 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

  4. 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

    • 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

      • 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

  5. 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

  6. Cool! :)

    Antony Stubbs

    May 27, 2010 at 8:07 am

  7. Örjan

    July 23, 2010 at 10:33 pm

    • No I have not seen it. Good to know that it’s there. Perhaps it should be used in a logging framework so everyone has the option to remove logging code by recompiling. I would not use that option myself I can’t think of a situation where I would physically remove the ability to turn on debug-logging. Perhaps it would make sense in more constrained environments such as android development… I think the downside is a bit extreme though…

      Interesting! Good to know and thanks for sharing this info. Have to think more about this.

      johlrogge

      July 23, 2010 at 11:28 pm

  8. You don’t mention here the important fact that the log field in your example is not static, and so each instance will have its own, and getLogger is re-executed for each instantiation. Hence your example is not equivalent with what people used to do in Java.

    ddekany

    January 10, 2011 at 10:20 pm

    • You’re absolutely right about that.

      To be fair, I never claimed the code was equivalent. In fact, I think it’s /better/ in many respects :). It does have the drawback you pointed out. I don’t think that is a big issue though. I have assumed that slf4j caches loggers so that they won’t have to be resolved on each getLogger. If that is not true then it’s easy to cache the loggers ourselves in a companionobject to the trait. I would be very surprised if this turns out to be a bottleneck in the average application but I have not benchmarked it.

      It is also possible to mix the trait in into a companion object but I think it’s more hassle than it’s worth.

      Anyway, thanks for pointing this out in case it was not clear to all readers. It is indeed possible that readers just assume that my code is equivalent in this respect and it’s not.

      johlrogge

      January 10, 2011 at 10:46 pm

  9. People underestimate the importance of this thing… since we are talking about logging here, it is an important difference, because:

    (a) If you extend your SomeClass class with SomeSubClass, the the logger in SomeClass will be suddenly do getLogger(classOf[SomeSubClass]). In Java, it would remain classOf[SomeClass] no mater what. We could argue which is the better, but for now the point is simply that there is a difference in semantic here.

    (b) The performance impact is often neglected in this topic, talking about premature optimization and such. But it has no much to do with optimization, but with expressing your intent, which is not that you want a logger for an object, but that you want a logger for a class (see point (a)). This translates to an in principle unnecessary slowdown (kind of an accidental complexity), which is not necessarily trivial either. There are classes that are for very light weight very short lived objects. Like, for an implicit conversion in Scala, a new instance is created for each single call of a method that is added by the implicit conversion. Plus, if your class extends other classes and traits and those also extend others and so on, and some of them mixes in the Log trait, you end up with several log fields per instance and several getLogger calls per instantiation. So I think it’s something people better be aware of before mixing in Log blindly everywhere. Unlike in Java, it’s not for free.

    ddekany

    January 11, 2011 at 10:38 am


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: