% -*- latex -*-

\chapter{Logging}
\label{chap:Logging}

\index{logging|(}

\VTKm features a logging system that allows status updates and timing.
\VTKm uses the loguru project\index{loguru} to provide runtime logging facilities.%
\footnote{
  A sample of the log output can be found at \url{https://gitlab.kitware.com/snippets/427}.
}
Logging is enabled by setting the CMake variable \cmakevar{VTKm\_ENABLE\_LOGGING}.
When this flag is enabled, any messages logged to the Info, Warn, Error, and Fatal levels are printed to stderr by default.

\section{Initializing Logging}
\label{sec:InitLogging}

\index{logging!initialization|(}

Additional logging features are enabled by calling \vtkmcont{Initialize} as described in Chapter \ref{chap:Initialization}.
Although calling \textidentifier{Initialize} is not strictly necessary for output messages, initialization adds the following features.

\begin{itemize}
\item
  Set human-readable names for the log levels in the output.
\item
  Allow the stderr logging level to be set at runtime by passing a \textcode{-v [level]} argument to the executable (if provided).
\item
  Name the main thread.
\item
  Print a preamble with details of the program's startup (arguments, etc).
\item
  Install signal handlers to automatically print stack traces and error contexts (Linux only) on crashes.
\end{itemize}

Example \ref{ex:InitializeLogging} in the following section provides an example of initializing with additional logging setup.

The logging implementation is thread-safe.
\index{thread name}
When working in a multithreaded environment, each thread may be assigned a human-readable name using \vtkmcont{SetThreadName} (which can later be retrieved with \vtkmcont{GetThreadName}.
This name will appear in the log output so that per-thread messages can be easily tracked.

\index{logging!initialization|)}

\section{Logging Levels}
\label{sec:LoggingLevels}

\index{logging!levels|(}

The logging in \VTKm 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.

\begin{commonerrors}
  All logging levels are assigned a number, and logging levels with a higher precedence actually have a smaller number.
\end{commonerrors}

All logging levels are listed in the \vtkmcont{LogLevel} enum.
The available logging levels, in order of precedence, are as follows.

\begin{description}
\item[\classmember{LogLevel}{Off}]
  A placeholder used to silence all logging.
\item[\classmember{LogLevel}{Fatal}]
  Fatal errors that should abort execution.
\item[\classmember{LogLevel}{Error}]
  Important but non-fatal errors, such as device fail-over.
\item[\classmember{LogLevel}{Warn}]
  Less important user errors, such as out-of-bounds parameters.
\item[\classmember{LogLevel}{Info}]
  Information messages (detected hardware, etc) and temporary debugging output.
\item[\classmember{LogLevel}{UserFirst}]
  The first in a range of logging levels reserved for code that uses \VTKm.
  Internal \VTKm code will not log on these levels but will report these logs.
\item[\classmember{LogLevel}{UserLast}]
  The last in a range of logging levels reserved for code that uses \VTKm.
\item[\classmember{LogLevel}{Perf}]
  General timing data and algorithm flow information, such as filter execution, worklet dispatches, and device algorithm calls.
\item[\classmember{LogLevel}{MemCont}]
  Host-side resource memory allocations and frees such as \textidentifier{ArrayHandle} control buffers.
\item[\classmember{LogLevel}{MemExec}]
  Device-side resource memory allocations and frees such as \textidentifier{ArrayHandle} device buffers)
\item[\classmember{LogLevel}{MemTransfer}]
  Transferring of data between a host and device.
\item[\classmember{LogLevel}{Cast}]
  Report when a dynamic object is (or is not) resolved via a \textcode{CastAndCall} or other casting method.
\item[\classmember{LogLevel}{UserVerboseFirst}]
  The first in a range of logging levels reserved for code that uses \VTKm.
  Internal \VTKm code will not log on these levels but will report these logs.
  These are used similarly to those in the \classmember*{LogLevel}{UserFirst} range but are at a lower precedence that also includes more verbose reporting from \VTKm.
\item[\classmember{LogLevel}{UserVerboseLast}]
  The last in a range of logging levels reserved for code that uses \VTKm.
\end{description}

When \VTKm outputs an entry in its log, it annotates the message with the logging level.
\VTKm will automatically provide descriptions for all log levels described in \vtkmcont{LogLevel}.
A custom log level can be described by calling the \vtkmcont{SetLogLevelName} function.
(The log name can likewise be retrieved with \vtkmcont{GetLogLevelName}.)

\begin{commonerrors}
  The \textidentifier{SetLogLevelName} function must be called before \vtkmcont{Initialize} to have an effect.
\end{commonerrors}

\begin{commonerrors}
  The descriptions for each log level are only set up if \vtkmcont{Initialize} is called.
  If it is not, then all log levels will be represented with a numerical value.
\end{commonerrors}

If \vtkmcont{Initialize} is called with \textcode{argc}/\textcode{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 \vtkmcont{SetStderrLogLevel}.

\vtkmlisting[ex:InitializeLogging]{Initializing logging.}{InitializeLogging.cxx}

\index{logging!levels|)}

\section{Log Entries}
\label{sec:LogEntries}

Log entries are created with a collection of macros provided in \vtkmheader{vtkm/cont}{Logging.h}.
In addition to basic log entries, \VTKm logging can also provide conditional logging, scope levels of logs, and generate special logs on crashes.

\subsection{Basic Log Entries}

The main logging entry points are the macros \vtkmmacro{VTKM\_LOG\_S} and \vtkmmacro{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.
\vtkmmacro{VTKM\_LOG\_S} takes a single argument with a C++ stream expression (so \textcode{<<} operators can exist in the expression).
\vtkmmacro{VTKM\_LOG\_F} takes a C string as its second argument that has printf-style formatting codes.
The remaining arguments fulfill those codes.

\vtkmlisting{Basic logging.}{BasicLogging.cxx}

\subsection{Conditional Log Entries}

The macros \vtkmmacro{VTKM\_LOG\_IF\_S} \vtkmmacro{VTKM\_LOG\_IF\_F} behave similarly to \vtkmmacro{VTKM\_LOG\_S} and \vtkmmacro{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.

\vtkmlisting{Conditional logging.}{ConditionalLogging.cxx}

\subsection{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.

\begin{commonerrors}
  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~\ref{chap:Timers} for information on more accurate timers.
\end{commonerrors}

Scoped log entries follow the same scoping of your C++ code.
A scoped log can be created with the \vtkmmacro{VTKM\_LOG\_SCOPE} macro.
This macro behaves similarly to \vtkmmacro{VTKM\_LOG\_F} except that it creates a scoped log that starts when \vtkmmacro{VTKM\_LOG\_SCOPE} and ends when the program leaves the given scope.

\vtkmlisting{Scoped logging.}{ScopedLogging.cxx}

It is also common, and typically good code structure, to structure scoped concepts around functions or methods.
Thus, \VTKm provides \vtkmmacro{VTKM\_LOG\_SCOPE\_FUNCTION}.
When placed at the beginning of a function or macro, \vtkmmacro{VTKM\_LOG\_SCOPE\_FUNCTION} will automatically create a scoped log around it.

\vtkmlisting{Scoped logging in a function.}{ScopedFunctionLogging.cxx}

\subsection{Error Context}

The \VTKm logging is capable of capturing some crashes and writing information to the log before the program terminates.
The \vtkmmacro{VTKM\_LOG\_ERROR\_CONTEXT} can be used to record some information that should be reported if an error occurs.
If the program terminates successfully, then information is never recorded to the log.

\vtkmlisting{Providing an error context for logging.}{LoggingErrorContext.cxx}

\section{Helper Functions}

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

\begin{didyouknow}
  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 \VTKm is compiled with logging off.
\end{didyouknow}

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

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

The \vtkmcont{GetStackTrace} function returns a string containing a trace of the stack, which can be helpful for debugging.
\textidentifier{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.

\vtkmlisting{Helper log functions.}{HelperLogFunctions.cxx}

\index{logging|)}
