Skip to content

Commit a5c7a39

Browse files
committed
printk/index: Printk index feature documentation
Document the printk index feature. The primary motivation is to explain that it is not creating KABI from particular printk() calls. Acked-by: Sergey Senozhatsky <senozhatsky@chromium.org> Reviewed-by: Chris Down <chris@chrisdown.name> Signed-off-by: Petr Mladek <pmladek@suse.com>
1 parent e11da67 commit a5c7a39

File tree

3 files changed

+139
-0
lines changed

3 files changed

+139
-0
lines changed

Documentation/core-api/index.rst

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ it.
2020
workqueue
2121
printk-basics
2222
printk-formats
23+
printk-index
2324
symbol-namespaces
2425

2526
Data structures and low-level utilities
Lines changed: 137 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,137 @@
1+
.. SPDX-License-Identifier: GPL-2.0
2+
3+
============
4+
Printk Index
5+
============
6+
7+
There are many ways how to monitor the state of the system. One important
8+
source of information is the system log. It provides a lot of information,
9+
including more or less important warnings and error messages.
10+
11+
There are monitoring tools that filter and take action based on messages
12+
logged.
13+
14+
The kernel messages are evolving together with the code. As a result,
15+
particular kernel messages are not KABI and never will be!
16+
17+
It is a huge challenge for maintaining the system log monitors. It requires
18+
knowing what messages were updated in a particular kernel version and why.
19+
Finding these changes in the sources would require non-trivial parsers.
20+
Also it would require matching the sources with the binary kernel which
21+
is not always trivial. Various changes might be backported. Various kernel
22+
versions might be used on different monitored systems.
23+
24+
This is where the printk index feature might become useful. It provides
25+
a dump of printk formats used all over the source code used for the kernel
26+
and modules on the running system. It is accessible at runtime via debugfs.
27+
28+
The printk index helps to find changes in the message formats. Also it helps
29+
to track the strings back to the kernel sources and the related commit.
30+
31+
32+
User Interface
33+
==============
34+
35+
The index of printk formats are split in into separate files. The files are
36+
named according to the binaries where the printk formats are built-in. There
37+
is always "vmlinux" and optionally also modules, for example::
38+
39+
/sys/kernel/debug/printk/index/vmlinux
40+
/sys/kernel/debug/printk/index/ext4
41+
/sys/kernel/debug/printk/index/scsi_mod
42+
43+
Note that only loaded modules are shown. Also printk formats from a module
44+
might appear in "vmlinux" when the module is built-in.
45+
46+
The content is inspired by the dynamic debug interface and looks like::
47+
48+
$> head -1 /sys/kernel/debug/printk/index/vmlinux; shuf -n 5 vmlinux
49+
# <level[,flags]> filename:line function "format"
50+
<5> block/blk-settings.c:661 disk_stack_limits "%s: Warning: Device %s is misaligned\n"
51+
<4> kernel/trace/trace.c:8296 trace_create_file "Could not create tracefs '%s' entry\n"
52+
<6> arch/x86/kernel/hpet.c:144 _hpet_print_config "hpet: %s(%d):\n"
53+
<6> init/do_mounts.c:605 prepare_namespace "Waiting for root device %s...\n"
54+
<6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
55+
56+
, where the meaning is:
57+
58+
- :level: log level value: 0-7 for particular severity, -1 as default,
59+
'c' as continuous line without an explicit log level
60+
- :flags: optional flags: currently only 'c' for KERN_CONT
61+
- :filename\:line: source filename and line number of the related
62+
printk() call. Note that there are many wrappers, for example,
63+
pr_warn(), pr_warn_once(), dev_warn().
64+
- :function: function name where the printk() call is used.
65+
- :format: format string
66+
67+
The extra information makes it a bit harder to find differences
68+
between various kernels. Especially the line number might change
69+
very often. On the other hand, it helps a lot to confirm that
70+
it is the same string or find the commit that is responsible
71+
for eventual changes.
72+
73+
74+
printk() Is Not a Stable KABI
75+
=============================
76+
77+
Several developers are afraid that exporting all these implementation
78+
details into the user space will transform particular printk() calls
79+
into KABI.
80+
81+
But it is exactly the opposite. printk() calls must _not_ be KABI.
82+
And the printk index helps user space tools to deal with this.
83+
84+
85+
Subsystem specific printk wrappers
86+
==================================
87+
88+
The printk index is generated using extra metadata that are stored in
89+
a dedicated .elf section ".printk_index". It is achieved using macro
90+
wrappers doing __printk_index_emit() together with the real printk()
91+
call. The same technique is used also for the metadata used by
92+
the dynamic debug feature.
93+
94+
The metadata are stored for a particular message only when it is printed
95+
using these special wrappers. It is implemented for the commonly
96+
used printk() calls, including, for example, pr_warn(), or pr_once().
97+
98+
Additional changes are necessary for various subsystem specific wrappers
99+
that call the original printk() via a common helper function. These needs
100+
their own wrappers adding __printk_index_emit().
101+
102+
Only few subsystem specific wrappers have been updated so far,
103+
for example, dev_printk(). As a result, the printk formats from
104+
some subsystes can be missing in the printk index.
105+
106+
107+
Subsystem specific prefix
108+
=========================
109+
110+
The macro pr_fmt() macro allows to define a prefix that is printed
111+
before the string generated by the related printk() calls.
112+
113+
Subsystem specific wrappers usually add even more complicated
114+
prefixes.
115+
116+
These prefixes can be stored into the printk index metadata
117+
by an optional parameter of __printk_index_emit(). The debugfs
118+
interface might then show the printk formats including these prefixes.
119+
For example, drivers/acpi/osl.c contains::
120+
121+
#define pr_fmt(fmt) "ACPI: OSL: " fmt
122+
123+
static int __init acpi_no_auto_serialize_setup(char *str)
124+
{
125+
acpi_gbl_auto_serialize_methods = FALSE;
126+
pr_info("Auto-serialization disabled\n");
127+
128+
return 1;
129+
}
130+
131+
This results in the following printk index entry::
132+
133+
<6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
134+
135+
It helps matching messages from the real log with printk index.
136+
Then the source file name, line number, and function name can
137+
be used to match the string with the source code.

MAINTAINERS

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15585,6 +15585,7 @@ F: kernel/printk/
1558515585
PRINTK INDEXING
1558615586
R: Chris Down <chris@chrisdown.name>
1558715587
S: Maintained
15588+
F: Documentation/core-api/printk-index.rst
1558815589
F: kernel/printk/index.c
1558915590
K: printk_index
1559015591

0 commit comments

Comments
 (0)