linux-kernel - Re: [PATCH RFC 0/2] Add basic tracing support for m68k

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <3a8f6faa-62c6-4d32-b544-3fb7c00730d7@yoseli.org>
Date: Fri, 15 Nov 2024 09:26:07 +0100
From: Jean-Michel Hautbois <jeanmichel.hautbois@...eli.org>
To: linux-m68k@...ts.linux-m68k.org
Cc: linux-kernel@...r.kernel.org, linux-trace-kernel@...r.kernel.org,
 rostedt@...dmis.org, Geert Uytterhoeven <geert@...ux-m68k.org>,
 Greg Ungerer <gerg@...ux-m68k.org>
Subject: Re: [PATCH RFC 0/2] Add basic tracing support for m68k

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@gandalf.local.home
> 
> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@...eli.org>
> ---
> 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,