lkml.org 
[lkml]   [2023]   [Mar]   [13]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
From
SubjectRe: Linux 6.3-rc2
On 3/13/23 16:11, Frederic Weisbecker wrote:
> On Mon, Mar 13, 2023 at 11:21:44AM -0700, Linus Torvalds wrote:
[ ... ]
> It would be interesting to see what the IRQ is interrupting. For example does it
> happen while softirqs are serviced or just disabled? Or are we even outside any
> of that? Any chance we can have a deeper stack trace? If not at least a print of
> preempt_count() would be helpful.
>
> Both would be awesome.
>
> diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
> index 50d4863974e7..a7d1a65e5425 100644
> --- a/kernel/locking/lockdep.c
> +++ b/kernel/locking/lockdep.c
> @@ -5523,6 +5523,7 @@ static noinstr void check_flags(unsigned long flags)
> */
> if (!hardirq_count()) {
> if (softirq_count()) {
> + printk("preempt_count(): %x", preempt_count());
> /* like the above, but with softirqs */
> DEBUG_LOCKS_WARN_ON(current->softirqs_enabled);
> } else {
>

That crashed nicely; it didn't like the unconditional printk().
With

diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 50d4863974e7..ea4f76e2d815 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -5524,7 +5524,9 @@ static noinstr void check_flags(unsigned long flags)
if (!hardirq_count()) {
if (softirq_count()) {
/* like the above, but with softirqs */
- DEBUG_LOCKS_WARN_ON(current->softirqs_enabled);
+ if (DEBUG_LOCKS_WARN_ON(current->softirqs_enabled))
+ printk("preempt_count(): %x softirq_count(): %lx",
+ preempt_count(), softirq_count());
} else {
/* lick the above, does it taste good? */
DEBUG_LOCKS_WARN_ON(!current->softirqs_enabled);
I got the following (decoded):

[ 11.360487] WARNING: CPU: 0 PID: 233 at kernel/locking/lockdep.c:5527 check_flags (./arch/arm/include/asm/current.h:36 (discriminator 12) ./include/asm-generic/preempt.h:11 (discriminator 12) kernel/locking/lockdep.c:5528 (discriminator 12))
[ 11.361102] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled)
[ 11.361173] Modules linked in:
[ 11.361730] CPU: 0 PID: 233 Comm: rcS Tainted: G N 6.3.0-rc2-dirty #2
[ 11.361921] Hardware name: Freescale i.MX6 Ultralite (Device Tree)
[ 11.362303] unwind_backtrace from show_stack (arch/arm/kernel/traps.c:258)
[ 11.362441] show_stack from dump_stack_lvl (lib/dump_stack.c:107 (discriminator 4))
[ 11.362519] dump_stack_lvl from __warn (./include/linux/jump_label.h:260 ./include/linux/jump_label.h:270 ./include/trace/events/error_report.h:69 kernel/panic.c:681)
[ 11.362598] __warn from warn_slowpath_fmt (./arch/arm/include/asm/current.h:36 ./include/asm-generic/preempt.h:16 ./include/asm-generic/preempt.h:59 ./include/linux/context_tracking.h:154 kernel/panic.c:706)
[ 11.362702] warn_slowpath_fmt from check_flags (./arch/arm/include/asm/current.h:36 (discriminator 12) ./include/asm-generic/preempt.h:11 (discriminator 12) kernel/locking/lockdep.c:5528 (discriminator 12))
[ 11.362780] check_flags from lock_is_held_type (./arch/arm/include/asm/percpu.h:37 kernel/locking/lockdep.c:462 kernel/locking/lockdep.c:5713)
[ 11.362851] lock_is_held_type from rcu_read_lock_sched_held (kernel/rcu/update.c:125)
[ 11.362933] rcu_read_lock_sched_held from trace_rcu_dyntick (./include/trace/events/rcu.h:480 (discriminator 28))
[ 11.363016] trace_rcu_dyntick from ct_nmi_enter (./arch/arm/include/asm/percpu.h:37 (discriminator 4) ./include/linux/context_tracking_state.h:90 (discriminator 4) kernel/context_tracking.c:301 (discriminator 4))
[ 11.363108] ct_nmi_enter from irq_enter (kernel/softirq.c:625)
[ 11.363177] irq_enter from generic_handle_arch_irq (kernel/irq/handle.c:238)
[ 11.363251] generic_handle_arch_irq from call_with_stack (arch/arm/lib/call_with_stack.S:45)
[ 11.363339] call_with_stack from __irq_svc (arch/arm/kernel/entry-armv.S:232)
[ 11.363438] Exception stack(0xd1819f60 to 0xd1819fa8)
[ 11.363629] 9f60: ecac8b10 40000000 b6f88418 c1c2607c 00000000 40000000 c4acc00b 00000001
[ 11.363740] 9f80: 00000b00 c0101278 c4acc0f0 00000000 00000051 d1819fb0 c01011c4 c0103c1c
[ 11.363833] 9fa0: 00000013 ffffffff
[ 11.363896] __irq_svc from vfp_reload_hw (arch/arm/vfp/vfphw.S:149)
[ 11.364015] irq event stamp: 1626
[ 11.364069] hardirqs last enabled at (1625): __und_usr (arch/arm/kernel/entry-armv.S:465)
[ 11.364199] hardirqs last disabled at (1626): __irq_svc (arch/arm/kernel/entry-armv.S:221)
[ 11.364290] softirqs last enabled at (1424): __do_softirq (./arch/arm/include/asm/current.h:36 ./include/asm-generic/preempt.h:11 kernel/softirq.c:415 kernel/softirq.c:600)
[ 11.364396] softirqs last disabled at (1323): __irq_exit_rcu (kernel/softirq.c:445 kernel/softirq.c:650)
[ 11.364494] ---[ end trace 0000000000000000 ]---
[ 11.364637] preempt_count(): 201 softirq_count(): 200
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ 11.364659] irq event stamp: 1626
[ 11.364757] hardirqs last enabled at (1625): __und_usr (arch/arm/kernel/entry-armv.S:465)
[ 11.364843] hardirqs last disabled at (1626): __irq_svc (arch/arm/kernel/entry-armv.S:221)
[ 11.364926] softirqs last enabled at (1424): __do_softirq (./arch/arm/include/asm/current.h:36 ./include/asm-generic/preempt.h:11 kernel/softirq.c:415 kernel/softirq.c:600)
[ 11.365014] softirqs last disabled at (1323): __irq_exit_rcu (kernel/softirq.c:445 kernel/softirq.c:650)
Does that tell you anything ?

Thanks,
Guenter

\
 
 \ /
  Last update: 2023-03-27 00:57    [W:0.113 / U:0.608 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site