* FYI, a few new KCSAN splats
@ 2021-12-14 4:57 Paul E. McKenney
2021-12-14 8:38 ` Zhouyi Zhou
0 siblings, 1 reply; 11+ messages in thread
From: Paul E. McKenney @ 2021-12-14 4:57 UTC (permalink / raw)
To: rcu
Hello!
At first glance, a WRITE_ONCE() in rcu_segcblist_set_flags() would cure
all these, but I thought I should double check. Thoughts?
Thanx, Paul
------------------------------------------------------------------------
BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_nocb_gp_kthread
[34453.430323] read (marked) to 0xffff9dd1df26cb50 of 1 bytes by task 24 on cpu 13:
[34453.431069] rcu_nocb_cb_kthread+0x18b/0x760
[34453.431523] kthread+0x29b/0x2b0
[34453.431864] ret_from_fork+0x22/0x30
[34453.432245]
[34453.432418] no locks held by rcuop/1/24.
[34453.432823] irq event stamp: 13161844
[34453.433208] hardirqs last enabled at (13161844): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[34453.434220] hardirqs last disabled at (13161843): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
[34453.435129] softirqs last enabled at (13161839): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
[34453.435979] softirqs last disabled at (13161837): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
[34453.436857]
[34453.437020] write to 0xffff9dd1df26cb50 of 1 bytes by task 15 on cpu 3:
[34453.437680] rcu_nocb_gp_kthread+0x3a3/0x1180
[34453.438137] kthread+0x29b/0x2b0
[34453.438482] ret_from_fork+0x22/0x30
[34453.438861]
[34453.439028] 1 lock held by rcuog/0/15:
[34453.439414] #0: ffff9dd1df26cc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
[34453.440382] irq event stamp: 22823959
[34453.440721] hardirqs last enabled at (22823958): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[34453.441892] hardirqs last disabled at (22823959): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
[34453.442831] softirqs last enabled at (22823695): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[34453.443721] softirqs last disabled at (22823672): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
0xffffffff811b275b is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:71).
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
70 {
71 return READ_ONCE(rsclp->flags) & flags;
72 }
73
74 /*
75 * Is the specified rcu_segcblist enabled, for example, not corresponding
0xffffffff811b17f3 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:59).
54 }
55
56 static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
57 int flags)
58 {
59 rsclp->flags |= flags;
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
------------------------------------------------------------------------
BUG: KCSAN: data-race in rcu_core / rcu_nocb_cb_kthread
[35979.380848]
[35979.380999] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by interrupt on cpu 15:
[35979.381735] rcu_core+0x57/0x860
[35979.382058] rcu_core_si+0x12/0x20
[35979.382400] __do_softirq+0x1f9/0x37c
[35979.382749] run_ksoftirqd+0x4c/0x80
[35979.383097] smpboot_thread_fn+0x28b/0x390
[35979.383492] kthread+0x29b/0x2b0
[35979.383805] ret_from_fork+0x22/0x30
[35979.384149]
[35979.384298] no locks held by ksoftirqd/15/173.
[35979.384711] irq event stamp: 2431400
[35979.385049] hardirqs last enabled at (2431400): [<ffffffff9ca000de>] __do_softirq+0xde/0x37c
[35979.385841] hardirqs last disabled at (2431398): [<ffffffff9b0c060e>] run_ksoftirqd+0x2e/0x80
[35979.386631] softirqs last enabled at (2431394): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
[35979.387429] softirqs last disabled at (2431399): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
[35979.388215]
[35979.388364] write to 0xffff9dd1df5ecb50 of 1 bytes by task 176 on cpu 10:
[35979.388996] rcu_nocb_cb_kthread+0x479/0x760
[35979.389427] kthread+0x29b/0x2b0
[35979.389752] ret_from_fork+0x22/0x30
[35979.390106]
[35979.390260] 1 lock held by rcuop/15/176:
[35979.390634] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
0xffffffff811ad657 is in rcu_core (kernel/rcu/rcu_segcblist.h:71).
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
70 {
71 return READ_ONCE(rsclp->flags) & flags;
72 }
73
74 /*
75 * Is the specified rcu_segcblist enabled, for example, not corresponding
0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
64 {
65 rsclp->flags &= ~flags;
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
------------------------------------------------------------------------
BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_rdp_is_offloaded
[27570.512032] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by task 0 on cpu 15:
[27570.512770] rcu_rdp_is_offloaded+0x63/0x1c0
[27570.513222] rcu_needs_cpu+0x80/0xa0
[27570.513601] tick_nohz_next_event+0x1d4/0x300
[27570.514063] tick_nohz_idle_stop_tick+0x8f/0x3d0
[27570.514532] do_idle+0x108/0x2b0
[27570.514884] cpu_startup_entry+0x15/0x20
[27570.515301] secondary_startup_64_no_verify+0xc3/0xcb
[27570.515858]
[27570.515997] write to 0xffff9dd1df5ecb50 of 1 bytes by task 176 on cpu 0:
[27570.516577] rcu_nocb_cb_kthread+0x479/0x760
[27570.517358] kthread+0x29b/0x2b0
[27570.517712] ret_from_fork+0x22/0x30
[27570.518121]
[27570.518284] 1 lock held by rcuop/15/176:
[27570.518691] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
[27570.519677] irq event stamp: 20494903
[27570.520068] hardirqs last enabled at (20494902): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
[27570.536982] hardirqs last disabled at (20494903): [<ffffffff9b1b28b7>] rcu_nocb_cb_kthread+0x2e7/0x760
[27570.537913] softirqs last enabled at (20494901): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
[27570.538697] softirqs last disabled at (20494899): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
rcu_rdp_is_offloaded+0x63
0xffffffff8119a543 is in rcu_rdp_is_offloaded (kernel/rcu/rcu_segcblist.h:71).
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
70 {
71 return READ_ONCE(rsclp->flags) & flags;
72 }
73
74 /*
75 * Is the specified rcu_segcblist enabled, for example, not corresponding
0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
64 {
65 rsclp->flags &= ~flags;
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
------------------------------------------------------------------------
BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_segcblist_ready_cbs
[22938.718032] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by interrupt on cpu 15:
[22938.718839] rcu_segcblist_ready_cbs+0x1a/0x40
[22938.719333] rcu_core+0x351/0x860
[22938.719703] rcu_core_si+0x12/0x20
[22938.720076] __do_softirq+0x1f9/0x37c
[22938.720470] run_ksoftirqd+0x4c/0x80
[22938.720879] smpboot_thread_fn+0x28b/0x390
[22938.721339] kthread+0x29b/0x2b0
[22938.721703] ret_from_fork+0x22/0x30
[22938.722089]
[22938.722252] no locks held by ksoftirqd/15/173.
[22938.722719] irq event stamp: 1553879
[22938.723104] hardirqs last enabled at (1553879): [<ffffffff9b1a7a8c>] note_gp_changes+0x1ac/0x1e0
[22938.723996] hardirqs last disabled at (1553878): [<ffffffff9b1a793b>] note_gp_changes+0x5b/0x1e0
[22938.724835] softirqs last enabled at (1553871): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
[22938.736913] softirqs last disabled at (1553876): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
[22938.737836]
[22938.738013] write to 0xffff9dd1df5ecb50 of 1 bytes by task 154 on cpu 10:
[22938.738725] rcu_nocb_gp_kthread+0x328/0x1180
[22938.739210] kthread+0x29b/0x2b0
[22938.739564] ret_from_fork+0x22/0x30
[22938.739963]
[22938.740141] 1 lock held by rcuog/12/154:
[22938.740578] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
[22938.741584] irq event stamp: 19190924
[22938.741987] hardirqs last enabled at (19190923): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[22938.743018] hardirqs last disabled at (19190924): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
[22938.743991] softirqs last enabled at (19189530): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[22938.744919] softirqs last disabled at (19189525): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
0xffffffff811b397a is in rcu_segcblist_ready_cbs (kernel/rcu/rcu_segcblist.h:71).
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
70 {
71 return READ_ONCE(rsclp->flags) & flags;
72 }
73
74 /*
75 * Is the specified rcu_segcblist enabled, for example, not corresponding
0xffffffff811b1778 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:65).
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
64 {
65 rsclp->flags &= ~flags;
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
------------------------------------------------------------------------
BUG: KCSAN: data-race in rcu_core / rcu_nocb_gp_kthread
[17703.531588] read (marked) to 0xffff9dd1df4ecb50 of 1 bytes by interrupt on cpu 11:
[17703.532349] rcu_segcblist_ready_cbs+0x1a/0x40
[17703.532801] rcu_core+0x351/0x860
[17703.533151] rcu_core_si+0x12/0x20
[17703.533515] __do_softirq+0x1f9/0x37c
[17703.533910] run_ksoftirqd+0x4c/0x80
[17703.534296] smpboot_thread_fn+0x28b/0x390
[17703.534741] kthread+0x29b/0x2b0
[17703.535111] ret_from_fork+0x22/0x30
[17703.535502]
[17703.535671] no locks held by ksoftirqd/11/143.
[17703.536162] irq event stamp: 1277315
[17703.536541] hardirqs last enabled at (1277315): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[17703.537604] hardirqs last disabled at (1277314): [<ffffffff9b1a793b>] note_gp_changes+0x5b/0x1e0
[17703.538666] softirqs last enabled at (1277307): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
[17703.539560] softirqs last disabled at (1277312): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
[17703.540445]
[17703.540611] write to 0xffff9dd1df4ecb50 of 1 bytes by task 117 on cpu 0:
[17703.541320] rcu_nocb_gp_kthread+0x328/0x1180
[17703.541774] kthread+0x29b/0x2b0
[17703.542154] ret_from_fork+0x22/0x30
[17703.542544]
[17703.542712] 1 lock held by rcuog/8/117:
[17703.543126] #0: ffff9dd1df4ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
[17703.544068] irq event stamp: 14934462
[17703.544454] hardirqs last enabled at (14934461): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[17703.545469] hardirqs last disabled at (14934462): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
[17703.546442] softirqs last enabled at (14934440): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[17703.547667] softirqs last disabled at (14934429): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
0xffffffff811b397a is in rcu_segcblist_ready_cbs (kernel/rcu/rcu_segcblist.h:71).
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
70 {
71 return READ_ONCE(rsclp->flags) & flags;
72 }
73
74 /*
75 * Is the specified rcu_segcblist enabled, for example, not corresponding
0xffffffff811b1778 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:65).
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
64 {
65 rsclp->flags &= ~flags;
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
------------------------------------------------------------------------
BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_nocb_rdp_deoffload
[25747.783445] read (marked) to 0xffff9dd1df5acb50 of 1 bytes by task 28476 on cpu 14:
[25747.784193] rcu_nocb_rdp_deoffload+0x1a3/0x380
[25747.784675] work_for_cpu_fn+0x32/0x50
[25747.785071] process_one_work+0x54f/0x840
[25747.785488] worker_thread+0x79c/0xa90
[25747.785884] kthread+0x29b/0x2b0
[25747.786230] ret_from_fork+0x22/0x30
[25747.786611]
[25747.786778] 2 locks held by kworker/14:2/28476:
[25747.787244] #0: ffff9dd1c1054738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x4d7/0x840
[25747.788196] #1: ffffabe581ce3dd0 ((work_completion)(&wfc.work)){+.+.}-{0:0}, at: process_one_work+0x508/0x840
[25747.789216] irq event stamp: 47423
[25747.789563] hardirqs last enabled at (47423): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[25747.790533] hardirqs last disabled at (47422): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
[25747.791450] softirqs last enabled at (47410): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[25747.792253] softirqs last disabled at (47405): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[25747.804153]
[25747.804319] write to 0xffff9dd1df5acb50 of 1 bytes by task 169 on cpu 13:
[25747.805254] rcu_nocb_cb_kthread+0x479/0x760
[25747.805701] kthread+0x29b/0x2b0
[25747.806156] ret_from_fork+0x22/0x30
[25747.806581]
[25747.806747] 1 lock held by rcuop/14/169:
[25747.807344] #0: ffff9dd1df5acc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
[25747.809333] irq event stamp: 19677863
[25747.810093] hardirqs last enabled at (19677862): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
[25747.820095] hardirqs last disabled at (19677863): [<ffffffff9b1b28b7>] rcu_nocb_cb_kthread+0x2e7/0x760
[25747.822317] softirqs last enabled at (19677861): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
[25747.824060] softirqs last disabled at (19677859): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
0xffffffff811a5853 is in rcu_nocb_rdp_deoffload (kernel/rcu/rcu_segcblist.h:71).
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
70 {
71 return READ_ONCE(rsclp->flags) & flags;
72 }
73
74 /*
75 * Is the specified rcu_segcblist enabled, for example, not corresponding
0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
64 {
65 rsclp->flags &= ~flags;
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
------------------------------------------------------------------------
BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_nocb_rdp_offload
[15688.905747] read (marked) to 0xffff9dd1df56cb50 of 1 bytes by task 154 on cpu 9:
[15688.906550] rcu_nocb_gp_kthread+0x237/0x1180
[15688.907050] kthread+0x29b/0x2b0
[15688.907421] ret_from_fork+0x22/0x30
[15688.907824]
[15688.908022] no locks held by rcuog/12/154.
[15688.908468] irq event stamp: 13085451
[15688.908865] hardirqs last enabled at (13085451): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[15688.909929] hardirqs last disabled at (13085450): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
[15688.910949] softirqs last enabled at (13085112): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[15688.911908] softirqs last disabled at (13085107): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[15688.912849]
[15688.913043] write to 0xffff9dd1df56cb50 of 1 bytes by task 16476 on cpu 13:
[15688.913830] rcu_nocb_rdp_offload+0x24e/0x2c0
[15688.914364] work_for_cpu_fn+0x32/0x50
[15688.914805] process_one_work+0x54f/0x840
[15688.915159] worker_thread+0x79c/0xa90
[15688.915544] kthread+0x29b/0x2b0
[15688.915907] ret_from_fork+0x22/0x30
[15688.916325]
[15688.916502] 3 locks held by kworker/13:0/16476:
[15688.917016] #0: ffff9dd1c1054738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x4d7/0x840
[15688.918073] #1: ffffabe585163dd0 ((work_completion)(&wfc.work)){+.+.}-{0:0}, at: process_one_work+0x508/0x840
[15688.919153] #2: ffff9dd1df56cc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_rdp_offload+0x237/0x2c0
[15688.920171] irq event stamp: 198553
[15688.920539] hardirqs last enabled at (198552): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[15688.921577] hardirqs last disabled at (198553): [<ffffffff9b1a5d5e>] rcu_nocb_rdp_offload+0x21e/0x2c0
[15688.922553] softirqs last enabled at (198341): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[15688.923462] softirqs last disabled at (198336): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
0xffffffff811b1687 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:71).
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
70 {
71 return READ_ONCE(rsclp->flags) & flags;
72 }
73
74 /*
75 * Is the specified rcu_segcblist enabled, for example, not corresponding
0xffffffff811a5d8e is in rcu_nocb_rdp_offload (kernel/rcu/rcu_segcblist.h:65).
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
64 {
65 rsclp->flags &= ~flags;
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
------------------------------------------------------------------------
BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_rdp_is_offloaded
[30067.322599] read (marked) to 0xffff9dd1df2ecb50 of 1 bytes by interrupt on cpu 3:
[30067.323367] rcu_rdp_is_offloaded+0x63/0x1c0
[30067.323929] rcu_sched_clock_irq+0x9d2/0x18d0
[30067.324269] update_process_times+0xe9/0x110
[30067.324692] tick_sched_timer+0xfd/0x170
[30067.325195] __hrtimer_run_queues+0x28a/0x450
[30067.325647] hrtimer_interrupt+0x234/0x6d0
[30067.326519] __sysvec_apic_timer_interrupt+0xb8/0x1a0
[30067.327039] sysvec_apic_timer_interrupt+0x9a/0xc0
[30067.327557] asm_sysvec_apic_timer_interrupt+0x12/0x20
[30067.328105] __tsan_read8+0x167/0x240
[30067.328503] rcutorture_one_extend+0x211/0x590
[30067.328994] rcu_torture_one_read+0x785/0xc90
[30067.329444] rcu_torture_reader+0x19b/0x2e0
[30067.330309] kthread+0x29b/0x2b0
[30067.330654] ret_from_fork+0x22/0x30
[30067.331075]
[30067.331240] 2 locks held by rcu_torture_rea/93:
[30067.331700] #0: ffffffff9d35c208 (rcu_read_lock_sched){....}-{1:2}, at: rcu_lock_acquire+0x11/0x40
[30067.332708] #1: ffffffff9d35c238 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x11/0x40
[30067.333656] irq event stamp: 2508045894
[30067.334185] hardirqs last enabled at (2508045893): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
[30067.335192] hardirqs last disabled at (2508045894): [<ffffffff9c70e1f7>] sysvec_apic_timer_interrupt+0x17/0xc0
[30067.342726] softirqs last enabled at (2508045892): [<ffffffff9b1956fd>] local_bh_enable+0xd/0x30
[30067.354637] softirqs last disabled at (2508045890): [<ffffffff9b1956cd>] local_bh_disable+0xd/0x30
[30067.355483]
[30067.355627] write to 0xffff9dd1df2ecb50 of 1 bytes by task 15 on cpu 0:
[30067.356228] rcu_nocb_gp_kthread+0x3a3/0x1180
[30067.356628] kthread+0x29b/0x2b0
[30067.356936] ret_from_fork+0x22/0x30
[30067.357284]
[30067.357431] 1 lock held by rcuog/0/15:
[30067.357873] #0: ffff9dd1df2ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
[30067.358746] irq event stamp: 19891260
[30067.359093] hardirqs last enabled at (19891259): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
[30067.359998] hardirqs last disabled at (19891260): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
[30067.360860] softirqs last enabled at (19890706): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
[30067.361694] softirqs last disabled at (19890697): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
0xffffffff8119a543 is in rcu_rdp_is_offloaded (kernel/rcu/rcu_segcblist.h:71).
66 }
67
68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
69 int flags)
70 {
71 return READ_ONCE(rsclp->flags) & flags;
72 }
73
74 /*
75 * Is the specified rcu_segcblist enabled, for example, not corresponding
0xffffffff811b17f3 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:59).
54 }
55
56 static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
57 int flags)
58 {
59 rsclp->flags |= flags;
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2021-12-14 4:57 FYI, a few new KCSAN splats Paul E. McKenney
@ 2021-12-14 8:38 ` Zhouyi Zhou
2021-12-14 14:48 ` Paul E. McKenney
2021-12-14 16:57 ` Marco Elver
0 siblings, 2 replies; 11+ messages in thread
From: Zhouyi Zhou @ 2021-12-14 8:38 UTC (permalink / raw)
To: paulmck; +Cc: rcu
Hi Paul,
On Tue, Dec 14, 2021 at 3:28 PM Paul E. McKenney <paulmck@kernel.org> wrote:
>
> Hello!
>
> At first glance, a WRITE_ONCE() in rcu_segcblist_set_flags() would cure
> all these, but I thought I should double check. Thoughts?
I think rcu_segcblist_clear_flags also needs a WRITE_ONCE()
>
> Thanx, Paul
>
> ------------------------------------------------------------------------
I tried to reproduce the KCSAN Bug Report on my virtual machine but I
can't, I don't know why (I have detected the KCSAN Bug in e1000 nic
driver using the same environment before)
1) My virtual machine:
kvm -cpu host -smp 16 -hda ./Images/debian10.qcow2 -m 4096 -net
user,hostfwd=tcp::5556-:22,hostfwd=tcp::5555-:19 -net nic,model=e1000
-vnc :30
2) The KCSAN kernel compile with clang-12:
CONFIG_HAVE_ARCH_KCSAN=y
CONFIG_HAVE_KCSAN_COMPILER=y
CONFIG_KCSAN=y
CONFIG_KCSAN_SELFTEST=y
# CONFIG_KCSAN_EARLY_ENABLE is not set
CONFIG_KCSAN_NUM_WATCHPOINTS=64
CONFIG_KCSAN_UDELAY_TASK=80
CONFIG_KCSAN_UDELAY_INTERRUPT=20
CONFIG_KCSAN_DELAY_RANDOMIZE=y
CONFIG_KCSAN_SKIP_WATCH=4000
CONFIG_KCSAN_SKIP_WATCH_RANDOMIZE=y
# CONFIG_KCSAN_INTERRUPT_WATCHER is not set
CONFIG_KCSAN_REPORT_ONCE_IN_MS=3000
# CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN is not set
# CONFIG_KCSAN_STRICT is not set
CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY=y
# CONFIG_KCSAN_ASSUME_PLAIN_WRITES_ATOMIC is not set
CONFIG_KCSAN_IGNORE_ATOMICS=y
CONFIG_KCSAN_PERMISSIVE=y
3)kernel command line
root@debian:~# cat /proc/cmdline
earlyprintk=serial net.ifnames=0
sysctl.kernel.hung_task_all_cpu_backtrace=1 ima_policy=tcb
nf-conntrack-ftp.ports=20000 nf-conntrack-tftp.ports=20000
nf-conntrack-sip.ports=20000 nf-conntrack-irc.ports=20000
nf-conntrack-sane.ports=20000 binder.debug_mask=0
rcupdate.rcu_expedited=1 no_hash_pointers page_owner=on
sysctl.vm.nr_hugepages=4 sysctl.vm.nr_overcommit_hugepages=4
secretmem.enable=1 root=/dev/sda console=ttyS0 vsyscall=native
numa=fake=2 kvm-intel.nested=1 spec_store_bypass_disable=prctl nopcid
vivid.n_devs=16 vivid.multiplanar=1,2,1,2,1,2,1,2,1,2,1,2,1,2,1,2
netrom.nr_ndevs=16 rose.rose_ndevs=16 dummy_hcd.num=8
watchdog_thresh=55 workqueue.watchdog_thresh=140
sysctl.net.core.netdev_unregister_timeout_secs=140
BOOT_IMAGE=/boot/vmlinuz-5.16.0-rc5+
root=UUID=85844675-467a-4aac-9014-ad7e85e833bd ro crashkernel=256M
iomem=relaxed quiet nohz_full=2,3 rcu_nocbs=2,3
4)The test:
modprobe rcutorture nocbs_nthreads=8
Thanks Zhouyi
>
> BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_nocb_gp_kthread
>
> [34453.430323] read (marked) to 0xffff9dd1df26cb50 of 1 bytes by task 24 on cpu 13:
> [34453.431069] rcu_nocb_cb_kthread+0x18b/0x760
> [34453.431523] kthread+0x29b/0x2b0
> [34453.431864] ret_from_fork+0x22/0x30
> [34453.432245]
> [34453.432418] no locks held by rcuop/1/24.
> [34453.432823] irq event stamp: 13161844
> [34453.433208] hardirqs last enabled at (13161844): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [34453.434220] hardirqs last disabled at (13161843): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> [34453.435129] softirqs last enabled at (13161839): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> [34453.435979] softirqs last disabled at (13161837): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
> [34453.436857]
> [34453.437020] write to 0xffff9dd1df26cb50 of 1 bytes by task 15 on cpu 3:
> [34453.437680] rcu_nocb_gp_kthread+0x3a3/0x1180
> [34453.438137] kthread+0x29b/0x2b0
> [34453.438482] ret_from_fork+0x22/0x30
> [34453.438861]
> [34453.439028] 1 lock held by rcuog/0/15:
> [34453.439414] #0: ffff9dd1df26cc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> [34453.440382] irq event stamp: 22823959
> [34453.440721] hardirqs last enabled at (22823958): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [34453.441892] hardirqs last disabled at (22823959): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> [34453.442831] softirqs last enabled at (22823695): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [34453.443721] softirqs last disabled at (22823672): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
>
> 0xffffffff811b275b is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:71).
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
> 70 {
> 71 return READ_ONCE(rsclp->flags) & flags;
> 72 }
> 73
> 74 /*
> 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
>
> 0xffffffff811b17f3 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:59).
> 54 }
> 55
> 56 static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> 57 int flags)
> 58 {
> 59 rsclp->flags |= flags;
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
>
> ------------------------------------------------------------------------
>
> BUG: KCSAN: data-race in rcu_core / rcu_nocb_cb_kthread
>
> [35979.380848]
> [35979.380999] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by interrupt on cpu 15:
> [35979.381735] rcu_core+0x57/0x860
> [35979.382058] rcu_core_si+0x12/0x20
> [35979.382400] __do_softirq+0x1f9/0x37c
> [35979.382749] run_ksoftirqd+0x4c/0x80
> [35979.383097] smpboot_thread_fn+0x28b/0x390
> [35979.383492] kthread+0x29b/0x2b0
> [35979.383805] ret_from_fork+0x22/0x30
> [35979.384149]
> [35979.384298] no locks held by ksoftirqd/15/173.
> [35979.384711] irq event stamp: 2431400
> [35979.385049] hardirqs last enabled at (2431400): [<ffffffff9ca000de>] __do_softirq+0xde/0x37c
> [35979.385841] hardirqs last disabled at (2431398): [<ffffffff9b0c060e>] run_ksoftirqd+0x2e/0x80
> [35979.386631] softirqs last enabled at (2431394): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> [35979.387429] softirqs last disabled at (2431399): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> [35979.388215]
> [35979.388364] write to 0xffff9dd1df5ecb50 of 1 bytes by task 176 on cpu 10:
> [35979.388996] rcu_nocb_cb_kthread+0x479/0x760
> [35979.389427] kthread+0x29b/0x2b0
> [35979.389752] ret_from_fork+0x22/0x30
> [35979.390106]
> [35979.390260] 1 lock held by rcuop/15/176:
> [35979.390634] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
>
> 0xffffffff811ad657 is in rcu_core (kernel/rcu/rcu_segcblist.h:71).
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
> 70 {
> 71 return READ_ONCE(rsclp->flags) & flags;
> 72 }
> 73
> 74 /*
> 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
>
> 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
> 64 {
> 65 rsclp->flags &= ~flags;
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
>
> ------------------------------------------------------------------------
>
> BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_rdp_is_offloaded
>
> [27570.512032] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by task 0 on cpu 15:
> [27570.512770] rcu_rdp_is_offloaded+0x63/0x1c0
> [27570.513222] rcu_needs_cpu+0x80/0xa0
> [27570.513601] tick_nohz_next_event+0x1d4/0x300
> [27570.514063] tick_nohz_idle_stop_tick+0x8f/0x3d0
> [27570.514532] do_idle+0x108/0x2b0
> [27570.514884] cpu_startup_entry+0x15/0x20
> [27570.515301] secondary_startup_64_no_verify+0xc3/0xcb
> [27570.515858]
> [27570.515997] write to 0xffff9dd1df5ecb50 of 1 bytes by task 176 on cpu 0:
> [27570.516577] rcu_nocb_cb_kthread+0x479/0x760
> [27570.517358] kthread+0x29b/0x2b0
> [27570.517712] ret_from_fork+0x22/0x30
> [27570.518121]
> [27570.518284] 1 lock held by rcuop/15/176:
> [27570.518691] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
> [27570.519677] irq event stamp: 20494903
> [27570.520068] hardirqs last enabled at (20494902): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> [27570.536982] hardirqs last disabled at (20494903): [<ffffffff9b1b28b7>] rcu_nocb_cb_kthread+0x2e7/0x760
> [27570.537913] softirqs last enabled at (20494901): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> [27570.538697] softirqs last disabled at (20494899): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
>
> rcu_rdp_is_offloaded+0x63
> 0xffffffff8119a543 is in rcu_rdp_is_offloaded (kernel/rcu/rcu_segcblist.h:71).
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
> 70 {
> 71 return READ_ONCE(rsclp->flags) & flags;
> 72 }
> 73
> 74 /*
> 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
>
> 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
> 64 {
> 65 rsclp->flags &= ~flags;
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
>
> ------------------------------------------------------------------------
>
> BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_segcblist_ready_cbs
>
> [22938.718032] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by interrupt on cpu 15:
> [22938.718839] rcu_segcblist_ready_cbs+0x1a/0x40
> [22938.719333] rcu_core+0x351/0x860
> [22938.719703] rcu_core_si+0x12/0x20
> [22938.720076] __do_softirq+0x1f9/0x37c
> [22938.720470] run_ksoftirqd+0x4c/0x80
> [22938.720879] smpboot_thread_fn+0x28b/0x390
> [22938.721339] kthread+0x29b/0x2b0
> [22938.721703] ret_from_fork+0x22/0x30
> [22938.722089]
> [22938.722252] no locks held by ksoftirqd/15/173.
> [22938.722719] irq event stamp: 1553879
> [22938.723104] hardirqs last enabled at (1553879): [<ffffffff9b1a7a8c>] note_gp_changes+0x1ac/0x1e0
> [22938.723996] hardirqs last disabled at (1553878): [<ffffffff9b1a793b>] note_gp_changes+0x5b/0x1e0
> [22938.724835] softirqs last enabled at (1553871): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> [22938.736913] softirqs last disabled at (1553876): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> [22938.737836]
> [22938.738013] write to 0xffff9dd1df5ecb50 of 1 bytes by task 154 on cpu 10:
> [22938.738725] rcu_nocb_gp_kthread+0x328/0x1180
> [22938.739210] kthread+0x29b/0x2b0
> [22938.739564] ret_from_fork+0x22/0x30
> [22938.739963]
> [22938.740141] 1 lock held by rcuog/12/154:
> [22938.740578] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> [22938.741584] irq event stamp: 19190924
> [22938.741987] hardirqs last enabled at (19190923): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [22938.743018] hardirqs last disabled at (19190924): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> [22938.743991] softirqs last enabled at (19189530): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [22938.744919] softirqs last disabled at (19189525): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
>
> 0xffffffff811b397a is in rcu_segcblist_ready_cbs (kernel/rcu/rcu_segcblist.h:71).
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
> 70 {
> 71 return READ_ONCE(rsclp->flags) & flags;
> 72 }
> 73
> 74 /*
> 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
>
> 0xffffffff811b1778 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:65).
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
> 64 {
> 65 rsclp->flags &= ~flags;
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
>
> ------------------------------------------------------------------------
>
> BUG: KCSAN: data-race in rcu_core / rcu_nocb_gp_kthread
>
> [17703.531588] read (marked) to 0xffff9dd1df4ecb50 of 1 bytes by interrupt on cpu 11:
> [17703.532349] rcu_segcblist_ready_cbs+0x1a/0x40
> [17703.532801] rcu_core+0x351/0x860
> [17703.533151] rcu_core_si+0x12/0x20
> [17703.533515] __do_softirq+0x1f9/0x37c
> [17703.533910] run_ksoftirqd+0x4c/0x80
> [17703.534296] smpboot_thread_fn+0x28b/0x390
> [17703.534741] kthread+0x29b/0x2b0
> [17703.535111] ret_from_fork+0x22/0x30
> [17703.535502]
> [17703.535671] no locks held by ksoftirqd/11/143.
> [17703.536162] irq event stamp: 1277315
> [17703.536541] hardirqs last enabled at (1277315): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [17703.537604] hardirqs last disabled at (1277314): [<ffffffff9b1a793b>] note_gp_changes+0x5b/0x1e0
> [17703.538666] softirqs last enabled at (1277307): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> [17703.539560] softirqs last disabled at (1277312): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> [17703.540445]
> [17703.540611] write to 0xffff9dd1df4ecb50 of 1 bytes by task 117 on cpu 0:
> [17703.541320] rcu_nocb_gp_kthread+0x328/0x1180
> [17703.541774] kthread+0x29b/0x2b0
> [17703.542154] ret_from_fork+0x22/0x30
> [17703.542544]
> [17703.542712] 1 lock held by rcuog/8/117:
> [17703.543126] #0: ffff9dd1df4ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> [17703.544068] irq event stamp: 14934462
> [17703.544454] hardirqs last enabled at (14934461): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [17703.545469] hardirqs last disabled at (14934462): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> [17703.546442] softirqs last enabled at (14934440): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [17703.547667] softirqs last disabled at (14934429): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
>
> 0xffffffff811b397a is in rcu_segcblist_ready_cbs (kernel/rcu/rcu_segcblist.h:71).
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
> 70 {
> 71 return READ_ONCE(rsclp->flags) & flags;
> 72 }
> 73
> 74 /*
> 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
>
> 0xffffffff811b1778 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:65).
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
> 64 {
> 65 rsclp->flags &= ~flags;
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
>
> ------------------------------------------------------------------------
>
> BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_nocb_rdp_deoffload
>
> [25747.783445] read (marked) to 0xffff9dd1df5acb50 of 1 bytes by task 28476 on cpu 14:
> [25747.784193] rcu_nocb_rdp_deoffload+0x1a3/0x380
> [25747.784675] work_for_cpu_fn+0x32/0x50
> [25747.785071] process_one_work+0x54f/0x840
> [25747.785488] worker_thread+0x79c/0xa90
> [25747.785884] kthread+0x29b/0x2b0
> [25747.786230] ret_from_fork+0x22/0x30
> [25747.786611]
> [25747.786778] 2 locks held by kworker/14:2/28476:
> [25747.787244] #0: ffff9dd1c1054738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x4d7/0x840
> [25747.788196] #1: ffffabe581ce3dd0 ((work_completion)(&wfc.work)){+.+.}-{0:0}, at: process_one_work+0x508/0x840
> [25747.789216] irq event stamp: 47423
> [25747.789563] hardirqs last enabled at (47423): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [25747.790533] hardirqs last disabled at (47422): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> [25747.791450] softirqs last enabled at (47410): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [25747.792253] softirqs last disabled at (47405): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [25747.804153]
> [25747.804319] write to 0xffff9dd1df5acb50 of 1 bytes by task 169 on cpu 13:
> [25747.805254] rcu_nocb_cb_kthread+0x479/0x760
> [25747.805701] kthread+0x29b/0x2b0
> [25747.806156] ret_from_fork+0x22/0x30
> [25747.806581]
> [25747.806747] 1 lock held by rcuop/14/169:
> [25747.807344] #0: ffff9dd1df5acc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
> [25747.809333] irq event stamp: 19677863
> [25747.810093] hardirqs last enabled at (19677862): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> [25747.820095] hardirqs last disabled at (19677863): [<ffffffff9b1b28b7>] rcu_nocb_cb_kthread+0x2e7/0x760
> [25747.822317] softirqs last enabled at (19677861): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> [25747.824060] softirqs last disabled at (19677859): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
>
> 0xffffffff811a5853 is in rcu_nocb_rdp_deoffload (kernel/rcu/rcu_segcblist.h:71).
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
> 70 {
> 71 return READ_ONCE(rsclp->flags) & flags;
> 72 }
> 73
> 74 /*
> 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
>
> 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
> 64 {
> 65 rsclp->flags &= ~flags;
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
>
> ------------------------------------------------------------------------
>
> BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_nocb_rdp_offload
>
> [15688.905747] read (marked) to 0xffff9dd1df56cb50 of 1 bytes by task 154 on cpu 9:
> [15688.906550] rcu_nocb_gp_kthread+0x237/0x1180
> [15688.907050] kthread+0x29b/0x2b0
> [15688.907421] ret_from_fork+0x22/0x30
> [15688.907824]
> [15688.908022] no locks held by rcuog/12/154.
> [15688.908468] irq event stamp: 13085451
> [15688.908865] hardirqs last enabled at (13085451): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [15688.909929] hardirqs last disabled at (13085450): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> [15688.910949] softirqs last enabled at (13085112): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [15688.911908] softirqs last disabled at (13085107): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [15688.912849]
> [15688.913043] write to 0xffff9dd1df56cb50 of 1 bytes by task 16476 on cpu 13:
> [15688.913830] rcu_nocb_rdp_offload+0x24e/0x2c0
> [15688.914364] work_for_cpu_fn+0x32/0x50
> [15688.914805] process_one_work+0x54f/0x840
> [15688.915159] worker_thread+0x79c/0xa90
> [15688.915544] kthread+0x29b/0x2b0
> [15688.915907] ret_from_fork+0x22/0x30
> [15688.916325]
> [15688.916502] 3 locks held by kworker/13:0/16476:
> [15688.917016] #0: ffff9dd1c1054738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x4d7/0x840
> [15688.918073] #1: ffffabe585163dd0 ((work_completion)(&wfc.work)){+.+.}-{0:0}, at: process_one_work+0x508/0x840
> [15688.919153] #2: ffff9dd1df56cc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_rdp_offload+0x237/0x2c0
> [15688.920171] irq event stamp: 198553
> [15688.920539] hardirqs last enabled at (198552): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [15688.921577] hardirqs last disabled at (198553): [<ffffffff9b1a5d5e>] rcu_nocb_rdp_offload+0x21e/0x2c0
> [15688.922553] softirqs last enabled at (198341): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [15688.923462] softirqs last disabled at (198336): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
>
> 0xffffffff811b1687 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:71).
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
> 70 {
> 71 return READ_ONCE(rsclp->flags) & flags;
> 72 }
> 73
> 74 /*
> 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
>
> 0xffffffff811a5d8e is in rcu_nocb_rdp_offload (kernel/rcu/rcu_segcblist.h:65).
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
> 64 {
> 65 rsclp->flags &= ~flags;
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
>
> ------------------------------------------------------------------------
>
> BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_rdp_is_offloaded
>
> [30067.322599] read (marked) to 0xffff9dd1df2ecb50 of 1 bytes by interrupt on cpu 3:
> [30067.323367] rcu_rdp_is_offloaded+0x63/0x1c0
> [30067.323929] rcu_sched_clock_irq+0x9d2/0x18d0
> [30067.324269] update_process_times+0xe9/0x110
> [30067.324692] tick_sched_timer+0xfd/0x170
> [30067.325195] __hrtimer_run_queues+0x28a/0x450
> [30067.325647] hrtimer_interrupt+0x234/0x6d0
> [30067.326519] __sysvec_apic_timer_interrupt+0xb8/0x1a0
> [30067.327039] sysvec_apic_timer_interrupt+0x9a/0xc0
> [30067.327557] asm_sysvec_apic_timer_interrupt+0x12/0x20
> [30067.328105] __tsan_read8+0x167/0x240
> [30067.328503] rcutorture_one_extend+0x211/0x590
> [30067.328994] rcu_torture_one_read+0x785/0xc90
> [30067.329444] rcu_torture_reader+0x19b/0x2e0
> [30067.330309] kthread+0x29b/0x2b0
> [30067.330654] ret_from_fork+0x22/0x30
> [30067.331075]
> [30067.331240] 2 locks held by rcu_torture_rea/93:
> [30067.331700] #0: ffffffff9d35c208 (rcu_read_lock_sched){....}-{1:2}, at: rcu_lock_acquire+0x11/0x40
> [30067.332708] #1: ffffffff9d35c238 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x11/0x40
> [30067.333656] irq event stamp: 2508045894
> [30067.334185] hardirqs last enabled at (2508045893): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> [30067.335192] hardirqs last disabled at (2508045894): [<ffffffff9c70e1f7>] sysvec_apic_timer_interrupt+0x17/0xc0
> [30067.342726] softirqs last enabled at (2508045892): [<ffffffff9b1956fd>] local_bh_enable+0xd/0x30
> [30067.354637] softirqs last disabled at (2508045890): [<ffffffff9b1956cd>] local_bh_disable+0xd/0x30
> [30067.355483]
> [30067.355627] write to 0xffff9dd1df2ecb50 of 1 bytes by task 15 on cpu 0:
> [30067.356228] rcu_nocb_gp_kthread+0x3a3/0x1180
> [30067.356628] kthread+0x29b/0x2b0
> [30067.356936] ret_from_fork+0x22/0x30
> [30067.357284]
> [30067.357431] 1 lock held by rcuog/0/15:
> [30067.357873] #0: ffff9dd1df2ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> [30067.358746] irq event stamp: 19891260
> [30067.359093] hardirqs last enabled at (19891259): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> [30067.359998] hardirqs last disabled at (19891260): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> [30067.360860] softirqs last enabled at (19890706): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> [30067.361694] softirqs last disabled at (19890697): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
>
> 0xffffffff8119a543 is in rcu_rdp_is_offloaded (kernel/rcu/rcu_segcblist.h:71).
> 66 }
> 67
> 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> 69 int flags)
> 70 {
> 71 return READ_ONCE(rsclp->flags) & flags;
> 72 }
> 73
> 74 /*
> 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
>
> 0xffffffff811b17f3 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:59).
> 54 }
> 55
> 56 static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> 57 int flags)
> 58 {
> 59 rsclp->flags |= flags;
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2021-12-14 8:38 ` Zhouyi Zhou
@ 2021-12-14 14:48 ` Paul E. McKenney
2021-12-14 15:46 ` Zhouyi Zhou
2021-12-14 16:57 ` Marco Elver
1 sibling, 1 reply; 11+ messages in thread
From: Paul E. McKenney @ 2021-12-14 14:48 UTC (permalink / raw)
To: Zhouyi Zhou; +Cc: rcu
On Tue, Dec 14, 2021 at 04:38:13PM +0800, Zhouyi Zhou wrote:
> Hi Paul,
>
> On Tue, Dec 14, 2021 at 3:28 PM Paul E. McKenney <paulmck@kernel.org> wrote:
> >
> > Hello!
> >
> > At first glance, a WRITE_ONCE() in rcu_segcblist_set_flags() would cure
> > all these, but I thought I should double check. Thoughts?
>
> I think rcu_segcblist_clear_flags also needs a WRITE_ONCE()
This is my reproducer on a 16-hardware-thread laptop:
tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus --duration 10h --configs "TREE01 TREE03 TREE04" --kcsan --kmake-arg "CC=clang-11" --trust-make
And many of these happened only once or twice during that 20-hour run
(10 hours of TREE03 and then another ten hours of TREE01 and TREE04).
Most of them were TREE01, so you could get there faster like this:
tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus --duration 5h --configs "2*TREE01" --kcsan --kmake-arg "CC=clang-11" --trust-make
So, no, it is not all that easy to reproduce. ;-)
Thanx, Paul
> > ------------------------------------------------------------------------
> I tried to reproduce the KCSAN Bug Report on my virtual machine but I
> can't, I don't know why (I have detected the KCSAN Bug in e1000 nic
> driver using the same environment before)
>
> 1) My virtual machine:
> kvm -cpu host -smp 16 -hda ./Images/debian10.qcow2 -m 4096 -net
> user,hostfwd=tcp::5556-:22,hostfwd=tcp::5555-:19 -net nic,model=e1000
> -vnc :30
>
> 2) The KCSAN kernel compile with clang-12:
> CONFIG_HAVE_ARCH_KCSAN=y
> CONFIG_HAVE_KCSAN_COMPILER=y
> CONFIG_KCSAN=y
> CONFIG_KCSAN_SELFTEST=y
> # CONFIG_KCSAN_EARLY_ENABLE is not set
> CONFIG_KCSAN_NUM_WATCHPOINTS=64
> CONFIG_KCSAN_UDELAY_TASK=80
> CONFIG_KCSAN_UDELAY_INTERRUPT=20
> CONFIG_KCSAN_DELAY_RANDOMIZE=y
> CONFIG_KCSAN_SKIP_WATCH=4000
> CONFIG_KCSAN_SKIP_WATCH_RANDOMIZE=y
> # CONFIG_KCSAN_INTERRUPT_WATCHER is not set
> CONFIG_KCSAN_REPORT_ONCE_IN_MS=3000
> # CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN is not set
> # CONFIG_KCSAN_STRICT is not set
> CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY=y
> # CONFIG_KCSAN_ASSUME_PLAIN_WRITES_ATOMIC is not set
> CONFIG_KCSAN_IGNORE_ATOMICS=y
> CONFIG_KCSAN_PERMISSIVE=y
>
> 3)kernel command line
> root@debian:~# cat /proc/cmdline
> earlyprintk=serial net.ifnames=0
> sysctl.kernel.hung_task_all_cpu_backtrace=1 ima_policy=tcb
> nf-conntrack-ftp.ports=20000 nf-conntrack-tftp.ports=20000
> nf-conntrack-sip.ports=20000 nf-conntrack-irc.ports=20000
> nf-conntrack-sane.ports=20000 binder.debug_mask=0
> rcupdate.rcu_expedited=1 no_hash_pointers page_owner=on
> sysctl.vm.nr_hugepages=4 sysctl.vm.nr_overcommit_hugepages=4
> secretmem.enable=1 root=/dev/sda console=ttyS0 vsyscall=native
> numa=fake=2 kvm-intel.nested=1 spec_store_bypass_disable=prctl nopcid
> vivid.n_devs=16 vivid.multiplanar=1,2,1,2,1,2,1,2,1,2,1,2,1,2,1,2
> netrom.nr_ndevs=16 rose.rose_ndevs=16 dummy_hcd.num=8
> watchdog_thresh=55 workqueue.watchdog_thresh=140
> sysctl.net.core.netdev_unregister_timeout_secs=140
> BOOT_IMAGE=/boot/vmlinuz-5.16.0-rc5+
> root=UUID=85844675-467a-4aac-9014-ad7e85e833bd ro crashkernel=256M
> iomem=relaxed quiet nohz_full=2,3 rcu_nocbs=2,3
>
> 4)The test:
> modprobe rcutorture nocbs_nthreads=8
>
> Thanks Zhouyi
> >
> > BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_nocb_gp_kthread
> >
> > [34453.430323] read (marked) to 0xffff9dd1df26cb50 of 1 bytes by task 24 on cpu 13:
> > [34453.431069] rcu_nocb_cb_kthread+0x18b/0x760
> > [34453.431523] kthread+0x29b/0x2b0
> > [34453.431864] ret_from_fork+0x22/0x30
> > [34453.432245]
> > [34453.432418] no locks held by rcuop/1/24.
> > [34453.432823] irq event stamp: 13161844
> > [34453.433208] hardirqs last enabled at (13161844): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [34453.434220] hardirqs last disabled at (13161843): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> > [34453.435129] softirqs last enabled at (13161839): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> > [34453.435979] softirqs last disabled at (13161837): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
> > [34453.436857]
> > [34453.437020] write to 0xffff9dd1df26cb50 of 1 bytes by task 15 on cpu 3:
> > [34453.437680] rcu_nocb_gp_kthread+0x3a3/0x1180
> > [34453.438137] kthread+0x29b/0x2b0
> > [34453.438482] ret_from_fork+0x22/0x30
> > [34453.438861]
> > [34453.439028] 1 lock held by rcuog/0/15:
> > [34453.439414] #0: ffff9dd1df26cc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> > [34453.440382] irq event stamp: 22823959
> > [34453.440721] hardirqs last enabled at (22823958): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [34453.441892] hardirqs last disabled at (22823959): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> > [34453.442831] softirqs last enabled at (22823695): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [34453.443721] softirqs last disabled at (22823672): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> >
> > 0xffffffff811b275b is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:71).
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> > 70 {
> > 71 return READ_ONCE(rsclp->flags) & flags;
> > 72 }
> > 73
> > 74 /*
> > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> >
> > 0xffffffff811b17f3 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:59).
> > 54 }
> > 55
> > 56 static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> > 57 int flags)
> > 58 {
> > 59 rsclp->flags |= flags;
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
> >
> > ------------------------------------------------------------------------
> >
> > BUG: KCSAN: data-race in rcu_core / rcu_nocb_cb_kthread
> >
> > [35979.380848]
> > [35979.380999] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by interrupt on cpu 15:
> > [35979.381735] rcu_core+0x57/0x860
> > [35979.382058] rcu_core_si+0x12/0x20
> > [35979.382400] __do_softirq+0x1f9/0x37c
> > [35979.382749] run_ksoftirqd+0x4c/0x80
> > [35979.383097] smpboot_thread_fn+0x28b/0x390
> > [35979.383492] kthread+0x29b/0x2b0
> > [35979.383805] ret_from_fork+0x22/0x30
> > [35979.384149]
> > [35979.384298] no locks held by ksoftirqd/15/173.
> > [35979.384711] irq event stamp: 2431400
> > [35979.385049] hardirqs last enabled at (2431400): [<ffffffff9ca000de>] __do_softirq+0xde/0x37c
> > [35979.385841] hardirqs last disabled at (2431398): [<ffffffff9b0c060e>] run_ksoftirqd+0x2e/0x80
> > [35979.386631] softirqs last enabled at (2431394): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > [35979.387429] softirqs last disabled at (2431399): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > [35979.388215]
> > [35979.388364] write to 0xffff9dd1df5ecb50 of 1 bytes by task 176 on cpu 10:
> > [35979.388996] rcu_nocb_cb_kthread+0x479/0x760
> > [35979.389427] kthread+0x29b/0x2b0
> > [35979.389752] ret_from_fork+0x22/0x30
> > [35979.390106]
> > [35979.390260] 1 lock held by rcuop/15/176:
> > [35979.390634] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
> >
> > 0xffffffff811ad657 is in rcu_core (kernel/rcu/rcu_segcblist.h:71).
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> > 70 {
> > 71 return READ_ONCE(rsclp->flags) & flags;
> > 72 }
> > 73
> > 74 /*
> > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> >
> > 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
> > 64 {
> > 65 rsclp->flags &= ~flags;
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> >
> > ------------------------------------------------------------------------
> >
> > BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_rdp_is_offloaded
> >
> > [27570.512032] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by task 0 on cpu 15:
> > [27570.512770] rcu_rdp_is_offloaded+0x63/0x1c0
> > [27570.513222] rcu_needs_cpu+0x80/0xa0
> > [27570.513601] tick_nohz_next_event+0x1d4/0x300
> > [27570.514063] tick_nohz_idle_stop_tick+0x8f/0x3d0
> > [27570.514532] do_idle+0x108/0x2b0
> > [27570.514884] cpu_startup_entry+0x15/0x20
> > [27570.515301] secondary_startup_64_no_verify+0xc3/0xcb
> > [27570.515858]
> > [27570.515997] write to 0xffff9dd1df5ecb50 of 1 bytes by task 176 on cpu 0:
> > [27570.516577] rcu_nocb_cb_kthread+0x479/0x760
> > [27570.517358] kthread+0x29b/0x2b0
> > [27570.517712] ret_from_fork+0x22/0x30
> > [27570.518121]
> > [27570.518284] 1 lock held by rcuop/15/176:
> > [27570.518691] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
> > [27570.519677] irq event stamp: 20494903
> > [27570.520068] hardirqs last enabled at (20494902): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> > [27570.536982] hardirqs last disabled at (20494903): [<ffffffff9b1b28b7>] rcu_nocb_cb_kthread+0x2e7/0x760
> > [27570.537913] softirqs last enabled at (20494901): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> > [27570.538697] softirqs last disabled at (20494899): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
> >
> > rcu_rdp_is_offloaded+0x63
> > 0xffffffff8119a543 is in rcu_rdp_is_offloaded (kernel/rcu/rcu_segcblist.h:71).
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> > 70 {
> > 71 return READ_ONCE(rsclp->flags) & flags;
> > 72 }
> > 73
> > 74 /*
> > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> >
> > 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
> > 64 {
> > 65 rsclp->flags &= ~flags;
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> >
> > ------------------------------------------------------------------------
> >
> > BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_segcblist_ready_cbs
> >
> > [22938.718032] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by interrupt on cpu 15:
> > [22938.718839] rcu_segcblist_ready_cbs+0x1a/0x40
> > [22938.719333] rcu_core+0x351/0x860
> > [22938.719703] rcu_core_si+0x12/0x20
> > [22938.720076] __do_softirq+0x1f9/0x37c
> > [22938.720470] run_ksoftirqd+0x4c/0x80
> > [22938.720879] smpboot_thread_fn+0x28b/0x390
> > [22938.721339] kthread+0x29b/0x2b0
> > [22938.721703] ret_from_fork+0x22/0x30
> > [22938.722089]
> > [22938.722252] no locks held by ksoftirqd/15/173.
> > [22938.722719] irq event stamp: 1553879
> > [22938.723104] hardirqs last enabled at (1553879): [<ffffffff9b1a7a8c>] note_gp_changes+0x1ac/0x1e0
> > [22938.723996] hardirqs last disabled at (1553878): [<ffffffff9b1a793b>] note_gp_changes+0x5b/0x1e0
> > [22938.724835] softirqs last enabled at (1553871): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > [22938.736913] softirqs last disabled at (1553876): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > [22938.737836]
> > [22938.738013] write to 0xffff9dd1df5ecb50 of 1 bytes by task 154 on cpu 10:
> > [22938.738725] rcu_nocb_gp_kthread+0x328/0x1180
> > [22938.739210] kthread+0x29b/0x2b0
> > [22938.739564] ret_from_fork+0x22/0x30
> > [22938.739963]
> > [22938.740141] 1 lock held by rcuog/12/154:
> > [22938.740578] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> > [22938.741584] irq event stamp: 19190924
> > [22938.741987] hardirqs last enabled at (19190923): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [22938.743018] hardirqs last disabled at (19190924): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> > [22938.743991] softirqs last enabled at (19189530): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [22938.744919] softirqs last disabled at (19189525): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> >
> > 0xffffffff811b397a is in rcu_segcblist_ready_cbs (kernel/rcu/rcu_segcblist.h:71).
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> > 70 {
> > 71 return READ_ONCE(rsclp->flags) & flags;
> > 72 }
> > 73
> > 74 /*
> > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> >
> > 0xffffffff811b1778 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:65).
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
> > 64 {
> > 65 rsclp->flags &= ~flags;
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> >
> > ------------------------------------------------------------------------
> >
> > BUG: KCSAN: data-race in rcu_core / rcu_nocb_gp_kthread
> >
> > [17703.531588] read (marked) to 0xffff9dd1df4ecb50 of 1 bytes by interrupt on cpu 11:
> > [17703.532349] rcu_segcblist_ready_cbs+0x1a/0x40
> > [17703.532801] rcu_core+0x351/0x860
> > [17703.533151] rcu_core_si+0x12/0x20
> > [17703.533515] __do_softirq+0x1f9/0x37c
> > [17703.533910] run_ksoftirqd+0x4c/0x80
> > [17703.534296] smpboot_thread_fn+0x28b/0x390
> > [17703.534741] kthread+0x29b/0x2b0
> > [17703.535111] ret_from_fork+0x22/0x30
> > [17703.535502]
> > [17703.535671] no locks held by ksoftirqd/11/143.
> > [17703.536162] irq event stamp: 1277315
> > [17703.536541] hardirqs last enabled at (1277315): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [17703.537604] hardirqs last disabled at (1277314): [<ffffffff9b1a793b>] note_gp_changes+0x5b/0x1e0
> > [17703.538666] softirqs last enabled at (1277307): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > [17703.539560] softirqs last disabled at (1277312): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > [17703.540445]
> > [17703.540611] write to 0xffff9dd1df4ecb50 of 1 bytes by task 117 on cpu 0:
> > [17703.541320] rcu_nocb_gp_kthread+0x328/0x1180
> > [17703.541774] kthread+0x29b/0x2b0
> > [17703.542154] ret_from_fork+0x22/0x30
> > [17703.542544]
> > [17703.542712] 1 lock held by rcuog/8/117:
> > [17703.543126] #0: ffff9dd1df4ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> > [17703.544068] irq event stamp: 14934462
> > [17703.544454] hardirqs last enabled at (14934461): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [17703.545469] hardirqs last disabled at (14934462): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> > [17703.546442] softirqs last enabled at (14934440): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [17703.547667] softirqs last disabled at (14934429): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> >
> > 0xffffffff811b397a is in rcu_segcblist_ready_cbs (kernel/rcu/rcu_segcblist.h:71).
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> > 70 {
> > 71 return READ_ONCE(rsclp->flags) & flags;
> > 72 }
> > 73
> > 74 /*
> > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> >
> > 0xffffffff811b1778 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:65).
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
> > 64 {
> > 65 rsclp->flags &= ~flags;
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> >
> > ------------------------------------------------------------------------
> >
> > BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_nocb_rdp_deoffload
> >
> > [25747.783445] read (marked) to 0xffff9dd1df5acb50 of 1 bytes by task 28476 on cpu 14:
> > [25747.784193] rcu_nocb_rdp_deoffload+0x1a3/0x380
> > [25747.784675] work_for_cpu_fn+0x32/0x50
> > [25747.785071] process_one_work+0x54f/0x840
> > [25747.785488] worker_thread+0x79c/0xa90
> > [25747.785884] kthread+0x29b/0x2b0
> > [25747.786230] ret_from_fork+0x22/0x30
> > [25747.786611]
> > [25747.786778] 2 locks held by kworker/14:2/28476:
> > [25747.787244] #0: ffff9dd1c1054738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x4d7/0x840
> > [25747.788196] #1: ffffabe581ce3dd0 ((work_completion)(&wfc.work)){+.+.}-{0:0}, at: process_one_work+0x508/0x840
> > [25747.789216] irq event stamp: 47423
> > [25747.789563] hardirqs last enabled at (47423): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [25747.790533] hardirqs last disabled at (47422): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> > [25747.791450] softirqs last enabled at (47410): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [25747.792253] softirqs last disabled at (47405): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [25747.804153]
> > [25747.804319] write to 0xffff9dd1df5acb50 of 1 bytes by task 169 on cpu 13:
> > [25747.805254] rcu_nocb_cb_kthread+0x479/0x760
> > [25747.805701] kthread+0x29b/0x2b0
> > [25747.806156] ret_from_fork+0x22/0x30
> > [25747.806581]
> > [25747.806747] 1 lock held by rcuop/14/169:
> > [25747.807344] #0: ffff9dd1df5acc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
> > [25747.809333] irq event stamp: 19677863
> > [25747.810093] hardirqs last enabled at (19677862): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> > [25747.820095] hardirqs last disabled at (19677863): [<ffffffff9b1b28b7>] rcu_nocb_cb_kthread+0x2e7/0x760
> > [25747.822317] softirqs last enabled at (19677861): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> > [25747.824060] softirqs last disabled at (19677859): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
> >
> > 0xffffffff811a5853 is in rcu_nocb_rdp_deoffload (kernel/rcu/rcu_segcblist.h:71).
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> > 70 {
> > 71 return READ_ONCE(rsclp->flags) & flags;
> > 72 }
> > 73
> > 74 /*
> > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> >
> > 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
> > 64 {
> > 65 rsclp->flags &= ~flags;
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> >
> > ------------------------------------------------------------------------
> >
> > BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_nocb_rdp_offload
> >
> > [15688.905747] read (marked) to 0xffff9dd1df56cb50 of 1 bytes by task 154 on cpu 9:
> > [15688.906550] rcu_nocb_gp_kthread+0x237/0x1180
> > [15688.907050] kthread+0x29b/0x2b0
> > [15688.907421] ret_from_fork+0x22/0x30
> > [15688.907824]
> > [15688.908022] no locks held by rcuog/12/154.
> > [15688.908468] irq event stamp: 13085451
> > [15688.908865] hardirqs last enabled at (13085451): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [15688.909929] hardirqs last disabled at (13085450): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> > [15688.910949] softirqs last enabled at (13085112): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [15688.911908] softirqs last disabled at (13085107): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [15688.912849]
> > [15688.913043] write to 0xffff9dd1df56cb50 of 1 bytes by task 16476 on cpu 13:
> > [15688.913830] rcu_nocb_rdp_offload+0x24e/0x2c0
> > [15688.914364] work_for_cpu_fn+0x32/0x50
> > [15688.914805] process_one_work+0x54f/0x840
> > [15688.915159] worker_thread+0x79c/0xa90
> > [15688.915544] kthread+0x29b/0x2b0
> > [15688.915907] ret_from_fork+0x22/0x30
> > [15688.916325]
> > [15688.916502] 3 locks held by kworker/13:0/16476:
> > [15688.917016] #0: ffff9dd1c1054738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x4d7/0x840
> > [15688.918073] #1: ffffabe585163dd0 ((work_completion)(&wfc.work)){+.+.}-{0:0}, at: process_one_work+0x508/0x840
> > [15688.919153] #2: ffff9dd1df56cc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_rdp_offload+0x237/0x2c0
> > [15688.920171] irq event stamp: 198553
> > [15688.920539] hardirqs last enabled at (198552): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [15688.921577] hardirqs last disabled at (198553): [<ffffffff9b1a5d5e>] rcu_nocb_rdp_offload+0x21e/0x2c0
> > [15688.922553] softirqs last enabled at (198341): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [15688.923462] softirqs last disabled at (198336): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> >
> > 0xffffffff811b1687 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:71).
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> > 70 {
> > 71 return READ_ONCE(rsclp->flags) & flags;
> > 72 }
> > 73
> > 74 /*
> > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> >
> > 0xffffffff811a5d8e is in rcu_nocb_rdp_offload (kernel/rcu/rcu_segcblist.h:65).
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
> > 64 {
> > 65 rsclp->flags &= ~flags;
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> >
> > ------------------------------------------------------------------------
> >
> > BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_rdp_is_offloaded
> >
> > [30067.322599] read (marked) to 0xffff9dd1df2ecb50 of 1 bytes by interrupt on cpu 3:
> > [30067.323367] rcu_rdp_is_offloaded+0x63/0x1c0
> > [30067.323929] rcu_sched_clock_irq+0x9d2/0x18d0
> > [30067.324269] update_process_times+0xe9/0x110
> > [30067.324692] tick_sched_timer+0xfd/0x170
> > [30067.325195] __hrtimer_run_queues+0x28a/0x450
> > [30067.325647] hrtimer_interrupt+0x234/0x6d0
> > [30067.326519] __sysvec_apic_timer_interrupt+0xb8/0x1a0
> > [30067.327039] sysvec_apic_timer_interrupt+0x9a/0xc0
> > [30067.327557] asm_sysvec_apic_timer_interrupt+0x12/0x20
> > [30067.328105] __tsan_read8+0x167/0x240
> > [30067.328503] rcutorture_one_extend+0x211/0x590
> > [30067.328994] rcu_torture_one_read+0x785/0xc90
> > [30067.329444] rcu_torture_reader+0x19b/0x2e0
> > [30067.330309] kthread+0x29b/0x2b0
> > [30067.330654] ret_from_fork+0x22/0x30
> > [30067.331075]
> > [30067.331240] 2 locks held by rcu_torture_rea/93:
> > [30067.331700] #0: ffffffff9d35c208 (rcu_read_lock_sched){....}-{1:2}, at: rcu_lock_acquire+0x11/0x40
> > [30067.332708] #1: ffffffff9d35c238 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x11/0x40
> > [30067.333656] irq event stamp: 2508045894
> > [30067.334185] hardirqs last enabled at (2508045893): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> > [30067.335192] hardirqs last disabled at (2508045894): [<ffffffff9c70e1f7>] sysvec_apic_timer_interrupt+0x17/0xc0
> > [30067.342726] softirqs last enabled at (2508045892): [<ffffffff9b1956fd>] local_bh_enable+0xd/0x30
> > [30067.354637] softirqs last disabled at (2508045890): [<ffffffff9b1956cd>] local_bh_disable+0xd/0x30
> > [30067.355483]
> > [30067.355627] write to 0xffff9dd1df2ecb50 of 1 bytes by task 15 on cpu 0:
> > [30067.356228] rcu_nocb_gp_kthread+0x3a3/0x1180
> > [30067.356628] kthread+0x29b/0x2b0
> > [30067.356936] ret_from_fork+0x22/0x30
> > [30067.357284]
> > [30067.357431] 1 lock held by rcuog/0/15:
> > [30067.357873] #0: ffff9dd1df2ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> > [30067.358746] irq event stamp: 19891260
> > [30067.359093] hardirqs last enabled at (19891259): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > [30067.359998] hardirqs last disabled at (19891260): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> > [30067.360860] softirqs last enabled at (19890706): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > [30067.361694] softirqs last disabled at (19890697): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> >
> > 0xffffffff8119a543 is in rcu_rdp_is_offloaded (kernel/rcu/rcu_segcblist.h:71).
> > 66 }
> > 67
> > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > 69 int flags)
> > 70 {
> > 71 return READ_ONCE(rsclp->flags) & flags;
> > 72 }
> > 73
> > 74 /*
> > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> >
> > 0xffffffff811b17f3 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:59).
> > 54 }
> > 55
> > 56 static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> > 57 int flags)
> > 58 {
> > 59 rsclp->flags |= flags;
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2021-12-14 14:48 ` Paul E. McKenney
@ 2021-12-14 15:46 ` Zhouyi Zhou
0 siblings, 0 replies; 11+ messages in thread
From: Zhouyi Zhou @ 2021-12-14 15:46 UTC (permalink / raw)
To: paulmck; +Cc: rcu
Thank Paul for your guidance.
The kvm.sh scripts under the tools directory looks very funny and
fantastic, and the BUG is really not easy to reproduce.
I should study it little by little (I think of this as research
because I benefit a lot during the process ;-))
Thanks again
Zhouyi
On Tue, Dec 14, 2021 at 10:48 PM Paul E. McKenney <paulmck@kernel.org> wrote:
>
> On Tue, Dec 14, 2021 at 04:38:13PM +0800, Zhouyi Zhou wrote:
> > Hi Paul,
> >
> > On Tue, Dec 14, 2021 at 3:28 PM Paul E. McKenney <paulmck@kernel.org> wrote:
> > >
> > > Hello!
> > >
> > > At first glance, a WRITE_ONCE() in rcu_segcblist_set_flags() would cure
> > > all these, but I thought I should double check. Thoughts?
> >
> > I think rcu_segcblist_clear_flags also needs a WRITE_ONCE()
>
> This is my reproducer on a 16-hardware-thread laptop:
>
> tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus --duration 10h --configs "TREE01 TREE03 TREE04" --kcsan --kmake-arg "CC=clang-11" --trust-make
>
> And many of these happened only once or twice during that 20-hour run
> (10 hours of TREE03 and then another ten hours of TREE01 and TREE04).
>
> Most of them were TREE01, so you could get there faster like this:
>
> tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus --duration 5h --configs "2*TREE01" --kcsan --kmake-arg "CC=clang-11" --trust-make
>
> So, no, it is not all that easy to reproduce. ;-)
>
> Thanx, Paul
>
> > > ------------------------------------------------------------------------
> > I tried to reproduce the KCSAN Bug Report on my virtual machine but I
> > can't, I don't know why (I have detected the KCSAN Bug in e1000 nic
> > driver using the same environment before)
> >
> > 1) My virtual machine:
> > kvm -cpu host -smp 16 -hda ./Images/debian10.qcow2 -m 4096 -net
> > user,hostfwd=tcp::5556-:22,hostfwd=tcp::5555-:19 -net nic,model=e1000
> > -vnc :30
> >
> > 2) The KCSAN kernel compile with clang-12:
> > CONFIG_HAVE_ARCH_KCSAN=y
> > CONFIG_HAVE_KCSAN_COMPILER=y
> > CONFIG_KCSAN=y
> > CONFIG_KCSAN_SELFTEST=y
> > # CONFIG_KCSAN_EARLY_ENABLE is not set
> > CONFIG_KCSAN_NUM_WATCHPOINTS=64
> > CONFIG_KCSAN_UDELAY_TASK=80
> > CONFIG_KCSAN_UDELAY_INTERRUPT=20
> > CONFIG_KCSAN_DELAY_RANDOMIZE=y
> > CONFIG_KCSAN_SKIP_WATCH=4000
> > CONFIG_KCSAN_SKIP_WATCH_RANDOMIZE=y
> > # CONFIG_KCSAN_INTERRUPT_WATCHER is not set
> > CONFIG_KCSAN_REPORT_ONCE_IN_MS=3000
> > # CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN is not set
> > # CONFIG_KCSAN_STRICT is not set
> > CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY=y
> > # CONFIG_KCSAN_ASSUME_PLAIN_WRITES_ATOMIC is not set
> > CONFIG_KCSAN_IGNORE_ATOMICS=y
> > CONFIG_KCSAN_PERMISSIVE=y
> >
> > 3)kernel command line
> > root@debian:~# cat /proc/cmdline
> > earlyprintk=serial net.ifnames=0
> > sysctl.kernel.hung_task_all_cpu_backtrace=1 ima_policy=tcb
> > nf-conntrack-ftp.ports=20000 nf-conntrack-tftp.ports=20000
> > nf-conntrack-sip.ports=20000 nf-conntrack-irc.ports=20000
> > nf-conntrack-sane.ports=20000 binder.debug_mask=0
> > rcupdate.rcu_expedited=1 no_hash_pointers page_owner=on
> > sysctl.vm.nr_hugepages=4 sysctl.vm.nr_overcommit_hugepages=4
> > secretmem.enable=1 root=/dev/sda console=ttyS0 vsyscall=native
> > numa=fake=2 kvm-intel.nested=1 spec_store_bypass_disable=prctl nopcid
> > vivid.n_devs=16 vivid.multiplanar=1,2,1,2,1,2,1,2,1,2,1,2,1,2,1,2
> > netrom.nr_ndevs=16 rose.rose_ndevs=16 dummy_hcd.num=8
> > watchdog_thresh=55 workqueue.watchdog_thresh=140
> > sysctl.net.core.netdev_unregister_timeout_secs=140
> > BOOT_IMAGE=/boot/vmlinuz-5.16.0-rc5+
> > root=UUID=85844675-467a-4aac-9014-ad7e85e833bd ro crashkernel=256M
> > iomem=relaxed quiet nohz_full=2,3 rcu_nocbs=2,3
> >
> > 4)The test:
> > modprobe rcutorture nocbs_nthreads=8
> >
> > Thanks Zhouyi
> > >
> > > BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_nocb_gp_kthread
> > >
> > > [34453.430323] read (marked) to 0xffff9dd1df26cb50 of 1 bytes by task 24 on cpu 13:
> > > [34453.431069] rcu_nocb_cb_kthread+0x18b/0x760
> > > [34453.431523] kthread+0x29b/0x2b0
> > > [34453.431864] ret_from_fork+0x22/0x30
> > > [34453.432245]
> > > [34453.432418] no locks held by rcuop/1/24.
> > > [34453.432823] irq event stamp: 13161844
> > > [34453.433208] hardirqs last enabled at (13161844): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [34453.434220] hardirqs last disabled at (13161843): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> > > [34453.435129] softirqs last enabled at (13161839): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> > > [34453.435979] softirqs last disabled at (13161837): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
> > > [34453.436857]
> > > [34453.437020] write to 0xffff9dd1df26cb50 of 1 bytes by task 15 on cpu 3:
> > > [34453.437680] rcu_nocb_gp_kthread+0x3a3/0x1180
> > > [34453.438137] kthread+0x29b/0x2b0
> > > [34453.438482] ret_from_fork+0x22/0x30
> > > [34453.438861]
> > > [34453.439028] 1 lock held by rcuog/0/15:
> > > [34453.439414] #0: ffff9dd1df26cc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> > > [34453.440382] irq event stamp: 22823959
> > > [34453.440721] hardirqs last enabled at (22823958): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [34453.441892] hardirqs last disabled at (22823959): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> > > [34453.442831] softirqs last enabled at (22823695): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [34453.443721] softirqs last disabled at (22823672): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > >
> > > 0xffffffff811b275b is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:71).
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > > 70 {
> > > 71 return READ_ONCE(rsclp->flags) & flags;
> > > 72 }
> > > 73
> > > 74 /*
> > > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> > >
> > > 0xffffffff811b17f3 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:59).
> > > 54 }
> > > 55
> > > 56 static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> > > 57 int flags)
> > > 58 {
> > > 59 rsclp->flags |= flags;
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
> > >
> > > ------------------------------------------------------------------------
> > >
> > > BUG: KCSAN: data-race in rcu_core / rcu_nocb_cb_kthread
> > >
> > > [35979.380848]
> > > [35979.380999] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by interrupt on cpu 15:
> > > [35979.381735] rcu_core+0x57/0x860
> > > [35979.382058] rcu_core_si+0x12/0x20
> > > [35979.382400] __do_softirq+0x1f9/0x37c
> > > [35979.382749] run_ksoftirqd+0x4c/0x80
> > > [35979.383097] smpboot_thread_fn+0x28b/0x390
> > > [35979.383492] kthread+0x29b/0x2b0
> > > [35979.383805] ret_from_fork+0x22/0x30
> > > [35979.384149]
> > > [35979.384298] no locks held by ksoftirqd/15/173.
> > > [35979.384711] irq event stamp: 2431400
> > > [35979.385049] hardirqs last enabled at (2431400): [<ffffffff9ca000de>] __do_softirq+0xde/0x37c
> > > [35979.385841] hardirqs last disabled at (2431398): [<ffffffff9b0c060e>] run_ksoftirqd+0x2e/0x80
> > > [35979.386631] softirqs last enabled at (2431394): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > > [35979.387429] softirqs last disabled at (2431399): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > > [35979.388215]
> > > [35979.388364] write to 0xffff9dd1df5ecb50 of 1 bytes by task 176 on cpu 10:
> > > [35979.388996] rcu_nocb_cb_kthread+0x479/0x760
> > > [35979.389427] kthread+0x29b/0x2b0
> > > [35979.389752] ret_from_fork+0x22/0x30
> > > [35979.390106]
> > > [35979.390260] 1 lock held by rcuop/15/176:
> > > [35979.390634] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
> > >
> > > 0xffffffff811ad657 is in rcu_core (kernel/rcu/rcu_segcblist.h:71).
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > > 70 {
> > > 71 return READ_ONCE(rsclp->flags) & flags;
> > > 72 }
> > > 73
> > > 74 /*
> > > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> > >
> > > 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
> > > 64 {
> > > 65 rsclp->flags &= ~flags;
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > >
> > > ------------------------------------------------------------------------
> > >
> > > BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_rdp_is_offloaded
> > >
> > > [27570.512032] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by task 0 on cpu 15:
> > > [27570.512770] rcu_rdp_is_offloaded+0x63/0x1c0
> > > [27570.513222] rcu_needs_cpu+0x80/0xa0
> > > [27570.513601] tick_nohz_next_event+0x1d4/0x300
> > > [27570.514063] tick_nohz_idle_stop_tick+0x8f/0x3d0
> > > [27570.514532] do_idle+0x108/0x2b0
> > > [27570.514884] cpu_startup_entry+0x15/0x20
> > > [27570.515301] secondary_startup_64_no_verify+0xc3/0xcb
> > > [27570.515858]
> > > [27570.515997] write to 0xffff9dd1df5ecb50 of 1 bytes by task 176 on cpu 0:
> > > [27570.516577] rcu_nocb_cb_kthread+0x479/0x760
> > > [27570.517358] kthread+0x29b/0x2b0
> > > [27570.517712] ret_from_fork+0x22/0x30
> > > [27570.518121]
> > > [27570.518284] 1 lock held by rcuop/15/176:
> > > [27570.518691] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
> > > [27570.519677] irq event stamp: 20494903
> > > [27570.520068] hardirqs last enabled at (20494902): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> > > [27570.536982] hardirqs last disabled at (20494903): [<ffffffff9b1b28b7>] rcu_nocb_cb_kthread+0x2e7/0x760
> > > [27570.537913] softirqs last enabled at (20494901): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> > > [27570.538697] softirqs last disabled at (20494899): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
> > >
> > > rcu_rdp_is_offloaded+0x63
> > > 0xffffffff8119a543 is in rcu_rdp_is_offloaded (kernel/rcu/rcu_segcblist.h:71).
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > > 70 {
> > > 71 return READ_ONCE(rsclp->flags) & flags;
> > > 72 }
> > > 73
> > > 74 /*
> > > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> > >
> > > 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
> > > 64 {
> > > 65 rsclp->flags &= ~flags;
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > >
> > > ------------------------------------------------------------------------
> > >
> > > BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_segcblist_ready_cbs
> > >
> > > [22938.718032] read (marked) to 0xffff9dd1df5ecb50 of 1 bytes by interrupt on cpu 15:
> > > [22938.718839] rcu_segcblist_ready_cbs+0x1a/0x40
> > > [22938.719333] rcu_core+0x351/0x860
> > > [22938.719703] rcu_core_si+0x12/0x20
> > > [22938.720076] __do_softirq+0x1f9/0x37c
> > > [22938.720470] run_ksoftirqd+0x4c/0x80
> > > [22938.720879] smpboot_thread_fn+0x28b/0x390
> > > [22938.721339] kthread+0x29b/0x2b0
> > > [22938.721703] ret_from_fork+0x22/0x30
> > > [22938.722089]
> > > [22938.722252] no locks held by ksoftirqd/15/173.
> > > [22938.722719] irq event stamp: 1553879
> > > [22938.723104] hardirqs last enabled at (1553879): [<ffffffff9b1a7a8c>] note_gp_changes+0x1ac/0x1e0
> > > [22938.723996] hardirqs last disabled at (1553878): [<ffffffff9b1a793b>] note_gp_changes+0x5b/0x1e0
> > > [22938.724835] softirqs last enabled at (1553871): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > > [22938.736913] softirqs last disabled at (1553876): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > > [22938.737836]
> > > [22938.738013] write to 0xffff9dd1df5ecb50 of 1 bytes by task 154 on cpu 10:
> > > [22938.738725] rcu_nocb_gp_kthread+0x328/0x1180
> > > [22938.739210] kthread+0x29b/0x2b0
> > > [22938.739564] ret_from_fork+0x22/0x30
> > > [22938.739963]
> > > [22938.740141] 1 lock held by rcuog/12/154:
> > > [22938.740578] #0: ffff9dd1df5ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> > > [22938.741584] irq event stamp: 19190924
> > > [22938.741987] hardirqs last enabled at (19190923): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [22938.743018] hardirqs last disabled at (19190924): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> > > [22938.743991] softirqs last enabled at (19189530): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [22938.744919] softirqs last disabled at (19189525): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > >
> > > 0xffffffff811b397a is in rcu_segcblist_ready_cbs (kernel/rcu/rcu_segcblist.h:71).
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > > 70 {
> > > 71 return READ_ONCE(rsclp->flags) & flags;
> > > 72 }
> > > 73
> > > 74 /*
> > > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> > >
> > > 0xffffffff811b1778 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:65).
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
> > > 64 {
> > > 65 rsclp->flags &= ~flags;
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > >
> > > ------------------------------------------------------------------------
> > >
> > > BUG: KCSAN: data-race in rcu_core / rcu_nocb_gp_kthread
> > >
> > > [17703.531588] read (marked) to 0xffff9dd1df4ecb50 of 1 bytes by interrupt on cpu 11:
> > > [17703.532349] rcu_segcblist_ready_cbs+0x1a/0x40
> > > [17703.532801] rcu_core+0x351/0x860
> > > [17703.533151] rcu_core_si+0x12/0x20
> > > [17703.533515] __do_softirq+0x1f9/0x37c
> > > [17703.533910] run_ksoftirqd+0x4c/0x80
> > > [17703.534296] smpboot_thread_fn+0x28b/0x390
> > > [17703.534741] kthread+0x29b/0x2b0
> > > [17703.535111] ret_from_fork+0x22/0x30
> > > [17703.535502]
> > > [17703.535671] no locks held by ksoftirqd/11/143.
> > > [17703.536162] irq event stamp: 1277315
> > > [17703.536541] hardirqs last enabled at (1277315): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [17703.537604] hardirqs last disabled at (1277314): [<ffffffff9b1a793b>] note_gp_changes+0x5b/0x1e0
> > > [17703.538666] softirqs last enabled at (1277307): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > > [17703.539560] softirqs last disabled at (1277312): [<ffffffff9b0c062c>] run_ksoftirqd+0x4c/0x80
> > > [17703.540445]
> > > [17703.540611] write to 0xffff9dd1df4ecb50 of 1 bytes by task 117 on cpu 0:
> > > [17703.541320] rcu_nocb_gp_kthread+0x328/0x1180
> > > [17703.541774] kthread+0x29b/0x2b0
> > > [17703.542154] ret_from_fork+0x22/0x30
> > > [17703.542544]
> > > [17703.542712] 1 lock held by rcuog/8/117:
> > > [17703.543126] #0: ffff9dd1df4ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> > > [17703.544068] irq event stamp: 14934462
> > > [17703.544454] hardirqs last enabled at (14934461): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [17703.545469] hardirqs last disabled at (14934462): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> > > [17703.546442] softirqs last enabled at (14934440): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [17703.547667] softirqs last disabled at (14934429): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > >
> > > 0xffffffff811b397a is in rcu_segcblist_ready_cbs (kernel/rcu/rcu_segcblist.h:71).
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > > 70 {
> > > 71 return READ_ONCE(rsclp->flags) & flags;
> > > 72 }
> > > 73
> > > 74 /*
> > > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> > >
> > > 0xffffffff811b1778 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:65).
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
> > > 64 {
> > > 65 rsclp->flags &= ~flags;
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > >
> > > ------------------------------------------------------------------------
> > >
> > > BUG: KCSAN: data-race in rcu_nocb_cb_kthread / rcu_nocb_rdp_deoffload
> > >
> > > [25747.783445] read (marked) to 0xffff9dd1df5acb50 of 1 bytes by task 28476 on cpu 14:
> > > [25747.784193] rcu_nocb_rdp_deoffload+0x1a3/0x380
> > > [25747.784675] work_for_cpu_fn+0x32/0x50
> > > [25747.785071] process_one_work+0x54f/0x840
> > > [25747.785488] worker_thread+0x79c/0xa90
> > > [25747.785884] kthread+0x29b/0x2b0
> > > [25747.786230] ret_from_fork+0x22/0x30
> > > [25747.786611]
> > > [25747.786778] 2 locks held by kworker/14:2/28476:
> > > [25747.787244] #0: ffff9dd1c1054738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x4d7/0x840
> > > [25747.788196] #1: ffffabe581ce3dd0 ((work_completion)(&wfc.work)){+.+.}-{0:0}, at: process_one_work+0x508/0x840
> > > [25747.789216] irq event stamp: 47423
> > > [25747.789563] hardirqs last enabled at (47423): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [25747.790533] hardirqs last disabled at (47422): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> > > [25747.791450] softirqs last enabled at (47410): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [25747.792253] softirqs last disabled at (47405): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [25747.804153]
> > > [25747.804319] write to 0xffff9dd1df5acb50 of 1 bytes by task 169 on cpu 13:
> > > [25747.805254] rcu_nocb_cb_kthread+0x479/0x760
> > > [25747.805701] kthread+0x29b/0x2b0
> > > [25747.806156] ret_from_fork+0x22/0x30
> > > [25747.806581]
> > > [25747.806747] 1 lock held by rcuop/14/169:
> > > [25747.807344] #0: ffff9dd1df5acc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_cb_kthread+0x2ff/0x760
> > > [25747.809333] irq event stamp: 19677863
> > > [25747.810093] hardirqs last enabled at (19677862): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> > > [25747.820095] hardirqs last disabled at (19677863): [<ffffffff9b1b28b7>] rcu_nocb_cb_kthread+0x2e7/0x760
> > > [25747.822317] softirqs last enabled at (19677861): [<ffffffff9b1ade6d>] local_bh_enable+0xd/0x30
> > > [25747.824060] softirqs last disabled at (19677859): [<ffffffff9b1ad5dd>] local_bh_disable+0xd/0x30
> > >
> > > 0xffffffff811a5853 is in rcu_nocb_rdp_deoffload (kernel/rcu/rcu_segcblist.h:71).
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > > 70 {
> > > 71 return READ_ONCE(rsclp->flags) & flags;
> > > 72 }
> > > 73
> > > 74 /*
> > > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> > >
> > > 0xffffffff811b2a49 is in rcu_nocb_cb_kthread (kernel/rcu/rcu_segcblist.h:65).
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
> > > 64 {
> > > 65 rsclp->flags &= ~flags;
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > >
> > > ------------------------------------------------------------------------
> > >
> > > BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_nocb_rdp_offload
> > >
> > > [15688.905747] read (marked) to 0xffff9dd1df56cb50 of 1 bytes by task 154 on cpu 9:
> > > [15688.906550] rcu_nocb_gp_kthread+0x237/0x1180
> > > [15688.907050] kthread+0x29b/0x2b0
> > > [15688.907421] ret_from_fork+0x22/0x30
> > > [15688.907824]
> > > [15688.908022] no locks held by rcuog/12/154.
> > > [15688.908468] irq event stamp: 13085451
> > > [15688.908865] hardirqs last enabled at (13085451): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [15688.909929] hardirqs last disabled at (13085450): [<ffffffff9c71b053>] _raw_spin_lock_irqsave+0x53/0xb0
> > > [15688.910949] softirqs last enabled at (13085112): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [15688.911908] softirqs last disabled at (13085107): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [15688.912849]
> > > [15688.913043] write to 0xffff9dd1df56cb50 of 1 bytes by task 16476 on cpu 13:
> > > [15688.913830] rcu_nocb_rdp_offload+0x24e/0x2c0
> > > [15688.914364] work_for_cpu_fn+0x32/0x50
> > > [15688.914805] process_one_work+0x54f/0x840
> > > [15688.915159] worker_thread+0x79c/0xa90
> > > [15688.915544] kthread+0x29b/0x2b0
> > > [15688.915907] ret_from_fork+0x22/0x30
> > > [15688.916325]
> > > [15688.916502] 3 locks held by kworker/13:0/16476:
> > > [15688.917016] #0: ffff9dd1c1054738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x4d7/0x840
> > > [15688.918073] #1: ffffabe585163dd0 ((work_completion)(&wfc.work)){+.+.}-{0:0}, at: process_one_work+0x508/0x840
> > > [15688.919153] #2: ffff9dd1df56cc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_rdp_offload+0x237/0x2c0
> > > [15688.920171] irq event stamp: 198553
> > > [15688.920539] hardirqs last enabled at (198552): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [15688.921577] hardirqs last disabled at (198553): [<ffffffff9b1a5d5e>] rcu_nocb_rdp_offload+0x21e/0x2c0
> > > [15688.922553] softirqs last enabled at (198341): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [15688.923462] softirqs last disabled at (198336): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > >
> > > 0xffffffff811b1687 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:71).
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > > 70 {
> > > 71 return READ_ONCE(rsclp->flags) & flags;
> > > 72 }
> > > 73
> > > 74 /*
> > > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> > >
> > > 0xffffffff811a5d8e is in rcu_nocb_rdp_offload (kernel/rcu/rcu_segcblist.h:65).
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
> > > 64 {
> > > 65 rsclp->flags &= ~flags;
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > >
> > > ------------------------------------------------------------------------
> > >
> > > BUG: KCSAN: data-race in rcu_nocb_gp_kthread / rcu_rdp_is_offloaded
> > >
> > > [30067.322599] read (marked) to 0xffff9dd1df2ecb50 of 1 bytes by interrupt on cpu 3:
> > > [30067.323367] rcu_rdp_is_offloaded+0x63/0x1c0
> > > [30067.323929] rcu_sched_clock_irq+0x9d2/0x18d0
> > > [30067.324269] update_process_times+0xe9/0x110
> > > [30067.324692] tick_sched_timer+0xfd/0x170
> > > [30067.325195] __hrtimer_run_queues+0x28a/0x450
> > > [30067.325647] hrtimer_interrupt+0x234/0x6d0
> > > [30067.326519] __sysvec_apic_timer_interrupt+0xb8/0x1a0
> > > [30067.327039] sysvec_apic_timer_interrupt+0x9a/0xc0
> > > [30067.327557] asm_sysvec_apic_timer_interrupt+0x12/0x20
> > > [30067.328105] __tsan_read8+0x167/0x240
> > > [30067.328503] rcutorture_one_extend+0x211/0x590
> > > [30067.328994] rcu_torture_one_read+0x785/0xc90
> > > [30067.329444] rcu_torture_reader+0x19b/0x2e0
> > > [30067.330309] kthread+0x29b/0x2b0
> > > [30067.330654] ret_from_fork+0x22/0x30
> > > [30067.331075]
> > > [30067.331240] 2 locks held by rcu_torture_rea/93:
> > > [30067.331700] #0: ffffffff9d35c208 (rcu_read_lock_sched){....}-{1:2}, at: rcu_lock_acquire+0x11/0x40
> > > [30067.332708] #1: ffffffff9d35c238 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x11/0x40
> > > [30067.333656] irq event stamp: 2508045894
> > > [30067.334185] hardirqs last enabled at (2508045893): [<ffffffff9b0bf40a>] __local_bh_enable_ip+0xca/0x120
> > > [30067.335192] hardirqs last disabled at (2508045894): [<ffffffff9c70e1f7>] sysvec_apic_timer_interrupt+0x17/0xc0
> > > [30067.342726] softirqs last enabled at (2508045892): [<ffffffff9b1956fd>] local_bh_enable+0xd/0x30
> > > [30067.354637] softirqs last disabled at (2508045890): [<ffffffff9b1956cd>] local_bh_disable+0xd/0x30
> > > [30067.355483]
> > > [30067.355627] write to 0xffff9dd1df2ecb50 of 1 bytes by task 15 on cpu 0:
> > > [30067.356228] rcu_nocb_gp_kthread+0x3a3/0x1180
> > > [30067.356628] kthread+0x29b/0x2b0
> > > [30067.356936] ret_from_fork+0x22/0x30
> > > [30067.357284]
> > > [30067.357431] 1 lock held by rcuog/0/15:
> > > [30067.357873] #0: ffff9dd1df2ecc70 (&rdp->nocb_lock){-.-.}-{2:2}, at: rcu_nocb_gp_kthread+0x2f2/0x1180
> > > [30067.358746] irq event stamp: 19891260
> > > [30067.359093] hardirqs last enabled at (19891259): [<ffffffff9c71b23a>] _raw_spin_unlock_irqrestore+0x3a/0x70
> > > [30067.359998] hardirqs last disabled at (19891260): [<ffffffff9b1b1722>] rcu_nocb_gp_kthread+0x2d2/0x1180
> > > [30067.360860] softirqs last enabled at (19890706): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > > [30067.361694] softirqs last disabled at (19890697): [<ffffffff9b0bf844>] __irq_exit_rcu+0x64/0xc0
> > >
> > > 0xffffffff8119a543 is in rcu_rdp_is_offloaded (kernel/rcu/rcu_segcblist.h:71).
> > > 66 }
> > > 67
> > > 68 static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
> > > 69 int flags)
> > > 70 {
> > > 71 return READ_ONCE(rsclp->flags) & flags;
> > > 72 }
> > > 73
> > > 74 /*
> > > 75 * Is the specified rcu_segcblist enabled, for example, not corresponding
> > >
> > > 0xffffffff811b17f3 is in rcu_nocb_gp_kthread (kernel/rcu/rcu_segcblist.h:59).
> > > 54 }
> > > 55
> > > 56 static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> > > 57 int flags)
> > > 58 {
> > > 59 rsclp->flags |= flags;
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2021-12-14 8:38 ` Zhouyi Zhou
2021-12-14 14:48 ` Paul E. McKenney
@ 2021-12-14 16:57 ` Marco Elver
2021-12-14 17:59 ` Zhouyi Zhou
1 sibling, 1 reply; 11+ messages in thread
From: Marco Elver @ 2021-12-14 16:57 UTC (permalink / raw)
To: Zhouyi Zhou; +Cc: paulmck, rcu
On Tue, 14 Dec 2021 at 09:38, Zhouyi Zhou <zhouzhouyi@gmail.com> wrote:
[...]
> 2) The KCSAN kernel compile with clang-12:
> CONFIG_HAVE_ARCH_KCSAN=y
> CONFIG_HAVE_KCSAN_COMPILER=y
> CONFIG_KCSAN=y
> CONFIG_KCSAN_SELFTEST=y
> # CONFIG_KCSAN_EARLY_ENABLE is not set
> CONFIG_KCSAN_NUM_WATCHPOINTS=64
> CONFIG_KCSAN_UDELAY_TASK=80
> CONFIG_KCSAN_UDELAY_INTERRUPT=20
> CONFIG_KCSAN_DELAY_RANDOMIZE=y
> CONFIG_KCSAN_SKIP_WATCH=4000
> CONFIG_KCSAN_SKIP_WATCH_RANDOMIZE=y
> # CONFIG_KCSAN_INTERRUPT_WATCHER is not set
> CONFIG_KCSAN_REPORT_ONCE_IN_MS=3000
> # CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN is not set
> # CONFIG_KCSAN_STRICT is not set
> CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY=y
> # CONFIG_KCSAN_ASSUME_PLAIN_WRITES_ATOMIC is not set
> CONFIG_KCSAN_IGNORE_ATOMICS=y
> CONFIG_KCSAN_PERMISSIVE=y
Note, rcutorture selects CONFIG_KCSAN_STRICT=y, which may be one part
of the issue. The other is that the -rcu tree has KCSAN enhancements
not yet available in mainline, which are enabled together with
CONFIG_KCSAN_STRICT, and make KCSAN slightly more aggressive (i.e.
finds data races faster) as well. Although you can also locally make
KCSAN a bit more aggressive by lowering CONFIG_KCSAN_SKIP_WATCH (boot
param kcsan.skip_watch=), to e.g. 2000-3000, but too low and you'll
hurt forward-progress.
-- Marco
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2021-12-14 16:57 ` Marco Elver
@ 2021-12-14 17:59 ` Zhouyi Zhou
2022-01-02 0:27 ` Zhouyi Zhou
0 siblings, 1 reply; 11+ messages in thread
From: Zhouyi Zhou @ 2021-12-14 17:59 UTC (permalink / raw)
To: Marco Elver; +Cc: paulmck, rcu
Thank Marco for giving me such valuable advice.
Both RCU and KCSAN are very attractive and amazing to me, I have
carefully read your advice and will strive to acquire expertise in the
following days.
Thanks again
Zhouyi
On Wed, Dec 15, 2021 at 12:57 AM Marco Elver <elver@google.com> wrote:
>
> On Tue, 14 Dec 2021 at 09:38, Zhouyi Zhou <zhouzhouyi@gmail.com> wrote:
> [...]
> > 2) The KCSAN kernel compile with clang-12:
> > CONFIG_HAVE_ARCH_KCSAN=y
> > CONFIG_HAVE_KCSAN_COMPILER=y
> > CONFIG_KCSAN=y
> > CONFIG_KCSAN_SELFTEST=y
> > # CONFIG_KCSAN_EARLY_ENABLE is not set
> > CONFIG_KCSAN_NUM_WATCHPOINTS=64
> > CONFIG_KCSAN_UDELAY_TASK=80
> > CONFIG_KCSAN_UDELAY_INTERRUPT=20
> > CONFIG_KCSAN_DELAY_RANDOMIZE=y
> > CONFIG_KCSAN_SKIP_WATCH=4000
> > CONFIG_KCSAN_SKIP_WATCH_RANDOMIZE=y
> > # CONFIG_KCSAN_INTERRUPT_WATCHER is not set
> > CONFIG_KCSAN_REPORT_ONCE_IN_MS=3000
> > # CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN is not set
> > # CONFIG_KCSAN_STRICT is not set
> > CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY=y
> > # CONFIG_KCSAN_ASSUME_PLAIN_WRITES_ATOMIC is not set
> > CONFIG_KCSAN_IGNORE_ATOMICS=y
> > CONFIG_KCSAN_PERMISSIVE=y
>
> Note, rcutorture selects CONFIG_KCSAN_STRICT=y, which may be one part
> of the issue. The other is that the -rcu tree has KCSAN enhancements
> not yet available in mainline, which are enabled together with
> CONFIG_KCSAN_STRICT, and make KCSAN slightly more aggressive (i.e.
> finds data races faster) as well. Although you can also locally make
> KCSAN a bit more aggressive by lowering CONFIG_KCSAN_SKIP_WATCH (boot
> param kcsan.skip_watch=), to e.g. 2000-3000, but too low and you'll
> hurt forward-progress.
>
> -- Marco
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2021-12-14 17:59 ` Zhouyi Zhou
@ 2022-01-02 0:27 ` Zhouyi Zhou
2022-01-04 18:42 ` Paul E. McKenney
0 siblings, 1 reply; 11+ messages in thread
From: Zhouyi Zhou @ 2022-01-02 0:27 UTC (permalink / raw)
To: Marco Elver; +Cc: paulmck, rcu
Thanks Paul and Marco for giving me valuable advice.
I studied the structure of kvm.sh and I found enabling
CONFIG_KCSAN_STRICT and lower kcsan.skip_watch will make the KCSAN
detect RCU's data-race within half an hour (I tried this for two
times).
Following is my command:
linux-rcu$git config --get remote.origin.url
https://kernel.source.codeaurora.cn/pub/scm/linux/kernel/git/paulmck/linux-rcu.git/
linux-rcu$tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus
--duration 10h --configs "TREE01" --kcsan --kmake-arg "CC=clang-12"
--trust-make --kconfig CONFIG_KCSAN_STRICT=y --bootargs
kcsan.skip_watch=1000
[ 1289.504892] rcu: De-offloading 5^M
[ 1289.761495] rcu: De-offloading 7^M
[ 1289.763556] ==================================================================^M
[ 1289.764531] BUG: KCSAN: data-race in call_rcu / rcu_nocb_cb_kthread^M
[ 1289.765388] ^M
[ 1289.765599] read (marked) to 0xffff94f2db7ec608 of 1 bytes by
interrupt on cpu 7:^M
[ 1289.766588] call_rcu+0xad/0xfd0^M
[ 1289.767035] rcu_torture_timer+0xdc/0xf0^M
[ 1289.767566] call_timer_fn+0x87/0x150^M
[ 1289.768065] __run_timers+0x2fd/0x450^M
[ 1289.768562] run_timer_softirq+0x29/0x60^M
[ 1289.769093] __do_softirq+0x1d9/0x35c^M
[ 1289.769540] __irq_exit_rcu+0x13d/0x150^M
[ 1289.770047] irq_exit_rcu+0x5/0x20^M
[ 1289.770520] sysvec_apic_timer_interrupt+0x8d/0xb0^M
[ 1289.771168] asm_sysvec_apic_timer_interrupt+0x12/0x20^M
[ 1289.771854] _raw_spin_unlock_irqrestore+0x33/0x50^M
[ 1289.772499] rdp_offload_toggle+0xc9/0x150^M
[ 1289.773050] rcu_nocb_rdp_deoffload+0x163/0x2c0^M
[ 1289.773670] work_for_cpu_fn+0x28/0x40^M
[ 1289.774185] process_one_work+0x50f/0x800^M
[ 1289.774726] worker_thread+0x71c/0x9f0^M
[ 1289.775237] kthread+0x23e/0x270^M
[ 1289.775675] ret_from_fork+0x22/0x30^M
[ 1289.776162] ^M
[ 1289.776377] 3 locks held by kworker/7:2/294:^M
[ 1289.776955] #0: ffff94f2c1050738
((wq_completion)events){+.+.}-{0:0}, at:
process_one_work+0x49c/0x800^M
[ 1289.778245] #1: ffffa5434093bde0
((work_completion)(&wfc.work)){+.+.}-{0:0}, at:
process_one_work+0x4cd/0x800^M
[ 1289.779605] #2: ffffa5434029cdf8 ((&t)){+.-.}-{0:0}, at:
call_timer_fn+0x51/0x150^M
[ 1289.780666] irq event stamp: 215649^M
[ 1289.781186] hardirqs last enabled at (215648):
[<ffffffff8d6afec2>] __local_bh_enable_ip+0xc2/0x120^M
[ 1289.782471] hardirqs last disabled at (215649):
[<ffffffff8d77c6a3>] call_rcu+0x73/0xfd0^M
[ 1289.783632] softirqs last enabled at (214628):
[<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
[ 1289.784866] softirqs last disabled at (215635):
[<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
[ 1289.786147] ^M
[ 1289.786379] write to 0xffff94f2db7ec608 of 1 bytes by task 63 on cpu 15:^M
[ 1289.787342] rcu_nocb_cb_kthread+0x2f7/0x740^M
[ 1289.787970] kthread+0x23e/0x270^M
[ 1289.788450] ret_from_fork+0x22/0x30^M
[ 1289.788964] ^M
The reader is at
0xffffffff8117c6dd: file kernel/rcu/tree.c, line 2991
2986 local_irq_save(flags);
2987 kasan_record_aux_stack(head);
2988 rdp = this_cpu_ptr(&rcu_data);
2989
2990 /* Add the callback to our list. */
2991 if (unlikely(!rcu_segcblist_is_enabled(&rdp->cblist))) {
2992 // This can trigger due to call_rcu() from offline CPU:
2993 WARN_ON_ONCE(rcu_scheduler_active != RCU_SCHEDULER_INACTIVE);
2994 WARN_ON_ONCE(!rcu_is_watching());
2995 // Very early boot, before rcu_init(). Initialize if needed
The writer is at
0xffffffff81191977: file kernel/rcu/rcu_segcblist.h, line 65
60 }
61
62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
63 int flags)
64 {
65 rsclp->flags &= ~flags;
66 }
67
I gained a lot during the study ;-)
Many thanks
Zhouyi
On Wed, Dec 15, 2021 at 1:59 AM Zhouyi Zhou <zhouzhouyi@gmail.com> wrote:
>
> Thank Marco for giving me such valuable advice.
>
> Both RCU and KCSAN are very attractive and amazing to me, I have
> carefully read your advice and will strive to acquire expertise in the
> following days.
>
> Thanks again
> Zhouyi
>
> On Wed, Dec 15, 2021 at 12:57 AM Marco Elver <elver@google.com> wrote:
> >
> > On Tue, 14 Dec 2021 at 09:38, Zhouyi Zhou <zhouzhouyi@gmail.com> wrote:
> > [...]
> > > 2) The KCSAN kernel compile with clang-12:
> > > CONFIG_HAVE_ARCH_KCSAN=y
> > > CONFIG_HAVE_KCSAN_COMPILER=y
> > > CONFIG_KCSAN=y
> > > CONFIG_KCSAN_SELFTEST=y
> > > # CONFIG_KCSAN_EARLY_ENABLE is not set
> > > CONFIG_KCSAN_NUM_WATCHPOINTS=64
> > > CONFIG_KCSAN_UDELAY_TASK=80
> > > CONFIG_KCSAN_UDELAY_INTERRUPT=20
> > > CONFIG_KCSAN_DELAY_RANDOMIZE=y
> > > CONFIG_KCSAN_SKIP_WATCH=4000
> > > CONFIG_KCSAN_SKIP_WATCH_RANDOMIZE=y
> > > # CONFIG_KCSAN_INTERRUPT_WATCHER is not set
> > > CONFIG_KCSAN_REPORT_ONCE_IN_MS=3000
> > > # CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN is not set
> > > # CONFIG_KCSAN_STRICT is not set
> > > CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY=y
> > > # CONFIG_KCSAN_ASSUME_PLAIN_WRITES_ATOMIC is not set
> > > CONFIG_KCSAN_IGNORE_ATOMICS=y
> > > CONFIG_KCSAN_PERMISSIVE=y
> >
> > Note, rcutorture selects CONFIG_KCSAN_STRICT=y, which may be one part
> > of the issue. The other is that the -rcu tree has KCSAN enhancements
> > not yet available in mainline, which are enabled together with
> > CONFIG_KCSAN_STRICT, and make KCSAN slightly more aggressive (i.e.
> > finds data races faster) as well. Although you can also locally make
> > KCSAN a bit more aggressive by lowering CONFIG_KCSAN_SKIP_WATCH (boot
> > param kcsan.skip_watch=), to e.g. 2000-3000, but too low and you'll
> > hurt forward-progress.
> >
> > -- Marco
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2022-01-02 0:27 ` Zhouyi Zhou
@ 2022-01-04 18:42 ` Paul E. McKenney
2022-01-04 22:51 ` Zhouyi Zhou
0 siblings, 1 reply; 11+ messages in thread
From: Paul E. McKenney @ 2022-01-04 18:42 UTC (permalink / raw)
To: Zhouyi Zhou; +Cc: Marco Elver, rcu, Frederic Weisbecker
On Sun, Jan 02, 2022 at 08:27:29AM +0800, Zhouyi Zhou wrote:
> Thanks Paul and Marco for giving me valuable advice.
>
> I studied the structure of kvm.sh and I found enabling
> CONFIG_KCSAN_STRICT and lower kcsan.skip_watch will make the KCSAN
> detect RCU's data-race within half an hour (I tried this for two
> times).
> Following is my command:
> linux-rcu$git config --get remote.origin.url
> https://kernel.source.codeaurora.cn/pub/scm/linux/kernel/git/paulmck/linux-rcu.git/
> linux-rcu$tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus
> --duration 10h --configs "TREE01" --kcsan --kmake-arg "CC=clang-12"
> --trust-make --kconfig CONFIG_KCSAN_STRICT=y --bootargs
> kcsan.skip_watch=1000
>
>
> [ 1289.504892] rcu: De-offloading 5^M
> [ 1289.761495] rcu: De-offloading 7^M
> [ 1289.763556] ==================================================================^M
> [ 1289.764531] BUG: KCSAN: data-race in call_rcu / rcu_nocb_cb_kthread^M
> [ 1289.765388] ^M
> [ 1289.765599] read (marked) to 0xffff94f2db7ec608 of 1 bytes by
> interrupt on cpu 7:^M
> [ 1289.766588] call_rcu+0xad/0xfd0^M
> [ 1289.767035] rcu_torture_timer+0xdc/0xf0^M
> [ 1289.767566] call_timer_fn+0x87/0x150^M
> [ 1289.768065] __run_timers+0x2fd/0x450^M
> [ 1289.768562] run_timer_softirq+0x29/0x60^M
> [ 1289.769093] __do_softirq+0x1d9/0x35c^M
> [ 1289.769540] __irq_exit_rcu+0x13d/0x150^M
> [ 1289.770047] irq_exit_rcu+0x5/0x20^M
> [ 1289.770520] sysvec_apic_timer_interrupt+0x8d/0xb0^M
> [ 1289.771168] asm_sysvec_apic_timer_interrupt+0x12/0x20^M
> [ 1289.771854] _raw_spin_unlock_irqrestore+0x33/0x50^M
> [ 1289.772499] rdp_offload_toggle+0xc9/0x150^M
> [ 1289.773050] rcu_nocb_rdp_deoffload+0x163/0x2c0^M
> [ 1289.773670] work_for_cpu_fn+0x28/0x40^M
> [ 1289.774185] process_one_work+0x50f/0x800^M
> [ 1289.774726] worker_thread+0x71c/0x9f0^M
> [ 1289.775237] kthread+0x23e/0x270^M
> [ 1289.775675] ret_from_fork+0x22/0x30^M
> [ 1289.776162] ^M
> [ 1289.776377] 3 locks held by kworker/7:2/294:^M
> [ 1289.776955] #0: ffff94f2c1050738
> ((wq_completion)events){+.+.}-{0:0}, at:
> process_one_work+0x49c/0x800^M
> [ 1289.778245] #1: ffffa5434093bde0
> ((work_completion)(&wfc.work)){+.+.}-{0:0}, at:
> process_one_work+0x4cd/0x800^M
> [ 1289.779605] #2: ffffa5434029cdf8 ((&t)){+.-.}-{0:0}, at:
> call_timer_fn+0x51/0x150^M
> [ 1289.780666] irq event stamp: 215649^M
> [ 1289.781186] hardirqs last enabled at (215648):
> [<ffffffff8d6afec2>] __local_bh_enable_ip+0xc2/0x120^M
> [ 1289.782471] hardirqs last disabled at (215649):
> [<ffffffff8d77c6a3>] call_rcu+0x73/0xfd0^M
> [ 1289.783632] softirqs last enabled at (214628):
> [<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
> [ 1289.784866] softirqs last disabled at (215635):
> [<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
> [ 1289.786147] ^M
> [ 1289.786379] write to 0xffff94f2db7ec608 of 1 bytes by task 63 on cpu 15:^M
> [ 1289.787342] rcu_nocb_cb_kthread+0x2f7/0x740^M
> [ 1289.787970] kthread+0x23e/0x270^M
> [ 1289.788450] ret_from_fork+0x22/0x30^M
> [ 1289.788964] ^M
>
> The reader is at
> 0xffffffff8117c6dd: file kernel/rcu/tree.c, line 2991
> 2986 local_irq_save(flags);
> 2987 kasan_record_aux_stack(head);
> 2988 rdp = this_cpu_ptr(&rcu_data);
> 2989
> 2990 /* Add the callback to our list. */
> 2991 if (unlikely(!rcu_segcblist_is_enabled(&rdp->cblist))) {
> 2992 // This can trigger due to call_rcu() from offline CPU:
> 2993 WARN_ON_ONCE(rcu_scheduler_active != RCU_SCHEDULER_INACTIVE);
> 2994 WARN_ON_ONCE(!rcu_is_watching());
> 2995 // Very early boot, before rcu_init(). Initialize if needed
>
> The writer is at
> 0xffffffff81191977: file kernel/rcu/rcu_segcblist.h, line 65
> 60 }
> 61
> 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> 63 int flags)
> 64 {
> 65 rsclp->flags &= ~flags;
> 66 }
> 67
>
> I gained a lot during the study ;-)
Glad the process was educational. ;-)
Thoughts on the alleged fix below?
Thanx, Paul
------------------------------------------------------------------------
commit 66b153e7e3980067de018ec8c478aa0aaf7ba2bd
Author: Paul E. McKenney <paulmck@kernel.org>
Date: Tue Jan 4 10:34:34 2022 -0800
rcu: Mark writes to the rcu_segcblist structure's ->flags field
KCSAN reports data races between the rcu_segcblist_clear_flags() and
rcu_segcblist_set_flags() functions, though misreporting the latter
as a call to rcu_segcblist_is_enabled() from call_rcu(). This commit
converts the updates of this field to WRITE_ONCE(), relying on the
resulting unmarked reads to continue to detect buggy concurrent writes
to this field.
Reported-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Frederic Weisbecker <frederic@kernel.org>
diff --git a/kernel/rcu/rcu_segcblist.h b/kernel/rcu/rcu_segcblist.h
index e373fbe44da5e..431cee212467d 100644
--- a/kernel/rcu/rcu_segcblist.h
+++ b/kernel/rcu/rcu_segcblist.h
@@ -56,13 +56,13 @@ static inline long rcu_segcblist_n_cbs(struct rcu_segcblist *rsclp)
static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
int flags)
{
- rsclp->flags |= flags;
+ WRITE_ONCE(rsclp->flags, rsclp->flags | flags);
}
static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
int flags)
{
- rsclp->flags &= ~flags;
+ WRITE_ONCE(rsclp->flags, rsclp->flags & ~flags);
}
static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2022-01-04 18:42 ` Paul E. McKenney
@ 2022-01-04 22:51 ` Zhouyi Zhou
2022-01-04 23:58 ` Paul E. McKenney
0 siblings, 1 reply; 11+ messages in thread
From: Zhouyi Zhou @ 2022-01-04 22:51 UTC (permalink / raw)
To: paulmck; +Cc: Marco Elver, rcu, Frederic Weisbecker
Thank Paul for your encouragement
May I make bold to suggest a possible small modification to git log as
below (use the knowledge and terms I learned from perfbook)
Thanks
Zhouyi
On Wed, Jan 5, 2022 at 2:42 AM Paul E. McKenney <paulmck@kernel.org> wrote:
>
> On Sun, Jan 02, 2022 at 08:27:29AM +0800, Zhouyi Zhou wrote:
> > Thanks Paul and Marco for giving me valuable advice.
> >
> > I studied the structure of kvm.sh and I found enabling
> > CONFIG_KCSAN_STRICT and lower kcsan.skip_watch will make the KCSAN
> > detect RCU's data-race within half an hour (I tried this for two
> > times).
> > Following is my command:
> > linux-rcu$git config --get remote.origin.url
> > https://kernel.source.codeaurora.cn/pub/scm/linux/kernel/git/paulmck/linux-rcu.git/
> > linux-rcu$tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus
> > --duration 10h --configs "TREE01" --kcsan --kmake-arg "CC=clang-12"
> > --trust-make --kconfig CONFIG_KCSAN_STRICT=y --bootargs
> > kcsan.skip_watch=1000
> >
> >
> > [ 1289.504892] rcu: De-offloading 5^M
> > [ 1289.761495] rcu: De-offloading 7^M
> > [ 1289.763556] ==================================================================^M
> > [ 1289.764531] BUG: KCSAN: data-race in call_rcu / rcu_nocb_cb_kthread^M
> > [ 1289.765388] ^M
> > [ 1289.765599] read (marked) to 0xffff94f2db7ec608 of 1 bytes by
> > interrupt on cpu 7:^M
> > [ 1289.766588] call_rcu+0xad/0xfd0^M
> > [ 1289.767035] rcu_torture_timer+0xdc/0xf0^M
> > [ 1289.767566] call_timer_fn+0x87/0x150^M
> > [ 1289.768065] __run_timers+0x2fd/0x450^M
> > [ 1289.768562] run_timer_softirq+0x29/0x60^M
> > [ 1289.769093] __do_softirq+0x1d9/0x35c^M
> > [ 1289.769540] __irq_exit_rcu+0x13d/0x150^M
> > [ 1289.770047] irq_exit_rcu+0x5/0x20^M
> > [ 1289.770520] sysvec_apic_timer_interrupt+0x8d/0xb0^M
> > [ 1289.771168] asm_sysvec_apic_timer_interrupt+0x12/0x20^M
> > [ 1289.771854] _raw_spin_unlock_irqrestore+0x33/0x50^M
> > [ 1289.772499] rdp_offload_toggle+0xc9/0x150^M
> > [ 1289.773050] rcu_nocb_rdp_deoffload+0x163/0x2c0^M
> > [ 1289.773670] work_for_cpu_fn+0x28/0x40^M
> > [ 1289.774185] process_one_work+0x50f/0x800^M
> > [ 1289.774726] worker_thread+0x71c/0x9f0^M
> > [ 1289.775237] kthread+0x23e/0x270^M
> > [ 1289.775675] ret_from_fork+0x22/0x30^M
> > [ 1289.776162] ^M
> > [ 1289.776377] 3 locks held by kworker/7:2/294:^M
> > [ 1289.776955] #0: ffff94f2c1050738
> > ((wq_completion)events){+.+.}-{0:0}, at:
> > process_one_work+0x49c/0x800^M
> > [ 1289.778245] #1: ffffa5434093bde0
> > ((work_completion)(&wfc.work)){+.+.}-{0:0}, at:
> > process_one_work+0x4cd/0x800^M
> > [ 1289.779605] #2: ffffa5434029cdf8 ((&t)){+.-.}-{0:0}, at:
> > call_timer_fn+0x51/0x150^M
> > [ 1289.780666] irq event stamp: 215649^M
> > [ 1289.781186] hardirqs last enabled at (215648):
> > [<ffffffff8d6afec2>] __local_bh_enable_ip+0xc2/0x120^M
> > [ 1289.782471] hardirqs last disabled at (215649):
> > [<ffffffff8d77c6a3>] call_rcu+0x73/0xfd0^M
> > [ 1289.783632] softirqs last enabled at (214628):
> > [<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
> > [ 1289.784866] softirqs last disabled at (215635):
> > [<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
> > [ 1289.786147] ^M
> > [ 1289.786379] write to 0xffff94f2db7ec608 of 1 bytes by task 63 on cpu 15:^M
> > [ 1289.787342] rcu_nocb_cb_kthread+0x2f7/0x740^M
> > [ 1289.787970] kthread+0x23e/0x270^M
> > [ 1289.788450] ret_from_fork+0x22/0x30^M
> > [ 1289.788964] ^M
> >
> > The reader is at
> > 0xffffffff8117c6dd: file kernel/rcu/tree.c, line 2991
> > 2986 local_irq_save(flags);
> > 2987 kasan_record_aux_stack(head);
> > 2988 rdp = this_cpu_ptr(&rcu_data);
> > 2989
> > 2990 /* Add the callback to our list. */
> > 2991 if (unlikely(!rcu_segcblist_is_enabled(&rdp->cblist))) {
> > 2992 // This can trigger due to call_rcu() from offline CPU:
> > 2993 WARN_ON_ONCE(rcu_scheduler_active != RCU_SCHEDULER_INACTIVE);
> > 2994 WARN_ON_ONCE(!rcu_is_watching());
> > 2995 // Very early boot, before rcu_init(). Initialize if needed
> >
> > The writer is at
> > 0xffffffff81191977: file kernel/rcu/rcu_segcblist.h, line 65
> > 60 }
> > 61
> > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > 63 int flags)
> > 64 {
> > 65 rsclp->flags &= ~flags;
> > 66 }
> > 67
> >
> > I gained a lot during the study ;-)
>
> Glad the process was educational. ;-)
>
> Thoughts on the alleged fix below?
>
> Thanx, Paul
>
> ------------------------------------------------------------------------
>
> commit 66b153e7e3980067de018ec8c478aa0aaf7ba2bd
> Author: Paul E. McKenney <paulmck@kernel.org>
> Date: Tue Jan 4 10:34:34 2022 -0800
>
> rcu: Mark writes to the rcu_segcblist structure's ->flags field
>
> KCSAN reports data races between the rcu_segcblist_clear_flags() and
> rcu_segcblist_set_flags() functions, though misreporting the latter
> as a call to rcu_segcblist_is_enabled() from call_rcu(). This commit
as a call to rcu_segcblist_is_enabled() from call_rcu() because
the compiler
optimizes the intermediate functions away. This commit
> converts the updates of this field to WRITE_ONCE(), relying on the
> resulting unmarked reads to continue to detect buggy concurrent writes
> to this field.
>
> Reported-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
> Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> Cc: Frederic Weisbecker <frederic@kernel.org>
>
> diff --git a/kernel/rcu/rcu_segcblist.h b/kernel/rcu/rcu_segcblist.h
> index e373fbe44da5e..431cee212467d 100644
> --- a/kernel/rcu/rcu_segcblist.h
> +++ b/kernel/rcu/rcu_segcblist.h
> @@ -56,13 +56,13 @@ static inline long rcu_segcblist_n_cbs(struct rcu_segcblist *rsclp)
> static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> int flags)
> {
> - rsclp->flags |= flags;
> + WRITE_ONCE(rsclp->flags, rsclp->flags | flags);
> }
>
> static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> int flags)
> {
> - rsclp->flags &= ~flags;
> + WRITE_ONCE(rsclp->flags, rsclp->flags & ~flags);
> }
>
> static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2022-01-04 22:51 ` Zhouyi Zhou
@ 2022-01-04 23:58 ` Paul E. McKenney
2022-01-05 0:41 ` Zhouyi Zhou
0 siblings, 1 reply; 11+ messages in thread
From: Paul E. McKenney @ 2022-01-04 23:58 UTC (permalink / raw)
To: Zhouyi Zhou; +Cc: Marco Elver, rcu, Frederic Weisbecker
On Wed, Jan 05, 2022 at 06:51:49AM +0800, Zhouyi Zhou wrote:
> Thank Paul for your encouragement
>
> May I make bold to suggest a possible small modification to git log as
> below (use the knowledge and terms I learned from perfbook)
>
> Thanks
> Zhouyi
> On Wed, Jan 5, 2022 at 2:42 AM Paul E. McKenney <paulmck@kernel.org> wrote:
> >
> > On Sun, Jan 02, 2022 at 08:27:29AM +0800, Zhouyi Zhou wrote:
> > > Thanks Paul and Marco for giving me valuable advice.
> > >
> > > I studied the structure of kvm.sh and I found enabling
> > > CONFIG_KCSAN_STRICT and lower kcsan.skip_watch will make the KCSAN
> > > detect RCU's data-race within half an hour (I tried this for two
> > > times).
> > > Following is my command:
> > > linux-rcu$git config --get remote.origin.url
> > > https://kernel.source.codeaurora.cn/pub/scm/linux/kernel/git/paulmck/linux-rcu.git/
> > > linux-rcu$tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus
> > > --duration 10h --configs "TREE01" --kcsan --kmake-arg "CC=clang-12"
> > > --trust-make --kconfig CONFIG_KCSAN_STRICT=y --bootargs
> > > kcsan.skip_watch=1000
> > >
> > >
> > > [ 1289.504892] rcu: De-offloading 5^M
> > > [ 1289.761495] rcu: De-offloading 7^M
> > > [ 1289.763556] ==================================================================^M
> > > [ 1289.764531] BUG: KCSAN: data-race in call_rcu / rcu_nocb_cb_kthread^M
> > > [ 1289.765388] ^M
> > > [ 1289.765599] read (marked) to 0xffff94f2db7ec608 of 1 bytes by
> > > interrupt on cpu 7:^M
> > > [ 1289.766588] call_rcu+0xad/0xfd0^M
> > > [ 1289.767035] rcu_torture_timer+0xdc/0xf0^M
> > > [ 1289.767566] call_timer_fn+0x87/0x150^M
> > > [ 1289.768065] __run_timers+0x2fd/0x450^M
> > > [ 1289.768562] run_timer_softirq+0x29/0x60^M
> > > [ 1289.769093] __do_softirq+0x1d9/0x35c^M
> > > [ 1289.769540] __irq_exit_rcu+0x13d/0x150^M
> > > [ 1289.770047] irq_exit_rcu+0x5/0x20^M
> > > [ 1289.770520] sysvec_apic_timer_interrupt+0x8d/0xb0^M
> > > [ 1289.771168] asm_sysvec_apic_timer_interrupt+0x12/0x20^M
> > > [ 1289.771854] _raw_spin_unlock_irqrestore+0x33/0x50^M
> > > [ 1289.772499] rdp_offload_toggle+0xc9/0x150^M
> > > [ 1289.773050] rcu_nocb_rdp_deoffload+0x163/0x2c0^M
> > > [ 1289.773670] work_for_cpu_fn+0x28/0x40^M
> > > [ 1289.774185] process_one_work+0x50f/0x800^M
> > > [ 1289.774726] worker_thread+0x71c/0x9f0^M
> > > [ 1289.775237] kthread+0x23e/0x270^M
> > > [ 1289.775675] ret_from_fork+0x22/0x30^M
> > > [ 1289.776162] ^M
> > > [ 1289.776377] 3 locks held by kworker/7:2/294:^M
> > > [ 1289.776955] #0: ffff94f2c1050738
> > > ((wq_completion)events){+.+.}-{0:0}, at:
> > > process_one_work+0x49c/0x800^M
> > > [ 1289.778245] #1: ffffa5434093bde0
> > > ((work_completion)(&wfc.work)){+.+.}-{0:0}, at:
> > > process_one_work+0x4cd/0x800^M
> > > [ 1289.779605] #2: ffffa5434029cdf8 ((&t)){+.-.}-{0:0}, at:
> > > call_timer_fn+0x51/0x150^M
> > > [ 1289.780666] irq event stamp: 215649^M
> > > [ 1289.781186] hardirqs last enabled at (215648):
> > > [<ffffffff8d6afec2>] __local_bh_enable_ip+0xc2/0x120^M
> > > [ 1289.782471] hardirqs last disabled at (215649):
> > > [<ffffffff8d77c6a3>] call_rcu+0x73/0xfd0^M
> > > [ 1289.783632] softirqs last enabled at (214628):
> > > [<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
> > > [ 1289.784866] softirqs last disabled at (215635):
> > > [<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
> > > [ 1289.786147] ^M
> > > [ 1289.786379] write to 0xffff94f2db7ec608 of 1 bytes by task 63 on cpu 15:^M
> > > [ 1289.787342] rcu_nocb_cb_kthread+0x2f7/0x740^M
> > > [ 1289.787970] kthread+0x23e/0x270^M
> > > [ 1289.788450] ret_from_fork+0x22/0x30^M
> > > [ 1289.788964] ^M
> > >
> > > The reader is at
> > > 0xffffffff8117c6dd: file kernel/rcu/tree.c, line 2991
> > > 2986 local_irq_save(flags);
> > > 2987 kasan_record_aux_stack(head);
> > > 2988 rdp = this_cpu_ptr(&rcu_data);
> > > 2989
> > > 2990 /* Add the callback to our list. */
> > > 2991 if (unlikely(!rcu_segcblist_is_enabled(&rdp->cblist))) {
> > > 2992 // This can trigger due to call_rcu() from offline CPU:
> > > 2993 WARN_ON_ONCE(rcu_scheduler_active != RCU_SCHEDULER_INACTIVE);
> > > 2994 WARN_ON_ONCE(!rcu_is_watching());
> > > 2995 // Very early boot, before rcu_init(). Initialize if needed
> > >
> > > The writer is at
> > > 0xffffffff81191977: file kernel/rcu/rcu_segcblist.h, line 65
> > > 60 }
> > > 61
> > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > 63 int flags)
> > > 64 {
> > > 65 rsclp->flags &= ~flags;
> > > 66 }
> > > 67
> > >
> > > I gained a lot during the study ;-)
> >
> > Glad the process was educational. ;-)
> >
> > Thoughts on the alleged fix below?
> >
> > Thanx, Paul
> >
> > ------------------------------------------------------------------------
> >
> > commit 66b153e7e3980067de018ec8c478aa0aaf7ba2bd
> > Author: Paul E. McKenney <paulmck@kernel.org>
> > Date: Tue Jan 4 10:34:34 2022 -0800
> >
> > rcu: Mark writes to the rcu_segcblist structure's ->flags field
> >
> > KCSAN reports data races between the rcu_segcblist_clear_flags() and
> > rcu_segcblist_set_flags() functions, though misreporting the latter
> > as a call to rcu_segcblist_is_enabled() from call_rcu(). This commit
> as a call to rcu_segcblist_is_enabled() from call_rcu() because
> the compiler
> optimizes the intermediate functions away. This commit
I agree, except that the rumor I heard was that the debugging information
was supposed to handle such inlining. And it has done so for me in
many cases.
Who knows? Maybe I have just been getting lucky. ;-)
Thanx, Paul
> > converts the updates of this field to WRITE_ONCE(), relying on the
> > resulting unmarked reads to continue to detect buggy concurrent writes
> > to this field.
> >
> > Reported-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
> > Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> > Cc: Frederic Weisbecker <frederic@kernel.org>
> >
> > diff --git a/kernel/rcu/rcu_segcblist.h b/kernel/rcu/rcu_segcblist.h
> > index e373fbe44da5e..431cee212467d 100644
> > --- a/kernel/rcu/rcu_segcblist.h
> > +++ b/kernel/rcu/rcu_segcblist.h
> > @@ -56,13 +56,13 @@ static inline long rcu_segcblist_n_cbs(struct rcu_segcblist *rsclp)
> > static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> > int flags)
> > {
> > - rsclp->flags |= flags;
> > + WRITE_ONCE(rsclp->flags, rsclp->flags | flags);
> > }
> >
> > static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > int flags)
> > {
> > - rsclp->flags &= ~flags;
> > + WRITE_ONCE(rsclp->flags, rsclp->flags & ~flags);
> > }
> >
> > static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: FYI, a few new KCSAN splats
2022-01-04 23:58 ` Paul E. McKenney
@ 2022-01-05 0:41 ` Zhouyi Zhou
0 siblings, 0 replies; 11+ messages in thread
From: Zhouyi Zhou @ 2022-01-05 0:41 UTC (permalink / raw)
To: paulmck; +Cc: Marco Elver, rcu, Frederic Weisbecker
Thank Paul for analyzing the phenomenon for me.
I realize that the original git log covers both cases (1. the compiler
optimizing case; 2. the debugging information inlining case)，
and I think the original git log by Paul suits the patch better.
Besides, I am very interested in studying the mechanism of debugging
information processing (I call this "research" for myself ;-)),
But this process will take an unpredictable long time for me ;-)
So, again, I think the original git log by Paul suits the patch better.
Many thanks
Zhouyi
On Wed, Jan 5, 2022 at 7:58 AM Paul E. McKenney <paulmck@kernel.org> wrote:
>
> On Wed, Jan 05, 2022 at 06:51:49AM +0800, Zhouyi Zhou wrote:
> > Thank Paul for your encouragement
> >
> > May I make bold to suggest a possible small modification to git log as
> > below (use the knowledge and terms I learned from perfbook)
> >
> > Thanks
> > Zhouyi
> > On Wed, Jan 5, 2022 at 2:42 AM Paul E. McKenney <paulmck@kernel.org> wrote:
> > >
> > > On Sun, Jan 02, 2022 at 08:27:29AM +0800, Zhouyi Zhou wrote:
> > > > Thanks Paul and Marco for giving me valuable advice.
> > > >
> > > > I studied the structure of kvm.sh and I found enabling
> > > > CONFIG_KCSAN_STRICT and lower kcsan.skip_watch will make the KCSAN
> > > > detect RCU's data-race within half an hour (I tried this for two
> > > > times).
> > > > Following is my command:
> > > > linux-rcu$git config --get remote.origin.url
> > > > https://kernel.source.codeaurora.cn/pub/scm/linux/kernel/git/paulmck/linux-rcu.git/
> > > > linux-rcu$tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus
> > > > --duration 10h --configs "TREE01" --kcsan --kmake-arg "CC=clang-12"
> > > > --trust-make --kconfig CONFIG_KCSAN_STRICT=y --bootargs
> > > > kcsan.skip_watch=1000
> > > >
> > > >
> > > > [ 1289.504892] rcu: De-offloading 5^M
> > > > [ 1289.761495] rcu: De-offloading 7^M
> > > > [ 1289.763556] ==================================================================^M
> > > > [ 1289.764531] BUG: KCSAN: data-race in call_rcu / rcu_nocb_cb_kthread^M
> > > > [ 1289.765388] ^M
> > > > [ 1289.765599] read (marked) to 0xffff94f2db7ec608 of 1 bytes by
> > > > interrupt on cpu 7:^M
> > > > [ 1289.766588] call_rcu+0xad/0xfd0^M
> > > > [ 1289.767035] rcu_torture_timer+0xdc/0xf0^M
> > > > [ 1289.767566] call_timer_fn+0x87/0x150^M
> > > > [ 1289.768065] __run_timers+0x2fd/0x450^M
> > > > [ 1289.768562] run_timer_softirq+0x29/0x60^M
> > > > [ 1289.769093] __do_softirq+0x1d9/0x35c^M
> > > > [ 1289.769540] __irq_exit_rcu+0x13d/0x150^M
> > > > [ 1289.770047] irq_exit_rcu+0x5/0x20^M
> > > > [ 1289.770520] sysvec_apic_timer_interrupt+0x8d/0xb0^M
> > > > [ 1289.771168] asm_sysvec_apic_timer_interrupt+0x12/0x20^M
> > > > [ 1289.771854] _raw_spin_unlock_irqrestore+0x33/0x50^M
> > > > [ 1289.772499] rdp_offload_toggle+0xc9/0x150^M
> > > > [ 1289.773050] rcu_nocb_rdp_deoffload+0x163/0x2c0^M
> > > > [ 1289.773670] work_for_cpu_fn+0x28/0x40^M
> > > > [ 1289.774185] process_one_work+0x50f/0x800^M
> > > > [ 1289.774726] worker_thread+0x71c/0x9f0^M
> > > > [ 1289.775237] kthread+0x23e/0x270^M
> > > > [ 1289.775675] ret_from_fork+0x22/0x30^M
> > > > [ 1289.776162] ^M
> > > > [ 1289.776377] 3 locks held by kworker/7:2/294:^M
> > > > [ 1289.776955] #0: ffff94f2c1050738
> > > > ((wq_completion)events){+.+.}-{0:0}, at:
> > > > process_one_work+0x49c/0x800^M
> > > > [ 1289.778245] #1: ffffa5434093bde0
> > > > ((work_completion)(&wfc.work)){+.+.}-{0:0}, at:
> > > > process_one_work+0x4cd/0x800^M
> > > > [ 1289.779605] #2: ffffa5434029cdf8 ((&t)){+.-.}-{0:0}, at:
> > > > call_timer_fn+0x51/0x150^M
> > > > [ 1289.780666] irq event stamp: 215649^M
> > > > [ 1289.781186] hardirqs last enabled at (215648):
> > > > [<ffffffff8d6afec2>] __local_bh_enable_ip+0xc2/0x120^M
> > > > [ 1289.782471] hardirqs last disabled at (215649):
> > > > [<ffffffff8d77c6a3>] call_rcu+0x73/0xfd0^M
> > > > [ 1289.783632] softirqs last enabled at (214628):
> > > > [<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
> > > > [ 1289.784866] softirqs last disabled at (215635):
> > > > [<ffffffff8d6b03dd>] __irq_exit_rcu+0x13d/0x150^M
> > > > [ 1289.786147] ^M
> > > > [ 1289.786379] write to 0xffff94f2db7ec608 of 1 bytes by task 63 on cpu 15:^M
> > > > [ 1289.787342] rcu_nocb_cb_kthread+0x2f7/0x740^M
> > > > [ 1289.787970] kthread+0x23e/0x270^M
> > > > [ 1289.788450] ret_from_fork+0x22/0x30^M
> > > > [ 1289.788964] ^M
> > > >
> > > > The reader is at
> > > > 0xffffffff8117c6dd: file kernel/rcu/tree.c, line 2991
> > > > 2986 local_irq_save(flags);
> > > > 2987 kasan_record_aux_stack(head);
> > > > 2988 rdp = this_cpu_ptr(&rcu_data);
> > > > 2989
> > > > 2990 /* Add the callback to our list. */
> > > > 2991 if (unlikely(!rcu_segcblist_is_enabled(&rdp->cblist))) {
> > > > 2992 // This can trigger due to call_rcu() from offline CPU:
> > > > 2993 WARN_ON_ONCE(rcu_scheduler_active != RCU_SCHEDULER_INACTIVE);
> > > > 2994 WARN_ON_ONCE(!rcu_is_watching());
> > > > 2995 // Very early boot, before rcu_init(). Initialize if needed
> > > >
> > > > The writer is at
> > > > 0xffffffff81191977: file kernel/rcu/rcu_segcblist.h, line 65
> > > > 60 }
> > > > 61
> > > > 62 static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > > 63 int flags)
> > > > 64 {
> > > > 65 rsclp->flags &= ~flags;
> > > > 66 }
> > > > 67
> > > >
> > > > I gained a lot during the study ;-)
> > >
> > > Glad the process was educational. ;-)
> > >
> > > Thoughts on the alleged fix below?
> > >
> > > Thanx, Paul
> > >
> > > ------------------------------------------------------------------------
> > >
> > > commit 66b153e7e3980067de018ec8c478aa0aaf7ba2bd
> > > Author: Paul E. McKenney <paulmck@kernel.org>
> > > Date: Tue Jan 4 10:34:34 2022 -0800
> > >
> > > rcu: Mark writes to the rcu_segcblist structure's ->flags field
> > >
> > > KCSAN reports data races between the rcu_segcblist_clear_flags() and
> > > rcu_segcblist_set_flags() functions, though misreporting the latter
> > > as a call to rcu_segcblist_is_enabled() from call_rcu(). This commit
> > as a call to rcu_segcblist_is_enabled() from call_rcu() because
> > the compiler
> > optimizes the intermediate functions away. This commit
>
> I agree, except that the rumor I heard was that the debugging information
> was supposed to handle such inlining. And it has done so for me in
> many cases.
>
> Who knows? Maybe I have just been getting lucky. ;-)
>
> Thanx, Paul
>
> > > converts the updates of this field to WRITE_ONCE(), relying on the
> > > resulting unmarked reads to continue to detect buggy concurrent writes
> > > to this field.
> > >
> > > Reported-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
> > > Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> > > Cc: Frederic Weisbecker <frederic@kernel.org>
> > >
> > > diff --git a/kernel/rcu/rcu_segcblist.h b/kernel/rcu/rcu_segcblist.h
> > > index e373fbe44da5e..431cee212467d 100644
> > > --- a/kernel/rcu/rcu_segcblist.h
> > > +++ b/kernel/rcu/rcu_segcblist.h
> > > @@ -56,13 +56,13 @@ static inline long rcu_segcblist_n_cbs(struct rcu_segcblist *rsclp)
> > > static inline void rcu_segcblist_set_flags(struct rcu_segcblist *rsclp,
> > > int flags)
> > > {
> > > - rsclp->flags |= flags;
> > > + WRITE_ONCE(rsclp->flags, rsclp->flags | flags);
> > > }
> > >
> > > static inline void rcu_segcblist_clear_flags(struct rcu_segcblist *rsclp,
> > > int flags)
> > > {
> > > - rsclp->flags &= ~flags;
> > > + WRITE_ONCE(rsclp->flags, rsclp->flags & ~flags);
> > > }
> > >
> > > static inline bool rcu_segcblist_test_flags(struct rcu_segcblist *rsclp,
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2022-01-05 0:42 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-12-14 4:57 FYI, a few new KCSAN splats Paul E. McKenney
2021-12-14 8:38 ` Zhouyi Zhou
2021-12-14 14:48 ` Paul E. McKenney
2021-12-14 15:46 ` Zhouyi Zhou
2021-12-14 16:57 ` Marco Elver
2021-12-14 17:59 ` Zhouyi Zhou
2022-01-02 0:27 ` Zhouyi Zhou
2022-01-04 18:42 ` Paul E. McKenney
2022-01-04 22:51 ` Zhouyi Zhou
2022-01-04 23:58 ` Paul E. McKenney
2022-01-05 0:41 ` Zhouyi Zhou
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.