Sender: Guenter Roeck <groeck7@gmail.com>
Message-ID: <dc031bc7-8ca4-7ca7-c24f-9db65b5547e4@roeck-us.net>
Date:   Mon, 13 Mar 2023 17:52:49 -0700
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.7.1
Content-Language: en-US
To:     Frederic Weisbecker <frederic@kernel.org>,
        Linus Torvalds <torvalds@linux-foundation.org>
Cc:     "Paul E. McKenney" <paulmck@kernel.org>,
        Peter Zijlstra <peterz@infradead.org>,
        Linux Kernel Mailing List <linux-kernel@vger.kernel.org>
References: <CAHk-=wii6BZtVKYfvQCQqbE3+t1_yAb-ea80-3PcJ4KxgpfHkA@mail.gmail.com>
 <d915df60-d06b-47d4-8b47-8aa1bbc2aac7@roeck-us.net>
 <CAHk-=wi8xQw6eTRncbJfWWYHHi0UBG2B_AfHrzZbPr=k0V_WYQ@mail.gmail.com>
 <ZA+ttVOPBvNOYHoC@lothringen>
From:   Guenter Roeck <linux@roeck-us.net>
Subject: Re: Linux 6.3-rc2
In-Reply-To: <ZA+ttVOPBvNOYHoC@lothringen>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit
Precedence: bulk

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