Re: [BUG] Re: Linux 6.4.4

Zhouyi Zhou
2023-07-22T01:00:30Z

On Fri, Jul 21, 2023 at 9:51 AM Zhouyi Zhou <zhouzhouyi@gmail.com> wrote:
>
> On Thu, Jul 20, 2023 at 9:31 PM Joel Fernandes <joel@joelfernandes.org> wrote:
> >
> > On Wed, Jul 19, 2023 at 05:06:39PM +0200, Greg Kroah-Hartman wrote:
> > > I'm announcing the release of the 6.4.4 kernel.
> > >
> > > All users of the 6.4 kernel series must upgrade.
> > >
> > > The updated 6.4.y git tree can be found at:
> > > git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git linux-6.4.y
> > > and can be browsed at the normal kernel.org git web browser:
> > > https://git.kernel.org/?p=linux/kernel/git/stable/linux-stable.git;a=summary
> >
> > I have been consistently hitting the following splat with rcutorture's TREE03
> > test on 6.4.4. This happened with 6.4.4-rc3 as well.
> Hi, I am also interested in this topic , I am going to test 6.4.4 on my laptop
I rcu tortured 6.4.4 on my Intel(R) Core(TM) i7-11800H laptop for 2
rounds each of which lasting 7 hours.
all of them report:
Summary: Successes: 55 Failures: 0.

Thanks, Zhouyi
>
> Thanks, Zhouyi
> >
> > Happens at:
> > WARN_ON_ONCE(n_rcu_torture_boost_failure); // boost failed (TIMER_SOFTIRQ RT prio?)
> >
> > So likely RCU boosting is failing:
> >
> > The full TREE03 splat:
> > [ 54.243588] ------------[ cut here ]------------
> > [ 54.244547] rcu-torture: rcu_torture_boost started
> > [ 54.247643] WARNING: CPU: 12 PID: 166 at kernel/rcu/rcutorture.c:2227 rcu_torture_stats_print+0x5b2/0x620
> > [ 54.273082] Modules linked in:
> > [ 54.278336] CPU: 12 PID: 166 Comm: rcu_torture_sta Not tainted 6.4.4-g62813c2d2a36 #1
> > [ 54.288540] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> > [ 54.300499] RIP: 0010:rcu_torture_stats_print+0x5b2/0x620
> > [ 54.307525] Code: 00 00 48 8b 05 3f 6c 46 02 e9 4a fe ff ff 0f 0b e9 02 fd ff ff 0f 0b e9 09 fd ff ff 0f 0b e9 10 fd ff ff 0f 0b e9 17 fd ff ff <0f> 0b e9 1e fd ff ff 0f 0b e9 21 fd ff ff e8 0b 54 ff ff 84 c0 0f
> > [ 54.331276] RSP: 0000:ffff9fef805efe08 EFLAGS: 00010202
> > [ 54.338374] RAX: 0000000000000000 RBX: ffff9fef805efe88 RCX: 00000000ffffdfff
> > [ 54.347738] RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000001
> > [ 54.358923] RBP: ffff9fef805efe30 R08: 00000000ffffdfff R09: 00000000ffffdfff
> > [ 54.368209] R10: ffffffff94e59280 R11: ffffffff94e59280 R12: 0000000000000001
> > [ 54.377367] R13: 0000000000000000 R14: 00000000000002fc R15: ffffffff93514000
> > [ 54.386739] FS: 0000000000000000(0000) GS:ffff9c901f500000(0000) knlGS:0000000000000000
> > [ 54.397130] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 54.404585] CR2: 0000000000000000 CR3: 000000000308e000 CR4: 00000000000006e0
> > [ 54.413884] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [ 54.423118] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [ 54.432192] Call Trace:
> > [ 54.435634] <TASK>
> > [ 54.438512] ? rcu_torture_stats_print+0x5b2/0x620
> > [ 54.444904] ? __warn+0x7c/0x130
> > [ 54.449221] ? rcu_torture_stats_print+0x5b2/0x620
> > [ 54.455737] ? report_bug+0x171/0x1a0
> > [ 54.460935] ? handle_bug+0x3c/0x70
> > [ 54.465874] ? exc_invalid_op+0x17/0x70
> > [ 54.471336] ? asm_exc_invalid_op+0x1a/0x20
> > [ 54.477092] ? __pfx_rcu_torture_stats+0x10/0x10
> > [ 54.483472] ? rcu_torture_stats_print+0x5b2/0x620
> > [ 54.490029] ? rcu_torture_stats_print+0x28a/0x620
> > [ 54.496565] ? finish_task_switch.isra.0+0x7e/0x240
> > [ 54.503261] rcu_torture_stats+0x25/0x70
> > [ 54.508686] kthread+0xe3/0x110
> > [ 54.513141] ? __pfx_kthread+0x10/0x10
> > [ 54.518330] ret_from_fork+0x2c/0x50
> > [ 54.523356] </TASK>
> > [ 54.526500] ---[ end trace 0000000000000000 ]---
> >
> > Also other issues in 6.4.4, I am seeing RCU failures with TREE07 about 40
> > minutes into the test. This warning indicates that an rcu_torture object from
> > the rcu_torture pool is still allocated which is an indiciation that RCU is
> > not working.
> >
> > [ 2169.481783] rcu_torture_writer: rtort_pipe_count: 9
> >
> > However, if we are to believe the '9', it appears the object did made it
> > quite some till the end of the pipe array but not until the free pool.
> >
> > The full TREE07 splat:
> > [ 2169.481783] rcu_torture_writer: rtort_pipe_count: 9
> > [ 2169.489413] WARNING: CPU: 4 PID: 130 at kernel/rcu/rcutorture.c:1584 rcu_torture_writer+0x7f2/0xd80
> > [ 2169.504064] Modules linked in:
> > [ 2169.508957] CPU: 4 PID: 130 Comm: rcu_torture_wri Not tainted 6.4.4-g62813c2d2a36 #2
> > [ 2169.521735] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> > [ 2169.540908] RIP: 0010:rcu_torture_writer+0x7f2/0xd80
> > [ 2169.548542] Code: 15 8b 62 45 02 49 8d 45 e8 48 39 c2 74 bf e8 85 03 08 00 41 8b 55 f8 48 c7 c6 d0 f7 e0 9d 48 c7 c7 d7 7b 28 9e e8 ce 29 f7 ff <0f> 0b 8b 05 9a 48 45 02 85 c0 75 97 89 d8 87 05 8e 48 45 02 85 c0
> > [ 2169.578445] RSP: 0000:ffffa645804cfe20 EFLAGS: 00010282
> > [ 2169.586793] RAX: 0000000000000000 RBX: 0000000000000001 RCX: 00000000ffffdfff
> > [ 2169.598069] RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000009ffb
> > [ 2169.609359] RBP: ffffa645804cff10 R08: 00000000ffffdfff R09: 00000000ffffdfff
> > [ 2169.620717] R10: ffffffff9e659220 R11: ffffffff9e659220 R12: 0000000000000017
> > [ 2169.631918] R13: ffffffff9f166b60 R14: 0000000000000000 R15: 0000000000000001
> > [ 2169.643365] FS: 0000000000000000(0000) GS:ffff8b3a5f300000(0000) knlGS:0000000000000000
> > [ 2169.655249] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 2169.663207] CR2: 0000000000000000 CR3: 000000001562e000 CR4: 00000000000006e0
> > [ 2169.672806] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [ 2169.682194] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [ 2169.693530] Call Trace:
> > [ 2169.698054] <TASK>
> > [ 2169.701786] ? rcu_torture_writer+0x7f2/0xd80
> > [ 2169.708853] ? __warn+0x7c/0x120
> > [ 2169.714088] ? rcu_torture_writer+0x7f2/0xd80
> > [ 2169.721066] ? report_bug+0x15d/0x180
> > [ 2169.726125] ? handle_bug+0x3c/0x70
> > [ 2169.730948] ? exc_invalid_op+0x17/0x70
> > [ 2169.736238] ? asm_exc_invalid_op+0x1a/0x20
> > [ 2169.742047] ? rcu_torture_writer+0x7f2/0xd80
> > [ 2169.747907] ? __pfx_rcu_torture_writer+0x10/0x10
> > [ 2169.754175] kthread+0xcb/0xf0
> > [ 2169.758407] ? __pfx_kthread+0x10/0x10
> > [ 2169.763501] ret_from_fork+0x2c/0x50
> > [ 2169.768420] </TASK>
> > [ 2169.771445] ---[ end trace 0000000000000000 ]---
> > [ 2169.777698] Dumping ftrace buffer:
> > [ 2169.782470] (ftrace buffer empty)
> > [ 2169.787241] ------------[ cut here ]------------
> >
> >
> > I will continue to monitor and debug these but since I recently re-started
> > testing stable (my infra was down for a long time), I don't have any
> > reference for when these started happening.
> >
> > thanks,
> >
> > - Joel
> >