[PATCH RFC 0/2] Add basic tracing support for m68k

[PATCH RFC 0/2] Add basic tracing support for m68k

[Jean-Michel Hautbois]

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.

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@yoseli.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,
-- 
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>

[PATCH RFC 1/2] m68k: Add tracirqs

[Jean-Michel Hautbois]

The TRACE_IRQFLAGS_SUPPORT requires the architecture to call
trace_hardirqs_off() when interrupts are disabled and
trace_hardirqs_on() when they are enabled.
Add those calls to do_IRQ function.

Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>
---
 arch/m68k/Kconfig      | 1 +
 arch/m68k/kernel/irq.c | 2 ++
 2 files changed, 3 insertions(+)

diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
index cc26df907bfe3c8143a931d259eceabb16af7411..ab3375475721fa63418c40d4ba6ac76679ebc77d 100644
--- a/arch/m68k/Kconfig
+++ b/arch/m68k/Kconfig
@@ -39,6 +39,7 @@ config M68K
 	select OLD_SIGSUSPEND3
 	select UACCESS_MEMCPY if !MMU
 	select ZONE_DMA
+	select TRACE_IRQFLAGS_SUPPORT
 
 config CPU_BIG_ENDIAN
 	def_bool y
diff --git a/arch/m68k/kernel/irq.c b/arch/m68k/kernel/irq.c
index 9ab4f550342e5de11c528f55781432675ffd66bf..74cf60ebbc4bca51f3caa4046dbd2bdb02355711 100644
--- a/arch/m68k/kernel/irq.c
+++ b/arch/m68k/kernel/irq.c
@@ -21,9 +21,11 @@ asmlinkage void do_IRQ(int irq, struct pt_regs *regs)
 {
 	struct pt_regs *oldregs = set_irq_regs(regs);
 
+	trace_hardirqs_off();
 	irq_enter();
 	generic_handle_irq(irq);
 	irq_exit();
+	trace_hardirqs_on();
 
 	set_irq_regs(oldregs);
 }

-- 
2.39.5

[PATCH RFC 2/2] arch: m68k: Add STACKTRACE support

[Jean-Michel Hautbois]

In order to use tracing, implement a basic arch_stack_walk() based on
the one in PowerPC.
Tested on a M54418 coldfire.

Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.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;
+}
+
+static inline int validate_sp(unsigned long sp, struct task_struct *task)
+{
+	unsigned long stack_start, stack_end;
+
+	if (task == current)
+		stack_start = (unsigned long)task_stack_page(task);
+	else
+		stack_start = (unsigned long)task->thread.esp0;
+
+	stack_end = stack_start + THREAD_SIZE;
+
+	if (sp < stack_start || sp >= stack_end)
+		return 0;
+
+	return 1;
+}
+
+void __no_sanitize_address arch_stack_walk(stack_trace_consume_fn consume_entry, void *cookie,
+					   struct task_struct *task, struct pt_regs *regs)
+{
+	unsigned long sp;
+
+	if (regs && !consume_entry(cookie, regs->pc))
+		return;
+
+	if (regs)
+		sp = (unsigned long) regs;
+	else if (task == current)
+		sp = current_stack_frame();
+	else
+		sp = task->thread.ksp;
+
+	for (;;) {
+		unsigned long *stack = (unsigned long *) sp;
+		unsigned long newsp, ip;
+
+		if (!validate_sp(sp, task))
+			return;
+
+		newsp = stack[0];
+		ip = stack[1];
+
+		if (!consume_entry(cookie, ip))
+			return;
+
+		sp = newsp;
+	}
+}

-- 
2.39.5

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Steven Rostedt]

On Mon, 21 Oct 2024 11:44:42 +0200
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:

> The TRACE_IRQFLAGS_SUPPORT requires the architecture to call
> trace_hardirqs_off() when interrupts are disabled and
> trace_hardirqs_on() when they are enabled.
> Add those calls to do_IRQ function.
> 
> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>
> ---
>  arch/m68k/Kconfig      | 1 +
>  arch/m68k/kernel/irq.c | 2 ++
>  2 files changed, 3 insertions(+)
> 
> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
> index cc26df907bfe3c8143a931d259eceabb16af7411..ab3375475721fa63418c40d4ba6ac76679ebc77d 100644
> --- a/arch/m68k/Kconfig
> +++ b/arch/m68k/Kconfig
> @@ -39,6 +39,7 @@ config M68K
>  	select OLD_SIGSUSPEND3
>  	select UACCESS_MEMCPY if !MMU
>  	select ZONE_DMA
> +	select TRACE_IRQFLAGS_SUPPORT
>  
>  config CPU_BIG_ENDIAN
>  	def_bool y
> diff --git a/arch/m68k/kernel/irq.c b/arch/m68k/kernel/irq.c
> index 9ab4f550342e5de11c528f55781432675ffd66bf..74cf60ebbc4bca51f3caa4046dbd2bdb02355711 100644
> --- a/arch/m68k/kernel/irq.c
> +++ b/arch/m68k/kernel/irq.c
> @@ -21,9 +21,11 @@ asmlinkage void do_IRQ(int irq, struct pt_regs *regs)
>  {
>  	struct pt_regs *oldregs = set_irq_regs(regs);
>  
> +	trace_hardirqs_off();
>  	irq_enter();
>  	generic_handle_irq(irq);
>  	irq_exit();
> +	trace_hardirqs_on();

This part of the patch shouldn't be needed because those shoudl be
called by irq_enter() and irq_exit(). Does this not work if you don't
have these?

-- Steve




>  
>  	set_irq_regs(oldregs);
>  }
> 

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Jean-Michel Hautbois]

Hi Steve,

On 22/10/2024 07:28, Steven Rostedt wrote:
> On Mon, 21 Oct 2024 11:44:42 +0200
> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> 
>> The TRACE_IRQFLAGS_SUPPORT requires the architecture to call
>> trace_hardirqs_off() when interrupts are disabled and
>> trace_hardirqs_on() when they are enabled.
>> Add those calls to do_IRQ function.
>>
>> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>
>> ---
>>   arch/m68k/Kconfig      | 1 +
>>   arch/m68k/kernel/irq.c | 2 ++
>>   2 files changed, 3 insertions(+)
>>
>> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
>> index cc26df907bfe3c8143a931d259eceabb16af7411..ab3375475721fa63418c40d4ba6ac76679ebc77d 100644
>> --- a/arch/m68k/Kconfig
>> +++ b/arch/m68k/Kconfig
>> @@ -39,6 +39,7 @@ config M68K
>>   	select OLD_SIGSUSPEND3
>>   	select UACCESS_MEMCPY if !MMU
>>   	select ZONE_DMA
>> +	select TRACE_IRQFLAGS_SUPPORT
>>   
>>   config CPU_BIG_ENDIAN
>>   	def_bool y
>> diff --git a/arch/m68k/kernel/irq.c b/arch/m68k/kernel/irq.c
>> index 9ab4f550342e5de11c528f55781432675ffd66bf..74cf60ebbc4bca51f3caa4046dbd2bdb02355711 100644
>> --- a/arch/m68k/kernel/irq.c
>> +++ b/arch/m68k/kernel/irq.c
>> @@ -21,9 +21,11 @@ asmlinkage void do_IRQ(int irq, struct pt_regs *regs)
>>   {
>>   	struct pt_regs *oldregs = set_irq_regs(regs);
>>   
>> +	trace_hardirqs_off();
>>   	irq_enter();
>>   	generic_handle_irq(irq);
>>   	irq_exit();
>> +	trace_hardirqs_on();
> 
> This part of the patch shouldn't be needed because those shoudl be
> called by irq_enter() and irq_exit(). Does this not work if you don't
> have these?

Thanks for your quick review !
Indeed, it works without those lines, so the patch is now a one-liner 
:-). I will wait for the second part to be reviewed before sending v2.

JM

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Steven Rostedt]

On Tue, 22 Oct 2024 07:42:10 +0200
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:

> > This part of the patch shouldn't be needed because those shoudl be
> > called by irq_enter() and irq_exit(). Does this not work if you don't
> > have these?  
> 
> Thanks for your quick review !

\o/

> Indeed, it works without those lines, so the patch is now a one-liner 
> :-). I will wait for the second part to be reviewed before sending v2.

I don't know enough about m68k to review that patch. Just incase you
were expecting me to review it.

-- Steve

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Jean-Michel Hautbois]

Hi Steve,

On 10/22/24 10:30, Steven Rostedt wrote:
> On Tue, 22 Oct 2024 07:42:10 +0200
> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> 
>>> This part of the patch shouldn't be needed because those shoudl be
>>> called by irq_enter() and irq_exit(). Does this not work if you don't
>>> have these?
>>
>> Thanks for your quick review !
> 
> \o/
> 
>> Indeed, it works without those lines, so the patch is now a one-liner
>> :-). I will wait for the second part to be reviewed before sending v2.
> 
> I don't know enough about m68k to review that patch. Just incase you
> were expecting me to review it.

I was not really expecting you to review the m68k one no :-).
I think I have other issues which might have impact on ftrace too.
For instance, when I launch cyclictest I have a warning about HRTIMERS:
# cyclictest -p 99
WARN: stat /dev/cpu_dma_latency failed: No such file or directory
WARN: High resolution timers not available
policy: fifo: loadavg: 1.21 0.40 0.14 1/122 245

T: 0 (  245) P:99 I:1000 C:  11203 Min:     92 Act:  623 Avg:  775 Max: 
   3516

The latencies are quite high...

But regarding ftrace it seems that the trace is not able to give me more 
than a microsecond precision. I addded a few trace_printk() in a driver 
of mine and I get:
  irq/182-dspi-sl-112     [000] D....   277.160000: dspi_interrupt: 
Received 2 bytes
  irq/182-dspi-sl-112     [000] D....   277.160000: dspi_interrupt: 
Received 2 bytes
  irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt: 
dspi_interrupt
  irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt: TX 
FIFO overflow
  irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt: 
Restart FIFO

Do you have any clue ?

Thanks !
JM

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Michael Schmitz]

Jean-Michel,

thanks for your patches!

Am 21.10.2024 um 22:44 schrieb Jean-Michel Hautbois:
> The TRACE_IRQFLAGS_SUPPORT requires the architecture to call
> trace_hardirqs_off() when interrupts are disabled and
> trace_hardirqs_on() when they are enabled.
> Add those calls to do_IRQ function.

You will also have to add these calls to the three sites in 
arch/m68k/coldfire/head.S where interrupts are enabled or disabled.

Here:
> ENTRY(system_call)
>         SAVE_ALL_SYS
>         move    #0x2000,%sr             /* enable intrs again */
>         GET_CURRENT(%d2)

and here:
> ret_from_exception:
>         move    #0x2700,%sr             /* disable intrs */
>         btst    #5,%sp@(PT_OFF_SR)      /* check if returning to kernel */
>         jeq     Luser_return            /* if so, skip resched, signals */

and here:
> Lwork_to_do:
>         movel   %a0@(TINFO_FLAGS),%d1   /* get thread_info->flags */
>         move    #0x2000,%sr             /* enable intrs again */
>         btst    #TIF_NEED_RESCHED,%d1
>         jne     reschedule

There's one similar site in arch/m68k/kernel/head.S (ret_from_exception) 
where interrupts are enabled that would need a similar change, if you 
want to enable this for all m68k.

Registers %d0-%d5 and %a0-%a2 are saved on the stack at this point and 
can be clobbered if need be.

Cheers,

	Michael


>
> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>
> ---
>  arch/m68k/Kconfig      | 1 +
>  arch/m68k/kernel/irq.c | 2 ++
>  2 files changed, 3 insertions(+)
>
> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
> index cc26df907bfe3c8143a931d259eceabb16af7411..ab3375475721fa63418c40d4ba6ac76679ebc77d 100644
> --- a/arch/m68k/Kconfig
> +++ b/arch/m68k/Kconfig
> @@ -39,6 +39,7 @@ config M68K
>  	select OLD_SIGSUSPEND3
>  	select UACCESS_MEMCPY if !MMU
>  	select ZONE_DMA
> +	select TRACE_IRQFLAGS_SUPPORT
>
>  config CPU_BIG_ENDIAN
>  	def_bool y
> diff --git a/arch/m68k/kernel/irq.c b/arch/m68k/kernel/irq.c
> index 9ab4f550342e5de11c528f55781432675ffd66bf..74cf60ebbc4bca51f3caa4046dbd2bdb02355711 100644
> --- a/arch/m68k/kernel/irq.c
> +++ b/arch/m68k/kernel/irq.c
> @@ -21,9 +21,11 @@ asmlinkage void do_IRQ(int irq, struct pt_regs *regs)
>  {
>  	struct pt_regs *oldregs = set_irq_regs(regs);
>
> +	trace_hardirqs_off();
>  	irq_enter();
>  	generic_handle_irq(irq);
>  	irq_exit();
> +	trace_hardirqs_on();
>
>  	set_irq_regs(oldregs);
>  }
>

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Jean-Michel Hautbois]

Hi Michael,

On 23/10/2024 05:53, Michael Schmitz wrote:
> Jean-Michel,
> 
> thanks for your patches!
> 
> Am 21.10.2024 um 22:44 schrieb Jean-Michel Hautbois:
>> The TRACE_IRQFLAGS_SUPPORT requires the architecture to call
>> trace_hardirqs_off() when interrupts are disabled and
>> trace_hardirqs_on() when they are enabled.
>> Add those calls to do_IRQ function.
> 
> You will also have to add these calls to the three sites in arch/m68k/ 
> coldfire/head.S where interrupts are enabled or disabled.

Thanks for this ! I prepared a v2 with those calls added. I am wondering 
if my second patch is ok, I think it is not, could you please review it 
? There may already be something related to the stack in the assembly 
part useful to implement arch_stack_walk() in a different way ?
> 
> Here:
>> ENTRY(system_call)
>>         SAVE_ALL_SYS
>>         move    #0x2000,%sr             /* enable intrs again */
>>         GET_CURRENT(%d2)
> 
> and here:
>> ret_from_exception:
>>         move    #0x2700,%sr             /* disable intrs */
>>         btst    #5,%sp@(PT_OFF_SR)      /* check if returning to 
>> kernel */
>>         jeq     Luser_return            /* if so, skip resched, 
>> signals */
> 
> and here:
>> Lwork_to_do:
>>         movel   %a0@(TINFO_FLAGS),%d1   /* get thread_info->flags */
>>         move    #0x2000,%sr             /* enable intrs again */
>>         btst    #TIF_NEED_RESCHED,%d1
>>         jne     reschedule
> 
> There's one similar site in arch/m68k/kernel/head.S (ret_from_exception) 
> where interrupts are enabled that would need a similar change, if you 
> want to enable this for all m68k.

I won't be able to test it though ;-).
I see there are a few interrupts disabling in 
arch/m68k/include/asm/entry.h too ?

> 
> Registers %d0-%d5 and %a0-%a2 are saved on the stack at this point and 
> can be clobbered if need be.

I don't know if they need to be clobbered...

Thanks,
JM

> 
> Cheers,
> 
>      Michael
> 
> 
>>
>> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>
>> ---
>>  arch/m68k/Kconfig      | 1 +
>>  arch/m68k/kernel/irq.c | 2 ++
>>  2 files changed, 3 insertions(+)
>>
>> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
>> index 
>> cc26df907bfe3c8143a931d259eceabb16af7411..ab3375475721fa63418c40d4ba6ac76679ebc77d 100644
>> --- a/arch/m68k/Kconfig
>> +++ b/arch/m68k/Kconfig
>> @@ -39,6 +39,7 @@ config M68K
>>      select OLD_SIGSUSPEND3
>>      select UACCESS_MEMCPY if !MMU
>>      select ZONE_DMA
>> +    select TRACE_IRQFLAGS_SUPPORT
>>
>>  config CPU_BIG_ENDIAN
>>      def_bool y
>> diff --git a/arch/m68k/kernel/irq.c b/arch/m68k/kernel/irq.c
>> index 
>> 9ab4f550342e5de11c528f55781432675ffd66bf..74cf60ebbc4bca51f3caa4046dbd2bdb02355711 100644
>> --- a/arch/m68k/kernel/irq.c
>> +++ b/arch/m68k/kernel/irq.c
>> @@ -21,9 +21,11 @@ asmlinkage void do_IRQ(int irq, struct pt_regs *regs)
>>  {
>>      struct pt_regs *oldregs = set_irq_regs(regs);
>>
>> +    trace_hardirqs_off();
>>      irq_enter();
>>      generic_handle_irq(irq);
>>      irq_exit();
>> +    trace_hardirqs_on();
>>
>>      set_irq_regs(oldregs);
>>  }
>>

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Michael Schmitz]

Hi Jean-Michel,

Am 23.10.2024 um 18:53 schrieb Jean-Michel Hautbois:
> Hi Michael,
>
> On 23/10/2024 05:53, Michael Schmitz wrote:
>> Jean-Michel,
>>
>> thanks for your patches!
>>
>> Am 21.10.2024 um 22:44 schrieb Jean-Michel Hautbois:
>>> The TRACE_IRQFLAGS_SUPPORT requires the architecture to call
>>> trace_hardirqs_off() when interrupts are disabled and
>>> trace_hardirqs_on() when they are enabled.
>>> Add those calls to do_IRQ function.
>>
>> You will also have to add these calls to the three sites in arch/m68k/
>> coldfire/head.S where interrupts are enabled or disabled.
>
> Thanks for this ! I prepared a v2 with those calls added. I am wondering

Good -

> if my second patch is ok, I think it is not, could you please review it

I'll have to read up on how arch_stack_walk is supposed to work - have 
never seen that code before.

> ? There may already be something related to the stack in the assembly
> part useful to implement arch_stack_walk() in a different way ?

I doubt it

>>
>> Here:
>>> ENTRY(system_call)
>>>         SAVE_ALL_SYS
>>>         move    #0x2000,%sr             /* enable intrs again */
>>>         GET_CURRENT(%d2)
>>
>> and here:
>>> ret_from_exception:
>>>         move    #0x2700,%sr             /* disable intrs */
>>>         btst    #5,%sp@(PT_OFF_SR)      /* check if returning to
>>> kernel */
>>>         jeq     Luser_return            /* if so, skip resched,
>>> signals */
>>
>> and here:
>>> Lwork_to_do:
>>>         movel   %a0@(TINFO_FLAGS),%d1   /* get thread_info->flags */
>>>         move    #0x2000,%sr             /* enable intrs again */
>>>         btst    #TIF_NEED_RESCHED,%d1
>>>         jne     reschedule
>>
>> There's one similar site in arch/m68k/kernel/head.S
>> (ret_from_exception) where interrupts are enabled that would need a
>> similar change, if you want to enable this for all m68k.
>
> I won't be able to test it though ;-).
> I see there are a few interrupts disabling in
> arch/m68k/include/asm/entry.h too ?

Right - that's different in the coldfire stack save/restore macros. I 
missed that before.

Looks like wherever SAVE_ALL_SYS, SAVE_ALL_INT and RESTORE_USER are 
used, calls to trace_irqs_on/off() are required as well.

RESTORE_USER only restores the IPL in the CONFIG_COLDFIRE_SW_A7, which 
makes this a little tricky ... you might have to add these calls to the 
macros to get the correct behaviour.

>
>>
>> Registers %d0-%d5 and %a0-%a2 are saved on the stack at this point and
>> can be clobbered if need be.
>
> I don't know if they need to be clobbered...

I meant to say that if you need registers to prepare function arguments 
for trace_irqs_on/off() on the stack, these can be used. But that may 
not be necessary in this case.

Cheers,

	Michael


>
> Thanks,
> JM
>
>>
>> Cheers,
>>
>>      Michael
>>
>>
>>>
>>> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>
>>> ---
>>>  arch/m68k/Kconfig      | 1 +
>>>  arch/m68k/kernel/irq.c | 2 ++
>>>  2 files changed, 3 insertions(+)
>>>
>>> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
>>> index
>>> cc26df907bfe3c8143a931d259eceabb16af7411..ab3375475721fa63418c40d4ba6ac76679ebc77d
>>> 100644
>>> --- a/arch/m68k/Kconfig
>>> +++ b/arch/m68k/Kconfig
>>> @@ -39,6 +39,7 @@ config M68K
>>>      select OLD_SIGSUSPEND3
>>>      select UACCESS_MEMCPY if !MMU
>>>      select ZONE_DMA
>>> +    select TRACE_IRQFLAGS_SUPPORT
>>>
>>>  config CPU_BIG_ENDIAN
>>>      def_bool y
>>> diff --git a/arch/m68k/kernel/irq.c b/arch/m68k/kernel/irq.c
>>> index
>>> 9ab4f550342e5de11c528f55781432675ffd66bf..74cf60ebbc4bca51f3caa4046dbd2bdb02355711
>>> 100644
>>> --- a/arch/m68k/kernel/irq.c
>>> +++ b/arch/m68k/kernel/irq.c
>>> @@ -21,9 +21,11 @@ asmlinkage void do_IRQ(int irq, struct pt_regs *regs)
>>>  {
>>>      struct pt_regs *oldregs = set_irq_regs(regs);
>>>
>>> +    trace_hardirqs_off();
>>>      irq_enter();
>>>      generic_handle_irq(irq);
>>>      irq_exit();
>>> +    trace_hardirqs_on();
>>>
>>>      set_irq_regs(oldregs);
>>>  }
>>>
>

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Steven Rostedt]

On Tue, 22 Oct 2024 11:21:34 +0200
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:

> 
> I was not really expecting you to review the m68k one no :-).
> I think I have other issues which might have impact on ftrace too.
> For instance, when I launch cyclictest I have a warning about HRTIMERS:
> # cyclictest -p 99
> WARN: stat /dev/cpu_dma_latency failed: No such file or directory
> WARN: High resolution timers not available
> policy: fifo: loadavg: 1.21 0.40 0.14 1/122 245
> 
> T: 0 (  245) P:99 I:1000 C:  11203 Min:     92 Act:  623 Avg:  775 Max: 
>    3516
> 
> The latencies are quite high...

Yes, if you don't have high resolution timers, the latency will be high.

> 
> But regarding ftrace it seems that the trace is not able to give me more 
> than a microsecond precision. I addded a few trace_printk() in a driver 
> of mine and I get:
>   irq/182-dspi-sl-112     [000] D....   277.160000: dspi_interrupt: 
> Received 2 bytes
>   irq/182-dspi-sl-112     [000] D....   277.160000: dspi_interrupt: 
> Received 2 bytes
>   irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt: 
> dspi_interrupt
>   irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt: TX 
> FIFO overflow
>   irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt: 
> Restart FIFO
> 
> Do you have any clue ?

Yes. The ring buffer clock is dependent on the architecture's clock. By
default, it uses whatever the scheduler clock uses. If the scheduler
clock is 1ms resolution, so will the tracing data be.

-- Steve

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Eero Tamminen]

Hi,

On 23.10.2024 8.53, Jean-Michel Hautbois wrote:
...
>> There's one similar site in arch/m68k/kernel/head.S 
>> (ret_from_exception) where interrupts are enabled that would need a 
>> similar change, if you want to enable this for all m68k.
> 
> I won't be able to test it though ;-).
> I see there are a few interrupts disabling in 
> arch/m68k/include/asm/entry.h too ?

I would suggest using Hatari for testing it, as that emulates real HW 
more accurately than Aranym, and provides better debugging & profiling 
utilities than either Aranym or real HW [1], especially for kernel side.

(Because ColdFire is close to m68k, Hatari can help in debugging also 
issues that are in Linux code they share.)

Here are detailed and IMHO easy instructions on how to do that:
https://hatari.tuxfamily.org/doc/m68k-linux.txt


I'd recommend using Git HEAD of Hatari [2] for testing though, because 
there was a recent fix to handling prefetch during bus errors, when 030 
MMU is enabled, and without that fix, prefetch + cache emulation would 
need to to be disabled for user-space to work correctly.  If you disable 
those (--compatible off --cycle-exact off), you can start with Hatari 
version from Linux distros though...

(You can mail me directly if you have problems with Hatari.  Getting 
ftrace working on m68k would be interesting.)


	- Eero

[1] https://hatari.tuxfamily.org/doc/debugger.html
[2] Upstream: https://git.tuxfamily.org/hatari/hatari.git/
     or mirror: https://github.com/hatari/hatari/

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Jean-Michel Hautbois]

Hi Michael,

On 23/10/2024 09:30, Michael Schmitz wrote:
> Hi Jean-Michel,
> 
> Am 23.10.2024 um 18:53 schrieb Jean-Michel Hautbois:
>> Hi Michael,
>>
>> On 23/10/2024 05:53, Michael Schmitz wrote:
>>> Jean-Michel,
>>>
>>> thanks for your patches!
>>>
>>> Am 21.10.2024 um 22:44 schrieb Jean-Michel Hautbois:
>>>> The TRACE_IRQFLAGS_SUPPORT requires the architecture to call
>>>> trace_hardirqs_off() when interrupts are disabled and
>>>> trace_hardirqs_on() when they are enabled.
>>>> Add those calls to do_IRQ function.
>>>
>>> You will also have to add these calls to the three sites in arch/m68k/
>>> coldfire/head.S where interrupts are enabled or disabled.
>>
>> Thanks for this ! I prepared a v2 with those calls added. I am wondering
> 
> Good -
> 
>> if my second patch is ok, I think it is not, could you please review it
> 
> I'll have to read up on how arch_stack_walk is supposed to work - have 
> never seen that code before.
> 
>> ? There may already be something related to the stack in the assembly
>> part useful to implement arch_stack_walk() in a different way ?
> 
> I doubt it
> 
>>>
>>> Here:
>>>> ENTRY(system_call)
>>>>         SAVE_ALL_SYS
>>>>         move    #0x2000,%sr             /* enable intrs again */
>>>>         GET_CURRENT(%d2)
>>>
>>> and here:
>>>> ret_from_exception:
>>>>         move    #0x2700,%sr             /* disable intrs */
>>>>         btst    #5,%sp@(PT_OFF_SR)      /* check if returning to
>>>> kernel */
>>>>         jeq     Luser_return            /* if so, skip resched,
>>>> signals */
>>>
>>> and here:
>>>> Lwork_to_do:
>>>>         movel   %a0@(TINFO_FLAGS),%d1   /* get thread_info->flags */
>>>>         move    #0x2000,%sr             /* enable intrs again */
>>>>         btst    #TIF_NEED_RESCHED,%d1
>>>>         jne     reschedule
>>>
>>> There's one similar site in arch/m68k/kernel/head.S
>>> (ret_from_exception) where interrupts are enabled that would need a
>>> similar change, if you want to enable this for all m68k.
>>
>> I won't be able to test it though ;-).
>> I see there are a few interrupts disabling in
>> arch/m68k/include/asm/entry.h too ?
> 
> Right - that's different in the coldfire stack save/restore macros. I 
> missed that before.
> 
> Looks like wherever SAVE_ALL_SYS, SAVE_ALL_INT and RESTORE_USER are 
> used, calls to trace_irqs_on/off() are required as well.
> 
> RESTORE_USER only restores the IPL in the CONFIG_COLDFIRE_SW_A7, which 
> makes this a little tricky ... you might have to add these calls to the 
> macros to get the correct behaviour.
> 

Sadly, not that straightforward.
I have this patch right now:
diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
index b2a3093af677..fc4a2d124514 100644
--- a/arch/m68k/Kconfig
+++ b/arch/m68k/Kconfig
@@ -41,6 +41,7 @@ config M68K
         select ZONE_DMA
         select ARCH_SUPPORTS_RT
         select IRQ_FORCED_THREADING
+       select TRACE_IRQFLAGS_SUPPORT

  config CPU_BIG_ENDIAN
         def_bool y
diff --git a/arch/m68k/coldfire/entry.S b/arch/m68k/coldfire/entry.S
index 4ea08336e2fb..fbdc4404f29e 100644
--- a/arch/m68k/coldfire/entry.S
+++ b/arch/m68k/coldfire/entry.S
@@ -57,6 +57,9 @@ enosys:
  ENTRY(system_call)
         SAVE_ALL_SYS
         move    #0x2000,%sr             /* enable intrs again */
+#ifdef CONFIG_TRACE_IRQFLAGS
+       jbsr    trace_hardirqs_on
+#endif
         GET_CURRENT(%d2)

         cmpl    #NR_syscalls,%d0
@@ -99,6 +102,9 @@ ENTRY(system_call)
         addql   #4,%sp

  ret_from_exception:
+#ifdef CONFIG_TRACE_IRQFLAGS
+       jbsr    trace_hardirqs_off
+#endif
         move    #0x2700,%sr             /* disable intrs */
         btst    #5,%sp@(PT_OFF_SR)      /* check if returning to kernel */
         jeq     Luser_return            /* if so, skip resched, signals */
@@ -140,6 +146,9 @@ Lreturn:
  Lwork_to_do:
         movel   %a0@(TINFO_FLAGS),%d1   /* get thread_info->flags */
         move    #0x2000,%sr             /* enable intrs again */
+#ifdef CONFIG_TRACE_IRQFLAGS
+       jbsr    trace_hardirqs_on
+#endif
         btst    #TIF_NEED_RESCHED,%d1
         jne     reschedule

But it fails when init is called:
[    5.313000] Run /bin/bash as init process
[    5.314000]   with arguments:
[    5.315000]     /bin/bash
[    5.316000]   with environment:
[    5.317000]     HOME=/
[    5.318000]     TERM=linux
[    5.684000] Kernel panic - not syncing: Attempted to kill init! 
exitcode=0x0000000b
[    5.684000] CPU: 0 UID: 0 PID: 1 Comm: bash Not tainted 
6.12.0-rc4-00049-g4393ca34ead3 #364
[    5.684000] Stack from 41a03e18:
[    5.684000]         41a03e18 41540187 41540187 0000000a ffffffff 
415a8fb4 4140dd90 41416588
[    5.684000]         41540187 4140d5de 4102ba84 4100b19c 4100b1a8 
00000000 41a38000 4102ba3a
[    5.684000]         41a03ea0 4100c34a 4150e87e 0000000b 0000000b 
41a03f80 0000000a 41a3c0d4
[    5.684000]         41a02000 400004d8 41a08000 4102ba3a 4102ba84 
00000000 00000000 000000ff
[    5.684000]         00000000 00000000 41a03ef4 4100cb82 0000000b 
0000000b 41a03f80 41a03f6c
[    5.684000]         41016cd2 0000000b 41a03f6c 0000001d 00000026 
0000048c ffffffff 00000006
[    5.684000] Call Trace: [<4140dd90>] _printk+0x0/0x18
[    5.684000]  [<41416588>] dump_stack+0xc/0x10
[    5.684000]  [<4140d5de>] panic+0xf2/0x2d4
[    5.684000]  [<4102ba84>] preempt_count_sub+0x0/0x2e
[    5.684000]  [<4100b19c>] arch_local_irq_enable+0x0/0xc
[    5.684000]  [<4100b1a8>] arch_irqs_disabled+0x0/0x10
[    5.684000]  [<4102ba3a>] preempt_count_add+0x0/0x1e
[    5.684000]  [<4100c34a>] do_exit+0x266/0x930
[    5.684000]  [<4102ba3a>] preempt_count_add+0x0/0x1e
[    5.684000]  [<4102ba84>] preempt_count_sub+0x0/0x2e
[    5.684000]  [<4100cb82>] do_group_exit+0x26/0xba
[    5.684000]  [<41016cd2>] get_signal+0x60e/0x76c
[    5.684000]  [<410044e8>] test_ti_thread_flag+0x0/0x14
[    5.684000]  [<4102ba94>] preempt_count_sub+0x10/0x2e
[    5.684000]  [<41004b68>] do_notify_resume+0x3a/0x4c6
[    5.684000]  [<41015d52>] force_sig_fault_to_task+0x32/0x3e
[    5.684000]  [<41015d72>] force_sig_fault+0x14/0x1a
[    5.684000]  [<41005606>] buserr_c+0x9a/0x188
[    5.684000]  [<410065fc>] Lsignal_return+0x14/0x24
[    5.684000]  [<410065de>] Lwork_to_do+0xe/0x18
[    5.684000]
[    5.684000] ---[ end Kernel panic - not syncing: Attempted to kill 
init! exitcode=0x0000000b ]---


JM

>>
>>>
>>> Registers %d0-%d5 and %a0-%a2 are saved on the stack at this point and
>>> can be clobbered if need be.
>>
>> I don't know if they need to be clobbered...
> 
> I meant to say that if you need registers to prepare function arguments 
> for trace_irqs_on/off() on the stack, these can be used. But that may 
> not be necessary in this case.
> 
> Cheers,
> 
>      Michael
> 
> 
>>
>> Thanks,
>> JM
>>
>>>
>>> Cheers,
>>>
>>>      Michael
>>>
>>>
>>>>
>>>> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>
>>>> ---
>>>>  arch/m68k/Kconfig      | 1 +
>>>>  arch/m68k/kernel/irq.c | 2 ++
>>>>  2 files changed, 3 insertions(+)
>>>>
>>>> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
>>>> index
>>>> cc26df907bfe3c8143a931d259eceabb16af7411..ab3375475721fa63418c40d4ba6ac76679ebc77d
>>>> 100644
>>>> --- a/arch/m68k/Kconfig
>>>> +++ b/arch/m68k/Kconfig
>>>> @@ -39,6 +39,7 @@ config M68K
>>>>      select OLD_SIGSUSPEND3
>>>>      select UACCESS_MEMCPY if !MMU
>>>>      select ZONE_DMA
>>>> +    select TRACE_IRQFLAGS_SUPPORT
>>>>
>>>>  config CPU_BIG_ENDIAN
>>>>      def_bool y
>>>> diff --git a/arch/m68k/kernel/irq.c b/arch/m68k/kernel/irq.c
>>>> index
>>>> 9ab4f550342e5de11c528f55781432675ffd66bf..74cf60ebbc4bca51f3caa4046dbd2bdb02355711
>>>> 100644
>>>> --- a/arch/m68k/kernel/irq.c
>>>> +++ b/arch/m68k/kernel/irq.c
>>>> @@ -21,9 +21,11 @@ asmlinkage void do_IRQ(int irq, struct pt_regs 
>>>> *regs)
>>>>  {
>>>>      struct pt_regs *oldregs = set_irq_regs(regs);
>>>>
>>>> +    trace_hardirqs_off();
>>>>      irq_enter();
>>>>      generic_handle_irq(irq);
>>>>      irq_exit();
>>>> +    trace_hardirqs_on();
>>>>
>>>>      set_irq_regs(oldregs);
>>>>  }
>>>>
>>

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Jean-Michel Hautbois]

Hi Steve,

On 23/10/2024 10:47, Steven Rostedt wrote:
> On Tue, 22 Oct 2024 11:21:34 +0200
> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> 
>>
>> I was not really expecting you to review the m68k one no :-).
>> I think I have other issues which might have impact on ftrace too.
>> For instance, when I launch cyclictest I have a warning about HRTIMERS:
>> # cyclictest -p 99
>> WARN: stat /dev/cpu_dma_latency failed: No such file or directory
>> WARN: High resolution timers not available
>> policy: fifo: loadavg: 1.21 0.40 0.14 1/122 245
>>
>> T: 0 (  245) P:99 I:1000 C:  11203 Min:     92 Act:  623 Avg:  775 Max:
>>     3516
>>
>> The latencies are quite high...
> 
> Yes, if you don't have high resolution timers, the latency will be high.
> 

According to my config, I should have those:
CONFIG_HIGH_RES_TIMERS=y

>>
>> But regarding ftrace it seems that the trace is not able to give me more
>> than a microsecond precision. I addded a few trace_printk() in a driver
>> of mine and I get:
>>    irq/182-dspi-sl-112     [000] D....   277.160000: dspi_interrupt:
>> Received 2 bytes
>>    irq/182-dspi-sl-112     [000] D....   277.160000: dspi_interrupt:
>> Received 2 bytes
>>    irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt:
>> dspi_interrupt
>>    irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt: TX
>> FIFO overflow
>>    irq/182-dspi-sl-112     [000] D....   277.163000: dspi_interrupt:
>> Restart FIFO
>>
>> Do you have any clue ?
> 
> Yes. The ring buffer clock is dependent on the architecture's clock. By
> default, it uses whatever the scheduler clock uses. If the scheduler
> clock is 1ms resolution, so will the tracing data be.

By default. So, I could change it to mono_raw for instance :-). It seems 
that timerlat is ok with it !

     irq/178-UART-99      [000] D.h1.    95.766649: #27138 context 
irq timer_latency    525376 ns
       timerlat/0-235     [000] .....    95.766826: #27138 context 
thread timer_latency    697920 ns
           <idle>-0       [000] dnh1.    95.767682: #27139 context 
irq timer_latency    559616 ns
       timerlat/0-235     [000] .....    95.767839: #27139 context 
thread timer_latency    713216 ns
           <idle>-0       [000] dnh1.    95.768701: #27140 context 
irq timer_latency    577984 ns
       timerlat/0-235     [000] .....    95.768861: #27140 context 
thread timer_latency    734656 ns
     irq/178-UART-99      [000] d.h1.    95.769671: #27141 context 
irq timer_latency    548736 ns
       timerlat/0-235     [000] .....    95.769838: #27141 context 
thread timer_latency    711552 ns
     irq/178-UART-99      [000] D.h1.    95.770664: #27142 context 
irq timer_latency    540992 ns
       timerlat/0-235     [000] .....    95.770841: #27142 context 
thread timer_latency    713024 ns

> 
> -- Steve
> 

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Geert Uytterhoeven]

Hi Jean-Michel,

On Wed, Oct 23, 2024 at 11:07 AM Jean-Michel Hautbois
<jeanmichel.hautbois@yoseli.org> wrote:
> On 23/10/2024 10:47, Steven Rostedt wrote:
> > On Tue, 22 Oct 2024 11:21:34 +0200
> > Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> >> I was not really expecting you to review the m68k one no :-).
> >> I think I have other issues which might have impact on ftrace too.
> >> For instance, when I launch cyclictest I have a warning about HRTIMERS:
> >> # cyclictest -p 99
> >> WARN: stat /dev/cpu_dma_latency failed: No such file or directory
> >> WARN: High resolution timers not available
> >> policy: fifo: loadavg: 1.21 0.40 0.14 1/122 245
> >>
> >> T: 0 (  245) P:99 I:1000 C:  11203 Min:     92 Act:  623 Avg:  775 Max:
> >>     3516
> >>
> >> The latencies are quite high...
> >
> > Yes, if you don't have high resolution timers, the latency will be high.
>
> According to my config, I should have those:
> CONFIG_HIGH_RES_TIMERS=y

Does your hardware have a high resolution timer, and do you have
a driver for it?

$ git grep hrtimer -- arch/m68k/
$

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Steven Rostedt]

On Wed, 23 Oct 2024 10:59:42 +0200
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:

> 
> Sadly, not that straightforward.
> I have this patch right now:
> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
> index b2a3093af677..fc4a2d124514 100644
> --- a/arch/m68k/Kconfig
> +++ b/arch/m68k/Kconfig
> @@ -41,6 +41,7 @@ config M68K
>          select ZONE_DMA
>          select ARCH_SUPPORTS_RT
>          select IRQ_FORCED_THREADING
> +       select TRACE_IRQFLAGS_SUPPORT
> 
>   config CPU_BIG_ENDIAN
>          def_bool y
> diff --git a/arch/m68k/coldfire/entry.S b/arch/m68k/coldfire/entry.S
> index 4ea08336e2fb..fbdc4404f29e 100644
> --- a/arch/m68k/coldfire/entry.S
> +++ b/arch/m68k/coldfire/entry.S
> @@ -57,6 +57,9 @@ enosys:
>   ENTRY(system_call)
>          SAVE_ALL_SYS
>          move    #0x2000,%sr             /* enable intrs again */
> +#ifdef CONFIG_TRACE_IRQFLAGS
> +       jbsr    trace_hardirqs_on
> +#endif

Note, the trace_hardirqs_on/off() needs to be done when interrupts are
disabled. That is:

	__local_irq_disable();
	trace_hardirqs_off();

	[..]

	trace_hardirqs_on();
	__local_irq_enable();

I don't know the m68k assembly, but from the comments it looks like you
are calling these with interrupts enabled.

-- Steve


>          GET_CURRENT(%d2)
> 
>          cmpl    #NR_syscalls,%d0
> @@ -99,6 +102,9 @@ ENTRY(system_call)
>          addql   #4,%sp
> 
>   ret_from_exception:
> +#ifdef CONFIG_TRACE_IRQFLAGS
> +       jbsr    trace_hardirqs_off
> +#endif
>          move    #0x2700,%sr             /* disable intrs */
>          btst    #5,%sp@(PT_OFF_SR)      /* check if returning to kernel */
>          jeq     Luser_return            /* if so, skip resched, signals */
> @@ -140,6 +146,9 @@ Lreturn:
>   Lwork_to_do:
>          movel   %a0@(TINFO_FLAGS),%d1   /* get thread_info->flags */
>          move    #0x2000,%sr             /* enable intrs again */
> +#ifdef CONFIG_TRACE_IRQFLAGS
> +       jbsr    trace_hardirqs_on
> +#endif
>          btst    #TIF_NEED_RESCHED,%d1
>          jne     reschedule
> 
> But it fails when init is called:
> [    5.313000] Run /bin/bash as init process
> [    5.314000]   with arguments:
> [    5.315000]     /bin/bash
> [    5.316000]   with environment:
> [    5.317000]     HOME=/
> [    5.318000]     TERM=linux
> [    5.684000] Kernel panic - not syncing: Attempted to kill init! 
> exitcode=0x0000000b
> [    5.684000] CPU: 0 UID: 0 PID: 1 Comm: bash Not tainted 
> 6.12.0-rc4-00049-g4393ca34ead3 #364
> [    5.684000] Stack from 41a03e18:
> [    5.684000]         41a03e18 41540187 41540187 0000000a ffffffff 
> 415a8fb4 4140dd90 41416588
> [    5.684000]         41540187 4140d5de 4102ba84 4100b19c 4100b1a8 
> 00000000 41a38000 4102ba3a
> [    5.684000]         41a03ea0 4100c34a 4150e87e 0000000b 0000000b 
> 41a03f80 0000000a 41a3c0d4
> [    5.684000]         41a02000 400004d8 41a08000 4102ba3a 4102ba84 
> 00000000 00000000 000000ff
> [    5.684000]         00000000 00000000 41a03ef4 4100cb82 0000000b 
> 0000000b 41a03f80 41a03f6c
> [    5.684000]         41016cd2 0000000b 41a03f6c 0000001d 00000026 
> 0000048c ffffffff 00000006
> [    5.684000] Call Trace: [<4140dd90>] _printk+0x0/0x18
> [    5.684000]  [<41416588>] dump_stack+0xc/0x10
> [    5.684000]  [<4140d5de>] panic+0xf2/0x2d4
> [    5.684000]  [<4102ba84>] preempt_count_sub+0x0/0x2e
> [    5.684000]  [<4100b19c>] arch_local_irq_enable+0x0/0xc
> [    5.684000]  [<4100b1a8>] arch_irqs_disabled+0x0/0x10
> [    5.684000]  [<4102ba3a>] preempt_count_add+0x0/0x1e
> [    5.684000]  [<4100c34a>] do_exit+0x266/0x930
> [    5.684000]  [<4102ba3a>] preempt_count_add+0x0/0x1e
> [    5.684000]  [<4102ba84>] preempt_count_sub+0x0/0x2e
> [    5.684000]  [<4100cb82>] do_group_exit+0x26/0xba
> [    5.684000]  [<41016cd2>] get_signal+0x60e/0x76c
> [    5.684000]  [<410044e8>] test_ti_thread_flag+0x0/0x14
> [    5.684000]  [<4102ba94>] preempt_count_sub+0x10/0x2e
> [    5.684000]  [<41004b68>] do_notify_resume+0x3a/0x4c6
> [    5.684000]  [<41015d52>] force_sig_fault_to_task+0x32/0x3e
> [    5.684000]  [<41015d72>] force_sig_fault+0x14/0x1a
> [    5.684000]  [<41005606>] buserr_c+0x9a/0x188
> [    5.684000]  [<410065fc>] Lsignal_return+0x14/0x24
> [    5.684000]  [<410065de>] Lwork_to_do+0xe/0x18
> [    5.684000]
> [    5.684000] ---[ end Kernel panic - not syncing: Attempted to kill 
> init! exitcode=0x0000000b ]---
> 
> 
> JM
> 
> >>  
> >>>
> >>> Registers %d0-%d5 and %a0-%a2 are saved on the stack at this point and
> >>> can be clobbered if need be.  
> >>
> >> I don't know if they need to be clobbered...  
> > 
> > I meant to say that if you need registers to prepare function arguments 
> > for trace_irqs_on/off() on the stack, these can be used. But that may 
> > not be necessary in this case.
> > 
> > Cheers,
> > 
> >      Michael
> > 
> >   
> >>
> >> Thanks,
> >> JM
> >>  
> >>>
> >>> Cheers,
> >>>
> >>>      Michael
> >>>
> >>>  
> >>>>
> >>>> Signed-off-by: Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org>
> >>>> ---
> >>>>  arch/m68k/Kconfig      | 1 +
> >>>>  arch/m68k/kernel/irq.c | 2 ++
> >>>>  2 files changed, 3 insertions(+)
> >>>>
> >>>> diff --git a/arch/m68k/Kconfig b/arch/m68k/Kconfig
> >>>> index
> >>>> cc26df907bfe3c8143a931d259eceabb16af7411..ab3375475721fa63418c40d4ba6ac76679ebc77d
> >>>> 100644
> >>>> --- a/arch/m68k/Kconfig
> >>>> +++ b/arch/m68k/Kconfig
> >>>> @@ -39,6 +39,7 @@ config M68K
> >>>>      select OLD_SIGSUSPEND3
> >>>>      select UACCESS_MEMCPY if !MMU
> >>>>      select ZONE_DMA
> >>>> +    select TRACE_IRQFLAGS_SUPPORT
> >>>>
> >>>>  config CPU_BIG_ENDIAN
> >>>>      def_bool y
> >>>> diff --git a/arch/m68k/kernel/irq.c b/arch/m68k/kernel/irq.c
> >>>> index
> >>>> 9ab4f550342e5de11c528f55781432675ffd66bf..74cf60ebbc4bca51f3caa4046dbd2bdb02355711
> >>>> 100644
> >>>> --- a/arch/m68k/kernel/irq.c
> >>>> +++ b/arch/m68k/kernel/irq.c
> >>>> @@ -21,9 +21,11 @@ asmlinkage void do_IRQ(int irq, struct pt_regs 
> >>>> *regs)
> >>>>  {
> >>>>      struct pt_regs *oldregs = set_irq_regs(regs);
> >>>>
> >>>> +    trace_hardirqs_off();
> >>>>      irq_enter();
> >>>>      generic_handle_irq(irq);
> >>>>      irq_exit();
> >>>> +    trace_hardirqs_on();
> >>>>
> >>>>      set_irq_regs(oldregs);
> >>>>  }
> >>>>  
> >>  

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Jean-Michel Hautbois]

Hi Geert,

On 23/10/2024 11:13, Geert Uytterhoeven wrote:
> Hi Jean-Michel,
> 
> On Wed, Oct 23, 2024 at 11:07 AM Jean-Michel Hautbois
> <jeanmichel.hautbois@yoseli.org> wrote:
>> On 23/10/2024 10:47, Steven Rostedt wrote:
>>> On Tue, 22 Oct 2024 11:21:34 +0200
>>> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
>>>> I was not really expecting you to review the m68k one no :-).
>>>> I think I have other issues which might have impact on ftrace too.
>>>> For instance, when I launch cyclictest I have a warning about HRTIMERS:
>>>> # cyclictest -p 99
>>>> WARN: stat /dev/cpu_dma_latency failed: No such file or directory
>>>> WARN: High resolution timers not available
>>>> policy: fifo: loadavg: 1.21 0.40 0.14 1/122 245
>>>>
>>>> T: 0 (  245) P:99 I:1000 C:  11203 Min:     92 Act:  623 Avg:  775 Max:
>>>>      3516
>>>>
>>>> The latencies are quite high...
>>>
>>> Yes, if you don't have high resolution timers, the latency will be high.
>>
>> According to my config, I should have those:
>> CONFIG_HIGH_RES_TIMERS=y
> 
> Does your hardware have a high resolution timer, and do you have
> a driver for it?
> 
> $ git grep hrtimer -- arch/m68k/
> $
>

No, there is nothing with hrtimer. But, the architecture has four dma 
timers, with a 8ns resolution at 125MHz says the documentation. I will 
try to find a way to implement the missing part.

Thanks,
JM

> Gr{oetje,eeting}s,
> 
>                          Geert
> 

Re: [PATCH RFC 1/2] m68k: Add tracirqs

[Jean-Michel Hautbois]

Hi Geert, all,

On 23/10/2024 11:31, Jean-Michel Hautbois wrote:
> Hi Geert,
> 
> On 23/10/2024 11:13, Geert Uytterhoeven wrote:
>> Hi Jean-Michel,
>>
>> On Wed, Oct 23, 2024 at 11:07 AM Jean-Michel Hautbois
>> <jeanmichel.hautbois@yoseli.org> wrote:
>>> On 23/10/2024 10:47, Steven Rostedt wrote:
>>>> On Tue, 22 Oct 2024 11:21:34 +0200
>>>> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
>>>>> I was not really expecting you to review the m68k one no :-).
>>>>> I think I have other issues which might have impact on ftrace too.
>>>>> For instance, when I launch cyclictest I have a warning about 
>>>>> HRTIMERS:
>>>>> # cyclictest -p 99
>>>>> WARN: stat /dev/cpu_dma_latency failed: No such file or directory
>>>>> WARN: High resolution timers not available
>>>>> policy: fifo: loadavg: 1.21 0.40 0.14 1/122 245
>>>>>
>>>>> T: 0 (  245) P:99 I:1000 C:  11203 Min:     92 Act:  623 Avg:  775 
>>>>> Max:
>>>>>      3516
>>>>>
>>>>> The latencies are quite high...
>>>>
>>>> Yes, if you don't have high resolution timers, the latency will be 
>>>> high.
>>>
>>> According to my config, I should have those:
>>> CONFIG_HIGH_RES_TIMERS=y
>>
>> Does your hardware have a high resolution timer, and do you have
>> a driver for it?
>>
>> $ git grep hrtimer -- arch/m68k/
>> $
>>
> 
> No, there is nothing with hrtimer. But, the architecture has four dma 
> timers, with a 8ns resolution at 125MHz says the documentation. I will 
> try to find a way to implement the missing part.
> 

I gave it a hacky try. And it seems to be *a lot* better:
# cyclictest -p 99 -l 10000
WARN: stat /dev/cpu_dma_latency failed: No such file or directory
policy: fifo: loadavg: 1.18 0.71 0.33 1/122 258

T: 0 (  258) P:99 I:1000 C:  10000 Min:    118 Act: 1104 Avg:  418 Max: 
   1858

I will try to clean it a bit for another patch set :-).

Thanks,
JM

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

[Jean-Michel Hautbois]

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@yoseli.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,

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

[Steven Rostedt]

On Fri, 15 Nov 2024 09:26:07 +0100
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:

> 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 :-).

Try running timerlat.

-- Steve

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

[Jean-Michel Hautbois]

Hi Steve,

On 15/11/2024 16:25, Steven Rostedt wrote:
> On Fri, 15 Nov 2024 09:26:07 +0100
> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> 
>> 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 :-).
> 
> Try running timerlat.

Thanks !
Here is what I get:
# echo timerlat > current_tracer
# echo 1 > events/osnoise/enable
# echo 25 > osnoise/stop_tracing_total_us
# tail -10 trace
             bash-224     [000] d.h..   153.268917: #77645 context 
irq timer_latency     45056 ns
             bash-224     [000] dnh..   153.268987: irq_noise: timer:206 
start 153.268879083 duration 93957 ns
             bash-224     [000] d....   153.269056: thread_noise: 
bash:224 start 153.268905324 duration 71045 ns
       timerlat/0-271     [000] .....   153.269103: #77645 context 
thread timer_latency    230656 ns
             bash-224     [000] d.h..   153.269735: irq_noise: timer:206 
start 153.269613847 duration 103558 ns
             bash-224     [000] d.h..   153.269911: #77646 context 
irq timer_latency     40640 ns
             bash-224     [000] dnh..   153.269982: irq_noise: timer:206 
start 153.269875367 duration 93190 ns
             bash-224     [000] d....   153.270053: thread_noise: 
bash:224 start 153.269900969 duration 72709 ns
       timerlat/0-271     [000] .....   153.270100: #77646 context 
thread timer_latency    227008 ns
       timerlat/0-271     [000] .....   153.270155: timerlat_main: stop 
tracing hit on cpu 0

It looks awful, right ?
JM

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

[Steven Rostedt]

On Fri, 15 Nov 2024 16:33:06 +0100
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:

> Hi Steve,
> 
> On 15/11/2024 16:25, Steven Rostedt wrote:
> > On Fri, 15 Nov 2024 09:26:07 +0100
> > Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> >   
> >> 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 :-).  
> > 
> > Try running timerlat.  
> 
> Thanks !
> Here is what I get:
> # echo timerlat > current_tracer
> # echo 1 > events/osnoise/enable
> # echo 25 > osnoise/stop_tracing_total_us
> # tail -10 trace
>              bash-224     [000] d.h..   153.268917: #77645 context  irq timer_latency     45056 ns
>              bash-224     [000] dnh..   153.268987: irq_noise: timer:206  start 153.268879083 duration 93957 ns
>              bash-224     [000] d....   153.269056: thread_noise:  bash:224 start 153.268905324 duration 71045 ns
>        timerlat/0-271     [000] .....   153.269103: #77645 context thread timer_latency    230656 ns
>              bash-224     [000] d.h..   153.269735: irq_noise: timer:206 start 153.269613847 duration 103558 ns
>              bash-224     [000] d.h..   153.269911: #77646 context irq timer_latency     40640 ns
>              bash-224     [000] dnh..   153.269982: irq_noise: timer:206 start 153.269875367 duration 93190 ns
>              bash-224     [000] d....   153.270053: thread_noise: bash:224 start 153.269900969 duration 72709 ns
>        timerlat/0-271     [000] .....   153.270100: #77646 context thread timer_latency    227008 ns
>        timerlat/0-271     [000] .....   153.270155: timerlat_main: stop tracing hit on cpu 0
> 
> It looks awful, right ?

awful is relative ;-) If that was on x86, I would say it was bad.

Also check out rtla (in tools/trace/rtla).

 # rtla timerlat top

                                     Timer Latency                                                                                       
  0 00:00:23   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)      |    Ret user Timer Latency (us)
CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max |      cur       min       avg       max
  0 #21515     |      580       573       599       827 |      598       585       641       860 |      606       589       659       889
  1 #21513     |      461       452       477       506 |      480       315       521       561 |      488       384       539       575
  2 #10827     |      962       961       988      1016 |      983       805      1026      1075 |      989       940      1045      1081
  3 #21512     |       68        61        86       313 |       87        73       128       190 |       95        79       146       338
  4 #21510     |      254       246       271       464 |      273        70       315       473 |      281       183       333       477
  5 #21509     |      397       388       414       441 |      416       215       457       649 |      424       338       475       655
  6 #21508     |      496       496       522       566 |      509       322       563       605 |      515       424       579       611
  7 #21507     |      658       648       675       702 |      676       471       717       757 |      684       627       735       763
---------------|----------------------------------------|----------------------------------------|---------------------------------------
ALL #161401 e0 |                 61       472      1016 |                 70       514      1075 |                 79       532      1081


Or on a virtual machine running on my x86 server:

 # rtla timerlat top

                                     Timer Latency                                                                                       
  0 00:00:19   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)      |    Ret user Timer Latency (us)
CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max |      cur       min       avg       max
  0 #4600      |        4         3      3104      3223 |       41        41      3131      3262 |       46        46      3143      3304
  1 #4589      |     3678         3      3675      3742 |     3705        15      3703      3814 |     3718        22      3716      3828
  2 #4571      |     3118        56      3135      3233 |     3145        79      3162      3260 |     3157        91      3175      3275
  3 #4579      |     3509         3      3514      3625 |     3535         7      3540      3665 |     3547         9      3553      3702
  4 #4676      |        2         1      2912      4016 |       10         5      2940      4044 |       15         7      2952      4060
  5 #4572      |     3446         9      3458      3517 |     3475        32      3486      3562 |     3488        41      3499      3576
  6 #4692      |     3948         0      3767      4002 |     3984         5      3794      4079 |     4000         7      3806      4108
  7 #4580      |     3141         2      3144      3269 |     3168        20      3171      3296 |     3180        30      3184      3332
---------------|----------------------------------------|----------------------------------------|---------------------------------------
ALL #36859  e0 |                  0      3339      4016 |                  5      3366      4079 |                  7      3379      4108

That has some really poor numbers.

-- Steve

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

[Jean-Michel Hautbois]

Hi Steve,

On 15/11/2024 20:55, Steven Rostedt wrote:
> On Fri, 15 Nov 2024 16:33:06 +0100
> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> 
>> Hi Steve,
>>
>> On 15/11/2024 16:25, Steven Rostedt wrote:
>>> On Fri, 15 Nov 2024 09:26:07 +0100
>>> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
>>>    
>>>> 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 :-).
>>>
>>> Try running timerlat.
>>
>> Thanks !
>> Here is what I get:
>> # echo timerlat > current_tracer
>> # echo 1 > events/osnoise/enable
>> # echo 25 > osnoise/stop_tracing_total_us
>> # tail -10 trace
>>               bash-224     [000] d.h..   153.268917: #77645 context  irq timer_latency     45056 ns
>>               bash-224     [000] dnh..   153.268987: irq_noise: timer:206  start 153.268879083 duration 93957 ns
>>               bash-224     [000] d....   153.269056: thread_noise:  bash:224 start 153.268905324 duration 71045 ns
>>         timerlat/0-271     [000] .....   153.269103: #77645 context thread timer_latency    230656 ns
>>               bash-224     [000] d.h..   153.269735: irq_noise: timer:206 start 153.269613847 duration 103558 ns
>>               bash-224     [000] d.h..   153.269911: #77646 context irq timer_latency     40640 ns
>>               bash-224     [000] dnh..   153.269982: irq_noise: timer:206 start 153.269875367 duration 93190 ns
>>               bash-224     [000] d....   153.270053: thread_noise: bash:224 start 153.269900969 duration 72709 ns
>>         timerlat/0-271     [000] .....   153.270100: #77646 context thread timer_latency    227008 ns
>>         timerlat/0-271     [000] .....   153.270155: timerlat_main: stop tracing hit on cpu 0
>>
>> It looks awful, right ?
> 
> awful is relative ;-) If that was on x86, I would say it was bad.
> 
> Also check out rtla (in tools/trace/rtla).

Thanks ! I knew it only by name, so I watched a presentation recorded 
during OSS summit given by Daniel Bristot de Oliveira who wrote it and 
it is really impressive !

I had to modify the source code a bit, as it does not compile with my 
uclibc toolchain:
diff --git a/tools/tracing/rtla/Makefile.rtla 
b/tools/tracing/rtla/Makefile.rtla
index cc1d6b615475..b22016a88d09 100644
--- a/tools/tracing/rtla/Makefile.rtla
+++ b/tools/tracing/rtla/Makefile.rtla
@@ -15,7 +15,7 @@ $(call allow-override,LD_SO_CONF_PATH,/etc/ld.so.conf.d/)
  $(call allow-override,LDCONFIG,ldconfig)
  export CC AR STRIP PKG_CONFIG LD_SO_CONF_PATH LDCONFIG

-FOPTS          := -flto=auto -ffat-lto-objects -fexceptions 
-fstack-protector-strong   \
+FOPTS          := -flto=auto -ffat-lto-objects -fexceptions \
                 -fasynchronous-unwind-tables -fstack-clash-protection
  WOPTS          := -O -Wall -Werror=format-security 
-Wp,-D_FORTIFY_SOURCE=2             \
                 -Wp,-D_GLIBCXX_ASSERTIONS -Wno-maybe-uninitialized
diff --git a/tools/tracing/rtla/src/timerlat_u.c 
b/tools/tracing/rtla/src/timerlat_u.c
index 01dbf9a6b5a5..92ad2388b123 100644
--- a/tools/tracing/rtla/src/timerlat_u.c
+++ b/tools/tracing/rtla/src/timerlat_u.c
@@ -15,10 +15,16 @@
  #include <pthread.h>
  #include <sys/wait.h>
  #include <sys/prctl.h>
+#include <sys/syscall.h>

  #include "utils.h"
  #include "timerlat_u.h"

+static inline pid_t gettid(void)
+{
+       return syscall(SYS_gettid);
+}
+
  /*
   * This is the user-space main for the tool timerlatu/ threads.
   *
diff --git a/tools/tracing/rtla/src/utils.c b/tools/tracing/rtla/src/utils.c
index 9ac71a66840c..b754dc1016a4 100644
--- a/tools/tracing/rtla/src/utils.c
+++ b/tools/tracing/rtla/src/utils.c
@@ -229,6 +229,9 @@ long parse_ns_duration(char *val)
  #elif __s390x__
  # define __NR_sched_setattr    345
  # define __NR_sched_getattr    346
+#elif __m68k__
+# define __NR_sched_setattr    349
+# define __NR_sched_getattr    350
  #endif

  #define SCHED_DEADLINE         6

But it is not enough, as executing rtla fails with a segfault.
I can dump a core, but I could not manage to build gdb for my board so I 
can't debug it (I don't know how to debug a coredump without gdb !).

JM

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

[Steven Rostedt]

[ Added Tomas as he knows this code better than I do ]

On Mon, 18 Nov 2024 11:11:48 +0100
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:

> Hi Steve,
> 
> On 15/11/2024 20:55, Steven Rostedt wrote:
> > On Fri, 15 Nov 2024 16:33:06 +0100
> > Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> >   
> >> Hi Steve,
> >>
> >> On 15/11/2024 16:25, Steven Rostedt wrote:  
> >>> On Fri, 15 Nov 2024 09:26:07 +0100
> >>> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> >>>      
> >>>> 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 :-).  
> >>>
> >>> Try running timerlat.  
> >>
> >> Thanks !
> >> Here is what I get:
> >> # echo timerlat > current_tracer
> >> # echo 1 > events/osnoise/enable
> >> # echo 25 > osnoise/stop_tracing_total_us
> >> # tail -10 trace
> >>               bash-224     [000] d.h..   153.268917: #77645 context  irq timer_latency     45056 ns
> >>               bash-224     [000] dnh..   153.268987: irq_noise: timer:206  start 153.268879083 duration 93957 ns
> >>               bash-224     [000] d....   153.269056: thread_noise:  bash:224 start 153.268905324 duration 71045 ns
> >>         timerlat/0-271     [000] .....   153.269103: #77645 context thread timer_latency    230656 ns
> >>               bash-224     [000] d.h..   153.269735: irq_noise: timer:206 start 153.269613847 duration 103558 ns
> >>               bash-224     [000] d.h..   153.269911: #77646 context irq timer_latency     40640 ns
> >>               bash-224     [000] dnh..   153.269982: irq_noise: timer:206 start 153.269875367 duration 93190 ns
> >>               bash-224     [000] d....   153.270053: thread_noise: bash:224 start 153.269900969 duration 72709 ns
> >>         timerlat/0-271     [000] .....   153.270100: #77646 context thread timer_latency    227008 ns
> >>         timerlat/0-271     [000] .....   153.270155: timerlat_main: stop tracing hit on cpu 0
> >>
> >> It looks awful, right ?  
> > 
> > awful is relative ;-) If that was on x86, I would say it was bad.
> > 
> > Also check out rtla (in tools/trace/rtla).  
> 
> Thanks ! I knew it only by name, so I watched a presentation recorded 
> during OSS summit given by Daniel Bristot de Oliveira who wrote it and 
> it is really impressive !
> 
> I had to modify the source code a bit, as it does not compile with my 
> uclibc toolchain:
> diff --git a/tools/tracing/rtla/Makefile.rtla 
> b/tools/tracing/rtla/Makefile.rtla
> index cc1d6b615475..b22016a88d09 100644
> --- a/tools/tracing/rtla/Makefile.rtla
> +++ b/tools/tracing/rtla/Makefile.rtla
> @@ -15,7 +15,7 @@ $(call allow-override,LD_SO_CONF_PATH,/etc/ld.so.conf.d/)
>   $(call allow-override,LDCONFIG,ldconfig)
>   export CC AR STRIP PKG_CONFIG LD_SO_CONF_PATH LDCONFIG
> 
> -FOPTS          := -flto=auto -ffat-lto-objects -fexceptions 
> -fstack-protector-strong   \
> +FOPTS          := -flto=auto -ffat-lto-objects -fexceptions \
>                  -fasynchronous-unwind-tables -fstack-clash-protection
>   WOPTS          := -O -Wall -Werror=format-security 
> -Wp,-D_FORTIFY_SOURCE=2             \
>                  -Wp,-D_GLIBCXX_ASSERTIONS -Wno-maybe-uninitialized

I'm not sure what the consequence of the above would be. Perhaps Daniel
just copied this from other code?

> diff --git a/tools/tracing/rtla/src/timerlat_u.c 
> b/tools/tracing/rtla/src/timerlat_u.c
> index 01dbf9a6b5a5..92ad2388b123 100644
> --- a/tools/tracing/rtla/src/timerlat_u.c
> +++ b/tools/tracing/rtla/src/timerlat_u.c
> @@ -15,10 +15,16 @@
>   #include <pthread.h>
>   #include <sys/wait.h>
>   #include <sys/prctl.h>
> +#include <sys/syscall.h>
> 
>   #include "utils.h"
>   #include "timerlat_u.h"
> 
> +static inline pid_t gettid(void)
> +{
> +       return syscall(SYS_gettid);
> +}
> +
>   /*
>    * This is the user-space main for the tool timerlatu/ threads.
>    *
> diff --git a/tools/tracing/rtla/src/utils.c b/tools/tracing/rtla/src/utils.c
> index 9ac71a66840c..b754dc1016a4 100644
> --- a/tools/tracing/rtla/src/utils.c
> +++ b/tools/tracing/rtla/src/utils.c
> @@ -229,6 +229,9 @@ long parse_ns_duration(char *val)
>   #elif __s390x__
>   # define __NR_sched_setattr    345
>   # define __NR_sched_getattr    346
> +#elif __m68k__
> +# define __NR_sched_setattr    349
> +# define __NR_sched_getattr    350
>   #endif
> 
>   #define SCHED_DEADLINE         6
> 
> But it is not enough, as executing rtla fails with a segfault.
> I can dump a core, but I could not manage to build gdb for my board so I 
> can't debug it (I don't know how to debug a coredump without gdb !).

printf()!  That's how I debug things without gdb ;-)

-- Steve

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

[Jean-Michel Hautbois]

Hi Steve !

On 18/11/2024 21:20, Steven Rostedt wrote:
> 
> [ Added Tomas as he knows this code better than I do ]

Thanks !

> 
> On Mon, 18 Nov 2024 11:11:48 +0100
> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> 
>> Hi Steve,
>>
>> On 15/11/2024 20:55, Steven Rostedt wrote:
>>> On Fri, 15 Nov 2024 16:33:06 +0100
>>> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
>>>    
>>>> Hi Steve,
>>>>
>>>> On 15/11/2024 16:25, Steven Rostedt wrote:
>>>>> On Fri, 15 Nov 2024 09:26:07 +0100
>>>>> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
>>>>>       
>>>>>> 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 :-).
>>>>>
>>>>> Try running timerlat.
>>>>
>>>> Thanks !
>>>> Here is what I get:
>>>> # echo timerlat > current_tracer
>>>> # echo 1 > events/osnoise/enable
>>>> # echo 25 > osnoise/stop_tracing_total_us
>>>> # tail -10 trace
>>>>                bash-224     [000] d.h..   153.268917: #77645 context  irq timer_latency     45056 ns
>>>>                bash-224     [000] dnh..   153.268987: irq_noise: timer:206  start 153.268879083 duration 93957 ns
>>>>                bash-224     [000] d....   153.269056: thread_noise:  bash:224 start 153.268905324 duration 71045 ns
>>>>          timerlat/0-271     [000] .....   153.269103: #77645 context thread timer_latency    230656 ns
>>>>                bash-224     [000] d.h..   153.269735: irq_noise: timer:206 start 153.269613847 duration 103558 ns
>>>>                bash-224     [000] d.h..   153.269911: #77646 context irq timer_latency     40640 ns
>>>>                bash-224     [000] dnh..   153.269982: irq_noise: timer:206 start 153.269875367 duration 93190 ns
>>>>                bash-224     [000] d....   153.270053: thread_noise: bash:224 start 153.269900969 duration 72709 ns
>>>>          timerlat/0-271     [000] .....   153.270100: #77646 context thread timer_latency    227008 ns
>>>>          timerlat/0-271     [000] .....   153.270155: timerlat_main: stop tracing hit on cpu 0
>>>>
>>>> It looks awful, right ?
>>>
>>> awful is relative ;-) If that was on x86, I would say it was bad.
>>>
>>> Also check out rtla (in tools/trace/rtla).
>>
>> Thanks ! I knew it only by name, so I watched a presentation recorded
>> during OSS summit given by Daniel Bristot de Oliveira who wrote it and
>> it is really impressive !
>>
>> I had to modify the source code a bit, as it does not compile with my
>> uclibc toolchain:
>> diff --git a/tools/tracing/rtla/Makefile.rtla
>> b/tools/tracing/rtla/Makefile.rtla
>> index cc1d6b615475..b22016a88d09 100644
>> --- a/tools/tracing/rtla/Makefile.rtla
>> +++ b/tools/tracing/rtla/Makefile.rtla
>> @@ -15,7 +15,7 @@ $(call allow-override,LD_SO_CONF_PATH,/etc/ld.so.conf.d/)
>>    $(call allow-override,LDCONFIG,ldconfig)
>>    export CC AR STRIP PKG_CONFIG LD_SO_CONF_PATH LDCONFIG
>>
>> -FOPTS          := -flto=auto -ffat-lto-objects -fexceptions
>> -fstack-protector-strong   \
>> +FOPTS          := -flto=auto -ffat-lto-objects -fexceptions \
>>                   -fasynchronous-unwind-tables -fstack-clash-protection
>>    WOPTS          := -O -Wall -Werror=format-security
>> -Wp,-D_FORTIFY_SOURCE=2             \
>>                   -Wp,-D_GLIBCXX_ASSERTIONS -Wno-maybe-uninitialized
> 
> I'm not sure what the consequence of the above would be. Perhaps Daniel
> just copied this from other code?
> 
>> diff --git a/tools/tracing/rtla/src/timerlat_u.c
>> b/tools/tracing/rtla/src/timerlat_u.c
>> index 01dbf9a6b5a5..92ad2388b123 100644
>> --- a/tools/tracing/rtla/src/timerlat_u.c
>> +++ b/tools/tracing/rtla/src/timerlat_u.c
>> @@ -15,10 +15,16 @@
>>    #include <pthread.h>
>>    #include <sys/wait.h>
>>    #include <sys/prctl.h>
>> +#include <sys/syscall.h>
>>
>>    #include "utils.h"
>>    #include "timerlat_u.h"
>>
>> +static inline pid_t gettid(void)
>> +{
>> +       return syscall(SYS_gettid);
>> +}
>> +
>>    /*
>>     * This is the user-space main for the tool timerlatu/ threads.
>>     *
>> diff --git a/tools/tracing/rtla/src/utils.c b/tools/tracing/rtla/src/utils.c
>> index 9ac71a66840c..b754dc1016a4 100644
>> --- a/tools/tracing/rtla/src/utils.c
>> +++ b/tools/tracing/rtla/src/utils.c
>> @@ -229,6 +229,9 @@ long parse_ns_duration(char *val)
>>    #elif __s390x__
>>    # define __NR_sched_setattr    345
>>    # define __NR_sched_getattr    346
>> +#elif __m68k__
>> +# define __NR_sched_setattr    349
>> +# define __NR_sched_getattr    350
>>    #endif
>>
>>    #define SCHED_DEADLINE         6
>>
>> But it is not enough, as executing rtla fails with a segfault.
>> I can dump a core, but I could not manage to build gdb for my board so I
>> can't debug it (I don't know how to debug a coredump without gdb !).
> 
> printf()!  That's how I debug things without gdb ;-)

Indeed printf gave me clues !
It appears to be a bug in libtracefs (v1.8.1). rtla segfaults when 
calling tracefs_local_events() in trace_instance_init().

Debugging libtracefs pointed me to the load_events() function, and the 
segfault happens after tep_parse_event() is called for 
"/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_write_folio/format".

Going through the calls I get to event_read_print_args().
I changed libtraceevent log level to get the warnings, and it says:
libtraceevent: Resource temporarily unavailable
   unknown op '.'
Segmentation fault

JM

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

[Steven Rostedt]

On Tue, 19 Nov 2024 15:24:00 +0100
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:

> Indeed printf gave me clues !
> It appears to be a bug in libtracefs (v1.8.1). rtla segfaults when 
> calling tracefs_local_events() in trace_instance_init().
> 
> Debugging libtracefs pointed me to the load_events() function, and the 
> segfault happens after tep_parse_event() is called for 
> "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_write_folio/format".
> 
> Going through the calls I get to event_read_print_args().
> I changed libtraceevent log level to get the warnings, and it says:
> libtraceevent: Resource temporarily unavailable
>    unknown op '.'
> Segmentation fault

Can you do me a favor and send me privately a tarball of:

 # cp -r /sys/kernel/tracing/events /tmp/events
 # cd /tmp
 # tar -cvjf events.tar.bz2 events

You can't call tar on the /sys/kernel/tracing files as those are pseudo
files with size of zero, and tar will just record empty files :-p

-- Steve

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

[Steven Rostedt]

On Tue, 19 Nov 2024 10:26:31 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> Can you do me a favor and send me privately a tarball of:
> 
>  # cp -r /sys/kernel/tracing/events /tmp/events
>  # cd /tmp
>  # tar -cvjf events.tar.bz2 events
> 
> You can't call tar on the /sys/kernel/tracing files as those are pseudo
> files with size of zero, and tar will just record empty files :-p

It crashes on parsing this:

name: mm_vmscan_write_folio
ID: 198
format:
	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;

	field:unsigned long pfn;	offset:8;	size:4;	signed:0;
	field:int reclaim_flags;	offset:12;	size:4;	signed:1;

print fmt: "page=%p pfn=0x%lx flags=%s", (mem_map + ((REC->pfn) - (m68k_memory[0].addr >> 13))), REC->pfn, (REC->reclaim_flags) ? __print_flags(REC->reclaim_flags, "|", {0x0001u, "RECLAIM_WB_ANON"}, {0x0002u, "RECLAIM_WB_FILE"}, {0x0010u, "RECLAIM_WB_MIXED"}, {0x0004u, "RECLAIM_WB_SYNC"}, {0x0008u, "RECLAIM_WB_ASYNC"} ) : "RECLAIM_WB_NONE"


It shouldn't crash, but it also found a bug in your code ;-)

You reference two variables that are not part of the event:

 "mem_map" and "m68k_memory[0].addr"

Do these variables ever change? Because the TP_printk() part of the
TRACE_EVENT() macro is called a long time after the event is recorded. It
could be seconds, minutes, days or even months (and unlikely possibly
years) later.

The event takes place and runs the TP_fast_assign() to record the event in
the ring buffer. Then some time later, when you read the "trace" file, the
TP_printk() portion gets run. If you wait months before reading that, it is
executed months later.

Now you have "mem_map" and "m68k_memory[0].addr" in that output that gets
run months after the fact. Are they constant throughout the boot?

Now another issue is that user space has no idea what those values are. Now
user space can not print the values. Currently the code crashes because you
are the first one to reference a global value from a trace event print fmt.
That should probably be fixed to simply fail to parse the event and ignore
the print format logic (which defaults to just printing the raw fields).

-- Steve

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

[Steven Rostedt]

On Tue, 19 Nov 2024 11:28:50 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> print fmt: "page=%p pfn=0x%lx flags=%s", (mem_map + ((REC->pfn) - (m68k_memory[0].addr >> 13))), REC->pfn, (REC->reclaim_flags) ? __print_flags(REC->reclaim_flags, "|", {0x0001u, "RECLAIM_WB_ANON"}, {0x0002u, "RECLAIM_WB_FILE"}, {0x0010u, "RECLAIM_WB_MIXED"}, {0x0004u, "RECLAIM_WB_SYNC"}, {0x0008u, "RECLAIM_WB_ASYNC"} ) : "RECLAIM_WB_NONE"

Running gdb on this, I found that it crashed on the "m68k_memory[0].addr"
because it failed to fail on the '.' that it doesn't know how to parse.

This patch should stop the crash (against libtraceevent)

-- Steve

diff --git a/src/event-parse.c b/src/event-parse.c
index 0427061603db..a6da8f04cbf3 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -2498,6 +2498,10 @@ process_op(struct tep_event *event, struct tep_print_arg *arg, char **tok)
 
 		/* higher prios need to be closer to the root */
 		prio = get_op_prio(*tok);
+		if (prio < 0) {
+			token = *tok;
+			goto out_free;
+		}
 
 		if (prio > arg->op.prio)
 			return process_op(event, arg, tok);

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

[Jean-Michel Hautbois]

Hi Steve,

On 19/11/2024 17:28, Steven Rostedt wrote:
> On Tue, 19 Nov 2024 10:26:31 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
>> Can you do me a favor and send me privately a tarball of:
>>
>>   # cp -r /sys/kernel/tracing/events /tmp/events
>>   # cd /tmp
>>   # tar -cvjf events.tar.bz2 events
>>
>> You can't call tar on the /sys/kernel/tracing files as those are pseudo
>> files with size of zero, and tar will just record empty files :-p
> 
> It crashes on parsing this:
> 
> name: mm_vmscan_write_folio
> ID: 198
> format:
> 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
> 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
> 	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
> 	field:int common_pid;	offset:4;	size:4;	signed:1;
> 
> 	field:unsigned long pfn;	offset:8;	size:4;	signed:0;
> 	field:int reclaim_flags;	offset:12;	size:4;	signed:1;
> 
> print fmt: "page=%p pfn=0x%lx flags=%s", (mem_map + ((REC->pfn) - (m68k_memory[0].addr >> 13))), REC->pfn, (REC->reclaim_flags) ? __print_flags(REC->reclaim_flags, "|", {0x0001u, "RECLAIM_WB_ANON"}, {0x0002u, "RECLAIM_WB_FILE"}, {0x0010u, "RECLAIM_WB_MIXED"}, {0x0004u, "RECLAIM_WB_SYNC"}, {0x0008u, "RECLAIM_WB_ASYNC"} ) : "RECLAIM_WB_NONE"
> 
> 
> It shouldn't crash, but it also found a bug in your code ;-)

In my code is a really big assumption :-).

> You reference two variables that are not part of the event:
> 
>   "mem_map" and "m68k_memory[0].addr"
> 
> Do these variables ever change? Because the TP_printk() part of the
> TRACE_EVENT() macro is called a long time after the event is recorded. It
> could be seconds, minutes, days or even months (and unlikely possibly
> years) later.

I am really not the best placed to answer.
AFAIK, it sounds like those are never changing.

> 
> The event takes place and runs the TP_fast_assign() to record the event in
> the ring buffer. Then some time later, when you read the "trace" file, the
> TP_printk() portion gets run. If you wait months before reading that, it is
> executed months later.
> 
> Now you have "mem_map" and "m68k_memory[0].addr" in that output that gets
> run months after the fact. Are they constant throughout the boot?

I don't know.

> Now another issue is that user space has no idea what those values are. Now
> user space can not print the values. Currently the code crashes because you
> are the first one to reference a global value from a trace event print fmt.
> That should probably be fixed to simply fail to parse the event and ignore
> the print format logic (which defaults to just printing the raw fields).

The patch you sent works...
But, it fails a bit later:
Dispatching timerlat u procs
starting loop
User-space timerlat pid 230 on cpu 0
Segmentation fault


> 
> -- Steve
> 

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

[Steven Rostedt]

On Tue, 19 Nov 2024 19:06:45 +0100
Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
> > 
> > It shouldn't crash, but it also found a bug in your code ;-)  
> 
> In my code is a really big assumption :-).

Well, not your personally, but I meant "your" as in m68k code.

> 
> > You reference two variables that are not part of the event:
> > 
> >   "mem_map" and "m68k_memory[0].addr"
> > 
> > Do these variables ever change? Because the TP_printk() part of the
> > TRACE_EVENT() macro is called a long time after the event is recorded. It
> > could be seconds, minutes, days or even months (and unlikely possibly
> > years) later.  
> 
> I am really not the best placed to answer.
> AFAIK, it sounds like those are never changing.

That would mean they are OK and will not corrupt the trace, but it will be
meaningless for tools like perf and trace-cmd.

> 
> > 
> > The event takes place and runs the TP_fast_assign() to record the event in
> > the ring buffer. Then some time later, when you read the "trace" file, the
> > TP_printk() portion gets run. If you wait months before reading that, it is
> > executed months later.
> > 
> > Now you have "mem_map" and "m68k_memory[0].addr" in that output that gets
> > run months after the fact. Are they constant throughout the boot?  
> 
> I don't know.
> 
> > Now another issue is that user space has no idea what those values are. Now
> > user space can not print the values. Currently the code crashes because you
> > are the first one to reference a global value from a trace event print fmt.
> > That should probably be fixed to simply fail to parse the event and ignore
> > the print format logic (which defaults to just printing the raw fields).  
> 
> The patch you sent works...
> But, it fails a bit later:
> Dispatching timerlat u procs
> starting loop
> User-space timerlat pid 230 on cpu 0
> Segmentation fault
> 

More printk? ;-)

-- Steve

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

[Michael Schmitz]

Hi Steve,

On 20/11/24 07:06, Jean-Michel Hautbois wrote:
>
>> You reference two variables that are not part of the event:
>>
>>   "mem_map" and "m68k_memory[0].addr"
>>
>> Do these variables ever change? Because the TP_printk() part of the
>> TRACE_EVENT() macro is called a long time after the event is 
>> recorded. It
>> could be seconds, minutes, days or even months (and unlikely possibly
>> years) later.
>
> I am really not the best placed to answer.
> AFAIK, it sounds like those are never changing.

m68k_memory[0].addr never changes (that segment is usually where the 
kernel is loaded to, and can't be hotplugged).

mem_map is equal to NODE_DATA(0)->node_mem_map on m68k 
(mm/mm_init.c:__init alloc_node_mem_map()) and won't change either.

Cheers,

     Michael

>
>>
>> The event takes place and runs the TP_fast_assign() to record the 
>> event in
>> the ring buffer. Then some time later, when you read the "trace" 
>> file, the
>> TP_printk() portion gets run. If you wait months before reading that, 
>> it is
>> executed months later.
>>
>> Now you have "mem_map" and "m68k_memory[0].addr" in that output that 
>> gets
>> run months after the fact. Are they constant throughout the boot?
>
> I don't know.
>
>> Now another issue is that user space has no idea what those values 
>> are. Now
>> user space can not print the values. Currently the code crashes 
>> because you
>> are the first one to reference a global value from a trace event 
>> print fmt.
>> That should probably be fixed to simply fail to parse the event and 
>> ignore
>> the print format logic (which defaults to just printing the raw fields).
>
> The patch you sent works...
> But, it fails a bit later:
> Dispatching timerlat u procs
> starting loop
> User-space timerlat pid 230 on cpu 0
> Segmentation fault
>
>
>>
>> -- Steve
>>
>
>

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

[Jean-Michel Hautbois]

Hi Steve,

On 19/11/2024 19:10, Steven Rostedt wrote:
> On Tue, 19 Nov 2024 19:06:45 +0100
> Jean-Michel Hautbois <jeanmichel.hautbois@yoseli.org> wrote:
>>>
>>> It shouldn't crash, but it also found a bug in your code ;-)
>>
>> In my code is a really big assumption :-).
> 
> Well, not your personally, but I meant "your" as in m68k code.
> 
>>
>>> You reference two variables that are not part of the event:
>>>
>>>    "mem_map" and "m68k_memory[0].addr"
>>>
>>> Do these variables ever change? Because the TP_printk() part of the
>>> TRACE_EVENT() macro is called a long time after the event is recorded. It
>>> could be seconds, minutes, days or even months (and unlikely possibly
>>> years) later.
>>
>> I am really not the best placed to answer.
>> AFAIK, it sounds like those are never changing.
> 
> That would mean they are OK and will not corrupt the trace, but it will be
> meaningless for tools like perf and trace-cmd.
> 
>>
>>>
>>> The event takes place and runs the TP_fast_assign() to record the event in
>>> the ring buffer. Then some time later, when you read the "trace" file, the
>>> TP_printk() portion gets run. If you wait months before reading that, it is
>>> executed months later.
>>>
>>> Now you have "mem_map" and "m68k_memory[0].addr" in that output that gets
>>> run months after the fact. Are they constant throughout the boot?
>>
>> I don't know.
>>
>>> Now another issue is that user space has no idea what those values are. Now
>>> user space can not print the values. Currently the code crashes because you
>>> are the first one to reference a global value from a trace event print fmt.
>>> That should probably be fixed to simply fail to parse the event and ignore
>>> the print format logic (which defaults to just printing the raw fields).
>>
>> The patch you sent works...
>> But, it fails a bit later:
>> Dispatching timerlat u procs
>> starting loop
>> User-space timerlat pid 230 on cpu 0
>> Segmentation fault
>>
> 
> More printk? ;-)

Indeed, but the result is not straightforward this time :-(.

Long story short: it fails at kbuffer_load_subbuffer() call in
read_cpu_pages().

I added printf in the kbuffer helpers in libevent, and it finishes at:
__read_long_4: call read_4 at 0x600230c2
__read_4_sw: ptr=0x8044e2ac

static unsigned int __read_4_sw(void *ptr)
{
	printf("%s: ptr=%p, value: %08x\n", __func__, ptr, *(unsigned int *)ptr);
	unsigned int data = *(unsigned int *)ptr;
	printf("%s: data=%08x\n", __func__, data);

	return swap_4(data);
}

As soon as ptr is dereferenced, the segfault appears.
ptr should be ok though, as the address is valid afaik...

I must say that now I am stuck :-(.

Thanks,
JM