[PATCH] printk/index: Printk index feature documentation

[PATCH] printk/index: Printk index feature documentation

[Petr Mladek]

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@suse.com>
Acked-by: Sergey Senozhatsky <senozhatsky@chromium.org>
---
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@pathway.suse.cz

 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::
+
+   $> 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
+   - 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@chrisdown.name>
 S:	Maintained
+F:	Documentation/core-api/printk-index.rst
 F:	kernel/printk/index.c
 
 PROC FILESYSTEM
-- 
2.26.2

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@suse.com>
>Acked-by: Sergey Senozhatsky <senozhatsky@chromium.org>

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

Reviewed-by: Chris Down <chris@chrisdown.name>

>---
>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@pathway.suse.cz
>
> 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@chrisdown.name>
> S:	Maintained
>+F:	Documentation/core-api/printk-index.rst
> F:	kernel/printk/index.c
>
> PROC FILESYSTEM
>-- 
>2.26.2
>

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

[Petr Mladek]

On Tue 2022-04-05 13:48:29, Petr Mladek wrote:
> 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@suse.com>
> Acked-by: Sergey Senozhatsky <senozhatsky@chromium.org>

JFYI, the patch has been committed into printk/linux.git,
branch for-5.19.

Best Regards,
Petr

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

[Petr Mladek]

On Tue 2022-04-05 13:22:49, Chris Down wrote:
> 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@suse.com>
> > Acked-by: Sergey Senozhatsky <senozhatsky@chromium.org>
> 
> This looks great, thanks a lot for spending the time to write this up. Just
> some very minor comments.

Ah, I forgot to do the small fixup when pushing. So, I did it now are rebased.

> > --- /dev/null
> > +++ b/Documentation/core-api/printk-index.rst
> > +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/::/:/

The double double dots '::' cause that the following paragraph will be
block quoting. There is only single ':' in the generated html.

> > +   $> 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::

I uses only single double dot here.

> > +   - level: log level
> 
> Maybe worth noting that level may not be there if we have a KERN_CONT.

I added:

   - :level: log level value: 0-7 for particular severity, -1 as default,
	'c' as continuous line without an explicit log level

> > +   - 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

I added few more double dots to generate bold: 'level', 'flags',
'filename:line', etc.

See the updated commit at
https://git.kernel.org/pub/scm/linux/kernel/git/printk/linux.git/commit/?h=for-5.19&id=a5c7a39f508ae1fd3288493b96dd26079bae41bf

Best Regards,
Petr