Login | Register
My pages Projects Community openCollabNet

argouml
Wiki: <<Subsystem>> Logging

Edit this page | Links to this page | Page information | Attachments | Refresh page

 
Purpose
to provide an api for debug log and trace messages.
Layer

<<Layer>> Low-level subsystems

ยด

Design of the subsystem

The purpose of debug log and trace messages is to provide a mechanism that allows the developer to enable output of minor events focused on a specific problem area and to follow what is going on inside ArgoUML.

The Logging uses log4j directly.

The Logging is an infrastructure subsystem.

ArgoUML uses the standard log4j logging facility. The following sections deal with the current implementation in ArgoUML. By default, logging is turned off and only the version information of all used libraries are shown on the console.

What to Log in ArgoUML

Logging entries in log4j belong to exactly one level.

The FATAL level designates very severe error events that will presumably lead the application to abort. Everything known about the reasons for the abortion of the application shall be logged.

The ERROR level designates error events that might still allow the application to continue running. Everything known about the reasons for this error condition shall be logged.

The WARN level designates potentially harmful situations.

The INFO level designates informational messages that highlight the progress of the application at coarse-grained level. This typically involves creating modules, subsystems, and singletons, loading and saving of files, imported files, opening and closing files.

The DEBUG level designates fine-grained informational events that are most useful to debug an application. This could be everything happening within the application.

This list is ordered according to the priority of these logging entries i.e. if logging on level WARN is enabled for a particular class/package, all logging entries that belong to the above levels ERROR and FATAL are logged as well.

How to Create Log Entries...

In the ArgoUML project have decided to have all loggers private static final with a static initializer.

The reason for making them private is that this reduces the coupling between classes i.e. there is no risk that one class uses some other class' Logger to do logging.

The reason for making them static is that our classes are more or less all either lightweight, like a representation of an object in the model, or a singleton. For the lightweight classes, having a reference to a logger object per object is a burden and for the singleton objects it doesn't care if the logger is static or not.

The reason for making this final is that it shall never be modified by the class.

The reason for having a static initializer is that then all classes can do this in the same way and we don't ever risk to forgot to create the Logger.

You should not use System.out.println in ArgoUML Java Code. The only exception of this rule is for output in non-GUI mode like to print the usage message in Main.java.

Example 5.2. Logging in ArgoUML

import org.apache.log4j.Logger;
...
public class theClass {
...
    private static final Logger LOG =
        Logger.getLogger(theClass.class);

...

    public void anExample() {
        LOG.debug("This is a debug message.");
        LOG.info("This is a info message.");
        LOG.warn("This is a warning.");
        LOG.error("This is an error.");
        LOG.fatal("This is fatal. The program stops now working...");
    }

How to Enable Logging...

log4j uses the command line parameter -Dlog4j.configuration = URL to configure itself where URL points to the location of your log4j configuration file.

Example 5.3. Various URLs

org/argouml/resource/filename.lcf

Reference to a configuration file filename.lcf within argouml.jar.

http://localhost/shared/argouml/filename.lcf

Reference to a configuration file filename.lcf on a remote server/localhost.

file://home/username/filename.lcf

Reference to a configuration file filename.lcf on your localmachine.

...when running ArgoUML from the command line

There are currently two ways of running ArgoUML from the command line:

Run ArgoUML using argouml.jar

Run ArgoUML using the ant script

In the first case, the configuration file is specified directly on the command line, whereas in the latter case this parameter is specified in the build.xml (which in that case needs to be modified). ArgoUML is then started as usual with ./build run.

Example 5.4. Command Line for argouml.jar

[localhost:~] billy% java -Dlog4j.configuration=URL -jar argouml.jar

Example 5.5. Modification of build.xml

<!-- =================================================================== -->
<!-- Run ArgoUML from compiled sources                                   -->
<!-- =================================================================== -->
<target
    name="run"
 depends="compile">
    <echo message="--- Executing ${Name} ---"/>
    <!-- Uncomment the sysproperty and change the value if you want -->
    <java class
    name="org.argouml.application.Main"

          fork="yes"
          classpath="${build.dest};${classpath}">
          < sysproperty key="log4j.configuration"
                       value="org/argouml/resource/filename.lcf"></sysproperty>
    </java>
</target>

...when running ArgoUML from WebStart

To view the console output, the ?WebStart user has to set Enable Java Console in the Java ?WebStart preferences. In the same dialog, there is also an option to save the Console Output to a file.

As you cannot provide any userspecific parameters to a ?WebStart Application from within ?WebStart, it is currently not possible to choose log4j configuration when running ArgoUML from Java Web Start.

...when running ArgoUML in other environments

Add the log4j configuration URL to the arguments.

Reasoning around the performance issues

Most of the log statements passed in ArgoUML are passed with logging turned off. This means that the only thing log4j should do is to determine that logging is off and return. Log4j has a really quick algorithm to determine if logging is on for a certain level so that is not a problem.

The problem is how to avoid the overhead of all the concatenations, data conversions and temporary objects that would be created otherwise. Even if logging is turned off for DEBUG and/or INFO level.

It is best explained by noticing the following log statement:

        int i;
...
        LOG.debug("Entry number: " + i + " is " + entry[i]);

It is quite innocent looking isn't it? That is because the java compiler is very helpful when it comes to handling strings and will convert it to the equivalent of:

        StringBuffer sb = new StringBuffer();
        sb.append("Entry number: ");
        sb.append(i);
        sb.append(" is ");
        sb.append(entry[i].toString());
        LOG.debug(sb.toString());

If entry[i] is some object with a lot of calculations this could cause a performance problem. If the toString() methods are simple you are still stuck with the overhead of creating a StringBuffer (and a String from the sb.toString()-statement.

References

The log4j project homepage at http://jakarta.apache.org/log4j


CategoryFromCookbook

<<Subsystem>> Logging (last edited 2009-02-08 10:44:22 -0800 by linus)