* Trying to trace when RT FF & RR threads hit RT Throttle limit (kernel.sched_rt_runtime_us) @ 2023-05-01 4:42 Brian Hutchinson 2023-05-01 14:17 ` Steven Rostedt 0 siblings, 1 reply; 6+ messages in thread From: Brian Hutchinson @ 2023-05-01 4:42 UTC (permalink / raw) To: linux-trace-users Hi, Using 5.10.69 kernel on a i.MX8 platform with isolated cpu's (isolcpus on cmd line) with RT_RUNTIME_SHARE and wanting to know if (and who) is hitting the RT Throttle limit. Since my kernel does not have a tracepoint for this, I used gdb and disassembled kernel/sched/rt.c to find the address where throttling gets set and then added a kprobe for it. When I look at the trace I'm seeing what looks like "idle" being throttled in addition to other things. I "think" my probe is working as when I look at the trace, the processes that show up look like they have run over the 95% limit of one period (defaulted to 1 second) but I'm confused as to why Idle shows up. I've not ran lttng trace capturing context switches yet to see what other processes might be involved around the time the throttle kicks in, at the moment I'm just trying to validate I'm going after the problem and setting it up the right way. I did identify a patch that enables a tracepoint for the rt throttle but it is for RT_GROUP_SCHED and we aren't using that at the moment. I suspect the application I'm trying to debug has some misbehaving realtime processes (not using a rt patched kernel) that are being throttled so I'm trying to identify them so they can be studied and made to behave better. If anyone has a better idea or advice on how to go about this please point me in the right direction. Below is a sample of a trace I captured using the kprobe I mentioned above when rt_throttled=1. I don't quite understand how Idle can be 3 levels deep in preemption or why "idle" is even showing up. CPU's 1, 2 and 3 have been isolated and the application that appears to be getting throttled is on core 2: # tracer: nop # # entries-in-buffer/entries-written: 592/592 #P:4 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | <idle>-0 [002] d.h3 508.964800: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 508.964815: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 508.964822: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 508.964831: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 509.964801: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 509.964817: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 509.964824: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 509.964832: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 510.964799: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 510.964814: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 510.964821: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 510.964832: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 511.964799: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 511.964816: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 511.964823: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 511.964830: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 512.964800: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 512.964815: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 512.964822: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 512.964829: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 513.964801: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 513.964817: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 513.964826: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 513.964835: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 514.964803: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 514.964818: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 514.964825: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 514.964832: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 515.964801: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 515.964818: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 515.964825: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 515.964834: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 516.964797: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 516.964809: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 516.964815: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 516.964820: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [000] d.h3 517.964804: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [000] d.h3 517.964820: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [000] d.h3 517.964829: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [000] d.h3 517.964839: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 518.964799: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 518.964815: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 518.964823: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 518.964831: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 519.964801: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 519.964817: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 519.964824: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 519.964833: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 520.964800: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 520.964815: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 520.964822: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 520.964831: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 521.964811: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 521.964828: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 521.964835: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 521.964847: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 522.964795: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 522.964811: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 522.964819: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 522.964826: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 irq/33-sdma-369 [002] dNh3 523.964811: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 irq/33-sdma-369 [002] dNh3 523.964826: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 irq/33-sdma-369 [002] dNh3 523.964833: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 irq/33-sdma-369 [002] dNh3 523.964842: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h4 524.964799: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h4 524.964816: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h4 524.964825: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h4 524.964834: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h3 525.964794: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h3 525.964810: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h3 525.964817: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h3 525.964825: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h2 526.964793: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h2 526.964808: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h2 526.964815: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 some-thread-758 [002] d.h2 526.964823: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 irq/33-sdma-369 [002] d.h4 527.964802: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 irq/33-sdma-369 [002] d.h4 527.964818: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 irq/33-sdma-369 [002] d.h4 527.964826: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 irq/33-sdma-369 [002] d.h4 527.964835: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h4 528.964803: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h4 528.964818: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h4 528.964827: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h4 528.964837: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 529.964797: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 529.964812: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 529.964820: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] d.h3 529.964830: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 530.964793: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 530.964808: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 530.964815: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 <idle>-0 [002] dNh3 530.964824: p_0x00000000223c0e95: (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 Thanks for any guidance/pointers. Regards, Brian ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Trying to trace when RT FF & RR threads hit RT Throttle limit (kernel.sched_rt_runtime_us) 2023-05-01 4:42 Trying to trace when RT FF & RR threads hit RT Throttle limit (kernel.sched_rt_runtime_us) Brian Hutchinson @ 2023-05-01 14:17 ` Steven Rostedt 2023-05-01 15:15 ` Brian Hutchinson 0 siblings, 1 reply; 6+ messages in thread From: Steven Rostedt @ 2023-05-01 14:17 UTC (permalink / raw) To: Brian Hutchinson; +Cc: linux-trace-users On Mon, 1 May 2023 00:42:03 -0400 Brian Hutchinson <b.hutchman@gmail.com> wrote: > Hi, > > Using 5.10.69 kernel on a i.MX8 platform with isolated cpu's (isolcpus > on cmd line) with RT_RUNTIME_SHARE and wanting to know if (and who) is > hitting the RT Throttle limit. Since my kernel does not have a > tracepoint for this, I used gdb and disassembled kernel/sched/rt.c to > find the address where throttling gets set and then added a kprobe for > it. Where exactly did you add this kprobe? > > When I look at the trace I'm seeing what looks like "idle" being > throttled in addition to other things. I "think" my probe is working > as when I look at the trace, the processes that show up look like they > have run over the 95% limit of one period (defaulted to 1 second) but > I'm confused as to why Idle shows up. Are you saying this because it's happening while idle is running? > > I've not ran lttng trace capturing context switches yet to see what > other processes might be involved around the time the throttle kicks > in, at the moment I'm just trying to validate I'm going after the > problem and setting it up the right way. > > I did identify a patch that enables a tracepoint for the rt throttle > but it is for RT_GROUP_SCHED and we aren't using that at the moment. > > I suspect the application I'm trying to debug has some misbehaving > realtime processes (not using a rt patched kernel) that are being > throttled so I'm trying to identify them so they can be studied and > made to behave better. > > If anyone has a better idea or advice on how to go about this please > point me in the right direction. > > Below is a sample of a trace I captured using the kprobe I mentioned > above when rt_throttled=1. I don't quite understand how Idle can be 3 > levels deep in preemption or why "idle" is even showing up. > > CPU's 1, 2 and 3 have been isolated and the application that appears > to be getting throttled is on core 2: > > # tracer: nop > # > # entries-in-buffer/entries-written: 592/592 #P:4 > # > # _-----=> irqs-off > # / _----=> need-resched > # | / _---=> hardirq/softirq > # || / _--=> preempt-depth > # ||| / delay > # TASK-PID CPU# |||| TIMESTAMP FUNCTION > # | | | |||| | | > <idle>-0 [002] d.h3 508.964800: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 Note the "d.h3", which means as the heading states, 'd' is interrupts are disabled, 'h' means it is running in hard interrupt context. That means, even though idle is the current task, an interrupt triggered, and this is running in interrupt context. I see it's running sched_rt_period_timer() which calls do_sched_rt_period_timer(), and if you look at that function, it does for_each_cpu(i, span), checking other CPUs to see if it should be throttled or not. It's not throttling idle, but the interrupt running on the idle CPU noticed that an RT task needs to be throttled. -- Steve > <idle>-0 [002] d.h3 508.964815: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 508.964822: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 508.964831: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 509.964801: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 509.964817: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 509.964824: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 509.964832: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 510.964799: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 510.964814: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 510.964821: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 510.964832: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 511.964799: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 511.964816: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 511.964823: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 511.964830: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 512.964800: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 512.964815: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 512.964822: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 512.964829: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 513.964801: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 513.964817: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 513.964826: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 513.964835: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 514.964803: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 514.964818: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 514.964825: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 514.964832: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 515.964801: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 515.964818: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 515.964825: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 515.964834: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 516.964797: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 516.964809: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 516.964815: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 516.964820: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [000] d.h3 517.964804: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [000] d.h3 517.964820: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [000] d.h3 517.964829: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [000] d.h3 517.964839: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 518.964799: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 518.964815: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 518.964823: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 518.964831: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 519.964801: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 519.964817: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 519.964824: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 519.964833: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 520.964800: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 520.964815: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 520.964822: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 520.964831: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 521.964811: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 521.964828: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 521.964835: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 521.964847: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 522.964795: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 522.964811: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 522.964819: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 522.964826: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > irq/33-sdma-369 [002] dNh3 523.964811: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > irq/33-sdma-369 [002] dNh3 523.964826: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > irq/33-sdma-369 [002] dNh3 523.964833: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > irq/33-sdma-369 [002] dNh3 523.964842: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h4 524.964799: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h4 524.964816: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h4 524.964825: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h4 524.964834: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h3 525.964794: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h3 525.964810: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h3 525.964817: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h3 525.964825: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h2 526.964793: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h2 526.964808: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h2 526.964815: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > some-thread-758 [002] d.h2 526.964823: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > irq/33-sdma-369 [002] d.h4 527.964802: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > irq/33-sdma-369 [002] d.h4 527.964818: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > irq/33-sdma-369 [002] d.h4 527.964826: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > irq/33-sdma-369 [002] d.h4 527.964835: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h4 528.964803: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h4 528.964818: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h4 528.964827: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h4 528.964837: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 529.964797: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 529.964812: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 529.964820: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] d.h3 529.964830: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 530.964793: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 530.964808: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 530.964815: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > <idle>-0 [002] dNh3 530.964824: p_0x00000000223c0e95: > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > > Thanks for any guidance/pointers. > > Regards, > > Brian ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Trying to trace when RT FF & RR threads hit RT Throttle limit (kernel.sched_rt_runtime_us) 2023-05-01 14:17 ` Steven Rostedt @ 2023-05-01 15:15 ` Brian Hutchinson 2023-05-01 15:21 ` Steven Rostedt 0 siblings, 1 reply; 6+ messages in thread From: Brian Hutchinson @ 2023-05-01 15:15 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-trace-users Hey Steve, good to hear from you. On Mon, May 1, 2023 at 10:17 AM Steven Rostedt <rostedt@goodmis.org> wrote: > > On Mon, 1 May 2023 00:42:03 -0400 > Brian Hutchinson <b.hutchman@gmail.com> wrote: > > > Hi, > > > > Using 5.10.69 kernel on a i.MX8 platform with isolated cpu's (isolcpus > > on cmd line) with RT_RUNTIME_SHARE and wanting to know if (and who) is > > hitting the RT Throttle limit. Since my kernel does not have a > > tracepoint for this, I used gdb and disassembled kernel/sched/rt.c to > > find the address where throttling gets set and then added a kprobe for > > it. > > Where exactly did you add this kprobe? It was: /sys/kernel/debug/tracing echo 'p 0xffff8000100a8e38 %x0' > kprobe_events Your "Fun with Dynamic Kernel Tracing Events" talk in 2018 was cool with all those examples but you never gave examples on how to do this kind of stuff wink, wink, ha, ha. > > > > > When I look at the trace I'm seeing what looks like "idle" being > > throttled in addition to other things. I "think" my probe is working > > as when I look at the trace, the processes that show up look like they > > have run over the 95% limit of one period (defaulted to 1 second) but > > I'm confused as to why Idle shows up. > > Are you saying this because it's happening while idle is running? I don't know what I'm saying. Part of me posting was me questioning if what I'm seeing is even valid ... but it makes more sense now that you point out that it's a hard interrupt happening while idle. Now I just have to figure out which interrupt. > > > > > I've not ran lttng trace capturing context switches yet to see what > > other processes might be involved around the time the throttle kicks > > in, at the moment I'm just trying to validate I'm going after the > > problem and setting it up the right way. > > > > I did identify a patch that enables a tracepoint for the rt throttle > > but it is for RT_GROUP_SCHED and we aren't using that at the moment. > > > > I suspect the application I'm trying to debug has some misbehaving > > realtime processes (not using a rt patched kernel) that are being > > throttled so I'm trying to identify them so they can be studied and > > made to behave better. > > > > If anyone has a better idea or advice on how to go about this please > > point me in the right direction. > > > > Below is a sample of a trace I captured using the kprobe I mentioned > > above when rt_throttled=1. I don't quite understand how Idle can be 3 > > levels deep in preemption or why "idle" is even showing up. > > > > CPU's 1, 2 and 3 have been isolated and the application that appears > > to be getting throttled is on core 2: > > > > # tracer: nop > > # > > # entries-in-buffer/entries-written: 592/592 #P:4 > > # > > # _-----=> irqs-off > > # / _----=> need-resched > > # | / _---=> hardirq/softirq > > # || / _--=> preempt-depth > > # ||| / delay > > # TASK-PID CPU# |||| TIMESTAMP FUNCTION > > # | | | |||| | | > > <idle>-0 [002] d.h3 508.964800: p_0x00000000223c0e95: > > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > > > Note the "d.h3", which means as the heading states, 'd' is interrupts are > disabled, 'h' means it is running in hard interrupt context. That means, > even though idle is the current task, an interrupt triggered, and this is > running in interrupt context. As I said above, makes more sense why idle is showing up now that you pointed that out. This is an app that was ported from a different OS that used a single core arch and now that's its on multicore arch (quad core A53's) with SMP Linux, I think there are some old school disable interrupts/preempt critical section areas that are going to need to be reworked ... which is one of the reasons I believe it was necessary to pin the apps to an isolated core on the i.MX8 to get them to even run. > > I see it's running sched_rt_period_timer() which calls > do_sched_rt_period_timer(), and if you look at that function, it does > for_each_cpu(i, span), checking other CPUs to see if it should be throttled > or not. ... about that. I screwed up and meant to say scheduler features is set to NO_RT_RUNTIME_SHARE in the original post as I've read there is some weirdness on "what" sched_rt_runtime_us means ... a limit on the system as a whole (all cpu's) or each individual cpu. I "believe" the way I'm running it is each individual cpu gets sched_rt_runtime_us for realtime stuff. > > It's not throttling idle, but the interrupt running on the idle CPU noticed > that an RT task needs to be throttled. The trace all appears to be cpu2 context at the moment. So now I just need to figure out how to tell which interrupt it is. Thanks Steve. Regards, Brian ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Trying to trace when RT FF & RR threads hit RT Throttle limit (kernel.sched_rt_runtime_us) 2023-05-01 15:15 ` Brian Hutchinson @ 2023-05-01 15:21 ` Steven Rostedt 2023-05-01 19:35 ` Brian Hutchinson 0 siblings, 1 reply; 6+ messages in thread From: Steven Rostedt @ 2023-05-01 15:21 UTC (permalink / raw) To: Brian Hutchinson; +Cc: linux-trace-users On Mon, 1 May 2023 11:15:45 -0400 Brian Hutchinson <b.hutchman@gmail.com> wrote: > Hey Steve, good to hear from you. > > On Mon, May 1, 2023 at 10:17 AM Steven Rostedt <rostedt@goodmis.org> wrote: > > > > On Mon, 1 May 2023 00:42:03 -0400 > > Brian Hutchinson <b.hutchman@gmail.com> wrote: > > > > > Hi, > > > > > > Using 5.10.69 kernel on a i.MX8 platform with isolated cpu's (isolcpus > > > on cmd line) with RT_RUNTIME_SHARE and wanting to know if (and who) is > > > hitting the RT Throttle limit. Since my kernel does not have a > > > tracepoint for this, I used gdb and disassembled kernel/sched/rt.c to > > > find the address where throttling gets set and then added a kprobe for > > > it. > > > > Where exactly did you add this kprobe? > > It was: > /sys/kernel/debug/tracing > > echo 'p 0xffff8000100a8e38 %x0' > kprobe_events I meant, where was the exact location that address pointed to in the code, not where in the user interface did you add it ;-) > > Your "Fun with Dynamic Kernel Tracing Events" talk in 2018 was cool > with all those examples but you never gave examples on how to do this > kind of stuff wink, wink, ha, ha. > > > > > > > > > When I look at the trace I'm seeing what looks like "idle" being > > > throttled in addition to other things. I "think" my probe is working > > > as when I look at the trace, the processes that show up look like they > > > have run over the 95% limit of one period (defaulted to 1 second) but > > > I'm confused as to why Idle shows up. > > > > Are you saying this because it's happening while idle is running? > > I don't know what I'm saying. Part of me posting was me questioning > if what I'm seeing is even valid ... but it makes more sense now that > you point out that it's a hard interrupt happening while idle. Now I > just have to figure out which interrupt. > > > > > > > > > I've not ran lttng trace capturing context switches yet to see what > > > other processes might be involved around the time the throttle kicks > > > in, at the moment I'm just trying to validate I'm going after the > > > problem and setting it up the right way. > > > > > > I did identify a patch that enables a tracepoint for the rt throttle > > > but it is for RT_GROUP_SCHED and we aren't using that at the moment. > > > > > > I suspect the application I'm trying to debug has some misbehaving > > > realtime processes (not using a rt patched kernel) that are being > > > throttled so I'm trying to identify them so they can be studied and > > > made to behave better. > > > > > > If anyone has a better idea or advice on how to go about this please > > > point me in the right direction. > > > > > > Below is a sample of a trace I captured using the kprobe I mentioned > > > above when rt_throttled=1. I don't quite understand how Idle can be 3 > > > levels deep in preemption or why "idle" is even showing up. > > > > > > CPU's 1, 2 and 3 have been isolated and the application that appears > > > to be getting throttled is on core 2: > > > > > > # tracer: nop > > > # > > > # entries-in-buffer/entries-written: 592/592 #P:4 > > > # > > > # _-----=> irqs-off > > > # / _----=> need-resched > > > # | / _---=> hardirq/softirq > > > # || / _--=> preempt-depth > > > # ||| / delay > > > # TASK-PID CPU# |||| TIMESTAMP FUNCTION > > > # | | | |||| | | > > > <idle>-0 [002] d.h3 508.964800: p_0x00000000223c0e95: > > > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > > > > > > Note the "d.h3", which means as the heading states, 'd' is interrupts are > > disabled, 'h' means it is running in hard interrupt context. That means, > > even though idle is the current task, an interrupt triggered, and this is > > running in interrupt context. > > As I said above, makes more sense why idle is showing up now that you > pointed that out. This is an app that was ported from a different OS > that used a single core arch and now that's its on multicore arch > (quad core A53's) with SMP Linux, I think there are some old school > disable interrupts/preempt critical section areas that are going to > need to be reworked ... which is one of the reasons I believe it was > necessary to pin the apps to an isolated core on the i.MX8 to get them > to even run. > > > > > I see it's running sched_rt_period_timer() which calls > > do_sched_rt_period_timer(), and if you look at that function, it does > > for_each_cpu(i, span), checking other CPUs to see if it should be throttled > > or not. > > ... about that. I screwed up and meant to say scheduler features is > set to NO_RT_RUNTIME_SHARE in the original post as I've read there is > some weirdness on "what" sched_rt_runtime_us means ... a limit on the > system as a whole (all cpu's) or each individual cpu. I "believe" the > way I'm running it is each individual cpu gets sched_rt_runtime_us for > realtime stuff. Correct. I've ran some tests on rt spinners where if their affinity is broad they bounce around CPUs and still maintain 100% CPU resource (but on different CPUs). But if you pin it to a single CPU, it will get throttled. > > > > > It's not throttling idle, but the interrupt running on the idle CPU noticed > > that an RT task needs to be throttled. > > The trace all appears to be cpu2 context at the moment. So now I just > need to figure out how to tell which interrupt it is. > > Thanks Steve. No problem. -- Steve ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Trying to trace when RT FF & RR threads hit RT Throttle limit (kernel.sched_rt_runtime_us) 2023-05-01 15:21 ` Steven Rostedt @ 2023-05-01 19:35 ` Brian Hutchinson 2023-05-02 20:43 ` Steven Rostedt 0 siblings, 1 reply; 6+ messages in thread From: Brian Hutchinson @ 2023-05-01 19:35 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-trace-users On Mon, May 1, 2023 at 11:21 AM Steven Rostedt <rostedt@goodmis.org> wrote: > > On Mon, 1 May 2023 11:15:45 -0400 > Brian Hutchinson <b.hutchman@gmail.com> wrote: > > > Hey Steve, good to hear from you. > > > > On Mon, May 1, 2023 at 10:17 AM Steven Rostedt <rostedt@goodmis.org> wrote: > > > > > > On Mon, 1 May 2023 00:42:03 -0400 > > > Brian Hutchinson <b.hutchman@gmail.com> wrote: > > > > > > > Hi, > > > > > > > > Using 5.10.69 kernel on a i.MX8 platform with isolated cpu's (isolcpus > > > > on cmd line) with RT_RUNTIME_SHARE and wanting to know if (and who) is > > > > hitting the RT Throttle limit. Since my kernel does not have a > > > > tracepoint for this, I used gdb and disassembled kernel/sched/rt.c to > > > > find the address where throttling gets set and then added a kprobe for > > > > it. > > > > > > Where exactly did you add this kprobe? > > > > It was: > > /sys/kernel/debug/tracing > > > > echo 'p 0xffff8000100a8e38 %x0' > kprobe_events > > I meant, where was the exact location that address pointed to in the code, > not where in the user interface did you add it ;-) Douh! Ok, sorry, my bad. First attempt I put it here: 915 if (rt_rq->rt_time || rt_rq->rt_nr_running) 916 idle = 0; 917 raw_spin_unlock(&rt_rq->rt_runtime_lock); 918 } else if (rt_rq->rt_nr_running) { 919 idle = 0; 920 if (!rt_rq_throttled(rt_rq)) 921 enqueue = 1; 922 } 923 if (rt_rq->rt_throttled) 924 throttled = 1; 925 926 if (enqueue) 927 sched_rt_rq_enqueue(rt_rq); 928 raw_spin_unlock(&rq->lock); 929 } on line 924. I'm not the most versed at A53 assembly code so I guessed which instruction to use (it's always tricky with pipelining etc.) then cheated and put a breakpoint on line 924 to confirm and used that address. Then later I did the same thing: 964 if (rt_rq->rt_time > runtime) { 965 struct rt_bandwidth *rt_b = sched_rt_bandwidth(rt_rq); 966 967 /* 968 * Don't actually throttle groups that have no runtime assigned 969 * but accrue some time due to boosting. 970 */ 971 if (likely(rt_b->rt_runtime)) { 972 rt_rq->rt_throttled = 1; 973 printk_deferred_once("sched: RT throttling activated\n"); 974 } else { 975 /* 976 * In case we did anyway, make it go away, 977 * replenishment is a joke, since it will replenish us 978 * with exactly 0 ns. 979 */ 980 rt_rq->rt_time = 0; 981 } 982 983 if (rt_rq_throttled(rt_rq)) { 984 sched_rt_rq_dequeue(rt_rq); 985 return 1; 986 } 987 } ... and put a breakpoint on line 972 and used that address for kprobe. When I did this I pretty much got the same results as before but I got a lot of trace records more quickly (most were "idle") and a kworker thread showed up in the mix too. I'm also not a scheduler expert so I don't quite know the differences between the two places rt_throttled gets set (although it should be easy from the copious amount of comments ... not!). I just suspect the throttle is kicking in which is choking off sched_other OS stuff and I'm trying to figure out who's doing it and why. > > > > > Your "Fun with Dynamic Kernel Tracing Events" talk in 2018 was cool > > with all those examples but you never gave examples on how to do this > > kind of stuff wink, wink, ha, ha. > > > > > > > > > > > > > When I look at the trace I'm seeing what looks like "idle" being > > > > throttled in addition to other things. I "think" my probe is working > > > > as when I look at the trace, the processes that show up look like they > > > > have run over the 95% limit of one period (defaulted to 1 second) but > > > > I'm confused as to why Idle shows up. > > > > > > Are you saying this because it's happening while idle is running? > > > > I don't know what I'm saying. Part of me posting was me questioning > > if what I'm seeing is even valid ... but it makes more sense now that > > you point out that it's a hard interrupt happening while idle. Now I > > just have to figure out which interrupt. > > > > > > > > > > > > > I've not ran lttng trace capturing context switches yet to see what > > > > other processes might be involved around the time the throttle kicks > > > > in, at the moment I'm just trying to validate I'm going after the > > > > problem and setting it up the right way. > > > > > > > > I did identify a patch that enables a tracepoint for the rt throttle > > > > but it is for RT_GROUP_SCHED and we aren't using that at the moment. > > > > > > > > I suspect the application I'm trying to debug has some misbehaving > > > > realtime processes (not using a rt patched kernel) that are being > > > > throttled so I'm trying to identify them so they can be studied and > > > > made to behave better. > > > > > > > > If anyone has a better idea or advice on how to go about this please > > > > point me in the right direction. > > > > > > > > Below is a sample of a trace I captured using the kprobe I mentioned > > > > above when rt_throttled=1. I don't quite understand how Idle can be 3 > > > > levels deep in preemption or why "idle" is even showing up. > > > > > > > > CPU's 1, 2 and 3 have been isolated and the application that appears > > > > to be getting throttled is on core 2: > > > > > > > > # tracer: nop > > > > # > > > > # entries-in-buffer/entries-written: 592/592 #P:4 > > > > # > > > > # _-----=> irqs-off > > > > # / _----=> need-resched > > > > # | / _---=> hardirq/softirq > > > > # || / _--=> preempt-depth > > > > # ||| / delay > > > > # TASK-PID CPU# |||| TIMESTAMP FUNCTION > > > > # | | | |||| | | > > > > <idle>-0 [002] d.h3 508.964800: p_0x00000000223c0e95: > > > > (sched_rt_period_timer+0x1f0/0x328) arg1=0x0 > > > > > > > > > Note the "d.h3", which means as the heading states, 'd' is interrupts are > > > disabled, 'h' means it is running in hard interrupt context. That means, > > > even though idle is the current task, an interrupt triggered, and this is > > > running in interrupt context. > > > > As I said above, makes more sense why idle is showing up now that you > > pointed that out. This is an app that was ported from a different OS > > that used a single core arch and now that's its on multicore arch > > (quad core A53's) with SMP Linux, I think there are some old school > > disable interrupts/preempt critical section areas that are going to > > need to be reworked ... which is one of the reasons I believe it was > > necessary to pin the apps to an isolated core on the i.MX8 to get them > > to even run. > > > > > > > > I see it's running sched_rt_period_timer() which calls > > > do_sched_rt_period_timer(), and if you look at that function, it does > > > for_each_cpu(i, span), checking other CPUs to see if it should be throttled > > > or not. > > > > ... about that. I screwed up and meant to say scheduler features is > > set to NO_RT_RUNTIME_SHARE in the original post as I've read there is > > some weirdness on "what" sched_rt_runtime_us means ... a limit on the > > system as a whole (all cpu's) or each individual cpu. I "believe" the > > way I'm running it is each individual cpu gets sched_rt_runtime_us for > > realtime stuff. > > Correct. I've ran some tests on rt spinners where if their affinity is > broad they bounce around CPUs and still maintain 100% CPU resource (but on > different CPUs). But if you pin it to a single CPU, it will get throttled. I don't "think" anything is moving around here unless the OS is going against what it's been told to do. The cpu's are isolated with cmdline at boot and the affinity of these processes has been selected when they startup so they should stay where they are put unless there is something going on I don't know about. I think I've seen talk before that the affinity is just a "suggestion" making me think there are cases where something could move but if that's true I don't know what those scenarios are. Regards, Brian ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Trying to trace when RT FF & RR threads hit RT Throttle limit (kernel.sched_rt_runtime_us) 2023-05-01 19:35 ` Brian Hutchinson @ 2023-05-02 20:43 ` Steven Rostedt 0 siblings, 0 replies; 6+ messages in thread From: Steven Rostedt @ 2023-05-02 20:43 UTC (permalink / raw) To: Brian Hutchinson; +Cc: linux-trace-users On Mon, 1 May 2023 15:35:43 -0400 Brian Hutchinson <b.hutchman@gmail.com> wrote: > I don't "think" anything is moving around here unless the OS is going > against what it's been told to do. The cpu's are isolated with > cmdline at boot and the affinity of these processes has been selected > when they startup so they should stay where they are put unless there > is something going on I don't know about. I think I've seen talk > before that the affinity is just a "suggestion" making me think there > are cases where something could move but if that's true I don't know > what those scenarios are. BTW, you may want to email the relevant maintainers of the scheduler (yes, I'm one of them), because it's getting off topic for linux-trace-users. -- Steve ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2023-05-02 20:43 UTC | newest] Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2023-05-01 4:42 Trying to trace when RT FF & RR threads hit RT Throttle limit (kernel.sched_rt_runtime_us) Brian Hutchinson 2023-05-01 14:17 ` Steven Rostedt 2023-05-01 15:15 ` Brian Hutchinson 2023-05-01 15:21 ` Steven Rostedt 2023-05-01 19:35 ` Brian Hutchinson 2023-05-02 20:43 ` Steven Rostedt
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).