- Table of contents
- Message Logging and TRACEing
- The Issues
- Usage Overview
- Header Files VS. Non-header Files
- The TRACE circular memory buffer destination
- Viewing the TRACE memory buffer with tshow
- Specific Usage Suggestions
Message Logging and TRACEing¶
Many of the issues/concepts mentioned here also apply to metrics.
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
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:
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
TRACE(lvl,msg,...) # uses TRACE_NAME as facility or "TRACE" is TRACE_NAME not defined TRACEN("facility",lvl,msg,...)
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; or TRACEN("my_template_class",lvl,msg,...)
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.
Configuration¶Configuring the memory buffer and the enabling of the additional debug/logging levels can the done via
- additional messagefacility fhicl configuration
- environment variables
- command line utility assuming memory buffer tracing has been activated
For more details on TRACEing, see the trace wiki page.
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:
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:
- TLOG's with "DEBUG" e.g.
TLOG(TLVL_DEBUG) or possibly TLOG(3)
- TLOG's with the level higher than 3 i.e 4-63
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:
- by setting environment variable TRACE_LVLS=-1 or 0xf or any 64 bit number which has the fourth bit (b3) set, or
- 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.