Visible Workings > Trace.java User's Guide

The Trace.Java User's Guide
Brian Marick

Introduction

Definitions

System Setup

Adding Tracing

Examples

System Setup

How is the trace system initialized?

What are trace properties?

How can properties be used in different styles of initialization?

What properties control the threshold?

What properties control the log and transient buffer?

How is the transient buffer dumped to the log?

How can the log be turned off in a delivered application?

How can subsystems be predefined?

How can you support changing tracing at runtime?


How is the trace system initialized?

Here is the default behavior of the Trace subsystem:

If you want to use these defaults, put this somewhere near the beginning of the program:

import com.visibleworkings.trace.TraceController;
...
TraceController.start();

This code doesn't have to be right at the beginning. If trace methods are invoked before Trace.java is started, log messages are queued up. You can use tracing in initialization code.

 

What are trace properties?

The tracing system is controlled by setting its properties at runtime or at launch time.

Another variant of TraceController.start takes a java.util.Properties argument. If, for example, you wanted the Trace subsystem to log to a file named "Mytrace.txt" instead of "Tracelog.txt", you would initialize in this way:

import com.visibleworkings.trace.TraceController;
import java.util.Properties;
...
Properties p = new Properties();
p.setProperty("TraceLog_tag", "Mytrace");
TraceController.start(
p);

After the trace subsystem has started, it is controlled by calls to TraceController.setProperty. So if you wanted to change the maximum size of the log to 100,000,000 characters, you would do that as follows:

TraceController.setProperty("TraceLog_size", "100000000");

The complete list of properties is given here and here.

Although this manual shows properties in StudlyCaps style, they are case-insensitive.

 

How can properties be used in different styles of initialization?

Suppose you're using tracing in a web server, and you want the following:

You would do that by overriding the defaults at launch time:

import com.visibleworkings.trace.TraceController;
import java.util.Properties;

...
Properties p = new Properties();
p.setProperty("TraceLog_size", "500000");
p.setProperty("TraceLog_backups", "one");
p.setProperty("TraceLog_timestamp", "true");
TraceController.start(p);

Or, suppose you are adding tracing to a system that has formerly used standard output for diagnostic messages. Putting log messages in a file would be awkward because you'd often have to refer to both standard output and the file. It's better to put all messages to standard output:

import com.visibleworkings.trace.TraceController;
import java.util.Properties;

...
Properties p = new Properties();
p.setProperty("TraceLog_name", "-");
TraceController.start(p);

The "-" means "standard output". (At the moment, there's no way to use standard error.)

 

What properties control the threshold?

The default threshold applies to all subsystems that have not been given their own thresholds. To set the default threshold for the transient buffer and log (respectively), use:

setProperty("TraceBuffer_default", "level");
setProperty("TraceLog_default", "level");

where level is one of "error", "warning", "world", "usage", "event", "debug", or "verbose". For example, setting the threshold to "warning" means that Error and Warning messages will be logged. Lower level messages will be discarded.

To set the threshold for a particular subsystem, use:

setProperty("TraceBuffer_subsystem", "level");
setProperty("TraceLog_subsystem", "level");

The subsystem name is not sensitive to case. Subsystem thresholds always take priority over the default threshold, whether they're higher or lower than it.

You can cause the subsystem to once again track the default threshold with:

setProperty("TraceBuffer_subsystem", "default");
setProperty("TraceLog_
subsystem", "default");

 

What properties control the log and transient buffer?

Some properties are used for controlling which file the log is written to.

setProperty("TraceLog_dir", "pathname"); The log by default goes in the current directory. Use this property to change the directory.
setProperty("TraceLog_tag", "name"); The tag is the first part of the log name. By default, it is "Tracelog".
setProperty("TraceLog_timestamp", "true-or-false"); The timestamp adds the date and time to the filename. Its format is ".yyyymmddhhmmss". If the value is "true", that format is used. If "false", the timestamp is omitted.
setProperty("TraceLog_name", "name"); Using the above properties, you can construct names of the form tag.timestamp.txt or tag.txt. If you want a name in a different format, such as "myfoo.log.bar", use this property. The "name" argument is the complete name to be used. The "TraceLog_dir" property still applies, unless the name is an absolute pathname. To write to standard output, have "name" be "-". (That's a dash.)

Note: on Windows, at least one VM incorrectly implements the Java specification. It thinks that "\temp" is not an absolute pathname. It is safest always to use a drive letter: "c:\temp\myfoo.log.bar".

If tracing has already been started, it's common to want to set several of these properties, then apply them all at once. That is done using "TraceLog_reopen", as follows:

TraceController.setProperty("TraceLog_tag", "mylog");
TraceController.setProperty("TraceLog_timestamp", "true");
TraceController.setProperty("TraceLog_reopen", "true");

To be specific: none of the properties that affect a log file's name have effect until the file is reopened. (Note: the argument to TraceLog_reopen is ignored. It can be "true", your birthday, your favorite color, whatever. I agree that this is kludgy.)

Some other properties control the behavior of the log.

setProperty("TraceLog_size", "characters"); This sets the maximum size of the log to approximately characters characters. Past that size, the log will, by default, be closed, renamed to Tracelog.sequence.txt, and a new log will be opened. Normally, the first sequence number is 000. To be precise, the sequence number is a zero-padded N+1, where N is the largest sequence number that already exists. This ensures that the sequence numbers are in order of creation, no matter how they were created or whether some were deleted along the way.

If the file has a timestamp, the backup file names will begin with Tracelog.timestamp.sequence.txt. (If the tag or extension were changed, those changes will be obeyed.)

If you picked a different file format (using TraceLog_name), the sequence number is appended: "mylog.foo.bar.000".

setProperty("TraceLog_size", "unlimited"); This restores the default behavior, which is that the logfile never fills up (unless the file system does).
setProperty("TraceLog_backups", "one");
setProperty("TraceLog_backups", "one");
If this property is set, there will be at most one backup file. It will have sequence number 000. If the backup file already exists, it will be overwritten.
setProperty("TraceLog_backups", "many"); Return to default behavior, always backing up a file with an unused sequence number.
setProperty("TraceLog_write", "false"); This property is usually given to TraceController.start(). A "false" value prevents the logfile from being created. Trace messages that would ordinarily go into the log are thrown away, but the transient buffer is unaffected.

If, at some later point, you want the logfile to be created, setting the property to "true" in TraceController.setProperty() does that. You can turn it back off by setting the property to "false". If you again set it to true, that acts as a TraceLog_reopen: it creates a new log file, making a backup file if necessary.

If, when a logfile is opened, a matching file exists, a new one is created and the old one is renamed according to the rules above.

 

Some other properties control the transient buffer:

setProperty("TraceBuffer_size", "new-maximum-size"); By default, the buffer stores at most 500 messages. (Note: messages, not characters.) When the 501'st message arrives, the first is discarded. This property changes the size.
setProperty("TraceBuffer_size", "default"); Change the buffer size back to the default.
setProperty("TraceBuffer_size", "unlimited"); The buffer should never discard any messages.
setProperty("TraceBuffer_dump", "ignored"); This property causes the transient buffer to be appended to the log. The second argument is ignored.

 

How is the transient buffer dumped to the log?

The buffer can be dumped to the log under program control like this:

import com.visibleworkings.trace.TraceController;
...
TraceController.setProperty("TraceBuffer_dump", "true");

But when should that code be called? Here are some possibilities:

  1. Your application may have a top-level exception handler that catches all otherwise uncaught exceptions. That's a good point at which to dump the transient buffer.
  2. Testers will be happy if there's some "hot key" or hidden dialog that lets them dump the transient buffer. So might your customer support people.
  3. Trace.errorm can be overloaded to automatically dump the buffer.
  4. A programmer adding a call to Trace.errorm can also dump the buffer if it seems appropriate for that error.

 

How can the log be turned off in a delivered application?

In some applications, you ordinarily don't want a log created. But you do want to support this scenario:

Customer (on phone): I have a problem with your application...

Customer service: OK. Start the program in this special way... That will cause a logfile named "TraceLog.txt" to be created. Now, navigate your way to where the problem occurs.

Customer: OK... Boom! I'm there.

Customer service: Good. Now type this magic sequence of keys. That will record in the log all the things you did. Please mail the log to [...]

The code supporting this scenario would look something like the following. For concreteness, I'm assuming the program is started from the command line and uses Posix-style options. One of the options, --trace, turns tracing on. That option controls use of the TraceLog_write property.

    import com.visibleworkings.trace.TraceController;
    import java.util.Properties;
    ...
    Properties p = new Properties();
    while (there are options left) {
        thisOption=...
        if (thisOption.equals("--trace")) {
            p.setProperty("TraceLog_write", "true");
        }
    }
    ...
    // if user didn't *explicitly* turn tracing on,
    // turn it off.
    if (p.getProperty("TraceLog_write") == null) {
        p.setProperty("TraceLog_write", "false");
    }
    
    TraceController.start(p);

If you want to completely remove tracing from a delivered application, your programmers will have to write trace calls specially. If all the programmers have done that, you can use the same trick to "compile out" trace startup code.

This is somewhat error-prone. If just one programmer leaves one trace method in the code, the whole Trace package will be dragged into memory. Moreover, a maximum of 700 trace messages' worth of memory will be consumed. Those 700 messages are of two types:

  1. Up to 500 messages in the transient buffer.
  2. Up to 200 messages in a special log queue. Trace.java allows trace messages to be posted before tracing is initialized. Messages above the log's default threshold are queued until TraceController.start is called. At that point, they're either flushed to the log or discarded (if TraceLog_write is false). The queue is capped at 200 messages, just in case TraceController.start is never called.

 

How can subsystems be predefined?

You can save the programmers the trouble of creating their own subsystems by predefining them. Edit Trace.java. You will see this list of predefined members:

/* Predefined subsystems */
static public Trace trace = new Trace("trace");
static public Trace console = new Trace("gui");

Add yours to the list. Once you have done so, programmers can use these subsystems like this:

Trace.predefined.errorm("...");

 

How can you support changing tracing at runtime?

Testers, customer support people, and others will probably want a way to change the level thresholds at runtime. For example, a tester might navigate the system to a particular dialog, then turn on much detailed tracing to help isolate a particular problem.

One interface I used in the past was a simple text input window. It took commands like these:

tracelog subsystem threshold
tracelog default threshold
tracebuffer subsystem threshold
tracebuffer dump

The code behind the interface made simple translations and called TraceController.setProperty. This worked fine.


Introduction

Definitions

System Setup

Adding Tracing

Examples

Copyright © 2000 by Brian Marick. This material may be distributed only subject to the terms and conditions set forth in the Open Publication License, draft v1.0 or later (the latest version is presently available at http://www.opencontent.org/openpub).

Please send comments on this document to marick@visibleworkings.com.