next up previous contents
Next: Modules, Algorithms and Candidates Up: The MINOS Off-line Software Previous: Job Control   Contents

Subsections


Message Service

Last significant change: 2005/03/04

Introduction

The message service serves two main functions. The first is to provide a convenient way to output formatted numerical data as the C++ ``$<<$'' operator is lacking in this regard. The second is to provide a utility to filter and direct text output such as debugging, warning, and error messages. The MINOS C++ coding conventions state that users are to use the message service rather than cout and cerr directly so that these messages are processed in a uniform way.

Configuring Message Service from Loon

In your loon .C script, you can configure Message service using a JobC object (even if you're not otherwise using JobControl).

Setting Logging Levels

You can set the log levels for different streams by doing:

{
  JobC jc;
  jc.Msg.SetLevel("Ugli","Warning"); // Print out only warning, 
                                     // error, and fatal messages
	                             // from UgliGeometry
}

The hiearchy of message levels is:
Fatal Really bad errors that are probably going to crash the program
Error Reports of something that has gone badly wrong
Warning Report of a problem that indicates a potential problem or suspect results
Info Messages related to normal operation.
Synopsis Summary information about how things are working
Debug Messages used primarly for debugging
Verbose Gory detail

By default, all streams are set to show Info messages and above.

Lowering the log level of any stream below the Info level can slow down the execution of the entire program. This is due to the extra overhead of looking up stream names when individual messages are filtered. In general, Debug and Verbose should be used with care (since they tend to spew quite a bit of spam).

Setting Stream Formats

Messages can be prefixed by information strings by setting the stream format flags.

Format Description Example
Priority Shows the level of the message =W=
Name Name of the stream MyStream
Host Name of the CPU running the job laptop.domain.edu
PID Process ID of the job laptop.domain.edu:26911
Time Time the message was printed 2005/03/04 14:39:38
File Name of file (if not using CVSid) MyClass.cxx
CVSId CVS revision of the file MyClass.cxx,v1.24
Line Line number of the message MyClass.cxx,v1.24:123
RunSnarl Run and Snarl number of the event [10123|5]
StackTrace Generates a stack trace of the code see below
Bold Make the prefix boldface  
Dim Make the prefix dim  
Underline Make the prefix underlined  
Blink Make the prefix flash on the screen (insert migrane here)
Reverse Make the prefix inverse text  
Black Make the prefix text black  
Green Make the prefix text green  
Yellow Make the prefix text yellow  
Blue Make the prefix text blue  
Magenta Make the prefix text black  
Cyan Make the prefix text cyan  
White Make the prefix text white  
BgWhite Make the prefix text background white  
... ...  
BgBlack Make the prefix text background black  
ColorAll Apply color/typeface to the entire message (Use at your own risk)

Table 2.2 shows the default formats that are applied to each stream.

You can change the defaults by doing the following at the beginning of your job:

{
   JobC jc;
   jc.Msg.SetDefaultFormat("Bold","Warning"); // Makes all warnings (and only warnings) bold
   jc.Msg.SetDefaultFormat("Blink","Error");  // Makes errors flash
   jc.Msg.SetDefaultFormat("RunSnarl");       // Turns on [run|snarl] for all messages
   // N.B. This only works before you make your path!

   jc.Path.Create()...
}

At any time, you can change the format on a specific stream with the Format command:

  jc.Msg.Format("Ugli:Warning","Bold");           // Makes Ugli warnings bold
  jc.Msg.Format("Ugli:Warning","Priority",false); // Turns off =W= on Ugli warnings.

The color and style formats use ANSI/Xterm escape codes. They are useful for looking at the output of the job by eye, but may not work on all terminals. If you redirect standrard output (for instance, because you are running batch jobs) then you can look at the resulting output with the ``less'' command using:

 \$ less -r loondump.txt

The StackTrace option is special in that it generates many lines of output (and takes a long time to build!) but can greatly ease debugging. The StackTrace format creates a short 'call list' of the functions currently being called.

For instance, assume that you are seeing a strange warning from the Plex: ``can not GetBestItem() from an empty list'', and you don't know what is causing it. Turn on the stack trace option with:

  jc.Msg.Format("Plex:Warning","StackTrace");

and then every time Plex generates a warning, you will see something like:

=W= Plex PlexSEIdAltL.cxx,v1.33:357> Stack Trace:
  [0] PlexSEIdAltL::GetBestItem() const @ MessageService/MsgStream.h:96
  [1] Coroner::RecordDeadStrips(Morgue*, CandRecord const*) @ Plex/PlexSEIdAltLItem.h:46
  [2] Coroner::Reco(MomNavigator*) @ Morgue/Coroner.cxx:87
  [3] JobCMethod::Execute(JobCModule*, MomNavigator*) const @ JobControl/JobCMethod.cxx:70
... Message: can not GetBestItem() from an empty list

This works just like gdb doing a 'where' command. It is easy to see that the function Coroner::RecordDeadStrips is causing the problem.


Writing Code using MessageService

Basics

The MessageService also allows users to send text messages to output streams. Each message is associated with a given package (specified by the prefix chosen for the package) and a priority level. The simplest use looks like this:
#include "MessageService/MsgService.h"
.
.
.
// The CVSID line is required so that the message service can tag 
// error messages with the version number attached to this file.
// The quoted string must start and end with a dollar sign and
// the starting dollar sign should be followed by 'Id:'; CVS will 
// expand the field between the colon and the trailing dollar sign 
// upon any commits, so nothing special need be there initially.
// Code that uses DbiResultPtr from the DatabaseInterface package
// must have CVSID after the MsgService.h include, but before the
// #include "DatabaseInterface/DbiResultPtr.tpl".
CVSID("$Id: message_service.tex,v 1.9 2007/03/01 16:27:38 rhatcher Exp $");
.
.
.
{
  MSG("Pkg", Msg::kVerbose)  << "This is a VERBOSE message\n";
  MSG("Pkg", Msg::kDebug)    << "This is a DEBUG message\n";
  MSG("Pkg", Msg::kSynopsis) << "This is a SYNOPSIS message\n";
  MSG("Pkg", Msg::kInfo)     << "This is an INFO message\n";
  MSG("Pkg", Msg::kWarning)  << "This is a WARNING message\n";
  MSG("Pkg", Msg::kError)    << "This is an ERROR message\n";
  MSG("Pkg", Msg::kFatal)    << "This is a FATAL message\n";

  MsgStream& m = MSGSTREAM("Pkg", Msg::kInfo);
  m << "This construct bypasses test to see if stream is active\n";
}
which sends text messages from package Pkg with various priorities ranging from lowest to highest. The threshold for printing can be set package by package. For example, if you wanted to see all the Debug messages but not all the Verbose messages from the package Pkg you would set the threshold for the package Pkg to Debug. The default threshold is Info.

Note that messages that are below print threshold are not formatted. This means that unprinted messages cause only a negligible performance hit. On my machine (Pentium 350 MHz) the performance hit from 100000 unprinted messages was a total 0.15 seconds.

Very frequently, you will want a message that only prints the first few times the function is called. Although this is simple code to write, it can get very tedious and wordy. Thus was born the MAXMSG macro:

MAXMSG("Pkg",Msg::kWarning,10) << "This warning will print only 10 times." << endl;
MAXMSG works by inserting a few lines of code (including a static variable to track message counts) into your code by use of a C macro, but otherwise works similarly to MSG.


Formatting Numerical Data

The message service provides a simple class to allow users to specify the width and precision of numerical output in much the same way as provided by the C routine printf. For example:

#include "MessageService/MsgService.h"
#include "MessageService/MsgFormat.h"

int main(void) 
{
  int    i = 12345;
  double x = 123.456; 	
  MsgFormat ifmt("%9d");
  MsgFormat ffmt("%9.3f");

  // Don't worry about the MSG thing - its covered in the 
  // next section. Just think of it as a tricky "cout"
  MSG("XXX",Msg::kInfo) << "[" ifmt(i) << "]" << endl;
  MSG("XXX",Msg::kInfo) << "[" ffmt(x) << "]" << endl;
}
will print the number 12345 using a width of 9 characters and 123.456 with a width of 9 characters with a precision of 3 places beyond the decimal point. Output looks like this:
[____12345]
[__123.456]
where the underscores mark blank spaces. The formating options available are summarized in table 2.1.


Table 2.1: Format flags for use with class MsgFormat.
- Left justify in field
+ Always show sign
O Pad left with zeros
o Octal format
x,X Hexadecimal format
f Fixed format
e,E Scientific format
g,G General format


Hints and Tips

Easy formating.
Do you miss the old printf() format? No problem.. ROOT has a convenient way to do this using the Form() function.
#include "TString.h"
...
MSG("Pkg",Msg::kInfo) << Form("Number: \%3d 0x\%x \%10.2f",a,b,c) << std::endl;

Form() uses as set of circular buffers, so you can nest them safely. This is often the most convient way to do a lot of formatting.

Don't forget Munits!
Remember that all internal values used by our framework should be expressed as Munits. Whenever you print out a value, you should do the conversion explictly. For example:
#include "TString.h"
...
MSG("Pkg",Msg::kInfo) << "Time between digits: " << delta_t/Munits::ns<< endl;
MSG("Pkg",Msg::kInfo) << "Energy of the proton:" << e_prot/Munits::MeV << endl;

Remember the rule: divide when printing.

Use MAXMSG
If your screen is full of messages, it's hard to pull out the important ones. If you have a message that is likely to keep complaining through a job, but is also likely to be unimportant, then use the MAXMSG macro. For instance, it is used a lot in the Calibrator, where you may want to alert the user that a calibration isn't available, but you don't want to print an error line ever time a channel is calibrated through the whole job.

Setting the default format.
At the very beginning of your .C script, you can set all the MessageService formats to new defaults. This must be done before the Path has been created, so this should go at the top of you script. This is Nathaniel's current favorite setup:
  JobC jc;
  jc.Msg.SetDefaultFormat("RunSnarl,Bold","Warning");
  jc.Msg.SetDefaultFormat("RunSnarl,Reverse,Red","Error");
  jc.Msg.SetDefaultFormat("RunSnarl,StackTrace,Reverse,Red","Fatal");	
  jc.Path.Create(...)

Changing levels.
You can change the log level of a stream from within you code using:
MsgService::Instance()->GetStream("Pkg")->SetLogLevel(Msg::kDebug);

Advanced Features


Table 2.2: Default information attached to each message.
  Priority Prefix Date File CVS Version Line #
Verbose x x        
Debug x x        
Synopsis            
Info            
Warning x x        
Error x x x x x x
Fatal x x x x x x


The following outlines some of the more advanced features of the MessageService. Note that many of the code fragments shown will eventually be replaced by commands available from the JobControl package.

The Trip Wire Debug Facility

In the past we have encountered situations in which the same job, run twice without any intervening change to the software or the data, has produced different results indicating some randomising effect, such as the use of uninitialised data. One way to locate such problems is to use Valgrind. Another is simply to switch all print stream levels to some low level such as Debug, run the job multiple times and find the place where the output files first show differences. The snags of such an approach are:-

These snags are addressed by a trip wire facility. The basic idea is that the program execution is divided into segments, with a new one starting each time a message is requested. You configure the trip wire to suppress all messages until a particular segment is reach after which all stream message levels are lowered and segment identification is appended to all messages output.

Segments are identified by 3 counters:-

record set

The record set counter starts at zero and is incremented each time a JobCInputModule is called. If simply reading from a DaqSnarl stream then record sets are equivalent to snarls. If reading from multiple streams, a new record set is loaded each time any stream VldContext is crossed - see section 13.4.

node

The node counter starts at zero and is reset to zero each time the record set counter increments. It is incremented each time a node i.e. a JobCModule is called.

call

The call counter starts at zero and is reset to zero each time the node counter increments.

When messages are output, the values of these 3 counters is perpended, for example:-

10:7:47048: DmxUtilities.cxx:1663>  x = 0.238200 y = 0.802147 weight = 0.005958

is call 47048 from node 7 of record set 10. For simple job paths, the node number just corresponds entry in the path, for example in path:-

  jc.Path.Create("Reco",
		 "NoiseFilterModule::Ana "		 
		 "RecordSetupModule::Get "
		 "DigitListModule::Get "
		 "DigitListModule::Reco "
		 "FilterDigitListModule::Reco "
		 "FilterLIModule::Ana "
		 "DeMuxDigitListModule::Reco "
		 "DeMuxCosmicsModule::Ana "
		 "StripSRListModule::Reco "
		 "SliceSRListModule::Reco "
		 "ClusterSRListModule::Reco "
		 "ShowerSRListModule::Reco "
		 "TrackSRListModule::Reco "
		 "FitTrackSRListModule::Reco "
		 "EventSRListModule::Reco "
		 "RecordSetupModule::Reco "
		 "Output::Put");

node 7 would be:-

DeMuxDigitListModule::Reco

The trip wire facility is activated through the environmental variable: ENV_MSG_TRIP_WIRE which defined as a string containing 4 space-separated integers, the first three giving the record set, node and call values and the last the log level to be used once the trip wire point is reached. For example:-

    setenv ENV_MSG_TRIP_WIRE "4 3 2 1"

would set the trip wire to record set 4, node 3 call 2 and set the log level to 1 (debug). A typical way to look for problems would be to have a long run with only moderate (info) printout from the start:-

    setenv ENV_MSG_TRIP_WIRE "0 0 0 3"

then if a divergence is found on say record set 1234, have a second run that just processed 1234 record sets with:-

    setenv ENV_MSG_TRIP_WIRE "1234 0 0 0"

so that the record set has debug set to maximum.

A single MswTripWire object is used to hold the trip wire setting, the current program segment and the current log level. As an additional debug facility it has the dummy member function

  void Activated() const;

which is called just once, as the trip wire point is passed. Having found a divergence point the trip can be set to an earlier segment, the program debugged and a break point set on

  MswTripWire::Activated()

to starting looking for the problem with the debugger.


next up previous contents
Next: Modules, Algorithms and Candidates Up: The MINOS Off-line Software Previous: Job Control   Contents
MINOS Software 2017-10-29