TRACE: a useful debugging tool


When debugging fragment generators, as when debugging any piece of software, it's useful to print out statements, variable values, etc., to determine what the system is doing. One potential problem with this is that littering code with lots of lengthy print statements can affect the code execution time; this of special concern in a system which depends as heavily on execution time as a DAQ. Another problem is that it can be a hassle to recompile the code whenever you want to add or remove a print statement. A package called "TRACE" has been developed at Fermilab which is designed to address these two concerns.

Enabling TRACEs already in the code

The TRACE package gets set up whenever you source a dune-artdaq source file, /path/to/your/dune-artdaq/installation/setupDUNEARTDAQ. You'll notice that in many such source files, there are some Bash statements at the bottom of the source file which configure TRACE:

       export TRACE_FILE=/tmp/trace_example_buffer
       export TRACE_LIMIT_MS="5,1000,2000"

       toffM 15 -n CommandableFragmentGenerator
       tonM 15 -n CommandableFragmentGenerator 

Basically, TRACE is capable of sending print statements to a buffer on a disk defined by the environment variable TRACE_FILE at a much greater speed than print statements (printf, cout, etc.) can write to stdout. Normally you'd want to take advantage of this speed and send TRACE messages to buffer; however, you also have the option of sending TRACEs to stdout, and they need not be the same TRACEs sent to buffer. There are other environment variables which can further control TRACE's behavior; the TRACE_LIMIT_MS variable, above, is essentially saying "Don't print to stdout more than 5 identical messages to stdout in a 1000 millisecond (1 second) time window, and if you hit this limit, pause for 2000 milliseconds (2 seconds) before allowing further prints". Note that TRACE_LIMIT_MS doesn't apply to the statements being saved to the buffer, due to the buffer's speed.

The "toffM 15 -n CommandableFragmentGenerator" line tells TRACE that you want it not to print TRACE messages in artdaq's CommandableFragmentGenerator base class that are at level 15, and the following line "tonM 15 -n CommandableFragmentGenerator" tells you want it to. I'll describe what levels are in a moment, but first, the reason for the apparent uselessness of the "toffM" statement is that if you wish to turn off the printing of the message, you must do so by explicitly calling toffM. If you wish to turn off the TRACE statement, with the syntax above all you need to do is comment out the "tonM" statement, but without the "toffM" line it's very easy to forget that you need to call toffM and simply try commenting out tonM, which won't actually make the change you want.

Concerning what "level 15" means: all trace statements have a name and level associated with them. The name in this case is "CommandableFragmentGenerator", and the level in this case is 15. What this means is, in the code above, TRACE statements with name "CommandableFragmentGenerator" and level 15 would get printed. If you look at line 281 of the CommandableFragmentGenerator source code,✓&rev=v3_00_03a , you'll see

        TLOG_ARB(15, "CommandableFragmentGenerator") << "getDataBufferStats: Calculating buffer size" << TLOG_ENDL;
...this is an example of such a TRACE statement.

Examining TRACE statements sent to buffer

This raises the obvious question: if a TRACE statement is written to a buffer referred to by TRACE_FILE rather than to stdout or a logfile, how can one look at the statement? Note that the buffer isn't an ASCII file, and it can't simply be opened by a text editor. What you need to do after performing a run with the desired TRACEs enabled is to log onto the node where your fragment generator ran, and then do the following:

source <full pathname of the setupDUNEARTDAQ file sourced for the run>
tshow | tdelta -d 1 -ct 1 | less

what you'll then see looks like the following:

  idx                us_tod     delta   pid   tid cpu                                  name lvl r msg
-----      ---------------- --------- ----- ----- --- ------------------------------------- --- - -----------------------------
    0 03-30 21:13:59.603276         0 124131 124131   5                       BoardReaderMain nfo . Commandable Server ended, exiting...
    1 03-30 21:13:59.602884       392 124131 124131   5                      xmlrpc_commander dbg . server terminated
...etc. Basically, each TRACE statement gets its own row, and each row is composed of a set of fields, whose names are at the top of the output. The interpretation of the fields is as follows:

  1. idx: the idx-th most recent TRACE statement, counting from 0
  2. us_tod: the time of the TRACE statement, given to microsecond precision
  3. delta: the number of microseconds the TRACE was performed before the next TRACE statement
  4. pid: the process ID of the process in which the TRACE statement executed
  5. tid: the thread ID of the same
  6. cpu: the CPU # the TRACE statement executed on
  7. name: the name associated with the TRACE statement ("CommandableFragmentGenerator" in the example earlier on this page)
  8. lvl: the level of the TRACE statement (15 in the example earlier on this page)
  9. msg: the actual message contents of the TRACE statement

As you might imagine, it's very common to grep for specific rows of this output, as well as use tools such as awk to select on specific fields.

Adding TRACE statements to your fragment generator

Adding TRACE statements to your fragment generator is quite simple. First, you want to be sure to add the following #include to your source file:

#include "artdaq/DAQdata/Globals.hh"
And then, in your code, you can add lines such as the following:
TLOG(an_integer_with_the_level_of_this_message, a_string_with_the_name_of_this_message) << "A string containing the contents of this message, which can include " << a_variable << " since the syntax is simply C++ streaming syntax";
When you rebuild your code, you can then edit setupDUNEARTDAQ as described earlied to make sure that the TRACE you added is enabled so it will be sent to buffer during running.

-- JohnChristianFreeman - 2018-03-30

This topic: CENF > WebHome > RDProjects > DUNEProtSP > DUNEProtSPSubprojects > DUNEProtSPDAQ > ForDune-artdaqDevelopers
Topic revision: r2 - 2018-03-30 - JohnChristianFreeman
This site is powered by the TWiki collaboration platform Powered by PerlCopyright & 2008-2022 by the contributing authors. All material on this collaboration platform is the property of the contributing authors.
or Ideas, requests, problems regarding TWiki? use Discourse or Send feedback