Visible Workings > Trace.java User's Guide |
The Trace.Java
User's Guide |
Adding Tracing |
This section presumes that someone, perhaps you, has added the appropriate Trace.java initialization code somewhere in the system.
How are trace methods added to the code?
Are there predefined subsystems?
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?
Tracing is done by calling methods on Trace objects. Each trace method takes three forms.
object.toString()
appended.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.
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");
Whoever set up Trace.java may have predefined some subsystems. Ask that person.
Two subsystems are always predefined:
gui: the graphical user interface. Calls to it look like this:
Trace.gui.eventm("message");
trace: the tracing subsystem itself. Calls to it look like this:
Trace.trace.eventm("message");
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.
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.
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");
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.
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.)
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.
Adding Tracing |
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.