These two patches are independent, but better-together.
The second is a rather trivial patch that simply allows the developer
to change "/sbin/modprobe" to something else - e.g. the empty string,
so that all request_module() during early boot return -ENOENT early,
without even spawning a usermode helper, needlessly synchronizing with
the initramfs unpacking.
The first patch delegates decompressing the initramfs to a worker
thread, allowing do_initcalls() in main.c to proceed to the device_
and late_ initcalls without waiting for that decompression (and
populating of rootfs) to finish. Obviously, some of those later calls
may rely on the initramfs being available, so I've added
synchronization points in the firmware loader and usermodehelper paths
- there might be other places that would need this, but so far no one
has been able to think of any places I have missed.
There's not much to win if most of the functionality needed during
boot is only available as modules. But systems with a custom-made
.config and initramfs can boot faster, partly due to utilizing more
than one cpu earlier, partly by avoiding known-futile modprobe calls
(which would still trigger synchronization with the initramfs
unpacking, thus eliminating most of the first benefit).
Routing-wise, I hope akpm can handle both patches. Andrew, Luis?
v2 at <https://lore.kernel.org/lkml/[email protected]/>
Changes in v3:
- Make it asynchronous by default, and drop the CONFIG_ knob (Linus) -
the command line parameter escape hatch is still there.
With that change, it doesn't make sense to have wait_for_initramfs()
contain a micro-optimization in the form of an early return when
!initramfs_async.
I've opted to always push the work to the async machinery, but then
just do a wait_for_initramfs() in populate_rootfs when
!initramfs_async.
I did consider changing the name and sense of the command line
parameter to "initramfs_sync", but decided to keep the async, since
that's also the name of the subsystem being used.
- Add A-b, R-b to patch 2.
Rasmus Villemoes (2):
init/initramfs.c: do unpacking asynchronously
modules: add CONFIG_MODPROBE_PATH
.../admin-guide/kernel-parameters.txt | 12 ++++++
drivers/base/firmware_loader/main.c | 2 +
include/linux/initrd.h | 2 +
init/Kconfig | 12 ++++++
init/initramfs.c | 38 ++++++++++++++++++-
init/main.c | 1 +
kernel/kmod.c | 2 +-
kernel/umh.c | 2 +
8 files changed, 69 insertions(+), 2 deletions(-)
--
2.29.2
Most of the boot process doesn't actually need anything from the
initramfs, until of course PID1 is to be executed. So instead of doing
the decompressing and populating of the initramfs synchronously in
populate_rootfs() itself, push that off to a worker thread.
This is primarily motivated by an embedded ppc target, where unpacking
even the rather modest sized initramfs takes 0.6 seconds, which is
long enough that the external watchdog becomes unhappy that it doesn't
get attention soon enough. By doing the initramfs decompression in a
worker thread, we get to do the device_initcalls and hence start
petting the watchdog much sooner.
Normal desktops might benefit as well. On my mostly stock Ubuntu
kernel, my initramfs is a 26M xz-compressed blob, decompressing to
around 126M. That takes almost two seconds:
[ 0.201454] Trying to unpack rootfs image as initramfs...
[ 1.976633] Freeing initrd memory: 29416K
Before this patch, these lines occur consecutively in dmesg. With this
patch, the timestamps on these two lines is roughly the same as above,
but with 172 lines inbetween - so more than one cpu has been kept busy
doing work that would otherwise only happen after the
populate_rootfs() finished.
Should one of the initcalls done after rootfs_initcall time (i.e.,
device_ and late_ initcalls) need something from the initramfs (say, a
kernel module or a firmware blob), it will simply wait for the
initramfs unpacking to be done before proceeding, which should in
theory make this completely safe.
But if some driver pokes around in the filesystem directly and not via
one of the official kernel interfaces (i.e. request_firmware*(),
call_usermodehelper*) that theory may not hold - also, I certainly
might have missed a spot when sprinkling wait_for_initramfs(). So
there is an escape hatch in the form of an initramfs_async= command
line parameter.
Signed-off-by: Rasmus Villemoes <[email protected]>
---
.../admin-guide/kernel-parameters.txt | 12 ++++++
drivers/base/firmware_loader/main.c | 2 +
include/linux/initrd.h | 2 +
init/initramfs.c | 38 ++++++++++++++++++-
init/main.c | 1 +
kernel/umh.c | 2 +
6 files changed, 56 insertions(+), 1 deletion(-)
diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 04545725f187..861374df0414 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -1825,6 +1825,18 @@
initcall functions. Useful for debugging built-in
modules and initcalls.
+ initramfs_async= [KNL]
+ Format: <bool>
+ Default: 1
+ This parameter controls whether the initramfs
+ image is unpacked asynchronously, concurrently
+ with devices being probed and
+ initialized. This should normally just work,
+ but as a debugging aid, one can get the
+ historical behaviour of the initramfs
+ unpacking being completed before device_ and
+ late_ initcalls.
+
initrd= [BOOT] Specify the location of the initial ramdisk
initrdmem= [KNL] Specify a physical address and size from which to
diff --git a/drivers/base/firmware_loader/main.c b/drivers/base/firmware_loader/main.c
index 78355095e00d..4fdb8219cd08 100644
--- a/drivers/base/firmware_loader/main.c
+++ b/drivers/base/firmware_loader/main.c
@@ -15,6 +15,7 @@
#include <linux/kernel_read_file.h>
#include <linux/module.h>
#include <linux/init.h>
+#include <linux/initrd.h>
#include <linux/timer.h>
#include <linux/vmalloc.h>
#include <linux/interrupt.h>
@@ -504,6 +505,7 @@ fw_get_filesystem_firmware(struct device *device, struct fw_priv *fw_priv,
if (!path)
return -ENOMEM;
+ wait_for_initramfs();
for (i = 0; i < ARRAY_SIZE(fw_path); i++) {
size_t file_size = 0;
size_t *file_size_ptr = NULL;
diff --git a/include/linux/initrd.h b/include/linux/initrd.h
index 85c15717af34..1bbe9af48dc3 100644
--- a/include/linux/initrd.h
+++ b/include/linux/initrd.h
@@ -20,8 +20,10 @@ extern void free_initrd_mem(unsigned long, unsigned long);
#ifdef CONFIG_BLK_DEV_INITRD
extern void __init reserve_initrd_mem(void);
+extern void wait_for_initramfs(void);
#else
static inline void __init reserve_initrd_mem(void) {}
+static inline void wait_for_initramfs(void) {}
#endif
extern phys_addr_t phys_initrd_start;
diff --git a/init/initramfs.c b/init/initramfs.c
index d677e8e717f1..af27abc59643 100644
--- a/init/initramfs.c
+++ b/init/initramfs.c
@@ -1,5 +1,6 @@
// SPDX-License-Identifier: GPL-2.0
#include <linux/init.h>
+#include <linux/async.h>
#include <linux/fs.h>
#include <linux/slab.h>
#include <linux/types.h>
@@ -541,6 +542,14 @@ static int __init keepinitrd_setup(char *__unused)
__setup("keepinitrd", keepinitrd_setup);
#endif
+static bool __initdata initramfs_async = true;
+static int __init initramfs_async_setup(char *str)
+{
+ strtobool(str, &initramfs_async);
+ return 1;
+}
+__setup("initramfs_async=", initramfs_async_setup);
+
extern char __initramfs_start[];
extern unsigned long __initramfs_size;
#include <linux/initrd.h>
@@ -658,7 +667,7 @@ static void __init populate_initrd_image(char *err)
}
#endif /* CONFIG_BLK_DEV_RAM */
-static int __init populate_rootfs(void)
+static void __init do_populate_rootfs(void *unused, async_cookie_t cookie)
{
/* Load the built in initramfs */
char *err = unpack_to_rootfs(__initramfs_start, __initramfs_size);
@@ -693,6 +702,33 @@ static int __init populate_rootfs(void)
initrd_end = 0;
flush_delayed_fput();
+}
+
+static ASYNC_DOMAIN_EXCLUSIVE(initramfs_domain);
+static async_cookie_t initramfs_cookie;
+
+void wait_for_initramfs(void)
+{
+ if (!initramfs_cookie) {
+ /*
+ * Something before rootfs_initcall wants to access
+ * the filesystem/initramfs. Probably a bug. Make a
+ * note, avoid deadlocking the machine, and let the
+ * caller's access fail as it used to.
+ */
+ pr_warn_once("wait_for_initramfs() called before rootfs_initcalls\n");
+ return;
+ }
+ async_synchronize_cookie_domain(initramfs_cookie + 1, &initramfs_domain);
+}
+EXPORT_SYMBOL_GPL(wait_for_initramfs);
+
+static int __init populate_rootfs(void)
+{
+ initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
+ &initramfs_domain);
+ if (!initramfs_async)
+ wait_for_initramfs();
return 0;
}
rootfs_initcall(populate_rootfs);
diff --git a/init/main.c b/init/main.c
index 53b278845b88..64253b181a84 100644
--- a/init/main.c
+++ b/init/main.c
@@ -1538,6 +1538,7 @@ static noinline void __init kernel_init_freeable(void)
kunit_run_all_tests();
+ wait_for_initramfs();
console_on_rootfs();
/*
diff --git a/kernel/umh.c b/kernel/umh.c
index 3f646613a9d3..61f6b82c354b 100644
--- a/kernel/umh.c
+++ b/kernel/umh.c
@@ -27,6 +27,7 @@
#include <linux/ptrace.h>
#include <linux/async.h>
#include <linux/uaccess.h>
+#include <linux/initrd.h>
#include <trace/events/module.h>
@@ -107,6 +108,7 @@ static int call_usermodehelper_exec_async(void *data)
commit_creds(new);
+ wait_for_initramfs();
retval = kernel_execve(sub_info->path,
(const char *const *)sub_info->argv,
(const char *const *)sub_info->envp);
--
2.29.2
Allow the developer to specifiy the initial value of the
modprobe_path[] string. This can be used to set it to the empty string
initially, thus effectively disabling request_module() during early
boot until userspace writes a new value via the
/proc/sys/kernel/modprobe interface. [1]
When building a custom kernel (often for an embedded target), it's
normal to build everything into the kernel that is needed for booting,
and indeed the initramfs often contains no modules at all, so every
such request_module() done before userspace init has mounted the real
rootfs is a waste of time.
This is particularly useful when combined with the previous patch,
which made the initramfs unpacking asynchronous - for that to work, it
had to make any usermodehelper call wait for the unpacking to finish
before attempting to invoke the userspace helper. By eliminating all
such (known-to-be-futile) calls of usermodehelper, the initramfs
unpacking and the {device,late}_initcalls can proceed in parallel for
much longer.
For a relatively slow ppc board I'm working on, the two patches
combined lead to 0.2s faster boot - but more importantly, the fact
that the initramfs unpacking proceeds completely in the background
while devices get probed means I get to handle the gpio watchdog in
time without getting reset.
[1] __request_module() already has an early -ENOENT return when
modprobe_path is the empty string.
Reviewed-by: Greg Kroah-Hartman <[email protected]>
Acked-by: Jessica Yu <[email protected]>
Signed-off-by: Rasmus Villemoes <[email protected]>
---
init/Kconfig | 12 ++++++++++++
kernel/kmod.c | 2 +-
2 files changed, 13 insertions(+), 1 deletion(-)
diff --git a/init/Kconfig b/init/Kconfig
index 22946fe5ded9..18b4ec7346d4 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -2264,6 +2264,18 @@ config MODULE_ALLOW_MISSING_NAMESPACE_IMPORTS
If unsure, say N.
+config MODPROBE_PATH
+ string "Path to modprobe binary"
+ default "/sbin/modprobe"
+ help
+ When kernel code requests a module, it does so by calling
+ the "modprobe" userspace utility. This option allows you to
+ set the path where that binary is found. This can be changed
+ at runtime via the sysctl file
+ /proc/sys/kernel/modprobe. Setting this to the empty string
+ removes the kernel's ability to request modules (but
+ userspace can still load modules explicitly).
+
config TRIM_UNUSED_KSYMS
bool "Trim unused exported kernel symbols" if EXPERT
depends on !COMPILE_TEST
diff --git a/kernel/kmod.c b/kernel/kmod.c
index 3cd075ce2a1e..b717134ebe17 100644
--- a/kernel/kmod.c
+++ b/kernel/kmod.c
@@ -58,7 +58,7 @@ static DECLARE_WAIT_QUEUE_HEAD(kmod_wq);
/*
modprobe_path is set via /proc/sys.
*/
-char modprobe_path[KMOD_PATH_LEN] = "/sbin/modprobe";
+char modprobe_path[KMOD_PATH_LEN] = CONFIG_MODPROBE_PATH;
static void free_modprobe_argv(struct subprocess_info *info)
{
--
2.29.2
On Sat, Mar 13, 2021 at 10:25:27PM +0100, Rasmus Villemoes wrote:
> Most of the boot process doesn't actually need anything from the
> initramfs, until of course PID1 is to be executed. So instead of doing
> the decompressing and populating of the initramfs synchronously in
> populate_rootfs() itself, push that off to a worker thread.
>
> This is primarily motivated by an embedded ppc target, where unpacking
> even the rather modest sized initramfs takes 0.6 seconds, which is
> long enough that the external watchdog becomes unhappy that it doesn't
> get attention soon enough. By doing the initramfs decompression in a
> worker thread, we get to do the device_initcalls and hence start
> petting the watchdog much sooner.
>
> Normal desktops might benefit as well. On my mostly stock Ubuntu
> kernel, my initramfs is a 26M xz-compressed blob, decompressing to
> around 126M. That takes almost two seconds:
>
> [ 0.201454] Trying to unpack rootfs image as initramfs...
> [ 1.976633] Freeing initrd memory: 29416K
>
> Before this patch, these lines occur consecutively in dmesg. With this
> patch, the timestamps on these two lines is roughly the same as above,
> but with 172 lines inbetween - so more than one cpu has been kept busy
> doing work that would otherwise only happen after the
> populate_rootfs() finished.
>
> Should one of the initcalls done after rootfs_initcall time (i.e.,
> device_ and late_ initcalls) need something from the initramfs (say, a
> kernel module or a firmware blob), it will simply wait for the
> initramfs unpacking to be done before proceeding, which should in
> theory make this completely safe.
>
> But if some driver pokes around in the filesystem directly and not via
> one of the official kernel interfaces (i.e. request_firmware*(),
> call_usermodehelper*) that theory may not hold - also, I certainly
> might have missed a spot when sprinkling wait_for_initramfs(). So
> there is an escape hatch in the form of an initramfs_async= command
> line parameter.
>
> Signed-off-by: Rasmus Villemoes <[email protected]>
Reviewed-by: Luis Chamberlain <[email protected]>
Luis
On 15/03/2021 22.33, Andrew Morton wrote:
> On Sat, 13 Mar 2021 22:25:27 +0100 Rasmus Villemoes <[email protected]> wrote:
>
>> Most of the boot process doesn't actually need anything from the
>> initramfs, until of course PID1 is to be executed. So instead of doing
>> the decompressing and populating of the initramfs synchronously in
>> populate_rootfs() itself, push that off to a worker thread.
[...]
>
> This seems sensible. And nice.
Thanks.
> Are you sure that you've found all the code paths that require that
> initramfs be ready? You have one in init/main, one in the bowels of
> the firmware loader and one in UML. How do we know that there are no
> other such places?
No, I don't _know_ that I've found all such places, but nobody, Linus
included, have been able to come up with any that I've missed. At this
point, the only way to figure it out is to get the code into linux-next
(and the more time it gets before the merge window, the better). Since
it's default-on, it should get quite a bit of testing that way.
> Also, all this doesn't buy anything for uniprocessor machines. Is
> there a simple way of making it all go away if !CONFIG_SMP?
It absolutely does buy something for UP, at least for some special case:
The ppc machine I'm talking about is UP, and without getting the
initramfs unpacking pushed to the background, the machine doesn't get to
pet the external hardware watchdog soon enough. So this is really the
difference between booting successfully or being a power-consuming paper
weight. Also, lots of device initialization actually makes the CPU
twiddle its thumbs now and then, so having something other than the idle
thread to schedule makes better use of the single CPU.
Rasmus
On Sat, Mar 13, 2021 at 10:25:28PM +0100, Rasmus Villemoes wrote:
> Allow the developer to specifiy the initial value of the
> modprobe_path[] string. This can be used to set it to the empty string
> initially, thus effectively disabling request_module() during early
> boot until userspace writes a new value via the
> /proc/sys/kernel/modprobe interface. [1]
>
> When building a custom kernel (often for an embedded target), it's
> normal to build everything into the kernel that is needed for booting,
> and indeed the initramfs often contains no modules at all, so every
> such request_module() done before userspace init has mounted the real
> rootfs is a waste of time.
>
> This is particularly useful when combined with the previous patch,
> which made the initramfs unpacking asynchronous - for that to work, it
> had to make any usermodehelper call wait for the unpacking to finish
> before attempting to invoke the userspace helper. By eliminating all
> such (known-to-be-futile) calls of usermodehelper, the initramfs
> unpacking and the {device,late}_initcalls can proceed in parallel for
> much longer.
>
> For a relatively slow ppc board I'm working on, the two patches
> combined lead to 0.2s faster boot - but more importantly, the fact
> that the initramfs unpacking proceeds completely in the background
> while devices get probed means I get to handle the gpio watchdog in
> time without getting reset.
>
> [1] __request_module() already has an early -ENOENT return when
> modprobe_path is the empty string.
>
> Reviewed-by: Greg Kroah-Hartman <[email protected]>
> Acked-by: Jessica Yu <[email protected]>
> Signed-off-by: Rasmus Villemoes <[email protected]>
Acked-by: Luis Chamberlain <[email protected]>
Luis
On Sat, Mar 13, 2021 at 10:25:26PM +0100, Rasmus Villemoes wrote:
> Routing-wise, I hope akpm can handle both patches. Andrew, Luis?
I think it would be ideal for it to go through Andrew's tree.
Luis
On Sat, 13 Mar 2021 22:25:27 +0100 Rasmus Villemoes <[email protected]> wrote:
> Most of the boot process doesn't actually need anything from the
> initramfs, until of course PID1 is to be executed. So instead of doing
> the decompressing and populating of the initramfs synchronously in
> populate_rootfs() itself, push that off to a worker thread.
>
> This is primarily motivated by an embedded ppc target, where unpacking
> even the rather modest sized initramfs takes 0.6 seconds, which is
> long enough that the external watchdog becomes unhappy that it doesn't
> get attention soon enough. By doing the initramfs decompression in a
> worker thread, we get to do the device_initcalls and hence start
> petting the watchdog much sooner.
>
> Normal desktops might benefit as well. On my mostly stock Ubuntu
> kernel, my initramfs is a 26M xz-compressed blob, decompressing to
> around 126M. That takes almost two seconds:
>
> [ 0.201454] Trying to unpack rootfs image as initramfs...
> [ 1.976633] Freeing initrd memory: 29416K
>
> Before this patch, these lines occur consecutively in dmesg. With this
> patch, the timestamps on these two lines is roughly the same as above,
> but with 172 lines inbetween - so more than one cpu has been kept busy
> doing work that would otherwise only happen after the
> populate_rootfs() finished.
>
> Should one of the initcalls done after rootfs_initcall time (i.e.,
> device_ and late_ initcalls) need something from the initramfs (say, a
> kernel module or a firmware blob), it will simply wait for the
> initramfs unpacking to be done before proceeding, which should in
> theory make this completely safe.
>
> But if some driver pokes around in the filesystem directly and not via
> one of the official kernel interfaces (i.e. request_firmware*(),
> call_usermodehelper*) that theory may not hold - also, I certainly
> might have missed a spot when sprinkling wait_for_initramfs(). So
> there is an escape hatch in the form of an initramfs_async= command
> line parameter.
This seems sensible. And nice.
Are you sure that you've found all the code paths that require that
initramfs be ready? You have one in init/main, one in the bowels of
the firmware loader and one in UML. How do we know that there are no
other such places?
Also, all this doesn't buy anything for uniprocessor machines. Is
there a simple way of making it all go away if !CONFIG_SMP?
Hello,
since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
started seeing the following problem on s390 arch regularly:
[ 5.039734] wait_for_initramfs() called before rootfs_initcalls
[ 5.042003] cryptomgr_test (155) used greatest stack depth: 11952 bytes left
[ 5.214115] raid6: vx128x8 gen() 21961 MB/s
[ 5.384073] raid6: vx128x8 xor() 14882 MB/s
[ 5.384090] raid6: using algorithm vx128x8 gen() 21961 MB/s
[ 5.384094] raid6: .... xor() 14882 MB/s, rmw enabled
[ 5.384098] raid6: using s390xc recovery algorithm
[ 5.386338] iommu: Default domain type: Translated·
[ 5.387724] SCSI subsystem initialized
[ 5.393858] cio: Partition identifier 4.9
[ 6.361599] VFS: Disk quotas dquot_6.6.0
[ 6.361852] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 6.374790] NET: Registered PF_INET protocol family
[ 6.375187] IP idents hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[ 6.381935] tcp_listen_portaddr_hash hash table entries: 8192 (order: 7, 720896 bytes, linear)
[ 6.382234] TCP established hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[ 6.383133] TCP bind hash table entries: 65536 (order: 10, 5242880 bytes, vmalloc)
[ 6.385373] TCP: Hash tables configured (established 131072 bind 65536)
[ 6.394770] MPTCP token hash table entries: 16384 (order: 8, 1572864 bytes, linear)
[ 6.395586] UDP hash table entries: 8192 (order: 8, 1572864 bytes, linear)
[ 6.396531] UDP-Lite hash table entries: 8192 (order: 8, 1572864 bytes, linear)
[ 6.405284] NET: Registered PF_UNIX/PF_LOCAL protocol family
[ 6.405821] Trying to unpack rootfs image as initramfs...
[ 6.407794] alg: No test for crc32be (crc32be-vx)
[ 6.436676] Initialise system trusted keyrings
[ 6.436980] workingset: timestamp_bits=45 max_order=22 bucket_order=0
[ 6.500365] zbud: loaded
[ 6.516137] fuse: init (API version 7.34)
[ 6.517210] SGI XFS with ACLs, security attributes, realtime, quota, fatal assert, debug enabled
[ 6.544339] xor: automatically using best checksumming function xc········
[ 6.544363] Key type asymmetric registered
[ 6.544389] Asymmetric key parser 'x509' registered
[ 6.544448] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[ 6.545893] io scheduler mq-deadline registered
[ 6.545927] io scheduler kyber registered
[ 6.545933] blkcg_policy_register: BLKCG_MAX_POLS too small
[ 6.599433] rootfs image is not initramfs (broken padding); looks like an initrd
[ 6.669373] Freeing initrd memory: 24828K
It is very hard to reproduce, i haven't managed to do it yet and working
on it, but it occurs regularly, nearly every day once but only on a particular
test machine with our nightly s390 CI test runs.
Although the initramfs corruption is hard to reproduce,
the message 'wait_for_initramfs() called before rootfs_initcalls'
appears regularly on each boot at least since 2021-06-24 which we just
noticed a couple of days ago.
Appending 'initramfs_async=0' to the kernel command-line doesn't seem to
help with the 'wait_for_initramfs' message and i can still see it.
[ 0.890962] wait_for_initramfs() called before rootfs_initcalls
[ 1.060846] raid6: vx128x8 gen() 22394 MB/s
[ 1.230783] raid6: vx128x8 xor() 14998 MB/s
[ 1.230795] raid6: using algorithm vx128x8 gen() 22394 MB/s
[ 1.230797] raid6: .... xor() 14998 MB/s, rmw enabled
[ 1.230799] raid6: using s390xc recovery algorithm
[ 1.231122] iommu: Default domain type: Translated
[ 1.231331] SCSI subsystem initialized
[ 1.231804] cio: Partition identifier 3.4
[ 1.355331] PCI host bridge to bus 0000:00
[ 1.355340] pci_bus 0000:00: root bus resource [bus 00]
[ 1.355363] PCI host bridge to bus 0001:00
[ 1.355364] pci_bus 0001:00: root bus resource [bus 00]
[ 1.355490] pci 0000:00:00.0: [8086:0a54] type 00 class 0x010802
[ 1.355541] pci 0000:00:00.0: reg 0x10: [mem 0xffffc00000000000-0xffffc00000003fff 64bit]
[ 1.355611] pci 0000:00:00.0: reg 0x30: [mem 0x00000000-0x0000ffff pref]
[ 1.355625] pci 0000:00:00.0: enabling Extended Tags
[ 1.355921] pci 0000:00:00.0: Adding to iommu group 0
[ 1.632566] VFS: Disk quotas dquot_6.6.0
[ 1.632624] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 1.634327] NET: Registered PF_INET protocol family
[ 1.634395] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)
[ 1.635112] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)
[ 1.635129] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
[ 1.635296] TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear)
[ 1.635498] TCP: Hash tables configured (established 32768 bind 32768)
[ 1.635834] MPTCP token hash table entries: 4096 (order: 4, 98304 bytes, linear)
[ 1.635852] UDP hash table entries: 2048 (order: 4, 65536 bytes, linear)
[ 1.635882] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear)
[ 1.636249] NET: Registered PF_UNIX/PF_LOCAL protocol family
[ 1.636419] Trying to unpack rootfs image as initramfs...
[ 1.676907] Freeing initrd memory: 26056K
Regards
Alex
On 24/07/2021 09.46, Alexander Egorenkov wrote:
> Hello,
>
> since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
> started seeing the following problem on s390 arch regularly:
>
> [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
While that message was added as part of the same patch, it's a red
herring: It merely means that something ends up calling usermodehelper
(perhaps a request_module) before the init sequence has come around to
rootfs_initcalls. At that point, the rootfs is (with or without my async
patch) entirely empty, so those usermodehelper calls have always failed
with -ENOENT.
If you have CONFIG_UEVENT_HELPER=y and CONFIG_UEVENT_HELPER_PATH set to
a non-empty string, you can try setting the latter to the empty string.
But the message won't go away if it's really a request_module() and not
a uevent notification.
> [ 6.599433] rootfs image is not initramfs (broken padding); looks like an initrd
> [ 6.669373] Freeing initrd memory: 24828K
>
> It is very hard to reproduce, i haven't managed to do it yet and working
> on it, but it occurs regularly, nearly every day once but only on a particular
> test machine with our nightly s390 CI test runs.
So this looks somewhat similar to a ppc64 report
https://lore.kernel.org/lkml/CA+QYu4qxf2CYe2gC6EYnOHXPKS-+cEXL=MnUvqRFaN7W1i6ahQ@mail.gmail.com/T/#u
that ended up not being caused by e7cb072eb988, since it could also be
reproduced with that patch reverted. I don't know if Bruno found the
root cause, adding him to cc. Also cc += Dave Young who had some input
in that thread.
> Although the initramfs corruption is hard to reproduce,
> the message 'wait_for_initramfs() called before rootfs_initcalls'
> appears regularly on each boot at least since 2021-06-24 which we just
> noticed a couple of days ago.
>
> Appending 'initramfs_async=0' to the kernel command-line doesn't seem to
> help with the 'wait_for_initramfs' message and i can still see it.
Yes, that's expected. I should probably send a patch to move
usermodehelper_enable() from do_basic_setup() to populate_rootfs(), as
it really doesn't make sense to have usermodehelper enabled before
there's any content in the file system. But as I said, the warning is
harmless and merely indicates there's a bunch of futile work being done
to call a (at that point in time) non-existing usermode program.
> [ 0.890962] wait_for_initramfs() called before rootfs_initcalls
...
> [ 1.636419] Trying to unpack rootfs image as initramfs...
> [ 1.676907] Freeing initrd memory: 26056K
It would be interesting if you could boot with initramfs_async=0 enough
times to see if you can reproduce the problem; and/or do the same with
e7cb072eb988 reverted.
Thanks,
Rasmus
On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
<[email protected]> wrote:
>
> On 24/07/2021 09.46, Alexander Egorenkov wrote:
> > Hello,
> >
> > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
> > started seeing the following problem on s390 arch regularly:
> >
> > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
>
> While that message was added as part of the same patch, it's a red
> herring: It merely means that something ends up calling usermodehelper
> (perhaps a request_module) before the init sequence has come around to
> rootfs_initcalls. At that point, the rootfs is (with or without my async
> patch) entirely empty, so those usermodehelper calls have always failed
> with -ENOENT.
>
> If you have CONFIG_UEVENT_HELPER=y and CONFIG_UEVENT_HELPER_PATH set to
> a non-empty string, you can try setting the latter to the empty string.
> But the message won't go away if it's really a request_module() and not
> a uevent notification.
>
> > [ 6.599433] rootfs image is not initramfs (broken padding); looks like an initrd
> > [ 6.669373] Freeing initrd memory: 24828K
> >
> > It is very hard to reproduce, i haven't managed to do it yet and working
> > on it, but it occurs regularly, nearly every day once but only on a particular
> > test machine with our nightly s390 CI test runs.
>
> So this looks somewhat similar to a ppc64 report
>
> https://lore.kernel.org/lkml/CA+QYu4qxf2CYe2gC6EYnOHXPKS-+cEXL=MnUvqRFaN7W1i6ahQ@mail.gmail.com/T/#u
>
> that ended up not being caused by e7cb072eb988, since it could also be
> reproduced with that patch reverted. I don't know if Bruno found the
> root cause, adding him to cc. Also cc += Dave Young who had some input
> in that thread.
Unfortunately, we haven't been able to find the root cause, but since
June 23rd we haven't hit this panic...
Btw, this panic we were hitting only when testing kernels from "scsi"
and "block" trees.
Bruno
>
> > Although the initramfs corruption is hard to reproduce,
> > the message 'wait_for_initramfs() called before rootfs_initcalls'
> > appears regularly on each boot at least since 2021-06-24 which we just
> > noticed a couple of days ago.
> >
> > Appending 'initramfs_async=0' to the kernel command-line doesn't seem to
> > help with the 'wait_for_initramfs' message and i can still see it.
>
> Yes, that's expected. I should probably send a patch to move
> usermodehelper_enable() from do_basic_setup() to populate_rootfs(), as
> it really doesn't make sense to have usermodehelper enabled before
> there's any content in the file system. But as I said, the warning is
> harmless and merely indicates there's a bunch of futile work being done
> to call a (at that point in time) non-existing usermode program.
>
> > [ 0.890962] wait_for_initramfs() called before rootfs_initcalls
> ...
> > [ 1.636419] Trying to unpack rootfs image as initramfs...
> > [ 1.676907] Freeing initrd memory: 26056K
>
> It would be interesting if you could boot with initramfs_async=0 enough
> times to see if you can reproduce the problem; and/or do the same with
> e7cb072eb988 reverted.
>
> Thanks,
> Rasmus
>
On Tue, Jul 27, 2021 at 09:31:54AM +0200, Bruno Goncalves wrote:
> On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
> <[email protected]> wrote:
> >
> > On 24/07/2021 09.46, Alexander Egorenkov wrote:
> > > Hello,
> > >
> > > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
> > > started seeing the following problem on s390 arch regularly:
> > >
> > > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
So some context here, which might help.
The initramfs_cookie is initialized until a a rootfs_initcall() is
called, in this case populate_rootfs(). The code is small, so might
as well include it:
static int __init populate_rootfs(void)
{
initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
&initramfs_domain);
if (!initramfs_async)
wait_for_initramfs();
return 0;
}
rootfs_initcall(populate_rootfs);
The warning you see comes from a situation where a wait_for_initramfs()
gets called but we haven't yet initialized initramfs_cookie. There are
only a few calls for wait_for_initramfs() in the kernel, and the only
thing I can think of is that somehow s390 may rely on a usermode helper
early on, but not every time.
What umh calls does s390 issue?
> Unfortunately, we haven't been able to find the root cause, but since
> June 23rd we haven't hit this panic...
>
> Btw, this panic we were hitting only when testing kernels from "scsi"
> and "block" trees.
Do you use drdb maybe?
Luis
On Tue, Jul 27, 2021 at 3:55 PM Luis Chamberlain <[email protected]> wrote:
>
> On Tue, Jul 27, 2021 at 09:31:54AM +0200, Bruno Goncalves wrote:
> > On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
> > <[email protected]> wrote:
> > >
> > > On 24/07/2021 09.46, Alexander Egorenkov wrote:
> > > > Hello,
> > > >
> > > > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
> > > > started seeing the following problem on s390 arch regularly:
> > > >
> > > > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
>
> So some context here, which might help.
>
> The initramfs_cookie is initialized until a a rootfs_initcall() is
> called, in this case populate_rootfs(). The code is small, so might
> as well include it:
>
> static int __init populate_rootfs(void)
> {
> initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
> &initramfs_domain);
> if (!initramfs_async)
> wait_for_initramfs();
> return 0;
> }
> rootfs_initcall(populate_rootfs);
>
> The warning you see comes from a situation where a wait_for_initramfs()
> gets called but we haven't yet initialized initramfs_cookie. There are
> only a few calls for wait_for_initramfs() in the kernel, and the only
> thing I can think of is that somehow s390 may rely on a usermode helper
> early on, but not every time.
>
> What umh calls does s390 issue?
>
> > Unfortunately, we haven't been able to find the root cause, but since
> > June 23rd we haven't hit this panic...
> >
> > Btw, this panic we were hitting only when testing kernels from "scsi"
> > and "block" trees.
>
> Do you use drdb maybe?
No, the machines we were able to reproduce the problem don't have drdb.
Bruno
>
> Luis
>
On Tue, Jul 27, 2021 at 04:12:54PM +0200, Bruno Goncalves wrote:
> On Tue, Jul 27, 2021 at 3:55 PM Luis Chamberlain <[email protected]> wrote:
> >
> > On Tue, Jul 27, 2021 at 09:31:54AM +0200, Bruno Goncalves wrote:
> > > On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
> > > <[email protected]> wrote:
> > > >
> > > > On 24/07/2021 09.46, Alexander Egorenkov wrote:
> > > > > Hello,
> > > > >
> > > > > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
> > > > > started seeing the following problem on s390 arch regularly:
> > > > >
> > > > > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
> >
> > So some context here, which might help.
> >
> > The initramfs_cookie is initialized until a a rootfs_initcall() is
> > called, in this case populate_rootfs(). The code is small, so might
> > as well include it:
> >
> > static int __init populate_rootfs(void)
> > {
> > initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
> > &initramfs_domain);
> > if (!initramfs_async)
> > wait_for_initramfs();
> > return 0;
> > }
> > rootfs_initcall(populate_rootfs);
> >
> > The warning you see comes from a situation where a wait_for_initramfs()
> > gets called but we haven't yet initialized initramfs_cookie. There are
> > only a few calls for wait_for_initramfs() in the kernel, and the only
> > thing I can think of is that somehow s390 may rely on a usermode helper
> > early on, but not every time.
> >
> > What umh calls does s390 issue?
> >
> > > Unfortunately, we haven't been able to find the root cause, but since
> > > June 23rd we haven't hit this panic...
> > >
> > > Btw, this panic we were hitting only when testing kernels from "scsi"
> > > and "block" trees.
> >
> > Do you use drdb maybe?
>
> No, the machines we were able to reproduce the problem don't have drdb.
Are there *any* umh calls early on boot on the s390 systems? If so
chances are that is the droid you are looking for.
Luis
On Tue, Jul 27, 2021 at 4:21 PM Luis Chamberlain <[email protected]> wrote:
>
> On Tue, Jul 27, 2021 at 04:12:54PM +0200, Bruno Goncalves wrote:
> > On Tue, Jul 27, 2021 at 3:55 PM Luis Chamberlain <[email protected]> wrote:
> > >
> > > On Tue, Jul 27, 2021 at 09:31:54AM +0200, Bruno Goncalves wrote:
> > > > On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
> > > > <[email protected]> wrote:
> > > > >
> > > > > On 24/07/2021 09.46, Alexander Egorenkov wrote:
> > > > > > Hello,
> > > > > >
> > > > > > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
> > > > > > started seeing the following problem on s390 arch regularly:
> > > > > >
> > > > > > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
> > >
> > > So some context here, which might help.
> > >
> > > The initramfs_cookie is initialized until a a rootfs_initcall() is
> > > called, in this case populate_rootfs(). The code is small, so might
> > > as well include it:
> > >
> > > static int __init populate_rootfs(void)
> > > {
> > > initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
> > > &initramfs_domain);
> > > if (!initramfs_async)
> > > wait_for_initramfs();
> > > return 0;
> > > }
> > > rootfs_initcall(populate_rootfs);
> > >
> > > The warning you see comes from a situation where a wait_for_initramfs()
> > > gets called but we haven't yet initialized initramfs_cookie. There are
> > > only a few calls for wait_for_initramfs() in the kernel, and the only
> > > thing I can think of is that somehow s390 may rely on a usermode helper
> > > early on, but not every time.
> > >
> > > What umh calls does s390 issue?
> > >
> > > > Unfortunately, we haven't been able to find the root cause, but since
> > > > June 23rd we haven't hit this panic...
> > > >
> > > > Btw, this panic we were hitting only when testing kernels from "scsi"
> > > > and "block" trees.
> > >
> > > Do you use drdb maybe?
> >
> > No, the machines we were able to reproduce the problem don't have drdb.
>
> Are there *any* umh calls early on boot on the s390 systems? If so
> chances are that is the droid you are looking for.
Sorry Luis,
I was just replying the question mentioning an old thread
(https://lore.kernel.org/lkml/CA+QYu4qxf2CYe2gC6EYnOHXPKS-+cEXL=MnUvqRFaN7W1i6ahQ@mail.gmail.com/T/#u)
on ppc64le.
regarding the "umh" it doesn't show anything on ppc64le boot.
Bruno
>
> Luis
>
On Tue, Jul 27, 2021 at 04:27:08PM +0200, Bruno Goncalves wrote:
> On Tue, Jul 27, 2021 at 4:21 PM Luis Chamberlain <[email protected]> wrote:
> >
> > On Tue, Jul 27, 2021 at 04:12:54PM +0200, Bruno Goncalves wrote:
> > > On Tue, Jul 27, 2021 at 3:55 PM Luis Chamberlain <[email protected]> wrote:
> > > >
> > > > On Tue, Jul 27, 2021 at 09:31:54AM +0200, Bruno Goncalves wrote:
> > > > > On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
> > > > > <[email protected]> wrote:
> > > > > >
> > > > > > On 24/07/2021 09.46, Alexander Egorenkov wrote:
> > > > > > > Hello,
> > > > > > >
> > > > > > > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
> > > > > > > started seeing the following problem on s390 arch regularly:
> > > > > > >
> > > > > > > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
> > > >
> > > > So some context here, which might help.
> > > >
> > > > The initramfs_cookie is initialized until a a rootfs_initcall() is
> > > > called, in this case populate_rootfs(). The code is small, so might
> > > > as well include it:
> > > >
> > > > static int __init populate_rootfs(void)
> > > > {
> > > > initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
> > > > &initramfs_domain);
> > > > if (!initramfs_async)
> > > > wait_for_initramfs();
> > > > return 0;
> > > > }
> > > > rootfs_initcall(populate_rootfs);
> > > >
> > > > The warning you see comes from a situation where a wait_for_initramfs()
> > > > gets called but we haven't yet initialized initramfs_cookie. There are
> > > > only a few calls for wait_for_initramfs() in the kernel, and the only
> > > > thing I can think of is that somehow s390 may rely on a usermode helper
> > > > early on, but not every time.
> > > >
> > > > What umh calls does s390 issue?
> > > >
> > > > > Unfortunately, we haven't been able to find the root cause, but since
> > > > > June 23rd we haven't hit this panic...
> > > > >
> > > > > Btw, this panic we were hitting only when testing kernels from "scsi"
> > > > > and "block" trees.
> > > >
> > > > Do you use drdb maybe?
> > >
> > > No, the machines we were able to reproduce the problem don't have drdb.
> >
> > Are there *any* umh calls early on boot on the s390 systems? If so
> > chances are that is the droid you are looking for.
>
> Sorry Luis,
>
> I was just replying the question mentioning an old thread
> (https://lore.kernel.org/lkml/CA+QYu4qxf2CYe2gC6EYnOHXPKS-+cEXL=MnUvqRFaN7W1i6ahQ@mail.gmail.com/T/#u)
> on ppc64le.
>
> regarding the "umh" it doesn't show anything on ppc64le boot.
There is not a single pr_*() call on kernel/umh.c, and so unless the
respective ppc64le / s390 umh callers have a print, we won't know if you
really did use a print.
Can you reproduce the failure? How often?
Luis
On Tue, Jul 27, 2021 at 4:42 PM Luis Chamberlain <[email protected]> wrote:
>
> On Tue, Jul 27, 2021 at 04:27:08PM +0200, Bruno Goncalves wrote:
> > On Tue, Jul 27, 2021 at 4:21 PM Luis Chamberlain <[email protected]> wrote:
> > >
> > > On Tue, Jul 27, 2021 at 04:12:54PM +0200, Bruno Goncalves wrote:
> > > > On Tue, Jul 27, 2021 at 3:55 PM Luis Chamberlain <[email protected]> wrote:
> > > > >
> > > > > On Tue, Jul 27, 2021 at 09:31:54AM +0200, Bruno Goncalves wrote:
> > > > > > On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
> > > > > > <[email protected]> wrote:
> > > > > > >
> > > > > > > On 24/07/2021 09.46, Alexander Egorenkov wrote:
> > > > > > > > Hello,
> > > > > > > >
> > > > > > > > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
> > > > > > > > started seeing the following problem on s390 arch regularly:
> > > > > > > >
> > > > > > > > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
> > > > >
> > > > > So some context here, which might help.
> > > > >
> > > > > The initramfs_cookie is initialized until a a rootfs_initcall() is
> > > > > called, in this case populate_rootfs(). The code is small, so might
> > > > > as well include it:
> > > > >
> > > > > static int __init populate_rootfs(void)
> > > > > {
> > > > > initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
> > > > > &initramfs_domain);
> > > > > if (!initramfs_async)
> > > > > wait_for_initramfs();
> > > > > return 0;
> > > > > }
> > > > > rootfs_initcall(populate_rootfs);
> > > > >
> > > > > The warning you see comes from a situation where a wait_for_initramfs()
> > > > > gets called but we haven't yet initialized initramfs_cookie. There are
> > > > > only a few calls for wait_for_initramfs() in the kernel, and the only
> > > > > thing I can think of is that somehow s390 may rely on a usermode helper
> > > > > early on, but not every time.
> > > > >
> > > > > What umh calls does s390 issue?
> > > > >
> > > > > > Unfortunately, we haven't been able to find the root cause, but since
> > > > > > June 23rd we haven't hit this panic...
> > > > > >
> > > > > > Btw, this panic we were hitting only when testing kernels from "scsi"
> > > > > > and "block" trees.
> > > > >
> > > > > Do you use drdb maybe?
> > > >
> > > > No, the machines we were able to reproduce the problem don't have drdb.
> > >
> > > Are there *any* umh calls early on boot on the s390 systems? If so
> > > chances are that is the droid you are looking for.
> >
> > Sorry Luis,
> >
> > I was just replying the question mentioning an old thread
> > (https://lore.kernel.org/lkml/CA+QYu4qxf2CYe2gC6EYnOHXPKS-+cEXL=MnUvqRFaN7W1i6ahQ@mail.gmail.com/T/#u)
> > on ppc64le.
> >
> > regarding the "umh" it doesn't show anything on ppc64le boot.
>
> There is not a single pr_*() call on kernel/umh.c, and so unless the
> respective ppc64le / s390 umh callers have a print, we won't know if you
> really did use a print.
>
> Can you reproduce the failure? How often?
The ppc64le panic we were able to reproduce it often using specific
machines, but last time we've hit this panic was on June 23rd when we
tested commit 444ef33be31f3c27ea24e60d5d9f2de9247d64be on
https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git
since then we haven't hit the panic anymore.
Bruno
>
> Luis
>
Luis Chamberlain <[email protected]> writes:
> On Tue, Jul 27, 2021 at 09:31:54AM +0200, Bruno Goncalves wrote:
>> On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
>> <[email protected]> wrote:
>> >
>> > On 24/07/2021 09.46, Alexander Egorenkov wrote:
>> > > Hello,
>> > >
>> > > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
>> > > started seeing the following problem on s390 arch regularly:
>> > >
>> > > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
>
> So some context here, which might help.
>
> The initramfs_cookie is initialized until a a rootfs_initcall() is
> called, in this case populate_rootfs(). The code is small, so might
> as well include it:
>
> static int __init populate_rootfs(void)
> {
> initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
> &initramfs_domain);
> if (!initramfs_async)
> wait_for_initramfs();
> return 0;
> }
> rootfs_initcall(populate_rootfs);
>
> The warning you see comes from a situation where a wait_for_initramfs()
> gets called but we haven't yet initialized initramfs_cookie. There are
> only a few calls for wait_for_initramfs() in the kernel, and the only
> thing I can think of is that somehow s390 may rely on a usermode helper
> early on, but not every time.
>
> What umh calls does s390 issue?
>
>> Unfortunately, we haven't been able to find the root cause, but since
>> June 23rd we haven't hit this panic...
>>
>> Btw, this panic we were hitting only when testing kernels from "scsi"
>> and "block" trees.
>
> Do you use drdb maybe?
>
> Luis
You are right, it looks like wait_for_initramfs() is being triggered by drbg:
[ 3.396467] [<00000001f8d917e4>] call_usermodehelper_exec+0x44/0x1c8
[ 3.396470] [<00000001f8da5524>] __request_module+0x17c/0x3d0
[ 3.396473] [<00000001f93b4808>] crypto_alg_mod_lookup+0x228/0x290
[ 3.396475] [<00000001f93b4aae>] crypto_alloc_tfm_node+0x5e/0x158
[ 3.396477] [<00000001f93bbe14>] crypto_alloc_shash+0x34/0x40
[ 3.396480] [<00000001f93d2ee2>] drbg_init_hash_kernel+0x3a/0x100
[ 3.396482] [<00000001f93d306e>] drbg_alloc_state+0xc6/0x280
[ 3.396484] [<00000001f93d33d8>] drbg_kcapi_seed+0x1b0/0x310
[ 3.396486] [<00000001f93d1884>] crypto_rng_reset+0x5c/0xe0
[ 3.396488] [<00000001f93c1750>] alg_test_drbg+0x300/0x478
[ 3.396490] [<00000001f93c0934>] alg_test+0x304/0x530
[ 3.396493] [<00000001f93bedb8>] cryptomgr_test+0x68/0x70
[ 3.396495] [<00000001f8d9f40c>] kthread+0x14c/0x160
[ 3.396497] [<00000001f8d2af14>] __ret_from_fork+0x3c/0x58
[ 3.396500] [<00000001f984c86a>] ret_from_fork+0xa/0x30
Regards
Alex
Rasmus Villemoes <[email protected]> writes:
> On 24/07/2021 09.46, Alexander Egorenkov wrote:
>> Hello,
>>
>> since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
>> started seeing the following problem on s390 arch regularly:
>>
>> [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
>
> While that message was added as part of the same patch, it's a red
> herring: It merely means that something ends up calling usermodehelper
> (perhaps a request_module) before the init sequence has come around to
> rootfs_initcalls. At that point, the rootfs is (with or without my async
> patch) entirely empty, so those usermodehelper calls have always failed
> with -ENOENT.
>
> If you have CONFIG_UEVENT_HELPER=y and CONFIG_UEVENT_HELPER_PATH set to
> a non-empty string, you can try setting the latter to the empty string.
> But the message won't go away if it's really a request_module() and not
> a uevent notification.
>
Thanks for the helpful explanation. I disabled UEVENT on my test machine and
as you said, the message is being triggered by request_module() now.
[ 3.396467] [<00000001f8d917e4>] call_usermodehelper_exec+0x44/0x1c8
[ 3.396470] [<00000001f8da5524>] __request_module+0x17c/0x3d0
[ 3.396473] [<00000001f93b4808>] crypto_alg_mod_lookup+0x228/0x290
[ 3.396475] [<00000001f93b4aae>] crypto_alloc_tfm_node+0x5e/0x158
[ 3.396477] [<00000001f93bbe14>] crypto_alloc_shash+0x34/0x40
[ 3.396480] [<00000001f93d2ee2>] drbg_init_hash_kernel+0x3a/0x100
[ 3.396482] [<00000001f93d306e>] drbg_alloc_state+0xc6/0x280
[ 3.396484] [<00000001f93d33d8>] drbg_kcapi_seed+0x1b0/0x310
[ 3.396486] [<00000001f93d1884>] crypto_rng_reset+0x5c/0xe0
[ 3.396488] [<00000001f93c1750>] alg_test_drbg+0x300/0x478
[ 3.396490] [<00000001f93c0934>] alg_test+0x304/0x530
[ 3.396493] [<00000001f93bedb8>] cryptomgr_test+0x68/0x70
[ 3.396495] [<00000001f8d9f40c>] kthread+0x14c/0x160
[ 3.396497] [<00000001f8d2af14>] __ret_from_fork+0x3c/0x58
[ 3.396500] [<00000001f984c86a>] ret_from_fork+0xa/0x30
Regards
Alex
Luis Chamberlain <[email protected]> writes:
> On Tue, Jul 27, 2021 at 04:27:08PM +0200, Bruno Goncalves wrote:
>> On Tue, Jul 27, 2021 at 4:21 PM Luis Chamberlain <[email protected]> wrote:
>> >
>> > On Tue, Jul 27, 2021 at 04:12:54PM +0200, Bruno Goncalves wrote:
>> > > On Tue, Jul 27, 2021 at 3:55 PM Luis Chamberlain <[email protected]> wrote:
>> > > >
>> > > > On Tue, Jul 27, 2021 at 09:31:54AM +0200, Bruno Goncalves wrote:
>> > > > > On Mon, Jul 26, 2021 at 1:46 PM Rasmus Villemoes
>> > > > > <[email protected]> wrote:
>> > > > > >
>> > > > > > On 24/07/2021 09.46, Alexander Egorenkov wrote:
>> > > > > > > Hello,
>> > > > > > >
>> > > > > > > since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
>> > > > > > > started seeing the following problem on s390 arch regularly:
>> > > > > > >
>> > > > > > > [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
>> > > >
>> > > > So some context here, which might help.
>> > > >
>> > > > The initramfs_cookie is initialized until a a rootfs_initcall() is
>> > > > called, in this case populate_rootfs(). The code is small, so might
>> > > > as well include it:
>> > > >
>> > > > static int __init populate_rootfs(void)
>> > > > {
>> > > > initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
>> > > > &initramfs_domain);
>> > > > if (!initramfs_async)
>> > > > wait_for_initramfs();
>> > > > return 0;
>> > > > }
>> > > > rootfs_initcall(populate_rootfs);
>> > > >
>> > > > The warning you see comes from a situation where a wait_for_initramfs()
>> > > > gets called but we haven't yet initialized initramfs_cookie. There are
>> > > > only a few calls for wait_for_initramfs() in the kernel, and the only
>> > > > thing I can think of is that somehow s390 may rely on a usermode helper
>> > > > early on, but not every time.
>> > > >
>> > > > What umh calls does s390 issue?
>> > > >
>> > > > > Unfortunately, we haven't been able to find the root cause, but since
>> > > > > June 23rd we haven't hit this panic...
>> > > > >
>> > > > > Btw, this panic we were hitting only when testing kernels from "scsi"
>> > > > > and "block" trees.
>> > > >
>> > > > Do you use drdb maybe?
>> > >
>> > > No, the machines we were able to reproduce the problem don't have drdb.
>> >
>> > Are there *any* umh calls early on boot on the s390 systems? If so
>> > chances are that is the droid you are looking for.
>>
>> Sorry Luis,
>>
>> I was just replying the question mentioning an old thread
>> (https://lore.kernel.org/lkml/CA+QYu4qxf2CYe2gC6EYnOHXPKS-+cEXL=MnUvqRFaN7W1i6ahQ@mail.gmail.com/T/#u)
>> on ppc64le.
>>
>> regarding the "umh" it doesn't show anything on ppc64le boot.
>
> There is not a single pr_*() call on kernel/umh.c, and so unless the
> respective ppc64le / s390 umh callers have a print, we won't know if you
> really did use a print.
I instrumented the UMH code and it seems that all wait_for_initramfs()
are triggered by request_module() from drbg.
>
> Can you reproduce the failure? How often?
>
> Luis
The failure can be reproduced almost daily but on only one special test
machine and not immediately but after running many tests. I instrumented
our devel kernel in order to find out when/how the initramfs is being corrupted.
Still not reproducible on my own test machine. Very weird.
I'll report back as soon as we have something tangible.
Regards
Alex
On 28/07/2021 12.36, Alexander Egorenkov wrote:
> Rasmus Villemoes <[email protected]> writes:
>
>> On 24/07/2021 09.46, Alexander Egorenkov wrote:
>>> Hello,
>>>
>>> since e7cb072eb988 ("init/initramfs.c: do unpacking asynchronously"), we
>>> started seeing the following problem on s390 arch regularly:
>>>
>>> [ 5.039734] wait_for_initramfs() called before rootfs_initcalls
>>
>> While that message was added as part of the same patch, it's a red
>> herring: It merely means that something ends up calling usermodehelper
>> (perhaps a request_module) before the init sequence has come around to
>> rootfs_initcalls. At that point, the rootfs is (with or without my async
>> patch) entirely empty, so those usermodehelper calls have always failed
>> with -ENOENT.
>>
>> If you have CONFIG_UEVENT_HELPER=y and CONFIG_UEVENT_HELPER_PATH set to
>> a non-empty string, you can try setting the latter to the empty string.
>> But the message won't go away if it's really a request_module() and not
>> a uevent notification.
>>
>
> Thanks for the helpful explanation. I disabled UEVENT on my test machine and
> as you said, the message is being triggered by request_module() now.
Yes. But as I've said, the "called before rootfs_initcalls" message is
entirely harmless and not in any way related to whatever problems is
later encountered when the initramfs is actually being decompressed and
extracted.
I have this so far untested patch that I plan on sending, which should
remove that message
diff --git a/init/initramfs.c b/init/initramfs.c
index af27abc59643..51a686a8c929 100644
--- a/init/initramfs.c
+++ b/init/initramfs.c
@@ -727,6 +727,7 @@ static int __init populate_rootfs(void)
{
initramfs_cookie = async_schedule_domain(do_populate_rootfs, NULL,
&initramfs_domain);
+ usermodehelper_enable();
if (!initramfs_async)
wait_for_initramfs();
return 0;
diff --git a/init/main.c b/init/main.c
index f5b8246e8aa1..d5c5542fe142 100644
--- a/init/main.c
+++ b/init/main.c
@@ -1387,7 +1387,6 @@ static void __init do_basic_setup(void)
driver_init();
init_irq_proc();
do_ctors();
- usermodehelper_enable();
do_initcalls();
}
diff --git a/init/noinitramfs.c b/init/noinitramfs.c
index 3d62b07f3bb9..f1d9e5495cc1 100644
--- a/init/noinitramfs.c
+++ b/init/noinitramfs.c
@@ -18,6 +18,7 @@ static int __init default_rootfs(void)
{
int err;
+ usermodehelper_enable();
err = init_mkdir("/dev", 0755);
if (err < 0)
goto out;
because any call of a usermodehelper (be it a uevent hotplug
notification or a request_module) would just return -EBUSY during all
pure_, core_, postcore_, arch_, subsys_ and fs_ initcalls. (It is really
beyond me why rootfs_ initcalls are hidden between fs_ and device_
initcalls).
Currently (with or without my async patch) umh calls from those
initcalls probably return -ENOENT or whatever kernel_execve() returns
when there's no such binary. So if something actually looks at the
return value, the change from -ENOENT to -EBUSY might cause a
regression. But I doubt it.
Rasmus