HowTo: Controlling debug log verbosity with RmMsg

[mtijanic]

As you might have noticed in the codebase, we have a lot of NV_PRINTF() calls with various log levels, but very few of those make their way into dmesg by default.

When debugging issues it is often very helpful to up the log verbosity. nvidia.ko does this via the RmMsg global variable. The simplest and most often used value for RmMsg is ":" which enables all prints unconditionally.

The easiest way to set it is as a charp module param NVreg_RmMsg. For example:

sudo insmod nvidia.ko NVreg_RmMsg=":"
sudo modprobe nvidia NVreg_RmMsg=":"

or, in an /etc/modprobe.d/ configuration file:

options nvidia NVreg_RmMsg=":"

You can also change it at runtime using this tool.

The variable is parsed every time a print call is made, so any other way of modifying the memory (such as through a debugger) will also work. There is also a sequence of ioctl() calls that can modify it, but we'll cover that in a different post later.

The formal definition for RmMsg rules format is:

    rule = [!][filename|function][:startline][-endline][@level][^prefix]
    Format = rule[,rule]

Or, in other words, it's a comma-separated list of rules. Rules are parsed in order and in case of conflict the later ones override earlier ones.

• ! - makes this rule an exclusion rule instead of an inclusion rule
• file - a string matching all or part of the filename
• function - a string matching all or part of a function
• startline - a single line number or the start of a line range with endline
• endline - the end of an line range
• level - suppress messages < level. Level is the integer value for LEVEL_XXX constants.
• prefix - Modify the default message prefix (NVRM: <function-name>:)
  • '*' Enable all
  • 'n' Enable NVRM (default)
  • 'c' Enable filename
  • 'l' Enable line number
  • 'f' Enable function (default)
  • 't' Enable timestamp
  • Using a CAPITAL letter will disable printing of that prefix.
    • To suppress the default prefix, set "^NF"

Few examples:

• "gsp" - Enable any GSP related printf by substring match
• "kernel_gsp.c" - enable all printfs in kernel_gsp.c
• "_kgspProcessRpcEvent" - enable all printfs in function _kgspProcessRpcEvent
• "!_kgspProcessRpcEvent" - disable all printfs in function _kgspProcessRpcEvent
• "kernel_gsp.c:150" - enable printf on line 150 of kernel_gsp.c
• "kernel_gsp.c:100-200" - enable printf on lines 100-200 in kernel_gsp.c
• "kernel_gsp.c:100-200,!kernel_gsp.c:125" - same but disable printf on line 125
• "gsp^*" - enable verbose prefix for all gsp commands
• "rmapi^t" - enable timestamps for all RM API prints.
• ":" - enable all printfs (very noisy)
• "!" - disable all printfs (not recommended)
• "^*" - enable verbose prefix for all printfs

The rule checks are implemented in nvDbgRmMsgCheck().

When submitting bug reports, generally having more prints is better, so ":" is often the best option. But please be aware that the kernel message log buffer is limited and very spammy prints can fill it up and make it drop more useful earlier ones. If using ":" it might be a good idea to increase the buffer size.

[derpsteb]

Thanks a lot for this very informative post.
I just made a curious observation related to this: I am enabling all debug prints with modprobe nvidia NVreg_RmMsg=":" like you suggest. This works fine in a standard VM. When I run the vectorAdd example I can see lots of output in dmesg during execution.

However, when I turn on confidential computing and start a confidential VM (launch script: I am changing docc to false and setting the GPU's CC mode from devtools to off) I see some output from the kernel modules during boot, but absolutely nothing during execution of the example.

Any idea what could be up here?

[mtijanic]

Here is a tiny tool that will let you change RmMsg values at runtime without a driver reload. This only applies to new messages; any messages that were already discarded due to filtering are lost.

https://gist.github.com/mtijanic/32b077542b7e56dc603074115fcaea75

[whygyc]

Thank you very much for the tool; it works great!

As an addition:

The latest LEVEL_XXX values can be found here:

open-gpu-kernel-modules/src/nvidia/inc/libraries/utils/nvprintf_level.h

Lines 27 to 45 in ed4be64

	/// @defgroup NV_PRINTF_LEVELS Printf verbosity levels
	/// @{
	/// @brief Prints at this level are discarded
	#define LEVEL_SILENT 0x0
	/// @brief Verbose debug logging level (e.g. signaling function entry)
	#define LEVEL_INFO 0x1
	/// @brief Standard debug logging level (e.g. Illegal ctrcall call)
	#define LEVEL_NOTICE 0x2
	/// @brief Warning logging level (e.g. feature not supported)
	#define LEVEL_WARNING 0x3
	/// @brief Error logging level (e.g. resource allocation failed)
	#define LEVEL_ERROR 0x4
	/// @brief Recoverable HW error (e.g. RC events)
	#define LEVEL_HW_ERROR 0x5
	/// @brief Unrecoverable error (e.g. Bus timeout)
	#define LEVEL_FATAL 0x6
	/// @}
	#define NV_LEVEL_MAX LEVEL_FATAL

Using your tool, specifying @1 enables all logs at the info level and above:

./rmmsg "@1"

To clear the log configuration and revert to the default (disabling extra log prints):

./rmmsg ""