Visible Workings > Trace.java User's Guide

The Trace.Java User's Guide
Brian Marick

Introduction

Definitions

System Setup

Adding Tracing

Examples

Examples

These are small examples of the use of Trace.java. See the rest of this manual for more explanation.

Running the examples

Basic use and changing trace levels

Logging to a timestamped file

Logging to standard output

Dumping the transient buffer to get more detailed trace information

Timing your code

Multiple backup files

A single backup file

Can you inadvertently stomp on a logfile?

Switching logfiles in midstream

Preventing a logfile from being created

 


Running the examples

All of these examples can be found in the Documentation/Examples subdirectory of the Trace.java source. Each is in a single file. The name of the file is given in parentheses in the title of the example. You can click on the title to load the Java source.

On Unix, you can run an example this way:

script Example

If you're on Windows and have Unix tools installed (as with the Cygwin package), you can use the same script. Because classpaths have a different format on Windows, use the script this way:

script -windows Example

Note: The script assumes that the Trace jar file is in ../.. If it's somewhere else, you can give the location in the -jar option:

script -windows -jar e:/visibleworkings/trace/Trace.jar Example

(Note: the -windows option, if present, must be before -jar. I was too lazy to write a loop.)

If you're on Windows and don't have Unix tools, do this:

javac -classpath ..\..\Trace.jar;. Example.java
java -classpath ..\..\Trace.jar;. Example

Cleanup: to clean up the examples, simply remove all files matching *.class, T*.txt, and "*.frobboz*". In a Unix-like environment, "make clean" will do that.

 

Basic use and changing trace levels (Basic)

This example shows the simplest way to start the trace system. Messages can be posted before the trace system starts; they're queued until they can be delivered.

It shows how the default threshold allows only Error, Warning, and World level messages to go to the log.

It shows how the threshold can be changed to allow Usage, Event, and Debug messages as well.

It also shows how two different classes can be part of the same subsystem.

What you'll see: The log is in Tracelog.txt. The code sends trace messages at all levels, but only the following will be logged. (The message format is explained here.)

=== 2000/08/07 09:26:31.574 (LevelPrinter.printMessages:Basic.java:40) ERR
Basic: Here is a trace message at the ERROR level.
=== 2000/08/07 09:26:31.574 (LevelPrinter.printMessages:Basic.java:41) WRN
Basic: Here is a trace message at the WARNING level.
=== 2000/08/07 09:26:31.584 (LevelPrinter.printMessages:Basic.java:42) WLD
Basic: Here is a trace message at the WORLD level.

It then drops the level down to Debug and sends all the trace messages again. This time, more will come out:

=== 2000/08/07 09:26:31.594 (LevelPrinter.printMessages:Basic.java:40) ERR
Basic: Here is a trace message at the ERROR level.
=== 2000/08/07 09:26:31.594 (LevelPrinter.printMessages:Basic.java:41) WRN
Basic: Here is a trace message at the WARNING level.
=== 2000/08/07 09:26:31.594 (LevelPrinter.printMessages:Basic.java:42) WLD
Basic: Here is a trace message at the WORLD level.
=== 2000/08/07 09:26:31.594 (LevelPrinter.printMessages:Basic.java:43) USE
Basic: This USAGE message is normally at too low a level to appear in the log.
=== 2000/08/07 09:26:31.594 (LevelPrinter.printMessages:Basic.java:44) USE
Basic: This EVENT message is normally at too low a level to appear in the log.
=== 2000/08/07 09:26:31.604 (LevelPrinter.printMessages:Basic.java:45) USE
Basic: This DEBUG message is normally at too low a level to appear in the log.
=== 2000/08/07 09:26:31.604 (LevelPrinter.printMessages:Basic.java:46) USE
Basic: This VERBOSE message is normally at too low a level to appear in the log.

 

Logging to a timestamped file (Timestamp)

This example shows how properties can be used to initialize trace differently. In particular, it shows how the trace log's filename can be made to contain a timestamp. That's useful when you run a server. Each time the server restarts, it creates a different log file. If you're trying to figure out a problem that's been reported, you can use the time the problem was seen to know which log to look at.

What you'll see: The log will be in a file named "Tracelog.yyyymmddhhmmss.txt".

 

Logging to standard output (Stdout)

This example shows how properties can be used to initialize trace differently. In particular, it shows how the trace log can be sent to standard output. This is useful when the system already has debugging statements that go to System.out.println.

What you'll see: You'll see two messages printed to standard output, with a trace message between them.

This is a normal message to standard output.
=== 2000/08/07 11:06:26.424 (Stdout.main:Stdout.java:22) WLD
Stdout: Stdout subsystem starts.
This is another normal message to standard output.

 

Dumping the transient buffer to get more detailed trace information (DumpExample)

This example shows how properties can be used to initialize trace differently. It changes the log's name to "TraceDump.txt".

It shows how the transient buffer records Usage level trace messages by default. It show how to change the buffer's threshold to make it record Debug level messages.

Finally, it shows how the transient buffer is dumped into the log. This also shows a clumsiness in how properties work (described in a comment in DumpExample.java).

What you'll see: The program does the following:

  1. Issues a Usage level message. That goes only to the transient buffer.

  2. Issues a Debug level message. That goes nowhere.

  3. Sets the transient buffer's threshold to Debug.

  4. Issues a Debug level message. That now goes to the transient buffer (only).

  5. Dumps the buffer into the log.

When you look at "TraceDump.txt", there will be no log messages before the buffer dump. The dump is delimited by these trace messages:

=== 2000/08/07 11:47:06.553 (TraceBuffer.dump:TraceBuffer.java:line?) ERR
trace: ======= BEGIN INTERNAL TRACE BUFFER DUMP =========

=== 2000/08/07 11:47:06.613 (TraceBuffer.dump:TraceBuffer.java:line?) ERR
trace: ======= END INTERNAL TRACE BUFFER DUMP ===========

Notice that those messages are at the Error level. That's to make sure they appear in the log - Error messages always do. It's also very likely appropriate, since buffer dumping almost always happens in response to a program error.

After the first delimiter, you'll see messages from the Trace subsystem itself before the messages from the DumpExample subsystem:

=== 2000/08/07 11:47:06.503 (TraceBuffer.<init>:TraceBuffer.java:70) WLD
trace: Transient buffer begins.
=== 2000/08/07 11:47:06.523 (TraceController.start:TraceController.java:504) USE
trace: Tracing system being started.
=== 2000/08/07 11:47:06.533 (TraceLog.beginLogging:TraceLog.java:178) USE
trace: Logging begins on 'E:\visibleWorkings\trace\Documentation\Examples\TraceDump.txt'.

Next, you'll see the messages you'd expect from the above sequence of events:

=== 2000/08/07 11:47:06.553 (DumpExample.main:DumpExample.java:20) USE
DumpExample: This USAGE message will appear in the buffer. It will appear in the log once the buffer is dumped there.
=== 2000/08/07 11:47:06.553 (DumpExample.main:DumpExample.java:27) DBG
DumpExample: This DEBUG message will appear in the buffer. It will appear in the log once the buffer is dumped there.

And you'll see one internal message after them:

=== 2001/03/12 11:14:26.332 (TraceBuffer.dump:TraceBuffer.java:126) USE
trace: Dumping internal trace buffer.

 

Timing your code (TimingBuffer)

This example shows how to use the Trace timing level to time sections of your code. It times how long it takes to put one million trace messages into the transient buffer. It also shows the use of properties to control tracing at runtime.

What you'll see: The log is "Tracelog.txt". The first two lines will look something like this:

=== 2000/08/07 15:52:40.078 (TimingBuffer.main:TimingBuffer.java:line?) TIM
TimingBuffer: Starting message loop.
=== 2000/08/07 15:52:52.216 (TimingBuffer.main:TimingBuffer.java:line?) TIM
TimingBuffer: Ending message loop.

So, on my machine, one million messages take about 12 seconds. (This was on jdk1.2.2. On jdk1.3, it takes 28 seconds.)

To make sure the messages actually went somewhere, the example then dumped the buffer into the log (as in the previous example). Since the buffer's default maximum size is 500 messages, you'll next see that number of messages, not a million.

The example then tried another loop. Instead of a million instances of this message:

tr.usagem("By default, usage messages go only into the transient buffer.");

It sends a million instances of this one:

tr.usagem("Iteration " + i);

The timing messages for that loop are the last two in the log. On my machine, the string concatenation adds about 50% to the cost of the loop.

 

Multiple backup files (Multiple)

Normally, the log file is "infinite" - it doesn't fill up until the file system does. You can use trace properties to limit the size of the log file. By default, when it fills up, the logfile is closed, renamed to a backup file, then reopened.

This example also shows a different type of trace method, one that takes Java Objects as an additional argument.

What you'll see: The example limits the log file to 5000 characters. You'll get many logfiles. They look like this:

TraceMultiple.000.txt
TraceMultiple.001.txt
TraceMultiple.002.txt
TraceMultiple.003.txt
TraceMultiple.004.txt
TraceMultiple.005.txt
TraceMultiple.006.txt
TraceMultiple.007.txt
TraceMultiple.008.txt
TraceMultiple.009.txt
TraceMultiple.010.txt
TraceMultiple.011.txt
TraceMultiple.012.txt
TraceMultiple.013.txt
TraceMultiple.014.txt
TraceMultiple.015.txt
TraceMultiple.016.txt
TraceMultiple.017.txt
TraceMultiple.018.txt
TraceMultiple.019.txt
TraceMultiple.020.txt
TraceMultiple.txt

The most recent log file is always the one without a backup number. As you can see, the numbers start with 000 and increment up. There's no limit on the number of files.

If you look at the sizes of the files, you'll see that none of them are exactly 5000 characters. Trace messages aren't cut off in the middle. Since trace messages aren't generally megabytes in size, the overflow will be too small to hurt.

If you look inside one of the files, you'll see that the messages look like this:

=== 2000/08/07 12:06:16.436 (Multiple.main:Multiple.java:line?) WLD
Multiple: Hello, traceworld : 990

The ": 990" shows how trace messages print objects (in this case, the Integer 990).

 

A single backup file (One)

You might not want as many backup logfiles as in the previous example. This example shows how you can restrict Trace.java to one backup file. Trace will always create at least one backup. If it simply erased the logfile when it filled up and started writing from the beginning, you know that's exactly when a bug would happen.

What you'll see: The current log will be "TraceOne.txt". There will be a backup named "TraceOne.000.txt". Look inside the backup. You should see a message like this one:

=== 2000/08/07 12:29:25.393 (One.main:One.java:line?) WLD
One: Message : 934

This is the 934'th trace message. Earlier trace messages went into backup files that were subsequently overwritten.

 

Can you inadvertently stomp on a logfile? (Stomp)

What happens if the log is directed to a file that already exists? Trace uses (if possible) the filename you told it too, but it backs up the old file in the manner described in the previous two examples.

What you'll see: The example creates an empty file "TraceStomp.txt", then tries to start tracing with this file. You'll see that the empty file is renamed to "TraceStomp.000.txt" and a trace message is put into "TraceStomp.txt".

If you run the program again, you'll see that the previous log file ("TraceStomp.txt") is backed up to "TraceStomp.001.txt" and the program puts its trace messages in (again) "TraceStomp.txt".

 

Switching logfiles in midstream (Switch)

This example shows how the logfile can be closed and reopened, either as a new version (creating a backup) or with a new name.

What you'll see: This example does the following:

  1. Logs a trace message.

  2. Reopens the log file, making the old version a backup file.

  3. Logs another trace message

  4. Reopens the log file with a different name. In contrast to previous examples, the different name doesn't have the extension ".txt" - it's "Trace.quux.frobboz---".

  5. Logs another trace message

All that activity results in the following files:

  1. "TraceSwitch.000.txt", which contains the original message (step 1).

  2. "TraceSwitch.txt", which contains the message from step 3.

  3. "Trace.quux.frobboz---", which contains the message from step 5.

 

Preventing a log file from being created (Write)

This examples shows how the Tracelog_write property is used to prevent the logfile from being created at startup. It also shows how the log can be opened later, then shut down again.

What you'll see: The log is in TraceWrite.txt. It contains one message and a dump of the transient buffer. What's more important is what it doesn't contain: a message from before the log was created, a message from after writing was turned off again, and a transient buffer dump that has nowhere to go because the log has been shut down.


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.