diff mbox series

[paulmckrcu:dev.2024.08.05a,srcu] a7adbae9c5: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_stats_print[rcutorture]

Message ID 202408191537.5ab14400-lkp@intel.com (mailing list archive)
State New
Headers show
Series [paulmckrcu:dev.2024.08.05a,srcu] a7adbae9c5: WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_stats_print[rcutorture] | expand

Commit Message

kernel test robot Aug. 19, 2024, 8:19 a.m. UTC 
hi, Paul,

we actually want to consult you about this patch. by it, the config has below


then we saw issue show for this commit:

157f4b896656dfe6 a7adbae9c55d7f85b3b8c0e8e94
---------------- ---------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
           :6           67%           6:6     rcutorture.busted_srcud.fail
           :6           83%           6:6     dmesg.EIP:rcu_torture_stats_print
           :6           83%           6:6     dmesg.WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_stats_print[rcutorture]


another diff is, for parent, we can see:

[  465.948962] busted_srcud-torture:--- End of test: SUCCESS: nreaders=1 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 stall_cpu_repeat=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000 test_nmis=0


but for this commit:


[  417.566774] busted_srcud-torture:--- End of test: FAILURE: nreaders=1 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 stall_cpu_repeat=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000 test_nmis=0


are these expected? below full report FYI.


Hello,

kernel test robot noticed "WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_stats_print[rcutorture]" on:

commit: a7adbae9c55d7f85b3b8c0e8e9417e5d52793137 ("srcu: Enable Tiny SRCU On all CONFIG_SMP=n kernels")
https://github.com/paulmckrcu/linux dev.2024.08.05a

in testcase: rcutorture
version: 
with following parameters:

	runtime: 300s
	test: default
	torture_type: busted_srcud



compiler: gcc-12
test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 4G

(please refer to attached dmesg/kmsg for entire log/backtrace)



If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202408191537.5ab14400-lkp@intel.com


[  180.101544][  T569] busted_srcud-torture: !!! 
[  180.101750][  T569] ------------[ cut here ]------------
[  180.103079][  T569] WARNING: CPU: 0 PID: 569 at kernel/rcu/rcutorture.c:2263 rcu_torture_stats_print+0x361/0x5a2 [rcutorture]
[  180.104531][  T569] Modules linked in: rcutorture torture intel_rapl_msr ipmi_devintf ipmi_msghandler mousedev bochs drm_vram_helper intel_rapl_common drm_ttm_helper crc32_pclmul ttm aesni_intel crypto_simd serio_raw drm_kms_helper rapl fuse drm drm_panel_orientation_quirks backlight i2c_core
[  180.108333][  T569] CPU: 0 UID: 0 PID: 569 Comm: rcu_torture_sta Tainted: G                T  6.11.0-rc1-00103-ga7adbae9c55d #1 89f8a658c4adbda3212056ebb1acba93a3453734
[  180.110128][  T569] Tainted: [T]=RANDSTRUCT
[  180.110676][  T569] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[  180.111951][  T569] EIP: rcu_torture_stats_print+0x361/0x5a2 [rcutorture]
[  180.112889][  T569] Code: 74 02 0f 0b 6a 00 31 c9 b8 98 4d 54 ef 0f b6 db e8 9d 96 c1 c1 31 c9 89 da b8 80 4d 54 ef 6a 00 e8 8d 96 c1 c1 4e 58 5a 7e 02 <0f> 0b 6a 00 b8 68 4d 54 ef 31 c9 89 da e8 76 96 c1 c1 58 68 8d 96
[  180.115329][  T569] EAX: 00000000 EBX: 00000001 ECX: 00000000 EDX: 00000000
[  180.116208][  T569] ESI: 00000002 EDI: 00000000 EBP: b6be3f64 ESP: b6be3ee8
[  180.116977][  T569] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068 EFLAGS: 00010202
[  180.117817][  T569] CR0: 80050033 CR2: 08082db0 CR3: 069fb000 CR4: 00040690
[  180.118722][  T569] Call Trace:
[  180.119180][  T569]  ? show_regs+0x65/0x71
[  180.119838][  T569]  ? rcu_torture_stats_print+0x361/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
[  180.121034][  T569]  ? __warn+0x92/0xd3
[  180.121591][  T569]  ? report_bug+0xdd/0x156
[  180.122212][  T569]  ? rcu_torture_stats_print+0x361/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
[  180.123567][  T569]  ? exc_overflow+0x3d/0x3d
[  180.124162][  T569]  ? handle_bug+0x2b/0x4b
[  180.124693][  T569]  ? exc_invalid_op+0x24/0x61
[  180.125262][  T569]  ? handle_exception+0x164/0x164
[  180.125896][  T569]  ? exc_overflow+0x3d/0x3d
[  180.126448][  T569]  ? rcu_torture_stats_print+0x361/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
[  180.127705][  T569]  ? exc_overflow+0x3d/0x3d
[  180.128320][  T569]  ? rcu_torture_stats_print+0x361/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
[  180.129584][  T569]  rcu_torture_stats+0x3f/0x60 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
[  180.130712][  T569]  kthread+0x109/0x10e
[  180.131226][  T569]  ? rcu_torture_stats_print+0x5a2/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
[  180.136140][  T569]  ? list_del_init+0x25/0x25
[  180.136464][  T569]  ret_from_fork+0x34/0x4d
[  180.136776][  T569]  ? list_del_init+0x25/0x25
[  180.137093][  T569]  ret_from_fork_asm+0x12/0x20
[  180.137422][  T569]  entry_INT80_32+0x124/0x124
[  180.137758][  T569] irq event stamp: 1025
[  180.138078][  T569] hardirqs last  enabled at (1047): [<b10bdcb0>] console_unlock+0x9b/0xfd
[  180.138658][  T569] hardirqs last disabled at (1056): [<b10bdc97>] console_unlock+0x82/0xfd
[  180.139225][  T569] softirqs last  enabled at (1042): [<b106fcea>] handle_softirqs+0x28a/0x2f3
[  180.139838][  T569] softirqs last disabled at (1033): [<b1b627cf>] __do_softirq+0xf/0x13
[  180.140398][  T569] ---[ end trace 0000000000000000 ]---



The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20240819/202408191537.5ab14400-lkp@intel.com

Comments

Zqiang Aug. 19, 2024, 9:11 a.m. UTC | #1 
>
>
> hi, Paul,
>
> we actually want to consult you about this patch. by it, the config has below
> diff with parent in this tests (we use randconfig here)
>
> --- /pkg/linux/i386-randconfig-004-20240810/gcc-12/157f4b896656dfe6ad6d37c94ca9a885d52f35ab/.config     2024-08-12 04:00:50.715727095 +0800
> +++ /pkg/linux/i386-randconfig-004-20240810/gcc-12/a7adbae9c55d7f85b3b8c0e8e9417e5d52793137/.config     2024-08-12 04:02:38.647990561 +0800
> @@ -136,7 +136,7 @@ CONFIG_BSD_PROCESS_ACCT_V3=y
>  CONFIG_TREE_RCU=y
>  CONFIG_PREEMPT_RCU=y
>  CONFIG_RCU_EXPERT=y
> -CONFIG_TREE_SRCU=y
> +CONFIG_TINY_SRCU=y
>  CONFIG_TASKS_RCU_GENERIC=y
>  CONFIG_FORCE_TASKS_RCU=y
>  CONFIG_NEED_TASKS_RCU=y
>
>
> then we saw issue show for this commit:
>
> 157f4b896656dfe6 a7adbae9c55d7f85b3b8c0e8e94
> ---------------- ---------------------------
>        fail:runs  %reproduction    fail:runs
>            |             |             |
>            :6           67%           6:6     rcutorture.busted_srcud.fail
>            :6           83%           6:6     dmesg.EIP:rcu_torture_stats_print
>            :6           83%           6:6     dmesg.WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_stats_print[rcutorture]
>
>
> another diff is, for parent, we can see:
>
> [  465.948962] busted_srcud-torture:--- End of test: SUCCESS: nreaders=1 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 stall_cpu_repeat=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000 test_nmis=0
>
>
> but for this commit:
>
>
> [  417.566774] busted_srcud-torture:--- End of test: FAILURE: nreaders=1 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 stall_cpu_repeat=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000 test_nmis=0
>
>
> are these expected? below full report FYI.


Due to setting ->extendables=RCUTORTURE_MAX_EXTEND for busted_srcud testing,
they use abnormal reader critical sections,   this is expected
behavior. not a problem.


>
>
> Hello,
>
> kernel test robot noticed "WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_stats_print[rcutorture]" on:
>
> commit: a7adbae9c55d7f85b3b8c0e8e9417e5d52793137 ("srcu: Enable Tiny SRCU On all CONFIG_SMP=n kernels")
> https://github.com/paulmckrcu/linux dev.2024.08.05a
>
> in testcase: rcutorture
> version:
> with following parameters:
>
>         runtime: 300s
>         test: default
>         torture_type: busted_srcud
>
>
>
> compiler: gcc-12
> test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
>
> (please refer to attached dmesg/kmsg for entire log/backtrace)
>
>
>
> If you fix the issue in a separate patch/commit (i.e. not just a new version of
> the same patch/commit), kindly add following tags
> | Reported-by: kernel test robot <oliver.sang@intel.com>
> | Closes: https://lore.kernel.org/oe-lkp/202408191537.5ab14400-lkp@intel.com
>
>
> [  180.101544][  T569] busted_srcud-torture: !!!
> [  180.101750][  T569] ------------[ cut here ]------------
> [  180.103079][  T569] WARNING: CPU: 0 PID: 569 at kernel/rcu/rcutorture.c:2263 rcu_torture_stats_print+0x361/0x5a2 [rcutorture]
> [  180.104531][  T569] Modules linked in: rcutorture torture intel_rapl_msr ipmi_devintf ipmi_msghandler mousedev bochs drm_vram_helper intel_rapl_common drm_ttm_helper crc32_pclmul ttm aesni_intel crypto_simd serio_raw drm_kms_helper rapl fuse drm drm_panel_orientation_quirks backlight i2c_core
> [  180.108333][  T569] CPU: 0 UID: 0 PID: 569 Comm: rcu_torture_sta Tainted: G                T  6.11.0-rc1-00103-ga7adbae9c55d #1 89f8a658c4adbda3212056ebb1acba93a3453734
> [  180.110128][  T569] Tainted: [T]=RANDSTRUCT
> [  180.110676][  T569] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> [  180.111951][  T569] EIP: rcu_torture_stats_print+0x361/0x5a2 [rcutorture]
> [  180.112889][  T569] Code: 74 02 0f 0b 6a 00 31 c9 b8 98 4d 54 ef 0f b6 db e8 9d 96 c1 c1 31 c9 89 da b8 80 4d 54 ef 6a 00 e8 8d 96 c1 c1 4e 58 5a 7e 02 <0f> 0b 6a 00 b8 68 4d 54 ef 31 c9 89 da e8 76 96 c1 c1 58 68 8d 96
> [  180.115329][  T569] EAX: 00000000 EBX: 00000001 ECX: 00000000 EDX: 00000000
> [  180.116208][  T569] ESI: 00000002 EDI: 00000000 EBP: b6be3f64 ESP: b6be3ee8
> [  180.116977][  T569] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068 EFLAGS: 00010202
> [  180.117817][  T569] CR0: 80050033 CR2: 08082db0 CR3: 069fb000 CR4: 00040690
> [  180.118722][  T569] Call Trace:
> [  180.119180][  T569]  ? show_regs+0x65/0x71
> [  180.119838][  T569]  ? rcu_torture_stats_print+0x361/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
> [  180.121034][  T569]  ? __warn+0x92/0xd3
> [  180.121591][  T569]  ? report_bug+0xdd/0x156
> [  180.122212][  T569]  ? rcu_torture_stats_print+0x361/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
> [  180.123567][  T569]  ? exc_overflow+0x3d/0x3d
> [  180.124162][  T569]  ? handle_bug+0x2b/0x4b
> [  180.124693][  T569]  ? exc_invalid_op+0x24/0x61
> [  180.125262][  T569]  ? handle_exception+0x164/0x164
> [  180.125896][  T569]  ? exc_overflow+0x3d/0x3d
> [  180.126448][  T569]  ? rcu_torture_stats_print+0x361/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
> [  180.127705][  T569]  ? exc_overflow+0x3d/0x3d
> [  180.128320][  T569]  ? rcu_torture_stats_print+0x361/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
> [  180.129584][  T569]  rcu_torture_stats+0x3f/0x60 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
> [  180.130712][  T569]  kthread+0x109/0x10e
> [  180.131226][  T569]  ? rcu_torture_stats_print+0x5a2/0x5a2 [rcutorture c084aa8ea4885af620a5fd08bf5503a17a237677]
> [  180.136140][  T569]  ? list_del_init+0x25/0x25
> [  180.136464][  T569]  ret_from_fork+0x34/0x4d
> [  180.136776][  T569]  ? list_del_init+0x25/0x25
> [  180.137093][  T569]  ret_from_fork_asm+0x12/0x20
> [  180.137422][  T569]  entry_INT80_32+0x124/0x124
> [  180.137758][  T569] irq event stamp: 1025
> [  180.138078][  T569] hardirqs last  enabled at (1047): [<b10bdcb0>] console_unlock+0x9b/0xfd
> [  180.138658][  T569] hardirqs last disabled at (1056): [<b10bdc97>] console_unlock+0x82/0xfd
> [  180.139225][  T569] softirqs last  enabled at (1042): [<b106fcea>] handle_softirqs+0x28a/0x2f3
> [  180.139838][  T569] softirqs last disabled at (1033): [<b1b627cf>] __do_softirq+0xf/0x13
> [  180.140398][  T569] ---[ end trace 0000000000000000 ]---
>
>
>
> The kernel config and materials to reproduce are available at:
> https://download.01.org/0day-ci/archive/20240819/202408191537.5ab14400-lkp@intel.com
>
>
>
> --
> 0-DAY CI Kernel Test Service
> https://github.com/intel/lkp-tests/wiki
>
>
kernel test robot Aug. 20, 2024, 2:26 a.m. UTC | #2 
hi, Z qiang,

On Mon, Aug 19, 2024 at 05:11:44PM +0800, Z qiang wrote:
> >
> >
> > hi, Paul,
> >
> > we actually want to consult you about this patch. by it, the config has below
> > diff with parent in this tests (we use randconfig here)
> >
> > --- /pkg/linux/i386-randconfig-004-20240810/gcc-12/157f4b896656dfe6ad6d37c94ca9a885d52f35ab/.config     2024-08-12 04:00:50.715727095 +0800
> > +++ /pkg/linux/i386-randconfig-004-20240810/gcc-12/a7adbae9c55d7f85b3b8c0e8e9417e5d52793137/.config     2024-08-12 04:02:38.647990561 +0800
> > @@ -136,7 +136,7 @@ CONFIG_BSD_PROCESS_ACCT_V3=y
> >  CONFIG_TREE_RCU=y
> >  CONFIG_PREEMPT_RCU=y
> >  CONFIG_RCU_EXPERT=y
> > -CONFIG_TREE_SRCU=y
> > +CONFIG_TINY_SRCU=y
> >  CONFIG_TASKS_RCU_GENERIC=y
> >  CONFIG_FORCE_TASKS_RCU=y
> >  CONFIG_NEED_TASKS_RCU=y
> >
> >
> > then we saw issue show for this commit:
> >
> > 157f4b896656dfe6 a7adbae9c55d7f85b3b8c0e8e94
> > ---------------- ---------------------------
> >        fail:runs  %reproduction    fail:runs
> >            |             |             |
> >            :6           67%           6:6     rcutorture.busted_srcud.fail
> >            :6           83%           6:6     dmesg.EIP:rcu_torture_stats_print
> >            :6           83%           6:6     dmesg.WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_stats_print[rcutorture]
> >
> >
> > another diff is, for parent, we can see:
> >
> > [  465.948962] busted_srcud-torture:--- End of test: SUCCESS: nreaders=1 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 stall_cpu_repeat=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000 test_nmis=0
> >
> >
> > but for this commit:
> >
> >
> > [  417.566774] busted_srcud-torture:--- End of test: FAILURE: nreaders=1 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 stall_cpu_repeat=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000 test_nmis=0
> >
> >
> > are these expected? below full report FYI.
> 
> 
> Due to setting ->extendables=RCUTORTURE_MAX_EXTEND for busted_srcud testing,
> they use abnormal reader critical sections,   this is expected
> behavior. not a problem.


got it. thanks a lot for information.
diff mbox series

Patch

diff with parent in this tests (we use randconfig here)

--- /pkg/linux/i386-randconfig-004-20240810/gcc-12/157f4b896656dfe6ad6d37c94ca9a885d52f35ab/.config     2024-08-12 04:00:50.715727095 +0800
+++ /pkg/linux/i386-randconfig-004-20240810/gcc-12/a7adbae9c55d7f85b3b8c0e8e9417e5d52793137/.config     2024-08-12 04:02:38.647990561 +0800
@@ -136,7 +136,7 @@  CONFIG_BSD_PROCESS_ACCT_V3=y
 CONFIG_TREE_RCU=y
 CONFIG_PREEMPT_RCU=y
 CONFIG_RCU_EXPERT=y
-CONFIG_TREE_SRCU=y
+CONFIG_TINY_SRCU=y
 CONFIG_TASKS_RCU_GENERIC=y
 CONFIG_FORCE_TASKS_RCU=y
 CONFIG_NEED_TASKS_RCU=y