Peano 4
Loading...
Searching...
No Matches
Logging, tracing, statistics, profiling and assertions

Logging, tracing and assertion architecture

Peano is built upon a technical architecture (tarch) which provides logging, tracing and assertions. This is also the layer which decides which information is pre-prepared for the supported profiling tools. The two directory of relevance here is therefore tarch/logging plus the file Assertions.h. The latter file holds all the assertion macros, while the logging directory holds a file Log.h which holds all of the essential logging and tracing macros.

When we build Peano, we do distinguish different "debug" levels:

  • If a code is translated with -DPeanoDebug=0, all logging, tracing and assertion macros are disabled, i.e. replaced by empty statements. Warning, information and error messages are still displayed.
  • If a code is translated with -DPeanoDebug=1, all macros from -DPeanoDebug=0 remain defined. This time however, all tracing functionality is enabled. With this mode, it is possible to do production runs plus to extract some performance data, e.g.
  • If a code is translated with -DPeanoDebug=2, all the tracing macros from -DPeanoDebug=1 remain defined. On top of this, Peano's assertions now are enabled, i.e. assertion macros do not degenerate to nop but actually run tests. This might increase the runtime significantly yet the code permanently runs test.
  • If a code is translated with -DPeanoDebug=4, logging and assertion macros from -DPeanoDebug=4 remain defined. Furthermore, any debug information written through Peano's log interface is now not discarded (removed at compile time) but actually shown. This is the slowest mode yielding most of the data.

Using the logging and tracing interface

Peano relies on a plain interface to write out user information. All constituents of this interface are collected in the package tarch::logging. Documentation on this package can be found in the corresponding header files, files ending with .doxys, or the Peano webpage (section on sources). The usage paradigm is simple:

  1. Each class that wants to write logging information requires an instance of class tarch::logging::Log. As such an instance is required per class, it makes sense to make this field a static one.

    Please keep to the nomenclature of the class field to make all macros work. Please use as string argument in the constructor the fully qualified class name. See the remarks on log filters below for an explanation for this.

  2. Whenever you want to log, trace, write an error message or a warning, you should use Log's operations to write the messages. Alternatively, you may want to use the log macros from Log.h. They work with stringstreams internally, i.e. you may write things along the lines

    logInfo( "runAsMaster(...)", "time step " << i << ": dt=" << dt );

    where you concatenate the stream with data.

Peano offers four levels of logging through its macros:

  • Info. Should be used to inform your user about the application's state.
  • Warning. Should be used to inform your user about bothering behaviour. The MPI code uses it, e.g., if many messages arrive in a different order than expected. Messages written to the warning level are piped to cerr.
  • Error. Should be used for errors. Is piped to cerr as well.
  • Tracing. Used to keep track of when a method is entered and then left again.
  • Debug. Should be used to write debug data. It goes to cout and all debug data is removed if you do not translate with the compile flag -DDebug. Notably, use the logDebug macros when you write to the debug level, as all required log operations then are removed by the compiler once you create a release version of your code.

Logging devices, formats, backends and profiling support

The Log instance forwards the information to a logger. By default, this is the tarch::logging::ChromeTraceFileLogger. You may want to write your own alternative implementation or switch to another option. Logging can be very time-consuming. I therefore decided to link the Log objects to one particular log device statically. If you want to "redirect" your outcome, you can either manually edit the logging header, or you can retranslate your code with -DUseLogService=xxx. xxx is the class to be used. I detail the variants I currently ship with Peano below.

Supports the instrumentation of source code for particular performance analysis tools via its loggers. Notably all output to the trace target are forwarded to instrumentation APIs. To make this work, you either have to pick a particular logging device, or you switch to a tool-/vendor-specific toolchain.

CommandLineLogger

To select this logger, compile with -DUseLogService=CommandLineLogger. This logger is the default.

This logger dumps all information in a human readable format. It can be tailored towards your needs. For this, the logger provides a particular setter. Please consult the header or the webpage for details on the semantics of the arguments:

" ",
true, false, false, true, true,
"my-fancy.log-file"
);
void setLogFormat(const std::string &columnSeparator, bool logTimeStamp, bool logTimeStampHumanReadable, bool logMachineName, bool logThreadName, bool logMessageType, bool logTrace, const std::string &outputLogFileName)

The interface also allows you to pipe the output into a file rather than to the terminal. This is particular useful for MPI applications, as each rank is assigned a file of its own and messages are not screwed up. Typically, the logger is configured in the main of the application.

If you run Peano for long simulations and, notably, if you run Peano with debug information switched on, log files soon become massive. To ease the pain, Peano's command line logger offers an operation tarch::logging::CommandLineLogger::closeOutputStreamAndReopenNewOne() that works if you have specified an output file before (see setLogFormat above). Per close, you close all output files and start to stream the output into a new file. Typically, developers use this operation in their iterative schemes to stream each iteration to a different file. The output files are enumerated automatically.

ChromeTraceFileLogger

To select this logger, compile with -DUseLogService=ChromeTraceFileLogger.

This logger writes the one json file per rank. The format conforms to Google Chrome's tracing format, i.e. you can open the file in Google Chrome by typing in the URL chrome:///tracing and loading in the file in the GUI that pops up. As the format is prescribed, there are no opportunities to configure the output. While the majority of all output data goes into these Chrome files, warnings, errors and info messages are also dumped to the terminal in a format which can be read by humans easily.

NVTX logger (NVIDIA SDK)

To select this logger, compile with -DUseLogService=NVTXLogger. This logger forwards all trace commands to NVIDIA's profiling/tracing library. It is automatically enabled once you configure with

./configure --with-toolchain=nvidia

ITAC logger

To select this logger, configure with

./configure --with-toolchain=intel

This switch sets, automatically, the compile flag -DUseLogService=ITACLogger. You can however also set the logger via the CXXFLAGS.

The ITAC logger forwards all trace commands to Intel's profiling/tracing library. You can now compile 's tracing backend, and will continue to plot all info statements to the terminal. The trace statements however are piped directly into ITAC, i.e. if you analyse the code with Intel's traceanalyzer or VTune, you should see the -specific annotations and traces. You can also use 's log filter to filter which events are actually handed over to ITAC.

I've recognised that the Intel scripts often do not include the ITAC headers that requires in their search path. In this case, you will have to augment your configure call:

The class tarch::logging::ITACLogger provides further detail on the usage of the logging back-end. The punch line is that you have to translate in trace mode to get proper ITAC data. As the trace information of quickly becomes vast, I recommend to create a log filter, and start a run where you disable all but the top-level tracing information.

Log filter

The amount of log information often becomes hard to track; notably if you run in debug mode. Often, you are interested only in a subset of all log messages. For this, Peano offers log filters which provide a blacklist and whitelist mechanism to filter messages before they are written. A log filter entry is created by

tarch::logging::LogFilter::FilterListEntry::AlwaysOn
)
);
void addFilterListEntry(const FilterListEntry &entry)
Add one filter list entry.
static LogFilter & getInstance()
Represents one entry of the filter list.
Definition LogFilter.h:30
static const std::string TargetInfo
Definition LogFilter.h:34

The log filter is a singleton, and log filters can be used totally independently of the log output format.

Configuring log filters in your source code is a convenient option when you start a new project. On the long run, it is cumbersome if you have to recompile every time you want different log information. Therefore, the CommandLineLogger also offers a routine that allows you to load log filter entries from a text file. This facilitates work with log filters. The usage is straightforward

static bool parsePlainTextFile(const std::string &filename)
Tries to parse a simple text file where each line contains an entry.

and the format is very simple:

# Level                 Trace                    Rank          Black/white  When on
# info/debug/trace/all  trace of class affected  -1=all ranks
  debug                 tarch                    -1            black        always-on
  debug                 peano4                   -1            black        always-on
  info                  tarch                    -1            black        always-on
  info                  peano4                   -1            black        always-on
  trace                 tarch                    -1            black        always-on
  trace                 peano4                   -1            black        always-on
  all                   tarch                    -1            black        always-on
  all                   peano4                   -1            black        always-on

# Lines starting with hash are comments

# Switch on info output from one class on one rank only
info     examples::subdirectory::myClass    15    white  my-phase

For performance reasons, it is important to take two facts into account:

  1. Black- and whitelisting works only on the class level. While tracing, logging, and so forth all tell you which operation has logged a certain entry, you cannot filter on the method level.
  2. Black- and whitelisting are not dynamic. The very first time a class wants to dump information, it queries the log filter. The result of the log filter then is hold persistently.

Whether a log message is written or not results from the combination of compile flags (PeanoDebug flag) plus the log filters you have in place. If you translate with -DPeanoDebug=0, debug log filters play no role, as the underlying messages are not written anyway. In this context, you have to pay attention against which libraries you link. Peano builds the technical architecture, the core and tools in different versions with different optimisation levels and different log settings. Select the right one if you wanna see messages from the core or tarch.

You can have different log entries for different program phases. By default, the log filter does not keep track of the program phase, i.e. it does not know which program phase is on. You can use tarch::logging::LogFilter::switchProgramPhase():

void switchProgramPhase(const std::string &activeProgramPhase)

From hereon, only the log filter entries labelled with my-phase or with always-on will be used. You can use any string for my-phase. Some higher-level frameworks such as  define some program phases a priori.

Assertions

Peano provides its own assertion format which is independent of C++ assertions. Assertions are offered through macros, and if you choose a PeanoDebug level which does not support assertions, then they are removed at compile time from your code.

Peano's assertions interlink with the logging, i.e. before they shut down a rank, they ensure that all logs are flushed. Furthermore, they provide a few convenient variations that

  1. support numerical "equality" checks,
  2. support the logging of parameters, and
  3. support vector-valued comparisons.

It is best to study the macros in tarch/Assertions.h to get an overview.

Statistics

Peano has a statistics backend, which you can activate by switching into the statistics mode. This implies that you link against the statistics builds of the libraries. The statistics tool is relatively simply to use: You identify an identifier for your metric (a simple string) and then you log values for this identifier. The values have to be scalar doubles, and you don't have to register your identifier or similar things.

void log(const std::string &identifier, double value, bool disableSampling=false)
Log one particular value.
Definition Statistics.h:90
static Statistics & getInstance()
This is not the canonical realisation of singletons as I use it usually for stats in Peano.

The statistics backend samples over these calls and eventually writes a csv file with the logged entries over time. To trigger this write, you have to call tarch::logging::Statistics::writeToCSV(). I usually invoke the write at the end of the main routine.

If you activate the statistics, automatically writes some runtime statistics into the stats file. These statistics give you, for example, and overview how many tasks are in flight at any time, or how long 's MPI routines had to wait for incoming data. The output format is plain csv and thus straightforward to parse. Peano's directory python/peano4/postprocessing also holds some pre-manufactured scripts to visualise some standard metrics.