On 2005-01-24 17:28:06 Craig McClanahan wrote:
>I'm certainly not a universal example of how developers work, but >thinking back over 25 effort of work in this field, I have >consistently found logging more helpful (and interactive debugging >less than helpful) at understanding the behavior of complex systems. >It's great to be able to dive in with a debugger and see "aha, that >value is set to 'foo' but it should really have been 'bar'" -- but >that tends not to be the kind of mistake that I make. I usually get >the overall control flow wrong when I blow it ... and in a complex >system (especially multithreaded ones) it becomes difficult and/or >tiresome to locate these kinds of problems with debugging. If I can >go back and tweak some logging levels, though, problems like this >become much easier to locate.
have not looked at a debugger in the last 10 years and have no plans switching any time soon. :-)
>This isn't an argument for or against enter() and exit() as entry >points in a logging API (I'm not a fan yet, but not an opponent >either) -- but your arguments aren't about that either. You're simply >arguing against logging at all, which doesn't seem to make sense to >me.
I am advocating against *indiscriminate* logging, not logging in general. Since imho enter/exit methods encourage indiscriminate logging, they should be avoided. (What indiscriminate logging means is discussed below.)
Although log4j tries hard to reduce the computational cost of each log statement, each log statement still has a cost. This cost can range from just a few nanoseconds, for disabled statements, to roughly 1 millisecond when writing to a database.
On top of their computational cost, enabled log statements have a cost related to processing by humans. These days, the costs associated with 1 second of (human) brain time is much higher than the cost associated with 1 second of CPU time.
>>
>> >Likewise, errors can be caused by earlier events....the entry/exit flow
>> >information can help identify the factors related to such.. again based on
>> >conveniant boundries in the code.
>>
>> Theoretically speaking, there is no denying that as the quantity of
>> information about the system increases, so does the probability of
>> finding the cause of a given error. But where do you stop?
>
>You stop adding logging messages when you stop running into bugs :-).
>But you don't leave them enabled all the time, either. Or, at least
>*I* don't. If someone wants to leave Digester's debugging level set
>to trace all the time (which will generate quite a lot of output),
>though, that's not my concern anyway -- that is the conscious choice
>of the developer that is using it.
>
>On the other hand, without those logging statements being available,
>it is pretty difficult for most people to understand the dynamic
>behavior of something based on a SAX parser (as Digester is), which is
>pretty much backwards to the way most people write code. The ability
>to turn on those log messages on once in a while is tremendously
>helpful for this purpose.
Digester is a nice concrete example.
Considering that Digester is a mature package, let us assume that the logging output is mostly intended to debug digester rule sets, not Digester itself. In other words, logging will help clarify how Digester interprets a given set of rules and how it applies them to a given XML document. I call this use logging as "whiteboxing" a tool, for example Digester.
When whiteboxing, the developer of the tool should ideally design the logs to spit out enough output so that a new user can understand what the tool is doing, without overwhelming her.
Here is a simple xml document:
<?xml version="1.0" encoding="UTF-8" ?> <!DOCTYPE hello>
<hello> <world> </world> </hello>
Here is a sample test application:
import org.apache.commons.digester.*; import org.xml.sax.Attributes;
public class Dig {
public static void main(String[] args) throws Exception {
Digester digester = new Digester();
digester.addRule("*", new HelloRule());
digester.parse(args[0]);
}
}class HelloRule extends Rule {
// nothing to do
}When I run 'java Dig hello.xml', it generates the following log output.
DEBUG org.apache.commons.digester.Digester.sax - setDocumentLocator([EMAIL PROTECTED])
DEBUG org.apache.commons.digester.Digester.sax - startDocument()
DEBUG org.apache.commons.digester.Digester.sax - startElement(,,hello)
DEBUG org.apache.commons.digester.Digester - Pushing body text ''
DEBUG org.apache.commons.digester.Digester - New match='hello'
DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello'.
DEBUG org.apache.commons.digester.Digester.sax - characters()
DEBUG org.apache.commons.digester.Digester.sax - characters(
)
DEBUG org.apache.commons.digester.Digester.sax - characters( )
DEBUG org.apache.commons.digester.Digester.sax - startElement(,,world)
DEBUG org.apache.commons.digester.Digester - Pushing body text '
'
DEBUG org.apache.commons.digester.Digester - New match='hello/world'
DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello/world'.
DEBUG org.apache.commons.digester.Digester.sax - characters()
DEBUG org.apache.commons.digester.Digester.sax - characters(
)
DEBUG org.apache.commons.digester.Digester.sax - characters( )
DEBUG org.apache.commons.digester.Digester.sax - endElement(,,world)
DEBUG org.apache.commons.digester.Digester - match='hello/world'
DEBUG org.apache.commons.digester.Digester - bodyText='
'
DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello/world'.
DEBUG org.apache.commons.digester.Digester - Popping body text '
'
DEBUG org.apache.commons.digester.Digester.sax - characters()
DEBUG org.apache.commons.digester.Digester.sax - characters(
)
DEBUG org.apache.commons.digester.Digester.sax - endElement(,,hello)
DEBUG org.apache.commons.digester.Digester - match='hello'
DEBUG org.apache.commons.digester.Digester - bodyText='
' DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello'. DEBUG org.apache.commons.digester.Digester - Popping body text '' DEBUG org.apache.commons.digester.Digester.sax - endDocument()
40 lines of output for such a small file and such a small rule set is may be a bit too much. When I disable the output generated by o.a.c.d.D.sax, you get:
DEBUG org.apache.commons.digester.Digester - Pushing body text ''
DEBUG org.apache.commons.digester.Digester - New match='hello'
DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello'.
DEBUG org.apache.commons.digester.Digester - Pushing body text '
'
DEBUG org.apache.commons.digester.Digester - New match='hello/world'
DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello/world'.
DEBUG org.apache.commons.digester.Digester - match='hello/world'
DEBUG org.apache.commons.digester.Digester - bodyText='
'
DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello/world'.
DEBUG org.apache.commons.digester.Digester - Popping body text '
'
DEBUG org.apache.commons.digester.Digester - match='hello'
DEBUG org.apache.commons.digester.Digester - bodyText='
' DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello'. DEBUG org.apache.commons.digester.Digester - Popping body text ''
From the user's perspective the following output would have sufficed:
DEBUG org.apache.commons.digester.Digester - New match='hello'
WARN org.apache.commons.digester.Digester - No rules found matching 'hello'.
DEBUG org.apache.commons.digester.Digester - New match='hello/world'
WARN org.apache.commons.digester.Digester - No rules found matching 'hello/world'.
DEBUG org.apache.commons.digester.Digester - match='hello/world'
DEBUG org.apache.commons.digester.Digester - No rules found matching 'hello/world'.
DEBUG org.apache.commons.digester.Digester - match='hello'
WARN org.apache.commons.digester.Digester - No rules found matching 'hello'.
(Notice that I increased the level of "No rules for matching" messages to WARN.)
However, for any well-formed document the begin and end parts will match, so there may be no need to repeat the information related to the end part. Thus, the ideal log output would have been:
DEBUG org.apache.commons.digester.Digester - New match='hello'
WARN org.apache.commons.digester.Digester - No rules found matching 'hello'.
DEBUG org.apache.commons.digester.Digester - New match='hello/world'
WARN org.apache.commons.digester.Digester - No rules found matching 'hello/world'.
As far as the end-user is concerned, these 4 lines contain all the information needed to debug her rules. (She is interested to know why the "*" pattern did not match HelloRule.)
Now, imagine if Digester had an extra entry/exit log statement in Digester.getRules() With just two extra log statements, the log output would double or even triple in size, from about 40 lines to over 100 lines. Now imagine if every method had an entry/exit log stament. The number of log output generated would increase by hundreds of lines.
The point I am trying to make is that it is surprisingly easy to log too much.
As a designer of a package, your responsibility is to output just enough log output so as to whitebox your package for the end-user. Hibernate for instance, does quite a good job at this although it also logs a bit too much. I came across a few packages, some of which are located in Jakarta, which generate way too much log output. In the worst case, the useless logs cannot be turned off without also turning off the useful output.
>If you can't turn it off, enter/exit logging would definitely not be >to my taste. But a pretty significant number of my debug and trace >log statements tend to be simulations of enter/exit anyway, useful for >the reasons described earlier.
There a so many ways of getting enter/exit logging wrong that sanctifying the practice by adding enter()/exit() methods in the logger interface sound to me as an awfully bad idea.
Many mature and well-tested packages out there could convey the same amount of useful information with 10 times fewer logs. The fact that they don't, renders packages like log4j all the more useful. However, the existence of good tools should not serve as an excuse for encouraging bad practice.
-- Ceki G�lc�
The complete log4j manual: http://www.qos.ch/log4j/
--------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
