Visible Workings > Trace.java User's Guide

The Trace.Java User's Guide
Brian Marick

Introduction

Definitions

System Setup

Adding Tracing

Examples

Adding Tracing Statements to Your Code

This section presumes that someone, perhaps you, has added the appropriate Trace.java initialization code somewhere in the system.

What are the trace methods?

How are trace methods added to the code?

Are there predefined subsystems?

Where does trace output go?

How do I adjust which levels are printed?

How do I dump the transient buffer?

How much of a performance hit is tracing?

Can trace statements be compiled out of the code?

Can Trace.java be used for timing?


What are the trace methods?

Tracing is done by calling methods on Trace objects. Each trace method takes three forms.

method(String)
The given string is logged.
method(String, Object)
The given string is logged with the string resulting from object.toString()appended.
method(String, Throwable)
The given string is logged, followed by the stack trace contained in the Throwable object.

Each trace level has its own method. The method names are the names of the levels with 'm' appended. (The 'm' is a historical accident, due to a bug in a compiler.) So here's the complete list:

errorm
warningm
worldm
usagem
eventm
debugm
verbosem

A method has no effect if its level is below the current threshold. There are two destinations: the on-disk log and the in-memory transient buffer. By default, the log's threshold allows Error, Warning, and World messages. The transient buffer's threshold allows those plus Usage messages.

 

How are trace methods added to the code?

Put this at the head of every Java file that will use tracing:

import com.visibleworkings.trace.Trace;

If you want to add tracing to a class, add this code to it:

static private Trace tr = new Trace("subsystem");

Here, "subsystem" is the name of your subsystem. Many classes can use the same subsystem.

The subsystem needn't already exist. If the Trace constructor is given a string that's never been given before, a new subsystem is created. (So watch out for typos.)

Each subsystem can have its own threshold for each of the two destinations (the log and the transient buffer). You can ask for detailed tracing of your subsystem while not being bothered by messages from other people's.

After creating the trace object, you can invoke trace methods on it like this:

tr.eventm("message");

 

Are there predefined subsystems?

Whoever set up Trace.java may have predefined some subsystems. Ask that person.

Two subsystems are always predefined:

Trace.gui.eventm("message");

Trace.trace.eventm("message");

 

Where does trace output go?

By default, the trace log goes to a file named "Tracelog.txt" in the current directory. This location can be changed when the system is initialized or at runtime. Log output can also be sent to standard output. See the Setup section of this user's guide.

 

How do I adjust which levels are printed?

With luck, the person who installed Trace will have changed the system to make it easy for you to change level thresholds. For example, there might be a Properties file that's read on startup. Or there might be command-line arguments. Or there might be a dialog that you can pop up.

If not, you'll have to add the code to do it.

After the trace subsystem has started, it is controlled by calls to TraceController.setProperty. So if you wanted to change the "foo" subsystem's threshold to allow only Error messages in the log, you'd do it like this:

import com.visibleworkings.trace.TraceController;
...
TraceController.setProperty("TraceLog_foo", "error");

A complete description of the setProperty arguments that control the threshold can be found here.

If you want to change other properties of the Trace system, or you want to change the thresholds at Trace startup, see the Setup section of this manual.

 

How do I dump the transient buffer?

The transient buffer normally collects more detail than the log. That detail is invisible until the buffer is dumped into the log.

Again, the person who installed Trace may have provided an interface to do that. If not, you dump the log like this:

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

 

How much of a performance hit is tracing?

Trace.java can put roughly 80,500 messages/second into the transient buffer on a 450Mz PIII with 128M under NT4.0sp6 and Sun's Classic VM (build JDK-1.2.2-001). That should be sufficient. Since much less than one message per second will normally be put into the log, its performance is irrelevant.

There is also some overhead because the VM has to intern all the message strings when a class is loaded. On older VMs, that was painfully slow.

Here is another source of slowness due to Trace. Suppose you have this message in your code:

tr.debugm("PROBE message detected from IP address " + address);

Because this is a Debug level message, it will probably not appear anywhere. You might be slightly annoyed that address is being converted into a string, then concatenated to the "PROBE message" string, only to be discarded because Debug messages are going nowhere. If that bothers you, you can write the code this way:

if (tr.debug) { tr.debugm("PROBE message " + address); }

This saves you the concatenation and the method call if the message wouldn't be posted anyway. Note that the two forms are exactly equivalent except for efficiency.

You can also avoid string concatenation by giving the address to the trace method as a second argument:

tr.debugm("PROBE message detected from IP address ", address);

The method will concatenate for you if (and only if) the threshold allows Debug messages.

 

Can trace statements be compiled out of the code?

Yes, but in a somewhat awkward way. If you'll want to do that, write your code like this:

if (Trace.ON) { tr.debugm("PROBE message " + address); }

In a normal ("debug") build, tracing is turned on. A "release" build can be created by changing the definition of ON to false in the source file "Trace.java". A conforming Java compiler must then compile out the trace call. (Or so I'm told. As I read the spec, it seems that a conforming compiler is not required to compile out the code, but I am assured by others that my reading is wrong.)

 

Can Trace.java be used for timing?

In addition to the methods described above, there is a timingm method that can be used to log messages used in performance tuning. You use it the same way as other methods:

tr.timingm("Your message here");

This timing method is entirely independent of the methods associated with levels. It is not affected when the threshold is changed. Timing messages end with the tag "TIM".

Timing messages can be turned on with these properties. (See the discussion of how to adjust thresholds for more about properties.)

setProperty("TraceBuffer_subsystem_timing", "on"); Timing messages from the named subsystem are added to the transient buffer. You can use "true" as a synonym for "on".
setProperty("TraceBuffer_subsystem_timing", "off"); Stop adding timing messages from the named subsystem to the buffer. "false" is a synonym for "off".
setProperty("TraceLog_subsystem_timing", "on"); As with the TraceBuffer property, except that messages go to the log.
setProperty("TraceLog_subsystem_timing", "off"); As with the TraceBuffer property.

There is no way to turn timing on or off for all subsystems at once. That doesn't seem useful.


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.