[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <f54c213e-b8e2-418f-b7f4-a2fa72f098b1@paulmck-laptop>
Date: Thu, 24 Apr 2025 07:43:38 -0700
From: "Paul E. McKenney" <paulmck@...nel.org>
To: Petr Mladek <pmladek@...e.com>
Cc: Bert Karwatzki <spasswolf@....de>,
"Aithal, Srikanth" <sraithal@....com>,
Andrew Morton <akpm@...ux-foundation.org>,
Kuniyuki Iwashima <kuniyu@...zon.com>,
Mateusz Guzik <mjguzik@...il.com>,
Steven Rostedt <rostedt@...dmis.org>,
John Ogness <john.ogness@...utronix.de>,
Sergey Senozhatsky <senozhatsky@...omium.org>,
linux-kernel@...r.kernel.org,
Linux-Next Mailing List <linux-next@...r.kernel.org>
Subject: Re: commit dd4cf8c9e1f4 leads to failed boot
On Thu, Apr 24, 2025 at 09:36:22AM +0200, Petr Mladek wrote:
> On Wed 2025-04-23 12:56:53, Paul E. McKenney wrote:
> > On Wed, Apr 23, 2025 at 09:19:56PM +0200, Bert Karwatzki wrote:
> > > Am Mittwoch, dem 23.04.2025 um 11:07 -0700 schrieb Paul E. McKenney:
> > > > On Wed, Apr 23, 2025 at 08:49:08PM +0530, Aithal, Srikanth wrote:
> > > > > On 4/23/2025 7:48 PM, Paul E. McKenney wrote:
> > > > > > On Wed, Apr 23, 2025 at 07:09:42PM +0530, Aithal, Srikanth wrote:
> > > > > > > On 4/23/2025 5:24 PM, Bert Karwatzki wrote:
> > > > > > > > Since linux next-20250422 booting fails on my MSI Alpha 15 Laptop runnning
> > > > > > > > debian sid. When booting kernel message appear on screen but no messages from
> > > > > > > > init (systemd). There are also no logs written even thought emergency sync
> > > > > > > > via magic sysrq works (a message is printed on screen), presumably because
> > > > > > > > / is not mounted. I bisected this (from 6.15-rc3 to next-20250422) and found
> > > > > > > > commit dd4cf8c9e1f4 as the first bad commit.
> > > > > > > > Reverting commit dd4cf8c9e1f4 in next-20250422 fixes the issue.
> > > > > > >
> > > > > > >
> > > > > > > Hello,
> > > > > > >
> > > > > > > On AMD platform as well boot failed starting next-20250422, bisecting the
> > > > > > > issue led me to same commit dd4cf8c9e1f4. I have attached kernel config and
> > > > > > > logs.
> > > > > >
> > > > > > Thank you all for the bisection and the report!
> > > > > >
> > > > > > Please check out the predecessor of commit dd4cf8c9e1f4 ("ratelimit:
> > > > > > Force re-initialization when rate-limiting re-enabled"):
> > > > > >
> > > > > > 13fa70e052dd ("ratelimit: Allow zero ->burst to disable ratelimiting")
> > > > > >
> > > > > > Then please apply the patch shown below, and let me know what happens?
> > > > > > (Yes, I should have split that commit up...)
> > > > > >
> > > > > > Thanx, Paul
> > > > > >
> > > > > > ------------------------------------------------------------------------
> > > > > >
> > > > > > diff --git a/lib/ratelimit.c b/lib/ratelimit.c
> > > > > > index 04f16b8e24575..13ed636642270 100644
> > > > > > --- a/lib/ratelimit.c
> > > > > > +++ b/lib/ratelimit.c
> > > > > > @@ -35,7 +35,7 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
> > > > > > unsigned long flags;
> > > > > > int ret;
> > > > > > - if (!interval || !burst)
> > > > > > + if (interval <= 0 || burst <= 0)
> > > > > > return 1;
> > > > > > /*
> > > > >
> > > > >
> > > > > I applied above patch on top of 13fa70e052dd ("ratelimit: Allow zero ->burst
> > > > > to disable ratelimiting") [linux-20250423]. This is fixing the boot issue.
> > > > >
> > > > > Tested-by: Srikanth Aithal <sraithal@....com>
> > > >
> > > > Thank you both, and to Bert for intuiting the correct -next commit!
> > > >
> > > > Could you please try the next increment, which is this patch, again
> > > > on top of 24ff89c63355 ("ratelimit: Allow zero ->burst to > disable
> > > > ratelimiting")?
> > > >
> > > > In the meantime, I will expose the version you two just tested to
> > > > -next.
> > > >
> > > > Thanx, Paul
> > > >
> > > > ------------------------------------------------------------------------
> > > >
> > > > diff --git a/lib/ratelimit.c b/lib/ratelimit.c
> > > > index 04f16b8e24575..8f6c54f719ef2 100644
> > > > --- a/lib/ratelimit.c
> > > > +++ b/lib/ratelimit.c
> > > > @@ -35,8 +35,10 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
> > > > unsigned long flags;
> > > > int ret;
> > > >
> > > > - if (!interval || !burst)
> > > > + if (interval <= 0 || burst <= 0) {
> > > > + ret = burst > 0;
> > > > return 1;
> > > > + }
> > > >
> > > > /*
> > > > * If we contend on this state's lock then just check if
> > >
> > > If you set "ret = burst > 0", but "return 1" this will make no difference
> > > (except in the case of a major compiler bug, probably), as I wrote in my other
> > > email which overlapped yours, this fixes the issue in next-20250422:
> > >
> > > diff --git a/lib/ratelimit.c b/lib/ratelimit.c
> > > index b5c727e976d2..fc28f6cf8269 100644
> > > --- a/lib/ratelimit.c
> > > +++ b/lib/ratelimit.c
> > > @@ -40,7 +40,7 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
> > > * interval says never limit.
> > > */
> > > if (interval <= 0 || burst <= 0) {
> > > - ret = burst > 0;
> > > + ret = 1;
> > > if (!(READ_ONCE(rs->flags) & RATELIMIT_INITIALIZED) ||
> > > !raw_spin_trylock_irqsave(&rs->lock, flags))
> > > return ret;
> >
> > You are quite right, your patch does fix the issue that you three say.
>
> Honestly, I do not understand what a ratelimit user could cause this
> issue. And I am not able to reproduce it on my test system (x86_64,
> kvm). I mean that my system boots and I see the systemd meesages.
My bug was that interval==0 suppressed all ratelimited output, when
it is instead supposed to never suppress it, as illustrated by the
RATELIMIT_STATE_INIT_DISABLED() macro that I somehow managed to ignore.
(Yes, I need more tests! And I will do so.)
> > Unfortunately, it prevents someone from completely suppressing output
> > by setting burst to zero. Could you please try the patch below?
>
> I wondered whether some code used a non-initialized struct ratelimit_state.
> I tried the following patch:
>
> diff --git a/lib/ratelimit.c b/lib/ratelimit.c
> index b5c727e976d2..f949a18e9c2b 100644
> --- a/lib/ratelimit.c
> +++ b/lib/ratelimit.c
> @@ -35,6 +35,10 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
> unsigned long flags;
> int ret;
>
> + WARN_ONCE(interval <= 0 || burst <= 0,
> + "Possibly using a non-initilized ratelimit struct with interval:%d, burst:%d\n",
> + interval, burst);
> +
> /*
> * Non-positive burst says always limit, otherwise, non-positive
> * interval says never limit.
>
>
> And it triggered:
>
> [ 2.874504] ------------[ cut here ]------------
> [ 2.875552] Possibly using a non-initilized ratelimit struct with interval:0, burst:0
> [ 2.876990] WARNING: CPU: 2 PID: 1 at lib/ratelimit.c:38 ___ratelimit+0x1e8/0x200
> [ 2.878435] Modules linked in:
> [ 2.879045] CPU: 2 UID: 0 PID: 1 Comm: swapper/0 Tainted: G W 6.15.0-rc3-next-20250422-default+ #22 PREEMPT(full) f5d77f8de4aec34e420e26410c34bcb56f692aae
> [ 2.881287] Tainted: [W]=WARN
> [ 2.882010] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.3-2-gc13ff2cd-prebuilt.qemu.org 04/01/2014
> [ 2.886452] RIP: 0010:___ratelimit+0x1e8/0x200
> [ 2.888405] Code: 00 00 e9 b5 fe ff ff 41 bc 01 00 00 00 e9 f2 fe ff ff 89 ea 44 89 e6 48 c7 c7 f8 40 eb 92 c6 05 b5 4d 0f 01 01 e8 28 a0 de fe <0f> 0b e9 71 ff ff ff 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 80 00 00
> [ 2.891223] RSP: 0000:ffffcf1340013bd8 EFLAGS: 00010282
> [ 2.892033] RAX: 0000000000000000 RBX: ffff8a8cc2bfbaf0 RCX: 0000000000000000
> [ 2.893091] RDX: 0000000000000002 RSI: 00000000ffff7fff RDI: 00000000ffffffff
> [ 2.894158] RBP: 0000000000000000 R08: 00000000ffff7fff R09: ffff8a8d3fe3ffa8
> [ 2.895168] R10: 00000000ffff8000 R11: 0000000000000001 R12: 0000000000000000
> [ 2.896150] R13: ffffffff92e08d38 R14: ffff8a8cc369e400 R15: ffff8a8cc2e39f00
> [ 2.897138] FS: 0000000000000000(0000) GS:ffff8a8da6f3c000(0000) knlGS:0000000000000000
> [ 2.898224] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 2.899181] CR2: 0000000000000000 CR3: 0000000153256001 CR4: 0000000000370ef0
> [ 2.901865] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 2.903516] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 2.906593] Call Trace:
> [ 2.907143] <TASK>
> [ 2.907582] __ext4_msg+0x6e/0xa0
Ths is the ->s_msg_ratelimit_state field of the ext4_sb_info structure,
which is allocated via kzalloc(). It looks like these two statements:
EXT4_RW_ATTR_SBI_PI(msg_ratelimit_interval_ms, s_msg_ratelimit_state.interval);
EXT4_RW_ATTR_SBI_PI(msg_ratelimit_burst, s_msg_ratelimit_state.burst);
Allow the sysadm to specify rate-limiting if desired, with the default of
no rate limiting. And zero-initialization seems like a reasonable thing
to allow for a default-never-ratelimited ratelimit_state structure, not?
So given Bert's survey of the users, would it make sense to have your
WARN_ONCE(), but only if either burst or interval is negative?
Unless you tell me otherwise, I will add that with your Signed-off-by,
and noting Bert's good work.
Thanx, Paul
> [ 2.908132] ? lock_is_held_type+0xd8/0x130
> [ 2.908755] ext4_check_feature_compatibility+0x15e/0x2c0
> [ 2.909427] __ext4_fill_super+0x543/0x1480
> [ 2.910049] ext4_fill_super+0xcc/0x280
> [ 2.910641] ? setup_bdev_super+0xfc/0x200
> [ 2.911265] ? __pfx_ext4_fill_super+0x10/0x10
> [ 2.911882] get_tree_bdev_flags+0x13e/0x1e0
> [ 2.912485] vfs_get_tree+0x29/0xe0
> [ 2.912958] ? capable+0x3a/0x60
> [ 2.913407] do_new_mount+0x176/0x360
> [ 2.913920] init_mount+0x5a/0x90
> [ 2.914389] do_mount_root+0xa2/0x130
> [ 2.914923] mount_root_generic+0xdd/0x270
> [ 2.916127] ? mount_root+0x147/0x190
> [ 2.917989] prepare_namespace+0x1e0/0x230
> [ 2.919124] kernel_init_freeable+0x1ec/0x200
> [ 2.920907] ? __pfx_kernel_init+0x10/0x10
> [ 2.922113] kernel_init+0x1a/0x130
> [ 2.922616] ret_from_fork+0x31/0x50
> [ 2.923093] ? __pfx_kernel_init+0x10/0x10
> [ 2.923612] ret_from_fork_asm+0x1a/0x30
> [ 2.924110] </TASK>
> [ 2.924433] irq event stamp: 1696665
> [ 2.924955] hardirqs last enabled at (1696675): [<ffffffff913fa54e>] __up_console_sem+0x5e/0x70
> [ 2.926072] hardirqs last disabled at (1696686): [<ffffffff913fa533>] __up_console_sem+0x43/0x70
> [ 2.927149] softirqs last enabled at (1696612): [<ffffffff9135134e>] handle_softirqs+0x32e/0x400
> [ 2.928221] softirqs last disabled at (1696591): [<ffffffff91351509>] __irq_exit_rcu+0xd9/0x150
> [ 2.929167] ---[ end trace 0000000000000000 ]---
> [ 3.003162] EXT4-fs (vda2): mounted filesystem 587ae802-e330-4059-9b48-d5b845e1075a ro with ordered data mode. Quota mode: none.
>
> I guess that it happens because the structure is initialized too late,
> see:
>
> static int __ext4_fill_super(struct fs_context *fc, struct super_block *sb)
> {
>
> [ ... skipping a lot of initialization code ... ]
>
> /* Enable message ratelimiting. Default is 10 messages per 5 secs. */
> ratelimit_state_init(&sbi->s_err_ratelimit_state, 5 * HZ, 10);
> ratelimit_state_init(&sbi->s_warning_ratelimit_state, 5 * HZ, 10);
> ratelimit_state_init(&sbi->s_msg_ratelimit_state, 5 * HZ, 10);
>
> [...]
> }
>
> I guess that it is on purpose. They most likely do not want to
> ratelimit the _very initial messages_ printed when the initialization
> fails.
>
> Maybe, it is not a good idea to allow to disable the ratelimit by
> zero burst.
>
> Best Regards,
> Petr
Powered by blists - more mailing lists