Bug 1843410

Clark,

By looking at the trace, my initial guess for this issue
would be that drain_all_pages() or flush_work() is scheduling
work on the CPU where oslat is running (which is isolated).

In other words, work that originated in an housekeeping CPU
is being scheduled on an isolated CPU. Which will cause a stall,
since oslat won't let the kworker run.

Now, I might be completely wrong, but it does ring a bell to me
that we used to have a patch in RHEL7 RT that would prevent either
drain_all_pages() or flush_work() from scheduling work on isolated CPUs.

I hope I'm not just creating noise, but if this is correct then
this issue should be considered serious since it will affect
DPDK workloads on RHEL8.2 the same way.

Created attachment 1695007 [details]
Another Call Trace info in guest

"(3)Multiple VMs each with 1 rt vCPU" testing has finished. There are Call Trace in one of the four guests. It looks a bit different with above. I'm not sure if they are same issue, so I also paste it here and full # dmesg is attached. 

Luiz,Clark,

Please let me know if they are different issues, then I can file new bug to track it. Thanks.


[ 4363.236900] INFO: task cc1:77565 blocked for more than 600 seconds.
[ 4363.238025]       Not tainted 4.18.0-208.rt5.20.el8.x86_64 #1
[ 4363.239458] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4363.240796] cc1             D    0 77565  77560 0x00084080
[ 4363.241784] Call Trace:
[ 4363.242363]  __schedule+0x342/0x850
[ 4363.243059]  schedule+0x39/0xd0
[ 4363.243609]  schedule_timeout+0x20e/0x410
[ 4363.245349]  ? __schedule+0x34a/0x850
[ 4363.247042]  ? ___preempt_schedule+0x16/0x18
[ 4363.247757]  wait_for_completion+0x85/0xe0
[ 4363.249505]  flush_work+0x11a/0x1c0
[ 4363.251160]  ? flush_workqueue_prep_pwqs+0x130/0x130
[ 4363.253032]  drain_all_pages+0x140/0x190
[ 4363.253703]  __alloc_pages_slowpath+0x3f8/0xe20
[ 4363.255508]  __alloc_pages_nodemask+0x1ca/0x2b0
[ 4363.257310]  alloc_pages_vma+0xc5/0x170
[ 4363.260023]  ? __switch_to_asm+0x35/0x70
[ 4363.260700]  __handle_mm_fault+0x5a5/0xa70
[ 4363.262451]  ? __switch_to_asm+0x35/0x70
[ 4363.264165]  ? __switch_to_asm+0x41/0x70
[ 4363.264827]  handle_mm_fault+0xd2/0x1e0
[ 4363.266536]  __do_page_fault+0x28e/0x5d0
[ 4363.268246]  do_page_fault+0x47/0x1b0
[ 4363.269925]  ? async_page_fault+0x8/0x30
[ 4363.270598]  async_page_fault+0x1e/0x30
[ 4363.272298] RIP: 0033:0x56115b27ffb0
[ 4363.274020] Code: Bad RIP value.
[ 4363.274580] RSP: 002b:00007ffe5c70d8d0 EFLAGS: 00010202
[ 4363.276479] RAX: 00007feb25025000 RBX: 00007feb24f01370 RCX: 000000000000000c
[ 4363.278653] RDX: 000056115beb4c40 RSI: 00007feb25213cb0 RDI: 0000000000002227
[ 4363.281835] RBP: 00007feb26692c60 R08: 0000000000000001 R09: 0000000000000002
[ 4363.285054] R10: 00007feb25022400 R11: 0000000000000006 R12: 0000000000000000
[ 4363.287225] R13: 00007feb24f013b8 R14: 00007ffe5c70d8f0 R15: 00007feb25025008
[ 4985.829739] INFO: task cc1:77565 blocked for more than 600 seconds.
[ 4985.830822]       Not tainted 4.18.0-208.rt5.20.el8.x86_64 #1
[ 4985.832039] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4985.833382] cc1             D    0 77565  77560 0x00084080
[ 4985.834375] Call Trace:
[ 4985.834930]  __schedule+0x342/0x850
[ 4985.835534]  schedule+0x39/0xd0
[ 4985.836225]  schedule_timeout+0x20e/0x410
[ 4985.838968]  ? __schedule+0x34a/0x850
[ 4985.839595]  ? ___preempt_schedule+0x16/0x18
[ 4985.842383]  wait_for_completion+0x85/0xe0
[ 4985.845132]  flush_work+0x11a/0x1c0
[ 4985.847752]  ? flush_workqueue_prep_pwqs+0x130/0x130
[ 4985.848572]  drain_all_pages+0x140/0x190
[ 4985.852288]  __alloc_pages_slowpath+0x3f8/0xe20
[ 4985.855085]  __alloc_pages_nodemask+0x1ca/0x2b0
[ 4985.857889]  alloc_pages_vma+0xc5/0x170
[ 4985.858541]  ? __switch_to_asm+0x35/0x70
[ 4985.860546]  __handle_mm_fault+0x5a5/0xa70
[ 4985.862838]  ? __switch_to_asm+0x35/0x70
[ 4985.863498]  ? __switch_to_asm+0x41/0x70
[ 4985.866215]  handle_mm_fault+0xd2/0x1e0
[ 4985.867911]  __do_page_fault+0x28e/0x5d0
[ 4985.868575]  do_page_fault+0x47/0x1b0
[ 4985.870238]  ? async_page_fault+0x8/0x30
[ 4985.871946]  async_page_fault+0x1e/0x30
[ 4985.872601] RIP: 0033:0x56115b27ffb0
[ 4985.874263] Code: Bad RIP value.
[ 4985.875868] RSP: 002b:00007ffe5c70d8d0 EFLAGS: 00010202
[ 4985.877749] RAX: 00007feb25025000 RBX: 00007feb24f01370 RCX: 000000000000000c
[ 4985.879910] RDX: 000056115beb4c40 RSI: 00007feb25213cb0 RDI: 0000000000002227
[ 4985.882072] RBP: 00007feb26692c60 R08: 0000000000000001 R09: 0000000000000002
[ 4985.885242] R10: 00007feb25022400 R11: 0000000000000006 R12: 0000000000000000
[ 4985.887400] R13: 00007feb24f013b8 R14: 00007ffe5c70d8f0 R15: 00007feb25025008

drain_all_pages does:

        for_each_cpu(cpu, &cpus_with_pcps) {
                struct pcpu_drain *drain = per_cpu_ptr(&pcpu_drain, cpu);

                drain->zone = zone;
                INIT_WORK(&drain->work, drain_local_pages_wq);
                queue_work_on(cpu, mm_percpu_wq, &drain->work);
        }
        for_each_cpu(cpu, &cpus_with_pcps)
                flush_work(&per_cpu_ptr(&pcpu_drain, cpu)->work);


And worker thread can't run on isolated CPU with oslat (or DPDK with FIFO) running there.

One way to fix it would be to make drain_all_pages() aware of isolated CPUs probably by deriving the housekeeping CPUs via housekeeping_cpumask().
If so, then there are other callers of queue_work_on() as well that may not respect CPU isolation and maybe we should look into them as well.
eg. swap.c:
        for_each_online_cpu(cpu) {
                struct work_struct *work = &per_cpu(lru_add_drain_work, cpu);
...
                        INIT_WORK(work, lru_add_drain_per_cpu);
                        queue_work_on(cpu, mm_percpu_wq, work);

However, we have to test this change extensively to make sure that we are not breaking anything.

Options:

1) Do a first pass on non-isolated CPUs trying to drain their per-CPU queues.
Not guaranteed to work (but perhaps a workable intermediate fix).

2) Reduce the limit of pages in per-CPU free queue to a value that is 
not very significant (don't think its a good idea: if there is a free page
somewhere, should be able to use it before OOM'ing).

3) Drain pages when entering "task isolated" mode.

From task isolated patchset:

+
+       /* Drain the pagevecs to avoid unnecessary IPI flushes later. */
+       lru_add_drain();
+

(In reply to Marcelo Tosatti from comment #6)
> Options:
> 
> 1) Do a first pass on non-isolated CPUs trying to drain their per-CPU queues.
> Not guaranteed to work (but perhaps a workable intermediate fix).
> 

Yes, I agree there is a fair chance that this will fail. Since you mentioned this I don't think I will favor this now.

> 2) Reduce the limit of pages in per-CPU free queue to a value that is 
> not very significant (don't think its a good idea: if there is a free page
> somewhere, should be able to use it before OOM'ing).

+1, we should avoid doing this.

> 
> 3) Drain pages when entering "task isolated" mode.
> 
> From task isolated patchset:
> 
> +
> +       /* Drain the pagevecs to avoid unnecessary IPI flushes later. */
> +       lru_add_drain();
> +

It sounds like a decent idea, but I will also go through the code to understand if there are any downsides to it.

Verified with 4.18.0-221.rt7.33.el8.x86_64:

No any Call Trace in RT guest. 

(2)Single VM with 8 rt vCPUs:
 Max Latency:	 9 8 8 8 8 8 8 8 (us)


==Versions==
kernel-rt-4.18.0-221.rt7.33.el8.x86_64
qemu-kvm-5.0.0-0.scrmod+el8.3.0+7241+ccee766e.wrb200701.x86_64
tuned-2.14.0-2.el8.noarch
libvirt-6.4.0-1.scrmod+el8.3.0+7241+ccee766e.x86_64
python3-libvirt-6.3.0-1.module+el8.3.0+6485+695fc960.x86_64
microcode_ctl-20200609-2.el8.x86_64
rt-tests-1.8-3.el8.x86_64

So this bug has been fixed very well. Move to 'VERIFIED'.

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 (Moderate: 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-2020:4609