Back to home page

OSCL-LXR

 
 

    


0001 .. SPDX-License-Identifier: GPL-2.0
0002 
0003 ============
0004 Printk Index
0005 ============
0006 
0007 There are many ways how to monitor the state of the system. One important
0008 source of information is the system log. It provides a lot of information,
0009 including more or less important warnings and error messages.
0010 
0011 There are monitoring tools that filter and take action based on messages
0012 logged.
0013 
0014 The kernel messages are evolving together with the code. As a result,
0015 particular kernel messages are not KABI and never will be!
0016 
0017 It is a huge challenge for maintaining the system log monitors. It requires
0018 knowing what messages were updated in a particular kernel version and why.
0019 Finding these changes in the sources would require non-trivial parsers.
0020 Also it would require matching the sources with the binary kernel which
0021 is not always trivial. Various changes might be backported. Various kernel
0022 versions might be used on different monitored systems.
0023 
0024 This is where the printk index feature might become useful. It provides
0025 a dump of printk formats used all over the source code used for the kernel
0026 and modules on the running system. It is accessible at runtime via debugfs.
0027 
0028 The printk index helps to find changes in the message formats. Also it helps
0029 to track the strings back to the kernel sources and the related commit.
0030 
0031 
0032 User Interface
0033 ==============
0034 
0035 The index of printk formats are split in into separate files. The files are
0036 named according to the binaries where the printk formats are built-in. There
0037 is always "vmlinux" and optionally also modules, for example::
0038 
0039    /sys/kernel/debug/printk/index/vmlinux
0040    /sys/kernel/debug/printk/index/ext4
0041    /sys/kernel/debug/printk/index/scsi_mod
0042 
0043 Note that only loaded modules are shown. Also printk formats from a module
0044 might appear in "vmlinux" when the module is built-in.
0045 
0046 The content is inspired by the dynamic debug interface and looks like::
0047 
0048    $> head -1 /sys/kernel/debug/printk/index/vmlinux; shuf -n 5 vmlinux
0049    # <level[,flags]> filename:line function "format"
0050    <5> block/blk-settings.c:661 disk_stack_limits "%s: Warning: Device %s is misaligned\n"
0051    <4> kernel/trace/trace.c:8296 trace_create_file "Could not create tracefs '%s' entry\n"
0052    <6> arch/x86/kernel/hpet.c:144 _hpet_print_config "hpet: %s(%d):\n"
0053    <6> init/do_mounts.c:605 prepare_namespace "Waiting for root device %s...\n"
0054    <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
0055 
0056 , where the meaning is:
0057 
0058    - :level: log level value: 0-7 for particular severity, -1 as default,
0059         'c' as continuous line without an explicit log level
0060    - :flags: optional flags: currently only 'c' for KERN_CONT
0061    - :filename\:line: source filename and line number of the related
0062         printk() call. Note that there are many wrappers, for example,
0063         pr_warn(), pr_warn_once(), dev_warn().
0064    - :function: function name where the printk() call is used.
0065    - :format: format string
0066 
0067 The extra information makes it a bit harder to find differences
0068 between various kernels. Especially the line number might change
0069 very often. On the other hand, it helps a lot to confirm that
0070 it is the same string or find the commit that is responsible
0071 for eventual changes.
0072 
0073 
0074 printk() Is Not a Stable KABI
0075 =============================
0076 
0077 Several developers are afraid that exporting all these implementation
0078 details into the user space will transform particular printk() calls
0079 into KABI.
0080 
0081 But it is exactly the opposite. printk() calls must _not_ be KABI.
0082 And the printk index helps user space tools to deal with this.
0083 
0084 
0085 Subsystem specific printk wrappers
0086 ==================================
0087 
0088 The printk index is generated using extra metadata that are stored in
0089 a dedicated .elf section ".printk_index". It is achieved using macro
0090 wrappers doing __printk_index_emit() together with the real printk()
0091 call. The same technique is used also for the metadata used by
0092 the dynamic debug feature.
0093 
0094 The metadata are stored for a particular message only when it is printed
0095 using these special wrappers. It is implemented for the commonly
0096 used printk() calls, including, for example, pr_warn(), or pr_once().
0097 
0098 Additional changes are necessary for various subsystem specific wrappers
0099 that call the original printk() via a common helper function. These needs
0100 their own wrappers adding __printk_index_emit().
0101 
0102 Only few subsystem specific wrappers have been updated so far,
0103 for example, dev_printk(). As a result, the printk formats from
0104 some subsystes can be missing in the printk index.
0105 
0106 
0107 Subsystem specific prefix
0108 =========================
0109 
0110 The macro pr_fmt() macro allows to define a prefix that is printed
0111 before the string generated by the related printk() calls.
0112 
0113 Subsystem specific wrappers usually add even more complicated
0114 prefixes.
0115 
0116 These prefixes can be stored into the printk index metadata
0117 by an optional parameter of __printk_index_emit(). The debugfs
0118 interface might then show the printk formats including these prefixes.
0119 For example, drivers/acpi/osl.c contains::
0120 
0121   #define pr_fmt(fmt) "ACPI: OSL: " fmt
0122 
0123   static int __init acpi_no_auto_serialize_setup(char *str)
0124   {
0125         acpi_gbl_auto_serialize_methods = FALSE;
0126         pr_info("Auto-serialization disabled\n");
0127 
0128         return 1;
0129   }
0130 
0131 This results in the following printk index entry::
0132 
0133   <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
0134 
0135 It helps matching messages from the real log with printk index.
0136 Then the source file name, line number, and function name can
0137 be used to match the string with the source code.