dynamic debug

hi Andrew,

thanks for reviewing the last set of patches. In this iteration, I've attempted to simplify the interfaces, and provide a better explanation for the patches.

PROBLEM

Each kernel sub-system seems to have its own way of dealing with debugging statements. Some of these methods include 'dprintk', 'pr_debug', 'dev_debug', 'DEBUGP'. There are also a myriad of ways of enabling these statements. Some require CONFIG_ parameters to be set, some provide /proc interfaces, while others require 'DEBUG' to be set in header files. Most of these methods also require kernel re-compiles in order to set the appropriate knobs.

SOLUTION

I've attempted to standardize how how the kernel deals with debugging statements, both from the user as well as the kernel perspective. Why aren't these debug statements made into printk(KERN_DEBUG), and be done with it? The problem here is that 'dprintk', 'pr_debug', etc. were introduced b/c they are often provide too verbose a level of output, could potentially adversly affect system performance if they were always enabled, and they clutter up the system logs.

I've introduced CONFIG_DYNAMIC_PRINTK_DEBUG, which when enabled centralizes control of debugging statements on a per-module basis in one /proc file, currently, <debugfs>/dynamic_printk/modules. When, CONFIG_DYNAMIC_PRINTK_DEBUG, is not set, debugging statements can still be enabled as before, often by defining 'DEBUG' for the proper compilation unit. Thus, this patch set has not affect when CONFIG_DYNAMIC_PRINTK_DEBUG is not set. The rest of the discussion deals with the case where CONFIG_DYNAMIC_PRINTK_DEBUG is set.

INTERFACE - userspace

The file <debugfs>/dynamic_printk/modules is formatted as:

<module_name><enabled/disabled><debug type><level setting><flags><module names>

$cat /sys/kernel/debug/dynamic_printk/modules

uhci_hcd 0 boolean 0
dock 0 boolean 0
mount 0 boolean 0
main 0 boolean 0
driver 0 boolean 0
cpufreq_shared 0 flag 0
CPUFREQ_DEBUG_CORE CPUFREQ_DEBUG_DRIVER CPUFREQ_DEBUG_GOVERNOR acpi_cpufreq freq_table cpufreq_userspace cpufreq

<module_name> : Name of the module in which the debug call resides <enabled/disabled> : whether the the messages are enabled or not <debug type> : types are 'boolean', 'flag', or 'level'. 'boolean' is
is simply on/off. 'Flag' allows different flags to be turned on or off. 'Level' means that all messages above a certain level are enabled.
<level setting> : This the current value if 'flag' or 'level' is set <flags> : names of the flags that can be set if 'flag' type is set <module names> : name of modules in the grouping.

Enable a module:

$echo "enable <module_name>" > dynamic_printk/modules

Disable a module:

$echo "disable <module_name>" > dynamic_printk/modules

To set the level or flag value for type 'level' or 'flag':

$echo "set level=<#> <module_name>" > dynamic_printk/modules

Enable all modules:

$echo "add all" > dynamic_printk/modules

Disable all modules:

$echo "remove all" > dynamic_printk/modules

INTERFACE - kernel

I've tried to make the kernel interface as simple as possible. 'pr_debug()' and 'dev_dbg()' calls remain exactly the same, however the kernel now automatically recognizes these calls, and creates entries in /sys/kernel/debug/dynamic_printk/modules.

For more sophisticated types of debugging i've introduced 1 new interface:

int dynamic_dbg_enabled(type, level, current_level);

'dynamic_dbg_enabled' returns true (1) or false (0), depending on the settings in /sys/kernel/debug/dynamic_printk/modules. This allows printks or even blocks of code to be conditionally executed via:

if (dynamic_dbg_enabled() {
	<code block>;
}

There are 3 possible values for 'type':

'TYPE_BOOLEAN' : this simply means the dynamic_dbg_enabled() is toggled on/off 'TYPE_FLAG' : this allows the dynamic_dbg_enabled() to be associated with
a set of flags and a 'call flag'. The 'call flag' is associated with a particular dynamic_dbg_enabled() call, and if the 'call flag' is set in the flag set it return true o.t. false.
'TYPE_LEVEL' : Associates dynamic_dbg_enabled() with global level and a specific
level for the call site. If the (specific level) < (global level) returns true o.t. false.

Its probably best explained with an example (taken from cpufreq.c):

-#define dprintk(msg...) cpufreq_debug_printk(CPUFREQ_DEBUG_DRIVER, "gx-suspmod", msg) +#define dprintk(msg...) do { \
+ if (dynamic_dbg_enabled(TYPE_FLAG, CPUFREQ_DEBUG_DRIVER, cpufreq_debug)) \
+ cpufreq_debug_printk(CPUFREQ_DEBUG_DRIVER, "gx-suspmod", msg); \
+ } while (0)

So, now instead of calling cpufreq_debug_printk directly, we've made it contingent on 'dynamic_dbg_enabled()' call. The 'cpufreq' driver uses 'TYPE_FLAG', which allows invidual bits of flags to control the debugging level for cpufreq driver. The use of dynamic_dbg_enabled() automatically creates an entry in the /sys/kernel/debug/dynamic_printk/modules file, as was the case for 'pr_debug()' and 'dev_dbg()'. 'CPUFREQ_DEBUG_DRIVER' specifies the flag bit that needs to be set in order for cpufreq_debug_printk() to return true.

By default, each dynamic_dbg_enabled() call implicity, sets its module, and its debug type. However, modules can override these implicit types by including a few special #define. For, example for cpufreq, the #defines are:

#undef DYNAMIC_DEBUG_NUM_FLAGS
#define DYNAMIC_DEBUG_NUM_FLAGS "3"

#undef DYNAMIC_DEBUG_FLAG_NAMES
#define DYNAMIC_DEBUG_FLAG_NAMES "CPUFREQ_DEBUG_CORE,CPUFREQ_DEBUG_DRIVER,CPUFREQ_DEBUG_GOVERNOR"

#undef DYNAMIC_DEBUG_TYPE
#define DYNAMIC_DEBUG_TYPE "2"

#undef DYNAMIC_DEBUG_MODNAME
#define DYNAMIC_DEBUG_MODNAME "cpufreq_shared"

'DYNAMIC_DEBUG_NUM_FLAGS' : number of flags the module has 'DYNAMIC_DEBUG_FLAG_NAMES' : the names of these flags 'DYNAMIC_DEBUG_TYPE' : can be one of 'TYPE_BOOLEAN or 0', 'TYPE_LEVEL or 1', or
'TYPE_FLAG or 2'
'DYNAMIC_DEBUG_MODNAME' : overrides the default module name, for example to allow
different compilation units to share the same flags.

IMPLEMENTATION

The set of modules that can be dynamically controlled via /sys/kernel/debug/dynamic_printk/modules are created on the fly during bootup. Meta-data is implicity associated with each 'pr_debug()', dev_dbg()' and 'dynamic_debug_enabled()' call site. This meta-data includes the module name and the debug type, (one of boolean, flag, or level). The meta-data is contained in a special "verbose" section of the kernel binary. So this section is essentially scanned during bootup or module load/unload, and an internal kernel hash data structure is created. The "verbose" section is then freed. Thus, although the text size increases with this compile option (~2% in my testing), the runtime size remains the same.

The internal hash table that is created is a hash on the module name. The hash table has 32 buckets. Each bucket has a per-cpu 'int' type associated with it. This 'int' has bit 'n' set, if any module which hashes into the bucket row 'n' is enabled. Thus, when debugging is disabled we are testing a bit in a per-cpu integer. Only, if the bit is enabled do we make a function call. This function call checks to see if the level or flags are appropriately set and that the module is enabled before outputing the printk (in the case of pr_debug() or dev_dbg()), or returning true or false, in the case of 'dynamic_debug_enabled()'.

TODO

-allow modules to be set by using flag names
-fix up parsing in /proc file
-possibly move control file out of debugfs
-convert more modules to the infrastructure

Hi.

I propose to replace 'Pr_debug', 'Dev_debug', and 'DEBUGP' with
kernel markers. SystemTap is used for the output of the log.

I propose to make it to the function to output only specified
kernel markers as a log and the function in a word like LTTng of a simple version by using the framework and kernel markers of ftrace if the log is output by using debugfs.

Thank you,

--
Takashi Nishiie

perhaps markers could be used to replace 'pr_debug', 'dev_debug', and 'DEBUGP' but i have yet to see patches for that...

In a number of ways, these dynamic debug patches differ from markers:

-Markers have a pre-defined format string and arguments list, whereas debug statements have a 'printk' format
-these patches are built around per-module debugging, which is largely implicit whereas markers explicitly define sets of related markers.
-these patches allow 'flags' and levels to be set per-module, markers do not have this concept.
-these patches are tied into a procfs control file, whereas markers are controlled by kernel modules which register handlers.

These two patchsets are really addressing different problems afaict.

thanks,

-Jason

That would be a nice goal, but how are you going to handle dynamic strings?

It might be a nice long term goal, but this patchset is a much simpler approach for this time, not requiring systemtap or any external tool-set to be installed and set up properly.

thanks,

greg k-h

...which would make them unusable. You down want people trying to debug kernel problems install/configure systemtap...

(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Six fields

But only four fields here.

I assume the remaining two are optional?

If so, what happens if "flags" is empty and "module names" is non-empty? That's unparseable.

How about:

echo 1 > dynamic_printk/modules/module_name/enable

echo 0 > dynamic_printk/modules/module_name/disable

echo # > dynamic_printk/modules/module_name/level

remove this

remove this

?

By what means is the module_name identified in dynamic_dbg_enabled()? Implicitly THIS_MODULE?

If so, what happens if the "module" is linked into vmlinux? Or if we're using this for, say, the CPU scheduler?