[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Message-ID: <70ee3b94-1589-4d41-b68f-1ef16b4f13c4@yoseli.org>
Date: Tue, 3 Dec 2024 07:25:55 +0100
From: Jean-Michel Hautbois <jeanmichel.hautbois@...eli.org>
To: Greg Ungerer <gerg@...ux-m68k.org>, linux-m68k@...ts.linux-m68k.org
Cc: linux-kernel@...r.kernel.org, linux-trace-kernel@...r.kernel.org,
rostedt@...dmis.org, Michael Schmitz <schmitzmic@...il.com>,
Geert Uytterhoeven <geert@...ux-m68k.org>
Subject: Re: [PATCH RFC 2/2] arch: m68k: Add STACKTRACE support
Hi Greg,
On 03/12/2024 00:01, Greg Ungerer wrote:
> Hi JM,
>
> On 3/12/24 00:52, Jean-Michel Hautbois wrote:
>> On 02/12/2024 15:41, Greg Ungerer wrote:
>>> On 27/11/24 21:26, Jean-Michel Hautbois wrote:
>>>> On 21/10/2024 11:44, Jean-Michel Hautbois wrote:
>>>>> In order to use tracing, implement a basic arch_stack_walk() based on
>>>>> the one in PowerPC.
>>>>> Tested on a M54418 coldfire.
>>>>
>>>> Well, I said it was tested, but it was only compile tested basically.
>>>> AFAICT now, I think it is not working as when I use wakeup_rt as a
>>>> tracer, I don't have the stack trace:
>>>>
>>>> # wakeup_rt latency trace v1.1.5 on 6.12.0-10380-gb66f06337b66-dirty
>>>> # --------------------------------------------------------------------
>>>> # latency: 2000 us, #18/18, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
>>>> # -----------------
>>>> # | task: irq/100-enet-fe-118 (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
>>>> # \ / |||||| \ | /
>>>> kworker/-11 0dnh5. 0us : 11:120:R + [000] 22:
>>>> 98:R irq_work/0
>>>> kworker/-11 0dnh5. 0us : <stack trace>
>>>> kworker/-11 0dnh5. 0us : 0
>>>> kworker/-11 0d..3. 0us : __schedule
>>>> kworker/-11 0d..3. 0us : 11:120:R ==> [000] 22:
>>>> 98:R irq_work/0
>>>> kworker/-11 0d..3. 0us : <stack trace>
>>>> telnetd-229 0Dnh4. 0us : 229:120:R + [000]
>>>> 118: 49:R irq/100-enet-fe
>>>> telnetd-229 0Dnh4. 0us : <stack trace>
>>>> telnetd-229 0Dnh4. 0us : 0
>>>> telnetd-229 0D..3. 0us : __schedule
>>>> telnetd-229 0D..3. 0us : 229:120:R ==> [000]
>>>> 118: 49:R irq/100-enet-fe
>>>> telnetd-229 0D..3. 0us : <stack trace>
>>>> telnetd-229 0dn.5. 0us : 229:120:R + [000]
>>>> 118: 49:R irq/100-enet-fe
>>>> telnetd-229 0dn.5. 0us : <stack trace>
>>>> telnetd-229 0dn.5. 0us#: 0
>>>> telnetd-229 0d..3. 2000us : __schedule
>>>> telnetd-229 0d..3. 2000us : 229:120:R ==> [000]
>>>> 118: 49:R irq/100-enet-fe
>>>> telnetd-229 0d..3. 2000us : <stack trace>
>>>>
>>>> Geert, Greg, and maybe other highly skilled m68k people, could you
>>>> please help me with this particular function :-) ?
>>>>
>>>> Thanks !
>>>> JM
>>>>
>>>>>
>>>>> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@...eli.org>
>>>>> ---
>>>>> arch/m68k/Kconfig | 5 ++++
>>>>> arch/m68k/kernel/Makefile | 1 +
>>>>> arch/m68k/kernel/stacktrace.c | 70 ++++++++++++++++++++++++++++++
>>>>> ++ +++++++++++
>>>>> 3 files changed, 76 insertions(+)
>>>>>
>>>>> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
>>>>> index
>>>>> ab3375475721fa63418c40d4ba6ac76679ebc77d..7142f9759181a90269ae1ba9e682d331ee2ddbf6 100644
>>>>> --- a/arch/m68k/Kconfig
>>>>> +++ b/arch/m68k/Kconfig
>>>>> @@ -40,6 +40,7 @@ config M68K
>>>>> select UACCESS_MEMCPY if !MMU
>>>>> select ZONE_DMA
>>>>> select TRACE_IRQFLAGS_SUPPORT
>>>>> + select ARCH_STACKWALK
>>>>> config CPU_BIG_ENDIAN
>>>>> def_bool y
>>>>> @@ -107,6 +108,10 @@ config BOOTINFO_PROC
>>>>> Say Y to export the bootinfo used to boot the kernel in a
>>>>> "bootinfo" file in procfs. This is useful with kexec.
>>>>> +config STACKTRACE_SUPPORT
>>>>> + bool
>>>>> + default y
>>>>> +
>>>>> menu "Platform setup"
>>>>> source "arch/m68k/Kconfig.cpu"
>>>>> diff --git a/arch/m68k/kernel/Makefile b/arch/m68k/kernel/Makefile
>>>>> index
>>>>> f335bf3268a108a45bab079fbf0a1c8ead9beb71..4efe92af0b711b19cb1d5129f74e67a739e289b1 100644
>>>>> --- a/arch/m68k/kernel/Makefile
>>>>> +++ b/arch/m68k/kernel/Makefile
>>>>> @@ -31,3 +31,4 @@ obj-$(CONFIG_UBOOT) += uboot.o
>>>>> obj-$(CONFIG_EARLY_PRINTK) += early_printk.o
>>>>> +obj-y += stacktrace.o
>>>>> diff --git a/arch/m68k/kernel/stacktrace.c b/arch/m68k/kernel/
>>>>> stacktrace.c
>>>>> new file mode 100644
>>>>> index
>>>>> 0000000000000000000000000000000000000000..06c7459373bd25b3bb3540cfe2a909259c1db3ce
>>>>> --- /dev/null
>>>>> +++ b/arch/m68k/kernel/stacktrace.c
>>>>> @@ -0,0 +1,70 @@
>>>>> +// SPDX-License-Identifier: GPL-2.0
>>>>> +
>>>>> +/*
>>>>> + * Stack trace utility functions etc.
>>>>> + *
>>>>> + * Copyright 2024 Jean-Michel Hautbois, Yoseli SAS.
>>>>> + */
>>>>> +
>>>>> +#include <asm/current.h>
>>>>> +#include <asm/ptrace.h>
>>>>> +#include <linux/sched.h>
>>>>> +#include <linux/sched/task_stack.h>
>>>>> +#include <linux/stacktrace.h>
>>>>> +
>>>>> +static inline unsigned long current_stack_frame(void)
>>>>> +{
>>>>> + unsigned long sp;
>>>>> +
>>>>> + asm volatile("movl %%sp, %0" : "=r"(sp));
>>>>> + return sp;
>>>>> +}
>>>
>>> If I am understanding what this is intended to do then this is
>>> probably not right.
>>> This will be returning the current stack pointer, which will almost
>>> certainly not
>>> be the current stack frame pointer. This will be the top of stack at
>>> the call site,
>>> which will be after the pushed locals and saved registers at the very
>>> least for m68k.
>>>
>>> Does your kernel config have CONFIG_FRAME_POINTER enabled?
>>> The default for m68k is usually disabled. Without this there won't be a
>>> chain of frame pointers to follow like the code is trying to do below in
>>> arch_stack_walk().
>>
>> Sorry for my preceding mail, it *is* better:
>> # tail -10 trace
>> # |||| / _-=> migrate-disable
>> # ||||| / delay
>> # cmd pid |||||| time | caller
>> # \ / |||||| \ | /
>> <idle>-0 0dnh5. 11us+: 0:120:R + [000] 119:
>> 49:R irq/104-enet-fe
>> <idle>-0 0dnh5. 42us+: <stack trace>
>> <idle>-0 0dnh5. 57us!: wake_up_process <-
>> __handle_irq_event_percpu
>> <idle>-0 0d..3. 282us+: __schedule <-schedule_idle
>> <idle>-0 0d..3. 302us+: 0:120:R ==> [000] 119:
>> 49:R irq/104-enet-fe
>> <idle>-0 0d..3. 325us : <stack trace>
>
> Oh, yeah, there is more required.
>
> The current_stack_frame() function needs to change to actually return
> with the start of the frame pointer chain. You need it to look like this:
>
>
> static inline unsigned long current_stack_frame(void)
> {
> unsigned long sp;
>
> asm volatile("movl %%fp, %0" : "=r"(sp));
> return sp;
> }
>
>
> Note that it is returning the "%fp" register - the current frame pointer.
Oh, thank you for this !
It is now really helpful !
# cd /sys/kernel/debug/tracing/
# echo wakeup_rt > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# chrt -f 5 sleep 1
# echo 0 > tracing_on
# cat trace
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 6.13.0-rc1-00093-g2b74d5f38b38-dirty
# --------------------------------------------------------------------
# latency: 405 us, #6/6, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
# -----------------
# | task: irq/100-enet-fe-118 (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-229 0Dnh4. 13us+: 229:120:R + [000] 118:
49:R irq/100-enet-fe
telnetd-229 0Dnh4. 53us+: <stack trace>
=> __trace_stack
=> probe_wakeup
=> try_to_wake_up
=> wake_up_process
=> __handle_irq_event_percpu
=> handle_irq_event
=> handle_level_irq
=> generic_handle_irq
=> do_IRQ
=> inthandler
=> ip_finish_output2
=> __ip_finish_output
=> ip_output
=> __ip_queue_xmit
=> ip_queue_xmit
=> __tcp_transmit_skb
=> tcp_write_xmit
=> __tcp_push_pending_frames
=> tcp_push
=> tcp_sendmsg_locked
=> tcp_sendmsg
=> inet_sendmsg
=> sock_write_iter
=> vfs_write
=> ksys_write
=> sys_write
=> system_call
telnetd-229 0Dnh4. 68us!: wake_up_process
<-__handle_irq_event_percpu
telnetd-229 0D..3. 348us+: __schedule <-preempt_schedule_irq
telnetd-229 0D..3. 368us+: 229:120:R ==> [000] 118:
49:R irq/100-enet-fe
telnetd-229 0D..3. 395us : <stack trace>
=> __trace_stack
=> probe_wakeup_sched_switch
=> __schedule
=> preempt_schedule_irq
=> Lkernel_return
=> ip_finish_output2
=> __ip_finish_output
=> ip_output
=> __ip_queue_xmit
=> ip_queue_xmit
=> __tcp_transmit_skb
=> tcp_write_xmit
=> __tcp_push_pending_frames
=> tcp_push
=> tcp_sendmsg_locked
=> tcp_sendmsg
=> inet_sendmsg
=> sock_write_iter
=> vfs_write
=> ksys_write
=> sys_write
=> system_call
I will use it and see if I can have more informations but, this makes
ftrace working nicely now, and I will submit a real patch now !
Thanks,
JM
Powered by blists - more mailing lists