Re: [PATCH] printk/index: Printk index feature documentation

[Chris Down]

Petr Mladek writes:
> Document the printk index feature. The primary motivation is to
> explain that it is not creating KABI from particular printk() calls.
>
> Signed-off-by: Petr Mladek <pmladek@xxxxxxxx>
> Acked-by: Sergey Senozhatsky <senozhatsky@xxxxxxxxxxxx>

This looks great, thanks a lot for spending the time to write this up. Just 
some very minor comments.

Reviewed-by: Chris Down <chris@xxxxxxxxxxxxxx>

> ---
> Changes against RFC[*]:
>
>  + Updated text by feedback from Darrick.
>  + Updated index.rst and MAINTAINERS.
>  + Tested build of the html documentation.
>
> Did not add Sergey's ack because there were some changes.
>
> [*] https://lore.kernel.org/r/20220330145955.GB4384@xxxxxxxxxxxxxxx
>
> Documentation/core-api/index.rst        |   1 +
> Documentation/core-api/printk-index.rst | 136 ++++++++++++++++++++++++
> MAINTAINERS                             |   1 +
> 3 files changed, 138 insertions(+)
> create mode 100644 Documentation/core-api/printk-index.rst
>
> diff --git a/Documentation/core-api/index.rst b/Documentation/core-api/index.rst
> index 972d46a5ddf6..8a3fce1fe582 100644
> --- a/Documentation/core-api/index.rst
> +++ b/Documentation/core-api/index.rst
> @@ -20,6 +20,7 @@ it.
>    workqueue
>    printk-basics
>    printk-formats
> +   printk-index
>    symbol-namespaces
>
> Data structures and low-level utilities
> diff --git a/Documentation/core-api/printk-index.rst b/Documentation/core-api/printk-index.rst
> new file mode 100644
> index 000000000000..0de380b4a67c
> --- /dev/null
> +++ b/Documentation/core-api/printk-index.rst
> @@ -0,0 +1,136 @@
> +.. SPDX-License-Identifier: GPL-2.0
> +
> +============
> +Printk Index
> +============
> +
> +There are many ways how to monitor the state of the system. One important
> +source of information is the system log. It provides a lot of information,
> +including more or less important warnings and error messages.
> +
> +There are monitoring tools that filter and take action based on messages
> +logged.
> +
> +The kernel messages are evolving together with the code. As a result,
> +particular kernel messages are not KABI and never will be!
> +
> +It is a huge challenge for maintaining the system log monitors. It requires
> +knowing what messages were updated in a particular kernel version and why.
> +Finding these changes in the sources would require non-trivial parsers.
> +Also it would require matching the sources with the binary kernel which
> +is not always trivial. Various changes might be backported. Various kernel
> +versions might be used on different monitored systems.
> +
> +This is where the printk index feature might become useful. It provides
> +a dump of printk formats used all over the source code used for the kernel
> +and modules on the running system. It is accessible at runtime via debugfs.
> +
> +The printk index helps to find changes in the message formats. Also it helps
> +to track the strings back to the kernel sources and the related commit.
> +
> +
> +User Interface
> +==============
> +
> +The index of printk formats are split in into separate files. The files are
> +named according to the binaries where the printk formats are built-in. There
> +is always "vmlinux" and optionally also modules, for example::
> +
> +   /sys/kernel/debug/printk/index/vmlinux
> +   /sys/kernel/debug/printk/index/ext4
> +   /sys/kernel/debug/printk/index/scsi_mod
> +
> +Note that only loaded modules are shown. Also printk formats from a module
> +might appear in "vmlinux" when the module is built-in.
> +
> +The content is inspired by the dynamic debug interface and looks like::

s/::/:/

> +
> +   $> head -1 /sys/kernel/debug/printk/index/vmlinux; shuf -n 5 vmlinux
> +   # <level[,flags]> filename:line function "format"
> +   <5> block/blk-settings.c:661 disk_stack_limits "%s: Warning: Device %s is misaligned\n"
> +   <4> kernel/trace/trace.c:8296 trace_create_file "Could not create tracefs '%s' entry\n"
> +   <6> arch/x86/kernel/hpet.c:144 _hpet_print_config "hpet: %s(%d):\n"
> +   <6> init/do_mounts.c:605 prepare_namespace "Waiting for root device %s...\n"
> +   <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
> +
> +, where the meaning is::
> +
> +   - level: log level

Maybe worth noting that level may not be there if we have a KERN_CONT.

> +   - flags: optional flags: currently only 'c' for KERN_CONT
> +   - filename:line: source filename and line number of the related
> +	printk() call. Note that there are many wrappers, for example,
> +	pr_warn(), pr_warn_once(), dev_warn().
> +   - function: function name where the printk() call is used.
> +   - format: format string
> +
> +The extra information makes it a bit harder to find differences
> +between various kernels. Especially the line number might change
> +very often. On the other hand, it helps a lot to confirm that
> +it is the same string or find the commit that is responsible
> +for eventual changes.
> +
> +
> +printk() Is Not a Stable KABI
> +=============================
> +
> +Several developers are afraid that exporting all these implementation
> +details into the user space will transform particular printk() calls
> +into KABI.
> +
> +But it is exactly the opposite. printk() calls must _not_ be KABI.
> +And the printk index helps user space tools to deal with this.
> +
> +
> +Subsystem specific printk wrappers
> +==================================
> +
> +The printk index is generated using extra metadata that are stored in
> +a dedicated .elf section ".printk_index". It is achieved using macro
> +wrappers doing __printk_index_emit() together with the real printk()
> +call. The same technique is used also for the metadata used by
> +the dynamic debug feature.
> +
> +The metadata are stored for a particular message only when it is printed
> +using these special wrappers. It is implemented for the commonly
> +used printk() calls, including, for example, pr_warn(), or pr_once().
> +
> +Additional changes are necessary for various subsystem specific wrappers
> +that call the original printk() via a common helper function. These needs
> +their own wrappers adding __printk_index_emit().
> +
> +Only few subsystem specific wrappers have been updated so far,
> +for example, dev_printk(). As a result, the printk formats from
> +some subsystes can be missing in the printk index.
> +
> +
> +Subsystem specific prefix
> +=========================
> +
> +The macro pr_fmt() macro allows to define a prefix that is printed
> +before the string generated by the related printk() calls.
> +
> +Subsystem specific wrappers usually add even more complicated
> +prefixes.
> +
> +These prefixes can be stored into the printk index metadata
> +by an optional parameter of __printk_index_emit(). The debugfs
> +interface might then show the printk formats including these prefixes.
> +For example, drivers/acpi/osl.c contains::
> +
> +  #define pr_fmt(fmt) "ACPI: OSL: " fmt
> +
> +  static int __init acpi_no_auto_serialize_setup(char *str)
> +  {
> +	acpi_gbl_auto_serialize_methods = FALSE;
> +	pr_info("Auto-serialization disabled\n");
> +
> +	return 1;
> +  }
> +
> +This results in the following printk index entry::
> +
> +  <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
> +
> +It helps matching messages from the real log with printk index.
> +Then the source file name, line number, and function name can
> +be used to match the string with the source code.
> diff --git a/MAINTAINERS b/MAINTAINERS
> index fd768d43e048..ad8625130ea9 100644
> --- a/MAINTAINERS
> +++ b/MAINTAINERS
> @@ -15855,6 +15855,7 @@ F:	kernel/printk/
> PRINTK INDEXING
> R:	Chris Down <chris@xxxxxxxxxxxxxx>
> S:	Maintained
> +F:	Documentation/core-api/printk-index.rst
> F:	kernel/printk/index.c
>
> PROC FILESYSTEM
> --
> 2.26.2