Message Logging and TRACEing

Many of the issues/concepts mentioned here also apply to metrics.

The Issues

Usage Overview

Artdaq programs and modules will run in an environment where the Message Facility has been
initialized by artdaq::configureMessageFacility. Basically, this happens first.

When modules include artdaq/DAQdata/Globals.hh, they get TRACE wrappers around calls to the
message facility fundamentals. This header includes tracemf.h; non-artdaq code may include tracemf.h or trace.h directly.

#include "artdaq/DAQdata/Globals.hh" 
#define TRACE_NAME "BoardReaderName"  # recommended/optional default name for TLOG(lvl) and TRACE(lvl,...)

OR, less commonly,
#include "tracemf.h" 
#define TRACE_NAME "BoardReaderName"  # recommended/optional default name for TLOG(lvl) and TRACE(lvl,...)

A note on TRACE_NAME definition is here.
In this environment, we recommend writing logging/tracing/debugging messages using one of the two
major styles:
  TLOG_ERROR("facility") << message << TLOG_ENDL;          # see Limitations section below

  TLOG(<level:3-63>) << message;

In the above, "ERROR" can be replaced with WARNING, INFO, or DEBUG.
So, the full list of available macros is:
Streamer style:

  TLOG_ERROR("facility")      # non-maskable
  TLOG_WARNING("facility")    # non-maskable
  TLOG_INFO("facility")       # non-maskable in debug build only
  TLOG_DEBUG("facility")      # non-maskable in debug build only
  TLOG(lvl [,"facility"])     # intended for higher/dynamically enablable debug levels, facility optional

Printf style:
  TRACE(lvl,msg,...)          # uses TRACE_NAME as facility or "TRACE" is TRACE_NAME not defined

The "lvl" (or "level") can be a number in the range 0 to 63 (but usually in the range 4 to 63 as 0,1,2,3 are ERROR,WARNGING,INFO,DEBUG respectively).

Header Files VS. Non-header Files

Using #define TRACE_NAME in header files is discouraged as it can cause
a conflict with a #define TRACE_NAME in the non-header file from which they are included.

When "TRACES" are used in header files (in template or inline code), we recommend
using the variants which include the name/facility in them:

  TLOG(<level:3-63>,"my_template_class") << message;

The TRACE circular memory buffer destination

TRACEs can dynamically be configured to send messages to a circular memory buffer where they
can be displayed using the "tshow" display utility.
If the messages go only to memory, argument formatting is delayed, which significantly reduce the
impact (CPU time) of the tracing.

Additionally, memory TRACEing does not involve any system calls (getting time is a virtual syscall). This allows for maximal debug statements with minimal impact on application performance. With the write system call that is involved with file, console or network destinations, program flow can be interrupted/changed and backpressure to the application may result.

Process ID (pid), thread ID, CPU (core), and microsecond TOD information are stored in the trace memory.


Configuring the memory buffer and the enabling of the additional debug/logging levels can the done via
  1. additional messagefacility fhicl configuration
  2. environment variables
  3. command line utility assuming memory buffer tracing has been activated

For more details on TRACEing, see the trace wiki page.

Config - Message Flow Diagram

Viewing the TRACE memory buffer with tshow

When the TRACE UPS product is setup, and the appropriate TRACE_* env. var. is set, the "tshow" command can be used to display the TRACE entries. tshow is often used with the tdelta unix filter to add delta time (delta microseconds) and to convert the time number into a more human readable format.
Example tshow output:

export TRACE_FILE=/tmp/trace_buffer_daquser


Macro which have a name/facility argument

The first time a thread executes a TLOG_*( name ), a name-to-tid lookup occurs. The resulting tid is stored for subsequent executions.
This means the following code:

std::string name=std::string("label")+x;
TLOG_DEBUG(name) << "x=" << x;

executed 3 times with values of x equal to 1, 2, and 3, will produce messages with names as follows:
1st execution: name: "label1", message: x=1
2nd execution: name: "label1", message: x=2
3rd execution: name: "label1", message: x=3

Specific Usage Suggestions

Enabling Debug Messages in artdaqDriver

For the impatient, the quickest way to do this is to set the debug_cout parameter to "true" in the FHiCL file that you are using (Step 1, Option 1 in the 'More details' below). This should get you 95% of the way there.

Enabling Debug Messages from BoardReader processes (and other artdaq processes)

First, there are 2 groups of "Debug" messages:
  1. TLOG's with "DEBUG" e.g.
    TLOG(TLVL_DEBUG) or possibly TLOG(3)
  2. TLOG's with the level higher than 3 i.e 4-63
It is highly likely, that the TRACEing environment that the artdaq processes are run in, by default, will not have the either of the 2 Debug groups enabled.
In this case, DEBUG messages (specifically group 1) will not be seen in the logs/console, unless running a debug build (not the prof build).
If you want to see DEBUG messages when running prof builds, you have to have the "trace level" associated TLVL_DEBUG set (on), which can be done:
  1. by setting environment variable TRACE_LVLS=-1 or 0xf or any 64 bit number which has the fourth bit (b3) set, or
  2. by having the trace environment enabled and having the fourth bit in the appropriate "tlvls slow mask" set (see the "More details" section above).

Temporarily disabling the rate-limiting of messages

In some cases, we want to see all of the messages, even though some fraction of them might naturally be suppressed by the rate-limiting code that is enabled by default. To temporarily turn off the rate limitation, we can use the following command:

  • 'export TRACE_LIMIT_MS=0,0,0' # the first zero effectively turns off rate limiting
  • (the three values are the 'limit count', the 'ON milliseconds', and the 'OFF milliseconds')

To re-enable the default behavior, use

  • 'export TRACE_LIMIT_MS=10,500,1500'

PLEASE NOTE that changing these settings affects all applications that use the current TRACE environment, including any in the running DAQ. As such, there are probably better ways to modify our environment when using a more offline-focused application, such as an event dump program. In that case, it is probably better to unset the TRACE env vars that are set in the current environment (e.g. 'unset TRACE_NAME') and thereby avoid affecting other applications.