Debug Event Logging

From Mpich
Revision as of 16:14, 10 November 2012 by Balaji (talk | contribs)

Jump to: navigation, search

Overview and Rationale

A uniform mechanism for logging important events in the execution of code can be a tremendous help in debugging the code. The approach described here should be used with new code. This code is active if the log option is specified to --enable-g when MPICH is configured (we recommend --enable-g=dbg,log when developing MPICH).

If MPICH is already configured to including logging and you wish to create logs, the following environment variable settings are recommended:


This causes each MPI process to generate a separate file, numbered by rank in MPI_COMM_WORLD. If there are multiple worlds or multiple threads, the file names will contain the "world number" and the thread id. Alternately, you can run the program with these two additional options:

-mpich-dbg file -mpich-dbg-level=verbose

The script mpich/src/util/dbg/getfuncstack may be used to "pretty-print" the log files. For example

 cd examples
 mpiexec -n 4 ./cpi -mpich-dbg=file -mpich-dbg-class=thread,routine
 ../src/util/dbg/getfuncstack < dbg0.log | more

will show you where thread-related operations occur within the routines.

Quickstart Settings

from goodell@ The settings that I frequently use are:

 export MPICH_DBG_FILENAME="log/dbg-%w-%d.log"

Another set that is really great for debugging nemesis dynamic process issues is:

 export MPICH_DBG_FILENAME=log/dbg-%w-%d-%p.log

Adding an Event

There are five macros that may be used to add an event to the log. In most cases, the first macro is sufficient.



     MPIU_DBG_MSG(THREAD,TERSE,"Getting lock");

The strange format for the general case allows the macro to implement the general format by using snprintf into a local string. In addition, the following macro allows a statement (or a block) to be controlled in the same way:


For more complex situations, you can use the following template:

    if (MPIU_DBG_SELECTED(class,level)) {
       ... any code, including

The macros MPIU_DBG_OUT and MPIU_DBG_OUT_FMT are similar to the MPIU_DBG_MSG and MPID_DBG_MSG_FMT macros, except that they do not take a level argument, and their expansions perform no tests on the level or class values. These are appropriate when, for example, using a loop to write out multiple lines of data.

In all of these macros, the first two values are used to control which actions are active. These are discussed in the next section.

Event Classes and Levels

The predefined classes are

Point-to-point communication
Remote memory access communication
Thread-related actions, such as entering or leaving a critical section
Process-management related action
Routine entrance and exit (these may be part of the routine entrance and exit macros).
All (any) class

Multiple classes may be combined with the or (|) operator; internally, the class is stored as a bitmask and the test is on any bit set. The predefined message levels are:

Intended for messages that are always helpful when debugging
Intended for messages that are often helpful
Intended for detailed debugging

For example, when all "typical" message are requested, all messages with level "typical" and below are logged; e.g., both TERSE and TYPICAL messages are logged. Both the predefined classes and levels are prefixed with MPIU_DBG_; the macro implementation adds the prefix (with the ## preprocessor operation) as part of the macro expansiong.

Controlling the logging package

The general format for controlling the debugging package is the same for both command line and envionment variable versions:

Command line
Environment variables

The names and their meaning are:

Pattern contains %w for the world number, %d for rank in world, %p for pid, and %t for thread id. In addition, the conditionals @W...@ and @T...@ can be used to include a value only when there is more than one world or thread respectively (this is the same syntax used by the generic mpiexec labeling code in src/pm/util/labelout.c. For example
 setenv MPICH_DBG_FILENAME "dbg-%w-%d.log"
It is usually best if each thread logs events to a separate file; this avoids any problem with file system coherence. The default filename pattern is "dbg@W%w-@%d@T-%t@.log". For an MPI-1 application with a single thread, this creates output files for the form (here for rank=3):
For an MPI-2 dynamic application with 2 worlds and several threads, the filename would be
(for the rank=3 process in world=1 with thread id 43534).
The special pattern, -stdout-, will send all output to stdout. Likewise, -stderr- will send all output to stderr. An empty pattern will have the same effect as specifying -stdout-. NOTE: the code that determines world IDs is currently buggy, so you probably won't get quite what you want when using %w. One way to deal with the collision from the buggy %w code is to use the %p specifier to cause the process ID (pid) to be substituted.
Set the level of messages. For example
mpiexec a.out -mpich-dbg-level=typical
Turn on one or more classes of debugging output. For example
Select one rank in MPI_COMM_WORLD for logging. This is particularly useful when looking at the routine trace for a particular sequence of operations or to avoid problems caused by writing data from multiple processes to stdout.

These are processed by a hook in the implementation of MPI_Init_thread.

As a shorthand, the values

   setenv MPICH_DBG yes

may be used to turn on debugging with common options; this will normally be the "typical" level and all classes, sent to stdout.

Implementation Notes

The logging output format is roughly the following:


where \t is a tab character.

A simple implementation of MPIU_DBG_MSG might be

#define MPIU_DBG_MSG(_class,_level,_string) \
    if ((MPID_DBG_##_class & MPIU_DBG_ACTIVECLASSES) && \
         MPID_DBG_##_level <= MPIU_DBG_MAXLEVEL) {\
        fprintf( stderr, "%d\t%d\t%d\t%f\t%s\t%d\t%s\n", \
        PMPI_Wtime(), __FILE__, __LINE__, _string ); fflush( stderr );\

This assumes that MPID_DBG_WORLDNUM etc. are global variables that are accessible to the file, and (for the multi-threaded case) that fprintf is thread-safe. The actual implementation is more likely to look like

#define MPIU_DBG_MSG(_class,_level,_string) \
    if ((MPID_DBG_##_class & MPIU_DBG_ACTIVECLASSES) && \
         MPID_DBG_##_level <= MPIU_DBG_MAXLEVEL) {\
        MPIU_DBG_Outevent( __FILE__, __LINE__, _string ); }

where MPIU_DBG_Outevent is a routine that handles the output of the string (this will be a varargs routine, so that all of the macros above will use the same routine).

An additional feature that we may wish to consider (and which was implemented within MPICH-1) is a circular buffer of log events that is only output on failure (either an MPID_Abort or a signal such as SIGINT or SIGSEGV). This could be selected with the name "lastonly" as in

mpiexec -n 4 a.out -mpich-dbg-lastonly=500

(Only output the last 500 lines for each thread). Interpreting the Logs The script, dbgextract, in src/util/dbg is intended for use with -mpich-dbg-class=routine. It reads a log file and outputs a simplified version that indents the routine states according to their nesting level as executed, making it easier to see the trace of execution in MPICH.

Rationale for Design Choices

Why not use varadic macros (macros that allow a variable number of arguments)? They are part of the C99 standard.
Some important compilers, including the Portland Group compilers, do not support this feature yet (there are many compilers that do not support all of C99 yet).

Using the Older Debugging Code

To turn on the MPIDI_DBG_PRINTF debugging macro, you need to compile with the flag MPICH_DBG_OUTPUT (do "setenv CFLAGS -DMPICH_DBG_OUTPUT" before running configure) and at runtime you need to set the environment variable MPICH_DBG_OUTPUT to either "stdout", "file", or "memlog".

Note that this interface will be removed in a subsequent release of MPICH in favor of the MPIU_DBG_MSG interface described above.