[PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[Huang Shijie]

When tracepoint_debug is set, we may get the output in kernel log:
     [  380.013843] Probe 0 : 00000000f0d68cda

It is not readable, so change to print the function symbol.
After this patch, the output may becomes:
     [   54.930567] Probe 0 : perf_trace_sched_wakeup_template

Reviewed-by: Christoph Lameter <cl@linux.com>
Signed-off-by: Huang Shijie <shijie@os.amperecomputing.com>
---
 kernel/tracepoint.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
index 1848ce7e2976..82bef4b9400a 100644
--- a/kernel/tracepoint.c
+++ b/kernel/tracepoint.c
@@ -127,7 +127,7 @@ static void debug_print_probes(struct tracepoint_func *funcs)
 		return;
 
 	for (i = 0; funcs[i].func; i++)
-		printk(KERN_DEBUG "Probe %d : %p\n", i, funcs[i].func);
+		printk(KERN_DEBUG "Probe %d : %ps\n", i, funcs[i].func);
 }
 
 static struct tracepoint_func *
-- 
2.40.1

Re: [PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[Mathieu Desnoyers]

On 2025-03-04 20:55, Huang Shijie wrote:
> When tracepoint_debug is set, we may get the output in kernel log:
>       [  380.013843] Probe 0 : 00000000f0d68cda
> 
> It is not readable, so change to print the function symbol.
> After this patch, the output may becomes:
>       [   54.930567] Probe 0 : perf_trace_sched_wakeup_template

What would it print if the address is corrupted ?

Perhaps we could do like the backtrace code and print e.g.

[<00000000f0d68cda>] perf_trace_sched_wakeup_template+0xNN/0xMM

?

I don't care about the actual layout, but removing the address
from the formatted output appears to be removing useful data
in debug situations.

Thanks,

Mathieu

> 
> Reviewed-by: Christoph Lameter <cl@linux.com>
> Signed-off-by: Huang Shijie <shijie@os.amperecomputing.com>
> ---
>   kernel/tracepoint.c | 2 +-
>   1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
> index 1848ce7e2976..82bef4b9400a 100644
> --- a/kernel/tracepoint.c
> +++ b/kernel/tracepoint.c
> @@ -127,7 +127,7 @@ static void debug_print_probes(struct tracepoint_func *funcs)
>   		return;
>   
>   	for (i = 0; funcs[i].func; i++)
> -		printk(KERN_DEBUG "Probe %d : %p\n", i, funcs[i].func);
> +		printk(KERN_DEBUG "Probe %d : %ps\n", i, funcs[i].func);
>   }
>   
>   static struct tracepoint_func *


-- 
Mathieu Desnoyers
EfficiOS Inc.
https://www.efficios.com

Re: [PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[Steven Rostedt]

On Wed, 5 Mar 2025 08:53:43 -0500
Mathieu Desnoyers <mathieu.desnoyers@efficios.com> wrote:

> On 2025-03-04 20:55, Huang Shijie wrote:
> > When tracepoint_debug is set, we may get the output in kernel log:
> >       [  380.013843] Probe 0 : 00000000f0d68cda
> > 
> > It is not readable, so change to print the function symbol.
> > After this patch, the output may becomes:
> >       [   54.930567] Probe 0 : perf_trace_sched_wakeup_template  
> 
> What would it print if the address is corrupted ?
> 
> Perhaps we could do like the backtrace code and print e.g.
> 
> [<00000000f0d68cda>] perf_trace_sched_wakeup_template+0xNN/0xMM
> 
> ?
> 
> I don't care about the actual layout, but removing the address
> from the formatted output appears to be removing useful data
> in debug situations.
> 

Perhaps this can use "%pS" which shows both the function entry and the
offset. If no function is found, it ends up being the same as "%p".
Also, it's likely that the "%p" is hashed here and one couldn't use it to
debug either.

-- Steve

Re: [PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[Shijie Huang]

On 2025/3/5 23:47, Steven Rostedt wrote:
> On Wed, 5 Mar 2025 08:53:43 -0500
> Mathieu Desnoyers <mathieu.desnoyers@efficios.com> wrote:
>
>> On 2025-03-04 20:55, Huang Shijie wrote:
>>> When tracepoint_debug is set, we may get the output in kernel log:
>>>        [  380.013843] Probe 0 : 00000000f0d68cda
>>>
>>> It is not readable, so change to print the function symbol.
>>> After this patch, the output may becomes:
>>>        [   54.930567] Probe 0 : perf_trace_sched_wakeup_template
>> What would it print if the address is corrupted ?
>>
>> Perhaps we could do like the backtrace code and print e.g.
>>
>> [<00000000f0d68cda>] perf_trace_sched_wakeup_template+0xNN/0xMM
>>
>> ?
>>
>> I don't care about the actual layout, but removing the address
>> from the formatted output appears to be removing useful data
>> in debug situations.
>>
> Perhaps this can use "%pS" which shows both the function entry and the

okay, I can change it to use "%pS" in next version if we think it is 
good enough:

      [   55.225555] Probe 0 : perf_trace_sched_wakeup_template+0x0/0x20


Thanks

Huang Shijie

Re: [PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[Shijie Huang]

On 2025/3/5 21:53, Mathieu Desnoyers wrote:
> On 2025-03-04 20:55, Huang Shijie wrote:
>> When tracepoint_debug is set, we may get the output in kernel log:
>>       [  380.013843] Probe 0 : 00000000f0d68cda
>>
>> It is not readable, so change to print the function symbol.
>> After this patch, the output may becomes:
>>       [   54.930567] Probe 0 : perf_trace_sched_wakeup_template
>
> What would it print if the address is corrupted ?
>
> Perhaps we could do like the backtrace code and print e.g.
>
> [<00000000f0d68cda>] perf_trace_sched_wakeup_template+0xNN/0xMM 

If we want this format, we can change code to:

    ---
  kernel/tracepoint.c | 3 ++-
  1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
index abfd0ac1177f..5a5041f32cc8 100644
--- a/kernel/tracepoint.c
+++ b/kernel/tracepoint.c
@@ -127,7 +127,8 @@ static void debug_print_probes(struct 
tracepoint_func *funcs)
                 return;

         for (i = 0; funcs[i].func; i++)
-               printk(KERN_DEBUG "Probe %d : %p\n", i, funcs[i].func);
+               printk(KERN_DEBUG "Probe %d : [ %p ] %pS\n",
+                               i, funcs[i].func, funcs[i].func);
  }


The output will look like:

[   63.818829] Probe 0 : [ 0000000032848d41 ] 
perf_trace_sched_wakeup_template+0x0/0x20
[   63.819287] Probe 0 : [ 00000000fe8cca4d ] 
perf_trace_sched_switch+0x0/0x20
[   65.325638] Probe 0 : [ 0000000032848d41 ] 
perf_trace_sched_wakeup_template+0x0/0x20
[   65.695631] Probe 0 : [ 00000000fe8cca4d ] 
perf_trace_sched_switch+0x0/0x20

Thanks

Huang Shijie

Re: [PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[Steven Rostedt]

On Thu, 6 Mar 2025 11:37:38 +0800
Shijie Huang <shijie@amperemail.onmicrosoft.com> wrote:

> diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
> index abfd0ac1177f..5a5041f32cc8 100644
> --- a/kernel/tracepoint.c
> +++ b/kernel/tracepoint.c
> @@ -127,7 +127,8 @@ static void debug_print_probes(struct 
> tracepoint_func *funcs)
>                  return;
> 
>          for (i = 0; funcs[i].func; i++)
> -               printk(KERN_DEBUG "Probe %d : %p\n", i, funcs[i].func);
> +               printk(KERN_DEBUG "Probe %d : [ %p ] %pS\n",
> +                               i, funcs[i].func, funcs[i].func);
>   }
> 
> 
> The output will look like:
> 
> [   63.818829] Probe 0 : [ 0000000032848d41 ] 
> perf_trace_sched_wakeup_template+0x0/0x20
> [   63.819287] Probe 0 : [ 00000000fe8cca4d ] 
> perf_trace_sched_switch+0x0/0x20
> [   65.325638] Probe 0 : [ 0000000032848d41 ] 
> perf_trace_sched_wakeup_template+0x0/0x20
> [   65.695631] Probe 0 : [ 00000000fe8cca4d ] 
> perf_trace_sched_switch+0x0/0x20

I'm fine either way. Mathieu, what's your preference?

Although the above shows a hashed %p. Is that even useful?

-- Steve

Re: [PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[Mathieu Desnoyers]

On 2025-03-06 10:13, Steven Rostedt wrote:
> On Thu, 6 Mar 2025 11:37:38 +0800
> Shijie Huang <shijie@amperemail.onmicrosoft.com> wrote:
> 
>> diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
>> index abfd0ac1177f..5a5041f32cc8 100644
>> --- a/kernel/tracepoint.c
>> +++ b/kernel/tracepoint.c
>> @@ -127,7 +127,8 @@ static void debug_print_probes(struct
>> tracepoint_func *funcs)
>>                   return;
>>
>>           for (i = 0; funcs[i].func; i++)
>> -               printk(KERN_DEBUG "Probe %d : %p\n", i, funcs[i].func);
>> +               printk(KERN_DEBUG "Probe %d : [ %p ] %pS\n",
>> +                               i, funcs[i].func, funcs[i].func);
>>    }
>>
>>
>> The output will look like:
>>
>> [   63.818829] Probe 0 : [ 0000000032848d41 ]
>> perf_trace_sched_wakeup_template+0x0/0x20
>> [   63.819287] Probe 0 : [ 00000000fe8cca4d ]
>> perf_trace_sched_switch+0x0/0x20
>> [   65.325638] Probe 0 : [ 0000000032848d41 ]
>> perf_trace_sched_wakeup_template+0x0/0x20
>> [   65.695631] Probe 0 : [ 00000000fe8cca4d ]
>> perf_trace_sched_switch+0x0/0x20
> 
> I'm fine either way. Mathieu, what's your preference?
> 
> Although the above shows a hashed %p. Is that even useful?

The hashed %p is not really useful.

I think we could just print %Sb

e.g. from core-api/printk-formats.rst:

         %pSb    versatile_init+0x0/0x110 [module_name ed5019fdf5e53be37cb1ba7899292d7e143b259e]

AFAIU, when the kallsyms_lookup_buildid fails, it prints the raw address instead
(see __sprint_symbol).

Thanks,

Mathieu

-- 
Mathieu Desnoyers
EfficiOS Inc.
https://www.efficios.com

Re: [PATCH resend ] tracepoint: Print the function symbol when tracepoint_debug is set

[Shijie Huang]

On 2025/3/7 0:37, Mathieu Desnoyers wrote:
>
> I think we could just print %Sb
>
> e.g. from core-api/printk-formats.rst:
>
>         %pSb    versatile_init+0x0/0x110 [module_name 
> ed5019fdf5e53be37cb1ba7899292d7e143b259e]
>
> AFAIU, when the kallsyms_lookup_buildid fails, it prints the raw 
> address instead
> (see __sprint_symbol).

okay, I will use "%pSb" in version v2 later.


Thanks

Huang Shijie