4.2. Logging

VTK‑m features a logging system that allows status updates and timing. VTK‑m uses the loguru project to provide runtime logging facilities. A sample of the log output can be found at https://gitlab.kitware.com/snippets/427.

4.2.1. Initializing Logging

Logging features are enabled by calling vtkm::cont::Initialize() as described in Chapter 2.3 (Initialization). Although calling vtkm::cont::Initialize() is not strictly necessary for output messages, initialization adds the following features.

  • Set human-readable names for the log levels in the output.

  • Allow the stderr logging level to be set at runtime by passing a --vtkm-log-level [level] argument to the executable.

  • Name the main thread.

  • Print a preamble with details of the program’s startup (arguments, etc).

Example 4.36 in the following section provides an example of initializing with additional logging setup.

The logging implementation is thread-safe. When working in a multithreaded environment, each thread may be assigned a human-readable name using vtkm::cont::SetLogThreadName() (which can later be retrieved with vtkm::cont::GetLogThreadName()). This name will appear in the log output so that per-thread messages can be easily tracked.

void vtkm::cont::SetLogThreadName(const std::string &name)

Specifies a humman-readable name to identify the current thread in the log output.

std::string vtkm::cont::GetLogThreadName()

Specifies a humman-readable name to identify the current thread in the log output.

4.2.2. Logging Levels

The logging in VTK‑m provides several “levels” of logging. Logging levels are ordered by precedence. When selecting which log message to output, a single logging level is provided. Any logging message with that or a higher precedence is output. For example, if warning messages are on, then error messages are also outputted because errors are a higher precedence than warnings. Likewise, if information messages are on, then error and warning messages are also outputted.

Common Errors

All logging levels are assigned a number, and logging levels with a higher precedence actually have a smaller number.

All logging levels are listed in the vtkm::cont::LogLevel enum.

enum class vtkm::cont::LogLevel

Log levels for use with the logging macros.

Values:

enumerator Off

A placeholder used to silence all logging.

Do not actually log to this level.

enumerator Fatal

Fatal errors that should abort execution.

enumerator Error

Important but non-fatal errors, such as device fail-over.

enumerator Warn

Less important user errors, such as out-of-bounds parameters.

enumerator Info

Information messages (detected hardware, etc) and temporary debugging output.

enumerator UserFirst

The first in a range of logging levels reserved for code that uses VTK-m.

Internal VTK-m code will not log on these levels but will report these logs.

enumerator UserLast

The last in a range of logging levels reserved for code that uses VTK-m.

enumerator DevicesEnabled

Information about which devices are enabled/disabled.

enumerator Perf

General timing data and algorithm flow information, such as filter execution, worklet dispatches, and device algorithm calls.

enumerator MemCont

Host-side resource allocations/frees (e.g. ArrayHandle control buffers).

enumerator MemExec

Device-side resource allocations/frees (e.g ArrayHandle device buffers).

enumerator MemTransfer

Transferring of data between a host and device.

enumerator KernelLaunches

Details on device-side kernel launches.

enumerator Cast

Reports when a dynamic object is (or is not) resolved via a CastAndCall or other casting method.

enumerator UserVerboseFirst

The first in a range of logging levels reserved for code that uses VTK-m.

Internal VTK-m code will not log on these levels but will report these logs. These are used similarly to those in the UserFirst range but are at a lower precedence that also includes more verbose reporting from VTK-m.

enumerator UserVerboseLast

The last in a range of logging levels reserved for code that uses VTK-m.

When VTK‑m outputs an entry in its log, it annotates the message with the logging level. VTK‑m will automatically provide descriptions for all log levels described in vtkm::cont::LogLevel. A custom log level can be described by calling the vtkm::cont::SetLogLevelName() function. (The log name can likewise be retrieved with vtkm::cont::GetLogLevelName().)

void vtkm::cont::SetLogLevelName(vtkm::cont::LogLevel level, const std::string &name)

Register a custom name to identify a log level.

The name will be truncated to 4 characters internally.

Must not be called after InitLogging. Such calls will fail and log an error.

There is no need to call this for the default vtkm::cont::LogLevels. They are populated in InitLogging and will be overwritten.

std::string vtkm::cont::GetLogLevelName(vtkm::cont::LogLevel level)

Get a human readable name for the log level.

If a name has not been registered via InitLogging or SetLogLevelName, the returned string just contains the integer representation of the level.

Common Errors

The vtkm::cont::SetLogLevelName() function must be called before vtkm::cont::Initialize() to have an effect.

Common Errors

The descriptions for each log level are only set up if vtkm::cont::Initialize() is called. If it is not, then all log levels will be represented with a numerical value.

If vtkm::cont::Initialize() is called with argc/argv, then the user can control the logging level with the --vtkm-log-level command line argument. Alternatively, you can control which logging levels are reported with the vtkm::cont::SetStderrLogLevel().

void vtkm::cont::SetStderrLogLevel(vtkm::cont::LogLevel level)

Set the range of log levels that will be printed to stderr.

All levels with an enum value less-than-or-equal-to level will be printed.

void vtkm::cont::SetStderrLogLevel(const char *verbosity)

Set the range of log levels that will be printed to stderr.

All levels with an enum value less-than-or-equal-to level will be printed.

vtkm::cont::LogLevel vtkm::cont::GetStderrLogLevel()

Get the active highest log level that will be printed to stderr.

Example 4.36 Initializing logging.
 1static const vtkm::cont::LogLevel CustomLogLevel = vtkm::cont::LogLevel::UserFirst;
 2
 3int main(int argc, char** argv)
 4{
 5  vtkm::cont::SetLogLevelName(CustomLogLevel, "custom");
 6
 7  // For this example we will set the log level manually.
 8  // The user can override this with the --vtkm-log-level command line flag.
 9  vtkm::cont::SetStderrLogLevel(CustomLogLevel);
10
11  vtkm::cont::Initialize(argc, argv);
12
13  // Do interesting stuff...

4.2.3. Log Entries

Log entries are created with a collection of macros provided in vtkm/cont/Logging.h. In addition to basic log entries, VTK‑m logging can also provide conditional logging and scope levels of logs.

4.2.3.1. Basic Log Entries

The main logging entry points are the macros VTKM_LOG_S and VTKM_LOG_F, which use C++ stream and printf syntax, respectively. Both macros take a logging level as the first argument. The remaining arguments specify the message printed to the log. VTKM_LOG_S takes a single argument with a C++ stream expression (so << operators can exist in the expression). VTKM_LOG_F takes a C string as its second argument that has printf-style formatting codes. The remaining arguments fulfill those codes.

VTKM_LOG_S(level, ...)

Writes a message using stream syntax to the indicated log level.

The ellipsis may be replaced with the log message as if constructing a C++ stream, e.g:

VTKM_LOG_S(vtkm::cont::LogLevel::Perf,
           "Executed functor " << vtkm::cont::TypeToString(functor)
            << " on device " << deviceId.GetName());
VTKM_LOG_F(level, ...)

Writes a message using printf syntax to the indicated log level.

The ellipsis may be replaced with the log message as if constructing a printf call, e.g:

VTKM_LOG_F(vtkm::cont::LogLevel::Perf,
           "Executed functor %s on device %s",
           vtkm::cont::TypeToString(functor).c_str(),
           deviceId.GetName().c_str());
Example 4.37 Basic logging.
1  VTKM_LOG_F(vtkm::cont::LogLevel::Info,
2             "Base VTK-m version: %d.%d",
3             VTKM_VERSION_MAJOR,
4             VTKM_VERSION_MINOR);
5  VTKM_LOG_S(vtkm::cont::LogLevel::Info, "Full VTK-m version: " << VTKM_VERSION_FULL);

4.2.3.2. Conditional Log Entries

The macros VTKM_LOG_IF_S VTKM_LOG_IF_F behave similarly to VTKM_LOG_S and VTKM_LOG_F, respectively, except they have an extra argument that contains the condition. If the condition is true, then the log entry is created. If the condition is false, then the statement is ignored and nothing is recorded in the log.

VTKM_LOG_IF_S(level, cond, ...)

Same as VTKM_LOG_S, but only logs if cond is true.

VTKM_LOG_IF_F(level, cond, ...)

Same as VTKM_LOG_F, but only logs if cond is true.

Example 4.38 Conditional logging.
1  for (vtkm::Id i = 0; i < 5; i++)
2  {
3    VTKM_LOG_IF_S(vtkm::cont::LogLevel::Info, i % 2 == 0, "Found an even number: " << i);
4  }

4.2.3.3. Scoped Log Entries

The logging back end supports the concept of scopes. Scopes allow the nesting of log messages, which allows a complex operation to report when it starts, when it ends, and what log messages happen in the middle. Scoped log entries are also timed so you can get an idea of how long operations take. Scoping can happen to arbitrary depths.

Common Errors

Although the timing reported in scoped log entries can give an idea of the time each operation takes, the reported time should not be considered accurate in regards to timing parallel operations. If a parallel algorithm is invoked inside a log scope, the program may return from that scope before the parallel algorithm is complete. See Chapter 2.11 (Timers) for information on more accurate timers.

Scoped log entries follow the same scoping of your C++ code. A scoped log can be created with the VTKM_LOG_SCOPE macro. This macro behaves similarly to VTKM_LOG_F except that it creates a scoped log that starts when VTKM_LOG_SCOPE and ends when the program leaves the given scope.

VTKM_LOG_SCOPE(level, ...)

Creates a new scope at the requested level.

The log scope ends when the code scope ends. The ellipses form the scope name using printf syntax.

{
  VTKM_LOG_SCOPE(vtkm::cont::LogLevel::Perf,
                 "Executing filter %s",
                 vtkm::cont::TypeToString(myFilter).c_str());
  myFilter.Execute();
}
Example 4.39 Scoped logging.
 1  for (vtkm::IdComponent trial = 0; trial < numTrials; ++trial)
 2  {
 3    VTKM_LOG_SCOPE(CustomLogLevel, "Trial %d", trial);
 4
 5    VTKM_LOG_F(CustomLogLevel, "Do thing 1");
 6
 7    VTKM_LOG_F(CustomLogLevel, "Do thing 2");
 8
 9    //...
10  }

It is also common, and typically good code structure, to structure scoped concepts around functions or methods. Thus, VTK‑m provides VTKM_LOG_SCOPE_FUNCTION. When placed at the beginning of a function or macro, VTKM_LOG_SCOPE_FUNCTION will automatically create a scoped log around it.

VTKM_LOG_SCOPE_FUNCTION(level)

Equivalent to VTKM_LOG_SCOPE(level, __func__)

Example 4.40 Scoped logging in a function.
1void TestFunc()
2{
3  VTKM_LOG_SCOPE_FUNCTION(vtkm::cont::LogLevel::Info);
4  VTKM_LOG_S(vtkm::cont::LogLevel::Info, "Showcasing function logging");
5}

4.2.4. Helper Functions

The vtkm/cont/Logging.h header file also contains several helper functions that provide useful functions when reporting information about the system.

Did You Know?

Although provided with the logging utilities, these functions can be useful in contexts outside of the logging as well. These functions are available even if VTK‑m is compiled with logging off.

The vtkm::cont::TypeToString() function provides run-time type information (RTTI) based type-name information. vtkm::cont::TypeToString() is a templated function for which you have to explicitly declare the type. vtkm::cont::TypeToString() returns a std::string containing a representation of the type provided. When logging is enabled, vtkm::cont::TypeToString() uses the logging back end to demangle symbol names on supported platforms.

template<typename T>
inline std::string vtkm::cont::TypeToString()

Use RTTI information to retrieve the name of the type T.

If logging is enabled and the platform supports it, the type name will also be demangled.

template<typename T>
inline std::string vtkm::cont::TypeToString(const T&)

Use RTTI information to retrieve the name of the type T.

If logging is enabled and the platform supports it, the type name will also be demangled.

std::string vtkm::cont::TypeToString(const std::type_index &t)

Use RTTI information to retrieve the name of the type T.

If logging is enabled and the platform supports it, the type name will also be demangled.

std::string vtkm::cont::TypeToString(const std::type_info &t)

Use RTTI information to retrieve the name of the type T.

If logging is enabled and the platform supports it, the type name will also be demangled.

The vtkm::cont::GetHumanReadableSize() function takes a size of memory in bytes and returns a human readable string (for example “64 bytes”, “1.44 MiB”, “128 GiB”, etc). vtkm::cont::GetSizeString() is a similar function that returns the same thing as vtkm::cont::GetHumanReadableSize() followed by (# bytes) (with # replaced with the number passed to the function). Both vtkm::cont::GetHumanReadableSize() and vtkm::cont::GetSizeString() take an optional second argument that is the number of digits of precision to display. By default, they display 2 digits of precision.

std::string vtkm::cont::GetHumanReadableSize(vtkm::UInt64 bytes, int prec = 2)

Convert a size in bytes to a human readable string (such as “64 bytes”, “1.44 MiB”, “128 GiB”, etc).

prec controls the fixed point precision of the stringified number.

std::string vtkm::cont::GetSizeString(vtkm::UInt64 bytes, int prec = 2)

Returns “%1 (%2 bytes)” where %1 is the result from GetHumanReadableSize and %2 is the exact number of bytes.

The vtkm::cont::GetStackTrace() function returns a string containing a trace of the stack, which can be helpful for debugging. vtkm::cont::GetStackTrace() takes an optional argument for the number of stack frames to skip. Reporting the stack trace is not available on all platforms. On platforms that are not supported, a simple string reporting that the stack trace is unavailable is returned.

std::string vtkm::cont::GetStackTrace(vtkm::Int32 skip = 0)

Returns a stacktrace on supported platforms.

Argument is the number of frames to skip (GetStackTrace and below are already skipped).

Example 4.41 Helper functions provided for logging.
 1template<typename T>
 2void DoSomething(T&& x)
 3{
 4  VTKM_LOG_S(CustomLogLevel,
 5             "Doing something with type " << vtkm::cont::TypeToString<T>());
 6
 7  vtkm::Id arraySize = 100000 * sizeof(T);
 8  VTKM_LOG_S(CustomLogLevel,
 9             "Size of array is " << vtkm::cont::GetHumanReadableSize(arraySize));
10  VTKM_LOG_S(CustomLogLevel,
11             "More precisely it is " << vtkm::cont::GetSizeString(arraySize, 4));
12
13  VTKM_LOG_S(CustomLogLevel, "Stack location: " << vtkm::cont::GetStackTrace());