Hello Chunyu,

It could be casued by acquring 'running_trace_lock' with rcu read lock held, which
disables preempt.

Can you test the following build?

     https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33591095

And just the following change is applied:

diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
index 4be52ba6bc61..093b7d2b4879 100644
--- a/kernel/trace/blktrace.c
+++ b/kernel/trace/blktrace.c
@@ -46,7 +46,7 @@ static struct trace_array *blk_tr;
 static bool blk_tracer_enabled __read_mostly;
 
 static LIST_HEAD(running_trace_list);
-static __cacheline_aligned_in_smp DEFINE_SPINLOCK(running_trace_lock);
+static __cacheline_aligned_in_smp DEFINE_RAW_SPINLOCK(running_trace_lock);
 
 /* Select an alternative, minimalistic output than the original one */
 #define TRACE_BLK_OPT_CLASSIC  0x1

@@ -134,12 +134,12 @@ static void trace_note_tsk(struct task_struct *tsk)
        struct blk_trace *bt;
 
        tsk->btrace_seq = blktrace_seq;
-       spin_lock_irqsave(&running_trace_lock, flags);
+       raw_spin_lock_irqsave(&running_trace_lock, flags);
        list_for_each_entry(bt, &running_trace_list, running_list) {
                trace_note(bt, tsk->pid, BLK_TN_PROCESS, tsk->comm,
                           sizeof(tsk->comm), NULL);
        }
-       spin_unlock_irqrestore(&running_trace_lock, flags);
+       raw_spin_unlock_irqrestore(&running_trace_lock, flags);
 }
 
 static void trace_note_time(struct blk_trace *bt)
@@ -687,9 +687,9 @@ static int __blk_trace_startstop(struct request_queue *q, int start)
                        blktrace_seq++;
                        smp_mb();
                        bt->trace_state = Blktrace_running;
-                       spin_lock_irq(&running_trace_lock);
+                       raw_spin_lock_irq(&running_trace_lock);
                        list_add(&bt->running_list, &running_trace_list);
-                       spin_unlock_irq(&running_trace_lock);
+                       raw_spin_unlock_irq(&running_trace_lock);
 
                        trace_note_time(bt);
                        ret = 0;
@@ -697,9 +697,9 @@ static int __blk_trace_startstop(struct request_queue *q, int start)
        } else {
                if (bt->trace_state == Blktrace_running) {
                        bt->trace_state = Blktrace_stopped;
-                       spin_lock_irq(&running_trace_lock);
+                       raw_spin_lock_irq(&running_trace_lock);
                        list_del_init(&bt->running_list);
-                       spin_unlock_irq(&running_trace_lock);
+                       raw_spin_unlock_irq(&running_trace_lock);
                        relay_flush(bt->rchan);
                        ret = 0;
                }

(In reply to Ming Lei from comment #1)
> Hello Chunyu,
> 
> It could be casued by acquring 'running_trace_lock' with rcu read lock held,
> which
> disables preempt.
> 
> Can you test the following build?
> 
>      https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33591095
> 

The build looks like failed. And the issue I originally hit was with a kernel-rt-debug kernel.

(In reply to Chunyu Hu from comment #2)
> (In reply to Ming Lei from comment #1)
> > Hello Chunyu,
> > 
> > It could be casued by acquring 'running_trace_lock' with rcu read lock held,
> > which
> > disables preempt.
> > 
> > Can you test the following build?
> > 
> >      https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33591095
> > 
> 
> The build looks like failed. And the issue I originally hit was with a
> kernel-rt-debug kernel.

oops, the build should have been the following one:

https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33591645

But I don't know how to build kernel-rt yet, :-(

(In reply to Ming Lei from comment #3)
> (In reply to Chunyu Hu from comment #2)
> > (In reply to Ming Lei from comment #1)
> > > Hello Chunyu,
> > > 
> > > It could be casued by acquring 'running_trace_lock' with rcu read lock held,
> > > which
> > > disables preempt.
> > > 
> > > Can you test the following build?
> > > 
> > >      https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33591095
> > > 
> > 
> > The build looks like failed. And the issue I originally hit was with a
> > kernel-rt-debug kernel.
> 
> oops, the build should have been the following one:
> 
> https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33591645
> 
> But I don't know how to build kernel-rt yet, :-(

I have added Juri in the cc list, who works on kernel-rt. I'll submit a sched regression test with the build.

(In reply to Ming Lei from comment #3)
> (In reply to Chunyu Hu from comment #2)
> > (In reply to Ming Lei from comment #1)
> > > Hello Chunyu,
> > > 
> > > It could be casued by acquring 'running_trace_lock' with rcu read lock held,
> > > which
> > > disables preempt.
> > > 
> > > Can you test the following build?
> > > 
> > >      https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33591095
> > > 
> > 
> > The build looks like failed. And the issue I originally hit was with a
> > kernel-rt-debug kernel.
> 
> oops, the build should have been the following one:
> 
> https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33591645
> 
> But I don't know how to build kernel-rt yet, :-(

Same procedure as for kernel, but using kernel-rt repo/branch.

git://git.host.prod.eng.bos.redhat.com/kernel-rt.git rhel-rt-8.4.0

and then

make BUILDID=".<my_id>" rh-brew

(In reply to Juri Lelli from comment #5)
...
> 
> Same procedure as for kernel, but using kernel-rt repo/branch.
> 
> git://git.host.prod.eng.bos.redhat.com/kernel-rt.git rhel-rt-8.4.0
> 
> and then
> 
> make BUILDID=".<my_id>" rh-brew

Hi Chunyu,

Please test the following brew build for kernel-rt?

https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33597935


Hi Juri,

Thanks for sharing the kernel-rt build steps.

BTW, do you think if the following usage is a problem for PREEMPT_RT?

rcu_read_lock();                   //preempt is disabled
spin_lock_irqsave(lock, flags);    //convert to rt_spin_lock() which might sleep   
...
spin_lock_irqrestore(lock, flags);
rcu_read_unlock();

From the lockdep warning, looks the above is the reason.

I am not so sure is because I do see lots of such usage in block layer, :-)

Thanks,
Ming

(In reply to Ming Lei from comment #6)
> (In reply to Juri Lelli from comment #5)
> ...
> > 
> > Same procedure as for kernel, but using kernel-rt repo/branch.
> > 
> > git://git.host.prod.eng.bos.redhat.com/kernel-rt.git rhel-rt-8.4.0
> > 
> > and then
> > 
> > make BUILDID=".<my_id>" rh-brew
> 
> Hi Chunyu,
> 
> Please test the following brew build for kernel-rt?
> 
> https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33597935
> 
> 
> Hi Juri,
> 
> Thanks for sharing the kernel-rt build steps.
> 
> BTW, do you think if the following usage is a problem for PREEMPT_RT?
> 
> rcu_read_lock();                   //preempt is disabled
> spin_lock_irqsave(lock, flags);    //convert to rt_spin_lock() which might
> sleep   
> ...
> spin_lock_irqrestore(lock, flags);
> rcu_read_unlock();
> 
> From the lockdep warning, looks the above is the reason.

Indeed. With PREEMPT_RT spin_locks are converted to mutexes, so they can sleep.

> I am not so sure is because I do see lots of such usage in block layer, :-)

So, yeah. Patterns like the above are problematic. If you are so inclined, you
could have a look at current PREEMPT_RT upstream:

git://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git linux-5.10.y-rt

Thanks for looking into this BTW! :-)

(In reply to Ming Lei from comment #6)
> (In reply to Juri Lelli from comment #5)
> ...
> > 
> > Same procedure as for kernel, but using kernel-rt repo/branch.
> > 
> > git://git.host.prod.eng.bos.redhat.com/kernel-rt.git rhel-rt-8.4.0
> > 
> > and then
> > 
> > make BUILDID=".<my_id>" rh-brew
> 
> Hi Chunyu,
> 
> Please test the following brew build for kernel-rt?
> 
> https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=33597935
> 
> 

I submitted two x86 jobs to the kernel-rt-debug, but one of them aborted during installation, the other one finished the test. And in the finished one, I don't see the issue in comment#0, though there are many other wanings on locking/lockdeps. 

https://beaker.engineering.redhat.com/recipes/9166750#task118905648,task118905653,task118905654,task118905657,task118905658,task118905659
subtest Test-bz502573 is good.

I submitted another one this morning for double check, if you think it's enough with the finished result. Feel free to go ahead for your progress. Thanks.

(In reply to Chunyu Hu from comment #8)

> 
> I submitted another one this morning for double check, if you think it's
> enough with the finished result. Feel free to go ahead for your progress.
> Thanks.

The other job is good too. The bio warning was not shown.

(In reply to Chunyu Hu from comment #9)
> (In reply to Chunyu Hu from comment #8)
> 
> > 
> > I submitted another one this morning for double check, if you think it's
> > enough with the finished result. Feel free to go ahead for your progress.
> > Thanks.
> 
> The other job is good too. The bio warning was not shown.

Hi Chunyu,

The patch shouldn't make a difference, because rcu_read_lock() doesn't disable preempt
in kernel-rt because CONFIG_PREEMPT_RCU is enabled.

I tried to reproduce the issue, but can't succeed in runing simple blktrace.

So could you share us your test steps?


Thanks,
Ming

> 
> Hi Chunyu,
> 
> The patch shouldn't make a difference, because rcu_read_lock() doesn't
> disable preempt
> in kernel-rt because CONFIG_PREEMPT_RCU is enabled.
> 
> I tried to reproduce the issue, but can't succeed in runing simple blktrace.
> 
> So could you share us your test steps?

First you need to run kernel-rt-debug:
[root@hp-dl380pg8-17 Regression]# uname -r
4.18.0-260.rt7.25.el8.x86_64+debug


I checked the test sub script, it's indeed just doing blktrace on root device. And I can
reproduce it with my host currently running.

blktrace -w 15 -d /dev/mapper/rhel_hp--dl380pg8--17-root

To run this with kernel-kernel-errata-Regression

1) yum -y install kernel-kernel-errata-Regression
2) cd /mnt/tests/kernel/errata/Regression
3) make run BZLIST=502573 INST=NEVER
4) dmesg

[root@hp-dl380pg8-17 Regression]# dmesg
[  168.697555] dracut-install (3376) used greatest stack depth: 19376 bytes left
[  918.327322] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:968
[  918.327332] in_atomic(): 1, irqs_disabled(): 0, pid: 7661, name: mandb
[  918.327339] 2 locks held by mandb/7661:
[  918.327343]  #0: ffffffffaecd22c0 (rcu_read_lock){....}-{1:2}, at: blk_add_trace_bio+0x0/0x2f0
[  918.327376]  #1: ffffffffaea177a0 (running_trace_lock){+.+.}-{2:2}, at: __blk_add_trace+0x9ea/0xdf0
[  918.327397] Preemption disabled at:
[  918.327408] [<ffffffffac136743>] get_lock_stats+0x13/0x120
[  918.327422] CPU: 3 PID: 7661 Comm: mandb Kdump: loaded Tainted: G          I      --------- -  - 4.18.0-260.rt7.25.el8.x86_64+debug #1
[  918.327426] Hardware name: HP ProLiant DL380p Gen8, BIOS P70 07/01/2015
[  918.327431] Call Trace:
[  918.327447]  dump_stack+0x8e/0xd0
[  918.327465]  ? get_lock_stats+0x13/0x120
[  918.327475]  ___might_sleep.cold.58+0x54/0x77
[  918.327495]  rt_spin_lock+0x3e/0x120
[  918.327501]  ? __blk_add_trace+0x9ea/0xdf0
[  918.327513]  __blk_add_trace+0x9ea/0xdf0
[  918.327561]  ? rcu_read_lock_sched_held+0xe0/0xe0
[  918.327584]  blk_add_trace_bio+0x25d/0x2f0


[root@hp-dl380pg8-17 Regression]# grep 502573\( -A 18 /mnt/tests/kernel/errata/Regression/tests/rhel5.sh 
function bz502573(){
	local dir=$(pwd)
	local bin_file=$DIR_BIN/${FUNCNAME}_test
	local log_file=$DIR_LOG/${FUNCNAME}.log
	local src_file=$DIR_SRC/${FUNCNAME}_test.c
	local test_info="blktrace run makes the machine unresponsive"
	[ -n "$BZ_DEBUG" ] && local RUNTIME=25s || local RUNTIME=5m

	rlPhaseStartTest "Test ${FUNCNAME}"
		rlLogInfo "$test_info"
		rpm -q blktrace || rlRun "yum -y install blktrace"

		rlAssertRpm kernel
		rlAssertRpm blktrace
		mount |grep debugfs |grep /sys/kernel/debug || 
		rlRun "mount -t debugfs debugfs /sys/kernel/debug" 0 "Mounting debugfs"
		rlRun "Device=\`mount | grep 'on / type' | cut -d' ' -f1\`" 0 "Finding root device"
		local Runtime=15
		rlRun "blktrace -w $Runtime -d $Device" 0 "blktrace"

(In reply to Chunyu Hu from comment #11)
> 
> > 
> > Hi Chunyu,
> > 
> > The patch shouldn't make a difference, because rcu_read_lock() doesn't
> > disable preempt
> > in kernel-rt because CONFIG_PREEMPT_RCU is enabled.
> > 
> > I tried to reproduce the issue, but can't succeed in runing simple blktrace.
> > 
> > So could you share us your test steps?
> 
> First you need to run kernel-rt-debug:
> [root@hp-dl380pg8-17 Regression]# uname -r
> 4.18.0-260.rt7.25.el8.x86_64+debug
> 
> 
> I checked the test sub script, it's indeed just doing blktrace on root
> device. And I can
> reproduce it with my host currently running.
> 
> blktrace -w 15 -d /dev/mapper/rhel_hp--dl380pg8--17-root

Looks like run this directly won't trigger the mandb execution, so can't reproduce.

> 
> To run this with kernel-kernel-errata-Regression
> 
> 1) yum -y install kernel-kernel-errata-Regression
> 2) cd /mnt/tests/kernel/errata/Regression
> 3) make run BZLIST=502573 INST=NEVER
> 4) dmesg
> 


mandb ran during the process, not sure where it came from. But run as errata/Regression sub test, it's reproducible.

(In reply to Ming Lei from comment #10)
> (In reply to Chunyu Hu from comment #9)
> > (In reply to Chunyu Hu from comment #8)
> > 
> > > 
> > > I submitted another one this morning for double check, if you think it's
> > > enough with the finished result. Feel free to go ahead for your progress.
> > > Thanks.
> > 
> > The other job is good too. The bio warning was not shown.
> 
> Hi Chunyu,
> 
> The patch shouldn't make a difference, because rcu_read_lock() doesn't
> disable preempt
> in kernel-rt because CONFIG_PREEMPT_RCU is enabled.

But it indeed didn't see the same issue in the console.log in the job of comment#8.
[root@hp-dl380pg8-17 Regression]# curl -LkO https://beaker-archive.host.prod.eng.bos.redhat.com/beaker-logs/2020/12/47999/4799924/9166750/console.log
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 2618k  100 2618k    0     0   714k      0  0:00:03  0:00:03 --:--:--  714k

[root@hp-dl380pg8-17 Regression]# grep submit_bio console.log 
[root@hp-dl380pg8-17 Regression]# 

^^^^^ got nothing


While with the job in comment#0, easily got the trace in console log:

[root@hp-dl380pg8-17 Regression]# curl -LkO https://beaker.engineering.redhat.com/recipes/9159156/logs/console.log
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0   417    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0
100 3197k  100 3197k    0     0   600k      0  0:00:05  0:00:05 --:--:--  972k
[root@hp-dl380pg8-17 Regression]# grep submit_bio console.log 
[  284.528329]  ? submit_bio+0xcb/0x440 
[  284.528338]  submit_bio+0xcb/0x440 
[  285.544157]  ? submit_bio+0xcb/0x440 
[  285.544167]  submit_bio+0xcb/0x440 
[  286.579390]  ? submit_bio+0xcb/0x440 
[  286.579399]  submit_bio+0xcb/0x440 
[  287.620651]  ? submit_bio+0xcb/0x440 
[  287.620661]  submit_bio+0xcb/0x440 
[  293.137160]  ? submit_bio+0xcb/0x440 
[  293.137169]  submit_bio+0xcb/0x440 
[  294.240292]  ? submit_bio+0xcb/0x440 
[  294.240302]  submit_bio+0xcb/0x440 

There's another explanation that it's not 100% reproducible.

v2 of the patch https://lore.kernel.org/all/20211213123737.9147-1-wander@redhat.com/

Notice this affects RHEL 9 as well.

(In reply to Wander from comment #32)
> Notice this affects RHEL 9 as well.

Thanks. I cloned a rhel9.0 bz2047971, Wander, would you take that?

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Important: kernel-rt security and bug fix update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2022:1975

*** Bug 2052397 has been marked as a duplicate of this bug. ***