Ruby-Trace User's Guide - Tracing Simple Programs

Visible Workings > Ruby-Trace User's Guide

The Ruby-Trace User's Guide
Brian Marick

Contents

Simple Programs

Server Programs

API

Glossary

Tracing simple programs

This section introduces some of the key ideas of Ruby-trace by talking about tracing simple programs. Even if you're working on a big server program, you should read this section.

What's a simple program?

It's one that you can run from the command line. It's a script or a utility rather than a server that runs continuously.
It's one single blob of code, rather than being partitioned into distinct and relatively independent subsystems.

Unlike the tracing that's built into Ruby, you have to add tracing statements to your code. In exchange for that trouble, you get more control over what you see. In particular, you can arrange it so that you're not overwhelmed with detail.

A first example

Let's begin with a simple example, which you can find in print-example.rb in the doc/examples subdirectory of the Ruby-trace root directory. When you run that program in the normal way, it looks like any other Ruby program. You see no special output:

% ruby print-example.rb arg
called with 'arg'

However, if the program is behaving incorrectly, you can ask for trace output by invoking the program with ruby-trace:

% ruby-trace print-example.rb arg
print-example.rb:21:in `initialize'
= announce: New instance of Example: 'Example one'
print-example.rb:21:in `initialize'
= announce: New instance of Example: 'Example two'
called with 'arg'

Here, Ruby-trace is displaying announce messages, which mark significant occurrences in the life of the program. The programmer also added trace messages that provide more detail. By default, they're not displayed. To see that detail, you tell Ruby-trace to change the threshold that controls how much detail is printed:

% ruby-trace --threshold verbose print-example.rb arg
print-example.rb:21:in `initialize'
= announce: New instance of Example: 'Example one'
print-example.rb:21:in `initialize'
= announce: New instance of Example: 'Example two'
print-example.rb:25:in `do_something_detailed'
= verbose: something detailed has happened
called with 'arg'

(Note: if you are an Emacs user, you may find "visit-ruby-source.el" convenient. It lets you put the cursor on a line containing trace output, compiler error messages, or a location from a stack dump, hit a magic key, and be taken to the source. It's in the directory "elisp" under the Ruby-trace root directory.)

How does this all work? Here are the important parts of the example:

require 'ruby-trace/start/global'

class Example

  def initialize (tag)
    @tag = tag
    $trace.announce "New instance of #{self.class}: '#{self.inspect}'"
  end

  def do_something_detailed
    $trace.verbose 'something detailed has happened'
  end

The first line

require 'ruby-trace/start/global'

defines the global $trace, which we will call here a trace object. (In a later section, we'll see that it's actually two kinds of object.) You can send a trace message to the trace object. The following is an announce message.

$trace.announce "New instance of #{self.class}: #{self}"

This line sends a verbose message

$trace.verbose 'something detailed has happened'

There are several other levels - see below.

Now let's look at this new terminology in more detail.

The default trace object

The include file ruby-trace/start/global defines the global $trace. If you're allergic to global variables, you can instead add a method named trace to Object:

require 'ruby-trace/start/method'
...
trace.announce "New instance of #{self.class}: #{self}"

If you're allergic to all pollution of the global namespace, you can require ruby-trace/all. You'll then have to create trace objects yourself. That's not described in this section.

In the remainder of this documentation, I'll use the global $trace.

Trace levels

Trace messages have several levels. Programmers use lower level messages to provide more detail. You can control at runtime or launch time which level of messages you want to see. You may also define your own levels (described in later sections of this guide).

Here are the default levels, together with their usual meaning:

error: Use error messages when your program has detected an internal error.
warning: Warning messages are not as serious as errors, but they're signs of something odd. If the program blows up later, a warning message might mark the point where things started to go wrong.
announce: Announce messages record major milestones in the life of the program. For example, if the program connects to one of several FTP servers, does its work, and shuts down, an announce message might record which server it used.
event: Event messages will be sent more often than announce messages. They are typically used to record significant interactions with the outside world. For example, each command a user types might cause an event message to be logged. (In larger programs that are composed of multiple subsystems, event messages are typically used to record calls into subsystem interface methods.)
debug: Debug messages are normally not printed. Typically, they're added to help track down a bug. They might record that the program reached a certain point with certain significant values. If debug messages seem likely to be useful with similar bugs in the future, leave them in. Over time, you'll accumulate enough debugging that most bugs become easy to isolate.
verbose: Verbose messages provide even more detail than debug. They're probably mainly used when first getting the code to work.

The trace threshold

At any given moment, the threshold is set to one of the levels or to none. If it's set to a level, messages of that level and above will be logged. If the threshold is set to none, nothing will be logged.

Invoking trace methods

Trace methods may be invoked in three ways:

$trace.level aString: If the threshold allows, the given string is logged.
$trace.level: This has the same effect as if aString were "Reached here".

$trace.level { block }: The block should produce a string, which is logged as if it were given to the first form of the method. The block is only evaluated if the threshold is higher than or equal to the level. This is a useful alternative to the first form when construction of the string is expensive. For example, if the string is "val=#{ackerman(4,4)}", you'd hate to pay the expense of building the string unless level were actually above the threshold. Since, in Ruby, creating blocks seems to be cheaper than even the simplest strings, this is the form to use if you are worried about efficiency.

If you are worried about efficiency, you might like to know that the level methods are so constructed that they are empty if the level is below the threshold. That is, the default definition of $trace.verbose is this:

def $trace.verbose (aString)
end

It gets redefined if the threshold changes.

Thanks to a suggestion of Dave Thomas, there is a variant set of methods. It can be tiresome to write trace statements like this:

$trace.verbose { "name -> #{name}" }

So you can instead write this:

$trace.verbose_value {"name"}

Each of the level methods (error, warning, etc.) has a _value variant.

Turning tracing on at launch time

Normally, no tracing output appears because the threshold is set to none.

At startup, the trace object obeys an environment variable called TRACEENV. If that variable's value is

--threshold=level

then the threshold will be set to the given level. (The odd notation is because there are other things you can do with the environment.)

Here's an example, using the Bash shell:

export TRACEENV="--threshold=event"
ruby myprog.rb

Because messing with the environment is awkward, the ruby-trace program does it for you. The above is equivalent to this:

ruby-trace myprog.rb

Ruby-trace's options (--threshold and its equivalent, -t) just set the TRACEENV to different values.

Contents

Simple Programs

Server Programs

API

Glossary

Please send comments on this document to marick@visibleworkings.com. The ruby-trace mailing list is at at http://groups.yahoo.com/group/ruby-trace.

Copyright © 2001 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).