Do we see a behavior change between running this on a RHEL kernel vs an RT kernel?

Also, did an operator turn off FIFO throttling?

If you can snag them, would be nice to see the backtraces here.

We have not seen this exact problem on RHEL, but it does have the classic characteristics of an potential problem from running any SCHED_FIFO task in that some random task is initiating a kernel action that is requiring some information from a CPU where the SCHED_FIFO task is running or requiring an activity to be performed on that CPU.  I suspect that we are just getting unlucky in the OCP environment and that something that OCP is doing is causing such an activity to occur.

One thing that I have observed is that after awhile with testpmd running a kubelet task consumes 100% of a housekeeping core and then many node_exporter (I'm told this is related to prometheus data logging) tasks are consuming small amounts of CPU (I'll attach a top screen grab).  These appear to be blocked from making progress by the SCHED_FIFO task(s).  Previously, this always occurred when the node was essentially lost and it was hard to debug.

Yesterday (after our discussions) I proceeded to come up with some shell magic that will re-prioritize all SCHED_FIFO:1 tasks other than the testpmd tasks to SCHED_FIFO:2 and this is what I came up with:

for tid in $(ps -L -eo tid | sort -n); do if [ -e "${tid}/sched" ]; then policy=$(grep policy ${tid}/sched | awk '{ print $3 }'); if [ "${policy}" == "1" ]; then comm=$(cat ${tid}/comm); priority=$(grep prio ${tid}/sched | awk '{ print $3 }'); if [ "${priority}" == "98" ]; then echo "${tid} ${priority} ${comm}"; if echo "${comm}" | grep -qv lcore; then chrt -v -f -p 2 ${tid}; fi; fi; fi; fi; done

This moved quite a few tasks to SCHED_FIFO:2 and I then let the system run overnight.  This morning the system was still alive and OCP was not perturbed like it had been, but attempts to delete the Pod were unsuccessful until I manually intervened -- using a pre-created bash console (ssh core@node; sudo bash) I was able to use kill to terminate testpmd and then the Pod deletion succeeded.  This also unplugged whatever was holding back the kubelet/node_exporter tasks and they were then able to complete and exit/subside.  This would seem to imply that those tasks not progressing is not what is causing the catastrophic problem though since the system was still alive with that occurring.  It did take me a little while to get that shell command working to fixup the priorities so it is possible that some bad state was achieved prior to getting that working.  I'm going to try and reproduce this with the priorities fixed before ever launching testpmd.

I have explicitly tested deleting a Pod with SCHED_FIFO:1 testpmd tasks after creating it and bringing it up and that worked.  So that is not a combination that is 100% broken, something is happening via a timer and/or aging that is getting us into the problematic state.

It should be noted that when running testpmd with SCHED_FIFO:1 and the other tasks elevated to SCHED_FIFO:2 that the measured packet latency did increase substantially from a max of 16.5usec to 91.6usec.

--

If this the throttling that you are referring to I guess the answer is no:

[root@perf150 core]# cat /proc/sys/kernel/sched_rt_runtime_us 
-1

--

Do you mean the backtrace that is in the attached image file?  We don't have a serial console hooked up so I just had to do a screen grab of the iDRAC's remote console.

Created attachment 1700620 [details]
top output

After a fresh boot of the worker node I moved all the existing SCHED_FIFO:1 tasks to SCHED_FIFO:2, created a new Pod running testpmd, and then applied SCHED_FIFO:1 to the PMD threads spawned by testpmd.  At this point everything looked good.  I was watching the system via top for awhile and things were continuing to look good and I was targeting getting to 30 minutes of testpmd runtime and then recording some information.  Well, I got a bit distracted around 25 minutes and and didn't get to look at the system again until about 31 minutes and at that point I could see some funny stuff going on with kubelet/node_exporter (this grab is from ~46.5 minutes as I have been watching it to see if anything changed):

top - 16:49:51 up  1:57,  3 users,  load average: 100.24, 88.97, 58.62
Threads: 2071 total,  13 running, 2051 sleeping,   0 stopped,   7 zombie
%Cpu(s): 11.1 us,  8.8 sy,  0.0 ni, 80.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem : 192056.2 total, 172286.8 free,  17504.8 used,   2264.6 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used. 173483.0 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+  P COMMAND                                                                                                                                  
   2357 root      20   0 4742792 144136  62940 R  99.7   0.1  10:50.52  0 kubelet                                                                                                                                  
 291703 root      -2   0  256.2g  65208  11232 R  97.8   0.0  46:25.88  7 lcore-slave-7                                                                                                                            
 291704 root      -2   0  256.2g  65208  11232 R  97.8   0.0  46:26.01  9 lcore-slave-9                                                                                                                            
   7857 nobody    20   0  121272  49536   9684 D   8.8   0.0   1:16.26 14 node_exporter                                                                                                                            
  13703 nobody    20   0  121272  49536   9684 D   8.4   0.0   0:26.62 14 node_exporter                                                                                                                            
 165079 nobody    20   0  121272  49536   9684 D   8.1   0.0   0:23.32 14 node_exporter                                                                                                                            
 439006 nobody    20   0  121272  49536   9684 D   8.1   0.0   0:46.23 14 node_exporter                                                                                                                            
   7859 nobody    20   0  121272  49536   9684 D   7.8   0.0   0:32.73 14 node_exporter                                                                                                                            
   4789 nobody    20   0  121272  49536   9684 D   6.2   0.0   0:53.47 22 node_exporter                                                                                                                            
   7916 nobody    20   0  121272  49536   9684 D   6.2   0.0   0:40.02 22 node_exporter                                                                                                                            
 165076 nobody    20   0  121272  49536   9684 D   6.2   0.0   0:48.25 22 node_exporter                                                                                                                            
 439219 nobody    20   0  121272  49536   9684 D   5.6   0.0   0:54.51 22 node_exporter                                                                                                                            
   7872 nobody    20   0  121272  49536   9684 D   4.4   0.0   1:02.26  2 node_exporter                                                                                                                            
   7920 nobody    20   0  121272  49536   9684 D   4.4   0.0   0:56.53  2 node_exporter                                                                                                                            
 439100 nobody    20   0  121272  49536   9684 D   4.4   0.0   0:52.05  2 node_exporter                                                                                                                            
   7869 nobody    20   0  121272  49536   9684 D   4.1   0.0   0:38.95 10 node_exporter                                                                                                                            
   4790 nobody    20   0  121272  49536   9684 D   3.4   0.0   0:37.07 10 node_exporter                                                                                                                            
   7852 nobody    20   0  121272  49536   9684 D   3.4   0.0   0:23.85 21 node_exporter                                                                                                                            
   7873 nobody    20   0  121272  49536   9684 D   3.4   0.0   0:20.14 21 node_exporter

When I go look at the iDRAC console I see task blocked backtrace messages for kworkers for more than 600 seconds.  So I'm currently inclined to think that whatever is happening is occurring/starting around 20 minutes after starting testpmd and then due to the 600 second timeout we start seeing more evidence at around 30 minutes.

This may be obvious, but I should note that testpmd is continuing to function just fine while this is happening -- it is executing nearly uninterrupted after all.  So if observing the system remotely (say from our traffic generator) everything appears fine because packets continue to flow and performance is decent if not exceptional (depending on configuration).  It is only once taking a closer look at OCP and/or the worker node itself that the problems that are manifesting become apparent.

Created attachment 1700644 [details]
dmesg output

I recreated the scenario mentioned in comment #5 from a fresh boot and captured dmesg from the initial boot through the problem occurring.  The guest was booted right around the "[Fri Jul 10 17:30:08 2020]" timestamp.

Hi Karl,

I'm thinking that it might be interesting to try running this once
with -debug kernel.

I noticed from the dmesg you shared that blocked tasks seem to be
either blocked on netlink_sock cb_mutex (e.g., NetworkManager, agetty)
or css_set_lock, a mutex as well in RT (e.g., crio, kubelet).

When running with LOCKDEP enabled the hung task warning should
hopefully also print a list of all locks held in the system, so
we could try to use that additional info to figure out who is
holding the lock(s) the blocked tasks are waiting for.

Created attachment 1700879 [details]
dmesg output with debug kernel

Eventually got the RHCOS node to boot with the kernel-rt debug kernel and then fired off a Pod.  It took quite awhile for testpmd to come online, presumably do to debug overhead (it is pretty slow on RT as is due to memory mapping).

The problem seems to have taken much longer to manifest than previously seen but I imagine that has something to do with the debug overhead as well.

Attached is a new dmesg with the lockdep output.

Changing priority to urgent as this blocks OCP 4.6 release

Hi

Juri and I have been working the entire day on this problem, and here are our findings.

We found a way to reproduce the problem, and it consists of sending a signal -1 to the ovs-vswitchd daemon after setting the real-time priority to the testpmd threads. The signal makes ovs-vswitchd to restart, and as a consequence, it runs the functions of i40e that “causes” the problem (ovs-vswitchd waiting for a workqueue).

We also found that this action dispatched a workqueue on the CPUs that the testpmd threads were running as a busy-loop with real-time priority. If no action is taken, the system goes to a faulty state.

However, if we increase the priority of these kworkers (the WQ_HIGHPRI kworkers) to a real-time priority higher than the testpmd threads, the kworker runs, and the ovs-vswitchd makes progress, avoiding the faulty state.

With these in mind, we (mostly) discard our previous theory of a locking problem on i40e. At that point, we thought that the ovs-vswitchd was (indirectly) waiting for the kworker that was running i40e_service_task() work, but it is not the case. So, it seems to be a “classical” starvation bug.

Juri and I will continue debugging this problem.

I am attaching the instructions about how to reproduce and workaround the problem.

Thanks
Daniel Oliveira and Juri Lelli

Created attachment 1701936 [details]
Instructions about how to reproduce the problem (and how to workaround it)

Daniel,

What's the function that's causing the work items to be dispatched
to isolated CPUs? Is it in the workqueue subsystem or is some
specific function the i40e driver is calling?

We set the workqueue cpumask, but I remember this doesn't affect
all workqueues.

Hi Luiz

It is dispatched by net/core/dev.c:flush_all_backlogs(), inside a for_each_online_cpu(cpu), using the "system_highpri_wq" (iow: the high priority workqueues), which is per-cpu.

IIRC, we are setting the mask for the unbounded wq, that, as the name suggests, is not bounded to a specific CPU.

Hi Daniel,

That makes me think of bz1745111. In that we found that UNBOUND wq basically meant use the CPU of the submitting task, which in this case was causing the submitter to get migrated away by the load balancer since there would be 2 running tasks.   There was an upstream list discussion about it but I can't find it right now. Ming Lei posted a patch which started it I think.  Juri may remember, it was part of the SAP thing.  One of the attempted fixes which did work was to explicitly bind the work to a different CPU. In the above case it sounds the same if the task on the isolated CPU is doing the submitting. 

Fwiw,

Phil

Hi Phil, thanks for the heads up, but unfortunately this is not the same problem we are seeing :-(

Hi,

While userspace workaround (comment25) is tested and numbers gathered (as agreed during today's
sync call), we'd need to discuss possible (maybe longer term) fixes for the kernel.

In my understanding, the highprio workqueues that hang are scheduled onto the isolated core
running testpmd FIFO threads by net/core/dev.c flush_all_backlogs() functions that uses
for_each_online_cpu() to queue flushing of (potential) remaining packets on all online cpus.

We wonder if it might make sense to keep isolated cores out of the handling packets business
(unless strictly required), so that there will be no need to trigger flushing on them when an
interface is removed/reconfigured and consequently no need to queue highprio workqueues.

I discussed the issue and provided a bit of background to Paolo (now cc-ed) already and he had
interesting considerations that I kindly ask him to repeat in this thread as well so that everybody
can follow the discussion. Paolo, feel free, of course, to come back with questions if something is
not clear to you.

> I discussed the issue and provided a bit of background to Paolo (now cc-ed)
> already and he had interesting considerations that I kindly ask him to repeat in this thread as
> well so that everybody can follow the discussion.

First thing, the commit introducing the issue:

commit 145dd5f9c88f6ee645662df0be003e8f04bdae93
Author: Paolo Abeni <pabeni>
Date:   Thu Aug 25 15:58:44 2016 +0200

    net: flush the softnet backlog in process context

can't be easily reverted because is leveraged by later commit:

commit 41852497a9205964b958a245a9526040b980926f
Author: Eric Dumazet <edumazet>
Date:   Fri Aug 26 12:50:39 2016 -0700

    net: batch calls to flush_all_backlogs()

to speed-up netns removal time in case of many network device present, which is considered a quite critical metric.

flush_all_backlogs() needs to act on each online CPUs due to RPS - receive packet steering: each NIC can be configured via sysfs entry to redirect incoming packet to specific CPUs using the ingress packet RX hash for the demux operation. The target CPU can be selected even if isolated.

So a possible solution could be update RPS to be aware of isolated CPUs: store_rps_map() in net/core/net-sysfs.c must prevent isolated CPUs from being inserted into the map and flush_all_backlogs() could then skip isolated CPUs.

The above assuming that the isolated CPU lists did not change after the boot. Otherwise, at isolated CPU mask update time, the sofrnet_data.input_pkt_queue and softnet_data.process_queue of the newly isolated CPUs should be moved to others cores.

Note that the above will introduce a change of established behavior and may see some resistance upstream. Possibly doing the above under some specific boot params and/or Kconfig knob (CONFIG_CPU_ISOLATION???) could help. Does CPU isolation already prevent e.g. NICS from scheduling IRQs on the isolated cores? I'm asking to try to understand how much resistance could find upstream the mentioned change.

(In reply to Paolo Abeni from comment #27)
> > I discussed the issue and provided a bit of background to Paolo (now cc-ed)
> > already and he had interesting considerations that I kindly ask him to repeat in this thread as
> > well so that everybody can follow the discussion.
> 
> First thing, the commit introducing the issue:
> 
> commit 145dd5f9c88f6ee645662df0be003e8f04bdae93
> Author: Paolo Abeni <pabeni>
> Date:   Thu Aug 25 15:58:44 2016 +0200
> 
>     net: flush the softnet backlog in process context
> 
> can't be easily reverted because is leveraged by later commit:
> 
> commit 41852497a9205964b958a245a9526040b980926f
> Author: Eric Dumazet <edumazet>
> Date:   Fri Aug 26 12:50:39 2016 -0700
> 
>     net: batch calls to flush_all_backlogs()
> 
> to speed-up netns removal time in case of many network device present, which
> is considered a quite critical metric.
> 
> flush_all_backlogs() needs to act on each online CPUs due to RPS - receive
> packet steering: each NIC can be configured via sysfs entry to redirect
> incoming packet to specific CPUs using the ingress packet RX hash for the
> demux operation. The target CPU can be selected even if isolated.
> 
> So a possible solution could be update RPS to be aware of isolated CPUs:
> store_rps_map() in net/core/net-sysfs.c must prevent isolated CPUs from
> being inserted into the map and flush_all_backlogs() could then skip
> isolated CPUs.

I have recently worked on this change and this is already sitting in linux-next [1].
I did miss to include the netdev ml, which I should have. 
However, this particular change was reviewed Acked by David S. Miller [2].

[1] https://lore.kernel.org/lkml/20200625223443.2684-4-nitesh@redhat.com/
[2] https://lore.kernel.org/lkml/20200626.102038.1298513542272393362.davem@davemloft.net/

> 
> The above assuming that the isolated CPU lists did not change after the
> boot. Otherwise, at isolated CPU mask update time, the
> sofrnet_data.input_pkt_queue and softnet_data.process_queue of the newly
> isolated CPUs should be moved to others cores.
> 
> Note that the above will introduce a change of established behavior and may
> see some resistance upstream. Possibly doing the above under some specific
> boot params and/or Kconfig knob (CONFIG_CPU_ISOLATION???) could help. Does
> CPU isolation already prevent e.g. NICS from scheduling IRQs on the isolated
> cores? I'm asking to try to understand how much resistance could find
> upstream the mentioned change.

Yes, atleast the NIC drivers that use cpumask_local_spread to pick CPUs at the time
of vector allocation. This change is also made in the same patch-set [1].

[1] https://lore.kernel.org/lkml/20200625223443.2684-2-nitesh@redhat.com/

(In reply to Nitesh Narayan Lal from comment #28)
> (In reply to Paolo Abeni from comment #27)
> > > I discussed the issue and provided a bit of background to Paolo (now cc-ed)
> > > already and he had interesting considerations that I kindly ask him to repeat in this thread as
> > > well so that everybody can follow the discussion.
> > 
> > First thing, the commit introducing the issue:
> > 
> > commit 145dd5f9c88f6ee645662df0be003e8f04bdae93
> > Author: Paolo Abeni <pabeni>
> > Date:   Thu Aug 25 15:58:44 2016 +0200
> > 
> >     net: flush the softnet backlog in process context
> > 
> > can't be easily reverted because is leveraged by later commit:
> > 
> > commit 41852497a9205964b958a245a9526040b980926f
> > Author: Eric Dumazet <edumazet>
> > Date:   Fri Aug 26 12:50:39 2016 -0700
> > 
> >     net: batch calls to flush_all_backlogs()
> > 
> > to speed-up netns removal time in case of many network device present, which
> > is considered a quite critical metric.
> > 
> > flush_all_backlogs() needs to act on each online CPUs due to RPS - receive
> > packet steering: each NIC can be configured via sysfs entry to redirect
> > incoming packet to specific CPUs using the ingress packet RX hash for the
> > demux operation. The target CPU can be selected even if isolated.
> > 
> > So a possible solution could be update RPS to be aware of isolated CPUs:
> > store_rps_map() in net/core/net-sysfs.c must prevent isolated CPUs from
> > being inserted into the map and flush_all_backlogs() could then skip
> > isolated CPUs.
> 
> I have recently worked on this change and this is already sitting in
> linux-next [1].
> I did miss to include the netdev ml, which I should have. 
> However, this particular change was reviewed Acked by David S. Miller [2].
> 
> [1] https://lore.kernel.org/lkml/20200625223443.2684-4-nitesh@redhat.com/
> [2]
> https://lore.kernel.org/lkml/20200626.102038.1298513542272393362.
> davem/

Excellent! looks like we are on the same page! The mentioned commit was also discussed on an internal ML, but I did not follow closely.

If I read correctly, to completely address this issue we additionally need to mask out isolated CPUs in 
flush_backlog() loops. Am I missing something? Or are you planning such change, too?

Thanks,

Paolo

(In reply to Paolo Abeni from comment #29)
> (In reply to Nitesh Narayan Lal from comment #28)
> > (In reply to Paolo Abeni from comment #27)
> > > > I discussed the issue and provided a bit of background to Paolo (now cc-ed)
> > > > already and he had interesting considerations that I kindly ask him to repeat in this thread as
> > > > well so that everybody can follow the discussion.
> > > 
> > > First thing, the commit introducing the issue:
> > > 
> > > commit 145dd5f9c88f6ee645662df0be003e8f04bdae93
> > > Author: Paolo Abeni <pabeni>
> > > Date:   Thu Aug 25 15:58:44 2016 +0200
> > > 
> > >     net: flush the softnet backlog in process context
> > > 
> > > can't be easily reverted because is leveraged by later commit:
> > > 
> > > commit 41852497a9205964b958a245a9526040b980926f
> > > Author: Eric Dumazet <edumazet>
> > > Date:   Fri Aug 26 12:50:39 2016 -0700
> > > 
> > >     net: batch calls to flush_all_backlogs()
> > > 
> > > to speed-up netns removal time in case of many network device present, which
> > > is considered a quite critical metric.
> > > 
> > > flush_all_backlogs() needs to act on each online CPUs due to RPS - receive
> > > packet steering: each NIC can be configured via sysfs entry to redirect
> > > incoming packet to specific CPUs using the ingress packet RX hash for the
> > > demux operation. The target CPU can be selected even if isolated.
> > > 
> > > So a possible solution could be update RPS to be aware of isolated CPUs:
> > > store_rps_map() in net/core/net-sysfs.c must prevent isolated CPUs from
> > > being inserted into the map and flush_all_backlogs() could then skip
> > > isolated CPUs.
> > 
> > I have recently worked on this change and this is already sitting in
> > linux-next [1].
> > I did miss to include the netdev ml, which I should have. 
> > However, this particular change was reviewed Acked by David S. Miller [2].
> > 
> > [1] https://lore.kernel.org/lkml/20200625223443.2684-4-nitesh@redhat.com/
> > [2]
> > https://lore.kernel.org/lkml/20200626.102038.1298513542272393362.
> > davem/
> 
> Excellent! looks like we are on the same page! The mentioned commit was also
> discussed on an internal ML, but I did not follow closely.
> 
> If I read correctly, to completely address this issue we additionally need
> to mask out isolated CPUs in 
> flush_backlog() loops. Am I missing something? Or are you planning such
> change, too?

Yeah, that's also my impression.
Juri has told me that you will be taking care of the flush_backlog() change.
So once that is done we should be fine.

Thanks
Nitesh

> 
> Thanks,
> 
> Paolo

> If I read correctly, to completely address this issue we additionally need
> to mask out isolated CPUs in 
> flush_backlog() loops. Am I missing something? Or are you planning such
> change, too?


But we are not using isolated CPUs (isolcpus=domain=).  And over time these CPUs being used could change.  If this is a problem with RPS, why can't we check what CPUs are targets for RPS, and a CPU is not a target, can we just skip them?

(In reply to Andrew Theurer from comment #31)
> > If I read correctly, to completely address this issue we additionally need
> > to mask out isolated CPUs in 
> > flush_backlog() loops. Am I missing something? Or are you planning such
> > change, too?
> 
> 
> But we are not using isolated CPUs (isolcpus=domain=).  And over time these
> CPUs being used could change.  If this is a problem with RPS, why can't we
> check what CPUs are targets for RPS, and a CPU is not a target, can we just
> skip them?

RPS settings are per-device and can be modified dynamically at run-time. flush_backlog processes several device at once. It's fairly non trivial compute the minumal CPU set flush_device should run on. Additionally, a valid, useful and common configuration is spreading RPS on all the available CPUs. Without isolcpus looks impossible to me avoid this issue.

(In reply to Andrew Theurer from comment #31)
> > If I read correctly, to completely address this issue we additionally need
> > to mask out isolated CPUs in 
> > flush_backlog() loops. Am I missing something? Or are you planning such
> > change, too?
> 
> 
> But we are not using isolated CPUs (isolcpus=domain=).  And over time these
> CPUs being used could change.  If this is a problem with RPS, why can't we
> check what CPUs are targets for RPS, and a CPU is not a target, can we just
> skip them?

But I believe rcu_nocbs is used however, or am I wrong?

If that's the case, maybe we can think of an additional kernel/sysfs parameter
(i.e. something similar to standard workqueues) to configure RPS queues and
flush?

I fired up raggiro and just let the system run for a long time (overnight) and I still saw problems.  It looked like it was waiting indefinitely for a task that had been assigned deadline scheduling to complete.  When I looked at the list of runnable tasks on the isolated CPUs I saw quite a few.  This made me think that the way the script was written was finding a task to give deadline scheduling (and then it blocks waiting for that task to no longer be runnable) and never actually gives deadline scheduling classification to the task that is actually blocking forward progress for the other tasks.  So I have made some changes to raggiro and will post that as raggiro v2.  It it no longer filtering just on kworker threads and I had to tweak the logic some to allow it to tweak multiple tasks per CPU simultaneously.

Unfortunately, raggiro v2 is still not working.  It does appear to let the tasks make forward progress, albeit extremely slowly.  I saw a lot of messages like this from running it overnight:

[Tue Jul 28 01:42:57 2020] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[Tue Jul 28 01:42:57 2020] rcu:         Tasks blocked on level-1 rcu_node (CPUs 0-11): P85
[Tue Jul 28 01:42:57 2020] rcu:         (detected by 0, t=60002 jiffies, g=9520401, q=432287)
[Tue Jul 28 01:42:57 2020] ksoftirqd/7     R  running task        0    85      2 0x80000000
[Tue Jul 28 01:42:57 2020] Call Trace:
[Tue Jul 28 01:42:57 2020]  ? __schedule+0x25a/0x6a0
[Tue Jul 28 01:42:57 2020]  preempt_schedule_irq+0x43/0xa0
[Tue Jul 28 01:42:57 2020]  do_preempt_schedule_irq+0x5/0x7
[Tue Jul 28 01:42:57 2020] RIP: 0010:find_busiest_group+0x20b/0xac0
[Tue Jul 28 01:42:57 2020] Code: 08 48 8b 74 ce 08 48 39 f0 48 0f 42 c6 eb 84 8b 40 38 89 44 24 04 e9 7f fe ff ff 8b 4c 24 04 48 8d 34 10 48 8b 86 28 01 00 00 <85> c9 0f 84 61 ff ff ff 0f 1f 44 00 00 e9 57 ff ff ff 48 8b 4c 24
[Tue Jul 28 01:42:57 2020] RSP: 0000:ffffb006d49bfbb0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
[Tue Jul 28 01:42:57 2020] RAX: 0000000000000000 RBX: 0000000000025d00 RCX: 0000000000000002
[Tue Jul 28 01:42:57 2020] RDX: ffff9f339fa80000 RSI: ffff9f339faa5d00 RDI: ffff9f1c0d137030
[Tue Jul 28 01:42:57 2020] RBP: ffff9f339faa5d00 R08: 0000000000000015 R09: 0000000000000000
[Tue Jul 28 01:42:57 2020] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000015
[Tue Jul 28 01:42:57 2020] R13: 0000000000000000 R14: ffffb006d49bfbe0 R15: ffffb006d49bfd70
[Tue Jul 28 01:42:57 2020]  load_balance+0x16e/0xa70
[Tue Jul 28 01:42:57 2020]  rebalance_domains+0x25d/0x2e0
[Tue Jul 28 01:42:57 2020]  do_current_softirqs+0x223/0x3e0
[Tue Jul 28 01:42:57 2020]  ? smpboot_register_percpu_thread_cpumask+0x130/0x130
[Tue Jul 28 01:42:57 2020]  run_ksoftirqd+0x22/0x40
[Tue Jul 28 01:42:57 2020]  smpboot_thread_fn+0x1d6/0x2c0
[Tue Jul 28 01:42:57 2020]  kthread+0x112/0x130
[Tue Jul 28 01:42:57 2020]  ? kthread_flush_work_fn+0x10/0x10
[Tue Jul 28 01:42:57 2020]  ret_from_fork+0x35/0x40

I also still eventually saw a hung task timeout message:

[Tue Jul 28 02:00:27 2020] INFO: task rcub/1:15 blocked for more than 600 seconds.
[Tue Jul 28 02:00:27 2020]       Not tainted 4.18.0-147.8.1.rt24.101.el8_1.x86_64 #1
[Tue Jul 28 02:00:27 2020] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Tue Jul 28 02:00:27 2020] rcub/1          D    0    15      2 0x80000000
[Tue Jul 28 02:00:27 2020] Call Trace:
[Tue Jul 28 02:00:27 2020]  ? __schedule+0x25a/0x6a0
[Tue Jul 28 02:00:27 2020]  schedule+0x39/0xd0
[Tue Jul 28 02:00:27 2020]  __rt_mutex_slowlock+0xbe/0x130
[Tue Jul 28 02:00:27 2020]  ? __perf_event_task_sched_in+0x21/0x250
[Tue Jul 28 02:00:27 2020]  rt_mutex_slowlock_locked+0xbc/0x270
[Tue Jul 28 02:00:27 2020]  rt_mutex_slowlock+0x6d/0xc0
[Tue Jul 28 02:00:27 2020]  ? trace_rcu_utilization+0x80/0x80
[Tue Jul 28 02:00:27 2020]  rcu_boost_kthread+0xf7/0x370
[Tue Jul 28 02:00:27 2020]  ? trace_rcu_utilization+0x80/0x80
[Tue Jul 28 02:00:27 2020]  kthread+0x112/0x130
[Tue Jul 28 02:00:27 2020]  ? kthread_flush_work_fn+0x10/0x10
[Tue Jul 28 02:00:27 2020]  ret_from_fork+0x35/0x40

Created attachment 1702661 [details]
raggiro v2 script

Karl,

Can we have access to the system?

-- Daniel

Daniel

Sure.  The worker node is freshly booted, it was completely inaccessible this morning.

Karl

warning while using the C version of raggiro: -> https://bugzilla.redhat.com/show_bug.cgi?id=1861414

Fast report:

I was able to reproduce the RCU stall, and yeah, it happened because there was not enough time for RCU to make progress.

Now I am giving: 20us/second, during a three-second window, for each starving task that is waiting for more than 10 seconds as runnable [all tasks will receive at least three periods].

These parameters seem to be enough to allow RCU to stop complaining.

The SCHED_DEADLINE messages that are showing up there can be ignored, see comment #38.

[we are using a new version of raggiro, made in C...]

Let's see if the system stays up until tomorrow.

Thoughts?

-- Daniel

Sounds good.  I'm afraid we are going to have to let it run for long periods to see if it is actually avoiding the problems.

So the 20us/second is interesting.  We moved to 10us/second because our latency requirement is 20us.  So allowing 20us/second of interruption virtually guarantees that our latency requirement will be exceeded :/

Karl

guaranteein 20us latency is something more complex than that... mainly because we are doing very... let's say... optmistic tests (see: https://bristot.me/demystifying-the-real-time-linux-latency/ for a contrast).

But now I reduced the runtime to 10us, let's see!

Karl

The system survived without RCU messages using the 10us/sec setup.

Would you mind to install this kernel here: http://brew-task-repos.usersys.redhat.com/repos/scratch/jlelli/kernel-rt/4.18.0/147.23.1.rt24.117.el8_1.dlboost.test.cki.kt0/x86_64/

[it fixes a warning from SCHED_DEADLINE... Kudos for Juri]

and dispatches the raggiro I left in the /var/home/core/raggiro

with the following arguments:

/var/home/core/raggiro -c 7,9 -k -t 10 -r 10000

to see if the system survives?

Thanks!

Daniel

Will do.  Thanks!

Karl

(In reply to Andrew Theurer from comment #31)
> > If I read correctly, to completely address this issue we additionally need
> > to mask out isolated CPUs in 
> > flush_backlog() loops. Am I missing something? Or are you planning such
> > change, too?
> 
> 
> But we are not using isolated CPUs (isolcpus=domain=).  

Due to the above comment and fact I will not submit the suggested upstream patch: it will not apply here.

It could still be useful in other scenarios. I'll try to follow the discussion here and will act accordingly.

/P

So far this is looking a lot better, but I probably need to let it run a lot longer (ie. overnight) to be sure.

Daniel/Juri

Can you guys explain what the C version is doing differently than the scripted version was doing?  I did not actually see the code lurking anywhere but I also did not look very hard yet.

Karl

Hi Karl,

The C version is here:

https://github.com/bristot/starvation_monitor

The idea is basically the same. However, it differs from the bash version because instead of doing commands (that could (more likely) block on locks caused by the starvation), it gets the information straight from the kernel files, and does the system calls that control the prioritization more easily.

It is also easy to use, maintain and optimize as C code, and we will work to make it a production ready deamon.

Should this BZ state be ON_QA as stalld was delivered ?

I would say yes. I wonder what management thinks.

I will raise this topic on today's meeting.

Since bug 1878602 resolves this issue, I'm closing this as
a dupe. If you disagree, feel free to reopen at any time.

*** This bug has been marked as a duplicate of bug 1878602 ***