RE: [linux-next:master] [printk] 8bdbdd7f43: BUG:scheduling_while_atomic

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Greeting,

FYI, we noticed BUG:scheduling_while_atomic due to commit (built with clang-14):

commit: 8bdbdd7f43cd74c7faca6add8a62d541503ae21d ("printk: Prepare for SRCU console list protection")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master

in testcase: boot

on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


[    8.561823][    T0] BUG: scheduling while atomic: swapper/0/0x00000002
[    8.569154][    T0] no locks held by swapper/0.
[    8.571934][    T0] Modules linked in:
[    8.573001][    T0] CPU: 0 PID: 0 Comm: swapper Not tainted 6.1.0-rc1-00015-g8bdbdd7f43cd #1 9e431b4e696756e99f94acf7e74ac6e512df80ce
[    8.576740][    T0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-debian-1.16.0-4 04/01/2014
[    8.579942][    T0] Call Trace:
[    8.581143][    T0]  <TASK>
[ 8.582054][ T0] dump_stack_lvl (??:?) 
[ 8.583312][ T0] ? netdev_notice (??:?) 
[ 8.584753][ T0] ? lockdep_print_held_locks (lockdep.c:?) 
[ 8.586563][ T0] __schedule_bug (core.c:?) 
[ 8.588171][ T0] ? trace_sched_switch (core.c:?) 
[ 8.589753][ T0] ? save_trace (lockdep.c:?) 
[ 8.591135][ T0] schedule_debug (core.c:?) 
[ 8.592582][ T0] __schedule (core.c:?) 
[ 8.593902][ T0] ? __sched_text_start (core.c:?) 
[ 8.595356][ T0] ? add_chain_block (lockdep.c:?) 
[ 8.596847][ T0] ? find_held_lock (lockdep.c:?) 
[ 8.598368][ T0] schedule (??:?) 
[ 8.599564][ T0] schedule_timeout (??:?) 
[ 8.600937][ T0] ? console_conditional_schedule (??:?) 
[ 8.602773][ T0] do_wait_for_common (build_utility.c:?) 
[ 8.604522][ T0] ? console_conditional_schedule (??:?) 
[ 8.606462][ T0] ? bit_wait_io_timeout (build_utility.c:?) 
[ 8.608196][ T0] ? _raw_spin_lock_irq (??:?) 
[ 8.609935][ T0] ? lockdep_hardirqs_on (??:?) 
[ 8.611646][ T0] wait_for_completion (??:?) 
[ 8.613253][ T0] synchronize_srcu (??:?) 
[ 8.614825][ T0] ? srcu_gp_start_if_needed (??:?) 
[ 8.616664][ T0] ? rcu_read_lock_any_held (??:?) 
[ 8.618281][ T0] ? console_trylock_spinning (??:?) 
[ 8.620181][ T0] unregister_console (??:?) 
[ 8.621875][ T0] register_console (??:?) 
[ 8.623401][ T0] ? serial8250_isa_init_ports (8250_core.c:?) 
[ 8.625281][ T0] ? parse_options (super.c:?) 
[ 8.626887][ T0] univ8250_console_init (8250_core.c:?) 
[ 8.628583][ T0] console_init (??:?) 
[ 8.630025][ T0] start_kernel (??:?) 
[ 8.631558][ T0] secondary_startup_64_no_verify (??:?) 
[    8.633502][    T0]  </TASK>
[    8.634624][    T0] ------------[ cut here ]------------
[    8.636289][    T0] releasing a pinned lock
[ 8.638693][ T0] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:5352 lock_release (??:?) 
[    8.641591][    T0] Modules linked in:
[    8.642864][    T0] CPU: 0 PID: 0 Comm: swapper Tainted: G        W          6.1.0-rc1-00015-g8bdbdd7f43cd #1 9e431b4e696756e99f94acf7e74ac6e512df80ce
[    8.646469][    T0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-debian-1.16.0-4 04/01/2014
[ 8.649578][ T0] RIP: 0010:lock_release (??:?) 
[ 8.651243][ T0] Code: 00 00 e9 0f fe ff ff 48 83 05 06 f6 ff 06 01 e8 91 4e 2d 03 e9 67 fe ff ff 48 c7 c7 20 8c cf 84 e8 90 3f ec ff 48 8b 54 24 08 <0f> 0b 48 83 05 a9 f6 ff 06 01 e9 66 fc ff ff e8 67 c9 99 01 85 c0
All code
========
   0:	00 00                	add    %al,(%rax)
   2:	e9 0f fe ff ff       	jmpq   0xfffffffffffffe16
   7:	48 83 05 06 f6 ff 06 	addq   $0x1,0x6fff606(%rip)        # 0x6fff615
   e:	01 
   f:	e8 91 4e 2d 03       	callq  0x32d4ea5
  14:	e9 67 fe ff ff       	jmpq   0xfffffffffffffe80
  19:	48 c7 c7 20 8c cf 84 	mov    $0xffffffff84cf8c20,%rdi
  20:	e8 90 3f ec ff       	callq  0xffffffffffec3fb5
  25:	48 8b 54 24 08       	mov    0x8(%rsp),%rdx
  2a:*	0f 0b                	ud2    		<-- trapping instruction
  2c:	48 83 05 a9 f6 ff 06 	addq   $0x1,0x6fff6a9(%rip)        # 0x6fff6dd
  33:	01 
  34:	e9 66 fc ff ff       	jmpq   0xfffffffffffffc9f
  39:	e8 67 c9 99 01       	callq  0x199c9a5
  3e:	85 c0                	test   %eax,%eax

Code starting with the faulting instruction
===========================================
   0:	0f 0b                	ud2    
   2:	48 83 05 a9 f6 ff 06 	addq   $0x1,0x6fff6a9(%rip)        # 0x6fff6b3
   9:	01 
   a:	e9 66 fc ff ff       	jmpq   0xfffffffffffffc75
   f:	e8 67 c9 99 01       	callq  0x199c97b
  14:	85 c0                	test   %eax,%eax
[    8.656638][    T0] RSP: 0000:ffffffff862077c0 EFLAGS: 00010086
[    8.658249][    T0] RAX: 0000000000000017 RBX: ffffffff86244244 RCX: ffffffff8631a420
[    8.660383][    T0] RDX: ffffffff86244218 RSI: 0000000000000008 RDI: 0000000000000001
[    8.662798][    T0] RBP: ffffffff862078e0 R08: dffffc0000000000 R09: 00000000035545d9
[    8.665205][    T0] R10: dffff7fff0c40e7a R11: 0000000000000001 R12: ffffffff862fcf58
[    8.667420][    T0] R13: 1ffffffff0c40f06 R14: ffffffff86244220 R15: dffffc0000000000
[    8.669824][    T0] FS:  0000000000000000(0000) GS:ffffffff862ab000(0000) knlGS:0000000000000000
[    8.672552][    T0] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    8.674557][    T0] CR2: ffff88843ffff000 CR3: 0000000006235000 CR4: 00000000000406b0
[    8.677082][    T0] Call Trace:
[    8.678220][    T0]  <TASK>
[ 8.679230][ T0] ? __lock_acquire (??:?) 
[ 8.680709][ T0] ? kvm_sched_clock_read (kvmclock.c:?) 
[ 8.682309][ T0] ? sched_clock_cpu (??:?) 
[ 8.683854][ T0] ? kvm_sched_clock_read (kvmclock.c:?) 
[ 8.685268][ T0] _raw_spin_unlock (??:?) 
[ 8.686730][ T0] dequeue_task_idle (build_policy.c:?) 
[ 8.688259][ T0] ? set_next_task_idle (build_policy.c:?) 
[ 8.689822][ T0] ? update_rq_clock (??:?) 
[ 8.691387][ T0] __schedule (core.c:?) 
[ 8.692782][ T0] ? __sched_text_start (core.c:?) 
[ 8.694287][ T0] ? add_chain_block (lockdep.c:?) 
[ 8.695869][ T0] ? find_held_lock (lockdep.c:?) 
[ 8.697314][ T0] schedule (??:?) 
[ 8.698529][ T0] schedule_timeout (??:?) 
[ 8.701929][ T0] ? console_conditional_schedule (??:?) 
[ 8.703826][ T0] do_wait_for_common (build_utility.c:?) 
[ 8.705395][ T0] ? console_conditional_schedule (??:?) 
[ 8.707189][ T0] ? bit_wait_io_timeout (build_utility.c:?) 
[ 8.708779][ T0] ? _raw_spin_lock_irq (??:?) 
[ 8.710371][ T0] ? lockdep_hardirqs_on (??:?) 
[ 8.711982][ T0] wait_for_completion (??:?) 
[ 8.713487][ T0] synchronize_srcu (??:?) 
[ 8.715020][ T0] ? srcu_gp_start_if_needed (??:?) 
[ 8.716772][ T0] ? rcu_read_lock_any_held (??:?) 
[ 8.718477][ T0] ? console_trylock_spinning (??:?) 
[ 8.720179][ T0] unregister_console (??:?) 
[ 8.721644][ T0] register_console (??:?) 
[ 8.728846][ T0] ? serial8250_isa_init_ports (8250_core.c:?) 
[ 8.730692][ T0] ? parse_options (super.c:?) 
[ 8.732180][ T0] univ8250_console_init (8250_core.c:?) 
[ 8.733762][ T0] console_init (??:?) 
[ 8.735096][ T0] start_kernel (??:?) 
[ 8.736425][ T0] secondary_startup_64_no_verify (??:?) 
[    8.738088][    T0]  </TASK>
[    8.739057][    T0] irq event stamp: 494
[ 8.740376][ T0] hardirqs last enabled at (493): dump_stack_lvl (??:?) 
[ 8.743081][ T0] hardirqs last disabled at (494): __schedule (core.c:?) 
[ 8.745797][ T0] softirqs last enabled at (0): 0x0 
[ 8.747882][ T0] softirqs last disabled at (0): 0x0 
[    8.749889][    T0] ---[ end trace 0000000000000000 ]---
[    8.751520][    T0] bad: scheduling from the idle thread!
[    8.753351][    T0] CPU: 0 PID: 0 Comm: swapper Tainted: G        W          6.1.0-rc1-00015-g8bdbdd7f43cd #1 9e431b4e696756e99f94acf7e74ac6e512df80ce
[    8.757566][    T0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-debian-1.16.0-4 04/01/2014
[    8.760783][    T0] Call Trace:
[    8.761970][    T0]  <TASK>
[ 8.763067][ T0] dump_stack_lvl (??:?) 
[ 8.764611][ T0] ? netdev_notice (??:?) 
[ 8.766213][ T0] ? lockdep_hardirqs_on_prepare (??:?) 
[ 8.768214][ T0] ? print_irqtrace_events (??:?) 
[ 8.769911][ T0] ? kvm_sched_clock_read (kvmclock.c:?) 
[ 8.771550][ T0] dequeue_task_idle (build_policy.c:?) 
[ 8.773087][ T0] ? set_next_task_idle (build_policy.c:?) 
[ 8.774647][ T0] ? update_rq_clock (??:?) 
[ 8.776280][ T0] __schedule (core.c:?) 
[ 8.777729][ T0] ? __sched_text_start (core.c:?) 
[ 8.779238][ T0] ? add_chain_block (lockdep.c:?) 
[ 8.780922][ T0] ? find_held_lock (lockdep.c:?) 
[ 8.782560][ T0] schedule (??:?) 
[ 8.783988][ T0] schedule_timeout (??:?) 
[ 8.785515][ T0] ? console_conditional_schedule (??:?) 
[ 8.787500][ T0] do_wait_for_common (build_utility.c:?) 
[ 8.789162][ T0] ? console_conditional_schedule (??:?) 
[ 8.790997][ T0] ? bit_wait_io_timeout (build_utility.c:?) 
[ 8.792567][ T0] ? _raw_spin_lock_irq (??:?) 
[ 8.794292][ T0] ? lockdep_hardirqs_on (??:?) 
[ 8.796008][ T0] wait_for_completion (??:?) 
[ 8.797520][ T0] synchronize_srcu (??:?) 
[ 8.799001][ T0] ? srcu_gp_start_if_needed (??:?) 
[ 8.800696][ T0] ? rcu_read_lock_any_held (??:?) 
[ 8.802508][ T0] ? console_trylock_spinning (??:?) 
[ 8.804316][ T0] unregister_console (??:?) 
[ 8.805810][ T0] register_console (??:?) 
[ 8.807364][ T0] ? serial8250_isa_init_ports (8250_core.c:?) 
[ 8.811167][ T0] ? parse_options (super.c:?) 
[ 8.812693][ T0] univ8250_console_init (8250_core.c:?) 
[ 8.814269][ T0] console_init (??:?) 
[ 8.815765][ T0] start_kernel (??:?) 
[ 8.817296][ T0] secondary_startup_64_no_verify (??:?) 
[    8.819246][    T0]  </TASK>



Through the config file, it can be found that the following options are enabled

CONFIG_TINY_RCU=y
CONFIG_RCU_EXPERT=y
CONFIG_SRCU=y
CONFIG_TINY_SRCU=y

This problem should have been fixed:

https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git/commit/?id=0bf43fcbf8ebbf84a2b1b8770eaefcdb4a99afd6

commit dbc6ca150842650d513705f26e3e6b7a4e182ce9
Author: Zqiang <qiang1.zhang@xxxxxxxxx>
Date:   Wed Nov 9 15:36:38 2022 +0800

    srcu: Make Tiny synchronize_srcu() check for readers

    This commit adds lockdep checks for illegal use of synchronize_srcu()
    within same-type SRCU read-side critical sections and within normal
    RCU read-side critical sections.  It also makes synchronize_srcu()
    be a no-op during early boot.

    These changes bring Tiny synchronize_srcu() into line with both Tree
    synchronize_srcu() and Tiny synchronize_rcu().

    Signed-off-by: Zqiang <qiang1.zhang@xxxxxxxxx>
    Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>


Thanks
Zqiang







If you fix the issue, kindly add following tag
| Reported-by: kernel test robot <yujie.liu@xxxxxxxxx>
| Link: https://lore.kernel.org/oe-lkp/202211302358.ef0db537-yujie.liu@xxxxxxxxx


To reproduce:

        # build kernel
	cd linux
	cp config-6.1.0-rc1-00015-g8bdbdd7f43cd .config
	make HOSTCC=clang-14 CC=clang-14 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage modules
	make HOSTCC=clang-14 CC=clang-14 ARCH=x86_64 INSTALL_MOD_PATH=<mod-install-dir> modules_install
	cd <mod-install-dir>
	find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz


        git clone https://github.com/intel/lkp-tests.git
        cd lkp-tests
        bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email

        # if come across any failure that blocks the test,
        # please remove ~/.lkp and /lkp dir to run from a clean state.


-- 
0-DAY CI Kernel Test Service
https://01.org/lkp





[Index of Archives]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Bugtraq]     [Linux OMAP]     [Linux MIPS]     [eCos]     [Asterisk Internet PBX]     [Linux API]

  Powered by Linux