Maybe I'm showing my Naivete here, but if you have:

logger.debug("some string" + somevar + "another string" + anothervar);

Multiple StringBuffers would be created via the String concatenation *before*
ever callling the debug method.  Therefore, the only place to make this check is
*before* you call the debug method.  So, logger.isDebugEnabled() is entirely
necessary to be in your own code, even though it seems like a burden.  This
makes this a bug report against Java itself rather than Log4j.

Am I wrong?

Jake

Hello Jake! You are completely right. If I have

logger.debug("some string" + somevar + "another string" + anothervar);

the StringBuffer is created before ever calling the debug method and the test 
must be in my code. I don't like this and that is why I have suggested these 
improvements.

This is not a bug in Java, it is a design decision.

I've refactored your code, to provide a better solution, perhaps...

Create a single new method to log4j, or a wrapper class, as follows.

public void checkedDebug(Object message)
{
  if (isDebugEnabled()) {
            debug(message);
        }
}

Then create the following class

public class Concatenator
{
  Vector fItems = new Vector(5);

  public void addItem(Object newItem)
  {
    fItems.add(newItem);
  }

  public String toString()
  {
    String result = "";
    // iterate over fItems here
    // ...
    // for each Object in fItems
    result += curItem.toString();
    return result;
  }
}

I think this is the best solution to your problem.  If more details on this 
solution are required, please let me know.  (BTW, if you like this solution, 
perhaps it should be added to the FAQ).

  - Matt Munz
    mmunz@apelon.com

Hello Matt!

I don't see the point of your checkedDebug() method. It does exactly the same 
thing as the debug()-method except that same tests are run twice (if enabled).

Your suggestion is that I create a concatenation object instead of creating the 
StringBuffer. If I take some liberty with your suggestion this will look like 
this in my application (example from Jake):

logger.debug(new Concatenator("some string", somevar,
                              "another string", anothervar));

I considered this solution but I have two things against it. Firstly, this 
means that somewhere in my code I will have this utility class or more likely 
it will be implemented differently in several different parts of my code by 
different developers and some will forget about it. Secondly, this suggestion 
results in the creation of the Concatenator object wether debugging is on or 
off. It is better than the creation of StringBuffer+String but not good enough.

Linus,

Just an idea -- use it as you'd like.  

> I don't see the point of your checkedDebug() method. It does exactly the same 
> thing as the debug()-method except that same tests are run twice (if enabled).

I'm not aware of the implementation of debug().  If it performs the check, then 
you are correct, checkedDebug() is unnecessary.

> logger.debug(new Concatenator("some string", somevar,
>                              "another string", anothervar));

>I considered this solution but I have two things against it. Firstly, this 
>means that somewhere in my code I will have this utility class or more likely 
>it will be implemented differently in several different parts of my code by 
>different developers and some will forget about it. Secondly, this suggestion 

No, it just has to be on your classpath.  You could say the same thing about 
every class you use.  Vector or ArrayList?  Enumeration or Iterator?  Class 
duplication is a fact of life.  The only way to avoid it is to make sure that 
the developers on your team are on the same page as far as code conventions are 
concerned.  How do you enforce the use of Logger over System.out?  Use the same 
mechanism to enforce the use of your preferred Concatenation class.

>results in the creation of the Concatenator object wether debugging is on or 
>off. It is better than the creation of StringBuffer+String but not good enough.

OK.  This is Java.  (Almost) Everything is an object.  I too am a member of the 
society against the proliferation of objects.  But how much overhead is added 
to the memory footprint by the concatenation class?  "some string", 
somevar, "another string", and anothervar are going to get allocated either 
way, AFAIK.  That only leaves the pointers required to constitute the Vector in 
Concatenator.  Given that these can/will be garbage collected after use, this 
is not much of a performance loss, IMO.

Looking at your initial code (line 1), it appears that _headline.toString() is 
the expensive operation.  The Concatenation object saves you this method call.  

I will admit that I'm not a memory optimization expert, so perhaps I've missed 
something here.  If so, please let me know.

Also, as you might have guessed, I think the pattern

methodA(arg)
methodA(arg, arg)
methodA(arg, arg, arg)
methodA(arg, arg, arg, ..., arg)

is rather awkward from a design perspective.  I've got to think that there is a 
better way.

  - Matt Munz
    mmunz@apelon.com

What design perspective? What are the considerations?

Hi,

Just a short remark about this discussion: although I completely agree with the 
comments of Jacob Kjome on 2003-01-18 00:15 and Linus Tolke on 2003-01-18 20:43 
about multiple buffer and concatenation when writing something like

   logger.debug("some string" + somevar + "another string" + anothervar);

I think the whole point of the proposition of Linus is to replace this call by 

   logger.debug("some string" , somevar , "another string" , anothervar);

(i.e. using comas instead of '+'). Otherwise, the proposed extension is NOT 
used!

I think this kind of call is clean and easy to write (easier than 
the 'concatenator' one). And the implementation is short and straigthforward 
too.

The only drawback I see (and this is also true with the concatenator option) is 
that all the parameters must be Object, so no int, boolean,...

cheers...

Created attachment 11812 [details]
Illustrating example.

Here is a test case for you. Notice that theGood runs several times faster 
than theBad while producing the same output.

On my computer:
1000 laps 48 times faster.
3000 laps 387 times faster.
10000 laps 8025 times faster.

In theUgly, the code that actually does something is almost completely hidden 
by the log statements.

Well, JDK 1.5 is going to help us here, but I would think that what should 
normally be done, and only if performance is an issue, is that StringBuffers are 
used...

I would also think that if you are actually Logging that much in an intensive 
loop, AND in a production environment, you have to ask yourself if you need that 
much logging?

I would think that adding a 2nd argument version is just asking for method 
explosion, and lets just wait until JDK1.5 comes along to save us all.

Hello Paul!

Then, let me suggest that you update the FAQ at: 
http://logging.apache.org/log4j/docs/FAQ.html#fastLogging
to state that the fastest way of not logging is to remove the log statements 
from the source.

(. I had always thought that one of the purposes of having a logger tool like 
log4j was that it would be possible to leave the debug log statements in the 
production code but have debug logging turned off. .)

Yes, but to minimes heavy logging, you would have the pattern:

if(LOGGER.isDebugEnabled()){
 LOGGER.debug("Oh" + "Wow" + "What" + "A" + "LOT" + "OF object allocation");
}

Then that object allocation is never done, as it never gets into the IF block 
unless you have DEBUG on for that logger, and I assume you would not do that 
unless you REALLY need the information.

Yes, and I would prefer to have this handled in log4j than to clutter up my 
code with if statements. I thought my example was very clear on this.

If the consequences is a method explosion in log4j that can be reduced again 
with jdk1.5, so be it! It will be isolated to the logging tool.

Hello Linus,

How about this:
  logger.debug("Happy birthday {}. Your age of {} is respectable.", name, age);

This involves some parsing of the message. The parsed version could be cached 
within log4j itself.

It looks great! The parsing and caching is only needed if debugging is indeed 
on.

Parsing will only occur if the message needs to be logged. If the log stament 
is disabled, log4j will not parse it for pleasure. :-) 

Linus/Ceki, 

I would suggest using the java.text.MessageFormat class (I think this is JDK1.
2+, it's been around a while any way).  Then you could do something like this:


logger.debug("Happy birthday {1}. Your age of {0} is respectable.", new Object[]
age, name});

This has a number of advantages:

1. It would require no change to the Logger class, nice to minimise this 
signature change because of downstream compatibility issues 

2. This format allows the parameter order to be independanty of the order in 
which they are used in the string pattern (note that item 0 is placed last in my 
example).

3. It allows for an open-ended # arguments without having to "wait" for JDK1.5.

Since an array is an Object, the above would just require a change in the 
appending method to check if the Object is an array, and if so, use the 
MessageFormat class.  An Arrays .toString() method is pretty useless, so we 
could just perform this message parsing.  

If we were to do this, perhaps it is a good chance to do another convenience 
class check of the Object and check if it's a Throwable, and get the Stacktrace 
of the Throwable rather than just the .toString().  e.g:

}catch(Exception e){
  LOG.error(e);
}

This is SUCH a common mistake by a developer (even experienced log4j'ers), and 
probably an 'assumed' function, that we should consider it. (sorry for adding 
this feature into this bug, but I wanted to raise it while I thought of it).

cheers,

Paul Smith

> Linus/Ceki, 
> 
> I would suggest using the java.text.MessageFormat class (I think this is JDK1.
> 2+, it's been around a while any way).  Then you could do something like this:
> 
> 
> logger.debug("Happy birthday {1}. Your age of {0} is respectable.", new Object
[]
> age, name});
> 
> This has a number of advantages:
> 
> 1. It would require no change to the Logger class, nice to minimise this 
> signature change because of downstream compatibility issues 

? I am consused here. There is no method with signature 
  
  Logger.debug(Object, Object) 

which existing Logger method are you referring to?

> 2. This format allows the parameter order to be independanty of the order in 
> which they are used in the string pattern (note that item 0 is placed last in 
my 
> example).

I don't think allowing free parameter ordering as
java.text.MessageFormat does makes the API easier to use, on the
contrary.

We can expect the user to provide the arguments in the correct
order. That is really not too much to ask for. Moreover, if the
developer is as inattentive as to mix the order of arguments, the same
developer will also fail to correctly label/number the various anchor
strings, e.g. {4}.

The only advantage in labeled anchors is the ability to repeat the
same argument multiple times.

You can write

  l.debug("Hello {0}. The time is {1}. BTW, {0} is a nice name.", name, time);

but how often does that happen? 

> 3. It allows for an open-ended # arguments without having to "wait" for 
JDK1.5.
> 
> Since an array is an Object, the above would just require a change in the 
> appending method to check if the Object is an array, and if so, use the 
> MessageFormat class.  An Arrays .toString() method is pretty useless, so we 
> could just perform this message parsing.  

Interesting observation. We must also consider the fact that calling
new Object[] creates an object array (which as you observed is still
an object). For a *disabled* log statement,

 l.debug(new Object{"Hello {}.", "Paul"});

will be significantly slower than:

 l.debug("Hello {}.", "Paul");

Taking an object array as a parameter would allow us to handle an
unlimited number of parameters. How often do you need to print mopre
than two variable values in a message?

If you need 3 or more variables, you can always write:

  if(l.isDebugEnabled()) {
   l.debug("The lucky numbers are "+n1+", "+n2+", and "+n3+".");
  }

Despite all the above I am still interested on your comments on the
matter. Could we continue this discussion on log4j-dev@ please?


> If we were to do this, perhaps it is a good chance to do another convenience 
> class check of the Object and check if it's a Throwable, and get the 
Stacktrace 
> of the Throwable rather than just the .toString().  e.g:
> 
> }catch(Exception e){
>   LOG.error(e);
> }
> 
> This is SUCH a common mistake by a developer (even experienced log4j'ers), 
and 
> probably an 'assumed' function, that we should consider it. (sorry for adding 
> this feature into this bug, but I wanted to raise it while I thought of it).

This is a different matter. 
 

There are a lot of alternatives here.  Using isDebugEnabled is indeed more 
clutter, but that's a price to pay for higher performance.  Log4j 1.3 also 
provides parameterized logging with a couple of Objects, i.e. debug(message), 
debug(message, obj1), debug(message, obj1, obj2), but not more than that: more 
than that would be bloat.  When log4j 1.5 moves to J2SE 5.0, maybe varargs can 
be used.  Until then, you can use varargs on your end if you want.

Log4j 1.3alpha implements parametrized messages.

Please see http://logging.apache.org/log4j/docs/faq.html#2.3 and in particular the 
sub-section entitled "Better alternative based on message patterns".

UGLI also supports parametrized messages. Please see http://logging.apache.org/
log4j/docs/ugli.html