Received: by 2002:a05:6a10:2726:0:0:0:0 with SMTP id ib38csp955164pxb; Wed, 6 Apr 2022 05:14:57 -0700 (PDT) X-Google-Smtp-Source: ABdhPJzDC8SQfNdRkTVzVtWU9E/41hcbBF2lAljrVJHQnljAbFlUiUp+JLBTmZF4vk7McVa3lSdC X-Received: by 2002:a17:90b:1b01:b0:1c7:79d5:696 with SMTP id nu1-20020a17090b1b0100b001c779d50696mr9445430pjb.11.1649247296964; Wed, 06 Apr 2022 05:14:56 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1649247296; cv=none; d=google.com; s=arc-20160816; b=nysNJWtDTZsih8K9awLZUHhekUwX+r6nj2i/91bW81XNvmxKIb/+KOMY5Ykgfz40mG QvMXZtifWar+JCv4AY61ur0HLEVedQEDawxp3J8vtl2ZhMd6JQyG4eKWg9VdCHfOgXn6 fxhqyOD7MY0USvfnKNt1663B3XMGbwDNEeKsSlZkSQ46kQZCgt+IxsG+/+YtfgvVp85R 0LiU5j8b5aCX43B81uJHaGZfD574hLETR2nd/SGWv91bLPxagfrDwo0DOJYvmK9gLqEy mfrPrvxnTSz6lK77NoJl1vJlx2eP+Z9htXyxx+E453MN40L20fYhlu+Oq4xsw6shbmty fcTg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:content-transfer-encoding:mime-version :message-id:date:subject:cc:to:from:dkim-signature; bh=FG5W+X6iauWFlicsUD/KFyqhn8yb4pSpN2a+NvHudUE=; b=t4IWKYvuw0gIXzKEdPvJ+vp/gXPwPC8fbl/04x5T175r+QpO0VbWTuxpAmSDkjjAT5 iMClVvud/g3Ocwv1sBWbD3cVly4gmddU7a0ttu0f+9gJSrc3tGXXXHw1npbxxg1og+lb hFmNjNceoDbkw5FzrtB/Xy+BHk9uzpDhfqVMn7tCopFfh1u0jFWX0Whcv9yaSRYo/3HX ehnUtSryMzBKi8gg/F+2LdwG4OpO2cdt0NnSM1J0tSAVJyW/4eSHg0Jz/uwPY2v8IwEw OxoRqv+5Lyeuup053qwUtgiP8/FdwkWj5Ey3qlSYl97MEQYL5fEgARKqQ/1i8SDwONin A0ag== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@suse.com header.s=susede1 header.b=U+sas9du; spf=softfail (google.com: domain of transitioning linux-kernel-owner@vger.kernel.org does not designate 23.128.96.19 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=QUARANTINE sp=QUARANTINE dis=NONE) header.from=suse.com Return-Path: Received: from lindbergh.monkeyblade.net (lindbergh.monkeyblade.net. [23.128.96.19]) by mx.google.com with ESMTPS id k11-20020a63d84b000000b0038618399001si15584197pgj.26.2022.04.06.05.14.56 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 06 Apr 2022 05:14:56 -0700 (PDT) Received-SPF: softfail (google.com: domain of transitioning linux-kernel-owner@vger.kernel.org does not designate 23.128.96.19 as permitted sender) client-ip=23.128.96.19; Authentication-Results: mx.google.com; dkim=pass header.i=@suse.com header.s=susede1 header.b=U+sas9du; spf=softfail (google.com: domain of transitioning linux-kernel-owner@vger.kernel.org does not designate 23.128.96.19 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=QUARANTINE sp=QUARANTINE dis=NONE) header.from=suse.com Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by lindbergh.monkeyblade.net (Postfix) with ESMTP id C45E4517A55; Wed, 6 Apr 2022 03:54:27 -0700 (PDT) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1580554AbiDEXee (ORCPT + 99 others); Tue, 5 Apr 2022 19:34:34 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:51458 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241488AbiDEMp0 (ORCPT ); Tue, 5 Apr 2022 08:45:26 -0400 Received: from smtp-out2.suse.de (smtp-out2.suse.de [195.135.220.29]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 9D4E52611E for ; Tue, 5 Apr 2022 04:48:45 -0700 (PDT) Received: from relay2.suse.de (relay2.suse.de [149.44.160.134]) by smtp-out2.suse.de (Postfix) with ESMTP id 1079C1F745; Tue, 5 Apr 2022 11:48:44 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=suse.com; s=susede1; t=1649159324; h=from:from:reply-to:date:date:message-id:message-id:to:to:cc:cc: mime-version:mime-version: content-transfer-encoding:content-transfer-encoding; bh=FG5W+X6iauWFlicsUD/KFyqhn8yb4pSpN2a+NvHudUE=; b=U+sas9du3g1kGret/F44LxtQJ9gs5N95bX2kvPi+VTiTK5WxnIBohb43yoKrqojPmNWGy1 fuSEsvxN3kVlKJssR0JWHyLEUdciVUpPSmWHH0P0v5nkYidRj50rvmG79EsdXgCXjJv+0F 5muU73su1r/MZR1LNkD2GBsQqPSnDUA= Received: from alley.suse.cz (unknown [10.100.224.162]) by relay2.suse.de (Postfix) with ESMTP id 74F23A3BA6; Tue, 5 Apr 2022 11:48:43 +0000 (UTC) From: Petr Mladek To: Chris Down Cc: John Ogness , Sergey Senozhatsky , Steven Rostedt , Dave Chinner , "Darrick J . Wong" , linux-kernel@vger.kernel.org, Petr Mladek Subject: [PATCH] printk/index: Printk index feature documentation Date: Tue, 5 Apr 2022 13:48:29 +0200 Message-Id: <20220405114829.31837-1-pmladek@suse.com> X-Mailer: git-send-email 2.26.2 MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Spam-Status: No, score=-2.0 required=5.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS, MAILING_LIST_MULTI,RDNS_NONE,SPF_HELO_NONE,T_SCC_BODY_TEXT_LINE autolearn=no autolearn_force=no version=3.4.6 X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on lindbergh.monkeyblade.net Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 Acked-by: Sergey Senozhatsky --- 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 + # 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 S: Maintained +F: Documentation/core-api/printk-index.rst F: kernel/printk/index.c PROC FILESYSTEM -- 2.26.2