Hi all,
On 21/10/2024 11:44, Jean-Michel Hautbois wrote:
In order to debug latency issues, I wanted to use ftrace on my M54418
coldfire. Sadly, it is not supported yet.
Thanks to Steven [1] it does not sound too difficult.
This small series adds basic functions to make it work, and for the few
tests I could do, it seems to be working well.
I did a few tests (well, a *lot* to be honest :-)) after adding HR
timers support on my m68k coldfire kernel.
Now, I think ftrace shows a nice issue, but I think my stack_trace is
not correct ?
# wakeup_rt latency trace v1.1.5 on 6.12.0-rc4-00116-g2f00ff61fd82-dirty
# --------------------------------------------------------------------
# latency: 451 us, #6/6, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
# -----------------
# | task: irq/104-enet-fe-109 (uid:0 nice:0 policy:1 rt_prio:50)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off/BH-disabled
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / _-=> migrate-disable
# ||||| / delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
telnetd-224 0dnh4. 14us+: 224:120:R + [000] 109:
49:R irq/104-enet-fe
telnetd-224 0dnh4. 50us+: <stack trace>
telnetd-224 0dnh4. 65us!: 0
telnetd-224 0d..3. 396us+: __traceiter_sched_switch
telnetd-224 0d..3. 418us+: 224:120:R ==> [000] 109:
49:R irq/104-enet-fe
telnetd-224 0d..3. 440us : <stack trace>
Nevertheless it sounds like a really high latency for wake_up().
I have a custom driver which basically gets an IRQ, and calls wake_up on
a read() call. This wake_up() on a high cpu usage can be more than 1ms !
Even with a fifo/99 priority for my kernel thread !
I don't know if it rings any bell ?
I can obviously do more tests if it can help getting down to the issue :-).
Thanks !
Here is a simple output I get:
```
bash-232 [000] d..3. 947.629000: thread_noise: bash:232 start 947.629000000 duration 0 ns
timerlat/0-274 [000] ..... 947.629000: #51598 context thread timer_latency 409280 ns
bash-232 [000] d.h.. 947.630000: #51599 context irq timer_latency 110720 ns
bash-232 [000] dnh1. 947.630000: irq_noise: timer:206 start 947.629000000 duration 1000000 ns
bash-232 [000] d..3. 947.630000: thread_noise: bash:232 start 947.630000000 duration 0 ns
timerlat/0-274 [000] ..... 947.630000: #51599 context thread timer_latency 407168 ns
bash-232 [000] d.h.. 947.631000: #51600 context irq timer_latency 108608 ns
bash-232 [000] dnh1. 947.631000: irq_noise: timer:206 start 947.630000000 duration 1000000 ns
bash-232 [000] d..3. 947.631000: thread_noise: bash:232 start 947.631000000 duration 0 ns
timerlat/0-274 [000] ..... 947.631000: #51600 context thread timer_latency 401472 ns
```
I am very interested by any relevant test to do (switch events ?
Anything else ?) to improve the series (and the platform :-)).
I am quite sure I missed a *lot* of things, but it seems to do what I
need :-). I post it as RFC for now, in particular because I added a new
file, and I am not sure if it is the proper way.
Thanks for your remarks and improvements !
[1]: https://lore.kernel.org/linux-m68k/20241018124511.70d29198@xxxxxxxxxxxxxxxxxx
Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@xxxxxxxxxx>
---
Jean-Michel Hautbois (2):
m68k: Add tracirqs
arch: m68k: Add STACKTRACE support
arch/m68k/Kconfig | 6 ++++
arch/m68k/kernel/Makefile | 1 +
arch/m68k/kernel/irq.c | 2 ++
arch/m68k/kernel/stacktrace.c | 70 +++++++++++++++++++++++++++++++++++++++++++
4 files changed, 79 insertions(+)
---
base-commit: 42f7652d3eb527d03665b09edac47f85fb600924
change-id: 20241021-add-m68k-tracing-support-36c18d2233d8
Best regards,
