TP_printk() bug with %c, and more?

TP_printk() bug with %c, and more?

[Luca Ceresoli]

Hello Linux tracing maintainers,

I've come across an unexpected behaviour in the kernel tracing
infrastructure that looks like a bug, or maybe two.

Cc-ing ASoC maintainers for as it appeared using ASoC traces, but it
does not look ASoC-specific.

It all started when using this trace-cmd sequence on an ARM64 board
running a mainline 6.8.0-rc7 kernel:

  trace-cmd record -e snd_soc_dapm_path ./my-play
  trace-cmd report

While this produces perfectly valid traces for other asoc events,
the snd_soc_dapm_path produces:

  snd_soc_dapm_path:    >c<* MIC1_EN <- (direct) <-

instead of the expected:

  snd_soc_dapm_path:    *MIC1 <- (direct) <- MIC1_EN

The originating macro is:

	TP_printk("%c%s %s %s %s %s",
		(int) __entry->path_node &&
		(int) __entry->path_connect ? '*' : ' ',
		__get_str(wname), DAPM_ARROW(__entry->path_dir),
		__get_str(pname), DAPM_ARROW(__entry->path_dir),
		__get_str(pnname))

It appears as if the %c placeholder always produces the three ">c<"
characters, the '*' or ' ' char is printed as the first %s, all the
other strings are shifted right by one position and the last string is
never printed.

On my x86_64 laptop running the default Ubuntu kernel (6.5) I'm able to
trace a few events having a '%c' in their TP_printk() macros and the
result is:

  intel_pipe_update_start: dev 0000:00:02.0, pipe >c<, frame=1,
  scanline=107856, min=2208, max=2154

originating from:

  TP_printk("dev %s, pipe %c, frame=%u, scanline=%u, min=%u, max=%u",

Here it looks like the %c produced ">c<" again, but apparently without
any shifting.

Back on the ARM64 board I found a couple interesting clues.

First, using the <debugfs>/tracing/ interface instead of trace-cmd, I'm
getting correctly formatted strings:

trace-cmd: snd_soc_dapm_path: >c<* HPOUT_L -> (direct) ->
debugfs:   snd_soc_dapm_path: *HPOUT_L <- (direct) <- HPOUT_POP_SOUND_L

Notice the arrows pointing to the opposite direction though. The correct
arrow is the one in the debugfs run.

Second, I tried a simple test:

  TP_printk("(%c,%c,%c,%c) [%s,%s,%s,%s]",                                                                                                                                             
            'A',                                                                                                                                                                       
            'B',                                                                                                                                                                       
            'C',                                                                                                                                                                       
            'D',                                                                                                                                                                       
            "Just",                                                                                                                                                                     
            "a",                                                                                                                                                                   
            "stupid",                                                                                                                                                                
            "test")                                                                                                                                                                 

and this logs:

  snd_soc_dapm_path:    (>c<,>c<,>c<,>c<) [A,B,C,D]

so it looks like there really is something wrong with %c in
TP_printk(), and the %c in the format string do not consume any
parameters, de facto shifting them to the right.

As one may expect, avoiding the %c fixes formatting:

-       TP_printk("%c%s %s %s %s %s",
+       TP_printk("%s%s %s %s %s %s",
                (int) __entry->path_node &&
-               (int) __entry->path_connect ? '*' : ' ',
+               (int) __entry->path_connect ? "*" : " ",
                __get_str(wname), DAPM_ARROW(__entry->path_dir),
                __get_str(pname), DAPM_ARROW(__entry->path_dir),
                __get_str(pnname))

With this change, the string formatting is correct both with debugfs and
trace-cmd, but the arrows are still wrong with trace-cmd.

I have no idea how to further debug this and after a quick look at the
macros I can honestly say I'm not feeling brave enough to dig into them
in a late Friday afternoon.

Any hints?
Am I doing anything wrong?
Is %c supposed to work in tracing macros?

Best regards,
Luca

-- 
Luca Ceresoli, Bootlin
Embedded Linux and Kernel engineering
https://bootlin.com

Re: TP_printk() bug with %c, and more?

[Steven Rostedt]

On Fri, 15 Mar 2024 17:49:00 +0100
Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:

> Hello Linux tracing maintainers,

Hi Luca!

> 
> I've come across an unexpected behaviour in the kernel tracing
> infrastructure that looks like a bug, or maybe two.
> 
> Cc-ing ASoC maintainers for as it appeared using ASoC traces, but it
> does not look ASoC-specific.
> 
> It all started when using this trace-cmd sequence on an ARM64 board
> running a mainline 6.8.0-rc7 kernel:
> 
>   trace-cmd record -e snd_soc_dapm_path ./my-play
>   trace-cmd report
> 
> While this produces perfectly valid traces for other asoc events,
> the snd_soc_dapm_path produces:
> 
>   snd_soc_dapm_path:    >c<* MIC1_EN <- (direct) <-
> 
> instead of the expected:
> 
>   snd_soc_dapm_path:    *MIC1 <- (direct) <- MIC1_EN
> 
> The originating macro is:
> 
> 	TP_printk("%c%s %s %s %s %s",
> 		(int) __entry->path_node &&
> 		(int) __entry->path_connect ? '*' : ' ',
> 		__get_str(wname), DAPM_ARROW(__entry->path_dir),
> 		__get_str(pname), DAPM_ARROW(__entry->path_dir),
> 		__get_str(pnname))
> 
> It appears as if the %c placeholder always produces the three ">c<"
> characters, the '*' or ' ' char is printed as the first %s, all the
> other strings are shifted right by one position and the last string is
> never printed.
> 
> On my x86_64 laptop running the default Ubuntu kernel (6.5) I'm able to
> trace a few events having a '%c' in their TP_printk() macros and the
> result is:
> 
>   intel_pipe_update_start: dev 0000:00:02.0, pipe >c<, frame=1,
>   scanline=107856, min=2208, max=2154
> 

What does /sys/kernel/tracing/trace show?

If that's fine, then the bug is in libtraceevent and not the kernel.

I'm testing it out now, and I see %c not being processed properly by
libtraceevent. I'll take a deeper look.

Thanks for the report.

-- Steve


> originating from:
> 
>   TP_printk("dev %s, pipe %c, frame=%u, scanline=%u, min=%u, max=%u",
> 
> Here it looks like the %c produced ">c<" again, but apparently without
> any shifting.
> 
> Back on the ARM64 board I found a couple interesting clues.
> 
> First, using the <debugfs>/tracing/ interface instead of trace-cmd, I'm
> getting correctly formatted strings:
> 
> trace-cmd: snd_soc_dapm_path: >c<* HPOUT_L -> (direct) ->
> debugfs:   snd_soc_dapm_path: *HPOUT_L <- (direct) <- HPOUT_POP_SOUND_L
> 
> Notice the arrows pointing to the opposite direction though. The correct
> arrow is the one in the debugfs run.
> 
> Second, I tried a simple test:
> 
>   TP_printk("(%c,%c,%c,%c) [%s,%s,%s,%s]",                                                                                                                                             

Re: TP_printk() bug with %c, and more?

[Luca Ceresoli]

Hello Steven,

thanks for the quick feedback!

On Fri, 15 Mar 2024 13:21:46 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 15 Mar 2024 17:49:00 +0100
> Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:
> 
> > Hello Linux tracing maintainers,  
> 
> Hi Luca!
> 
> > 
> > I've come across an unexpected behaviour in the kernel tracing
> > infrastructure that looks like a bug, or maybe two.
> > 
> > Cc-ing ASoC maintainers for as it appeared using ASoC traces, but it
> > does not look ASoC-specific.
> > 
> > It all started when using this trace-cmd sequence on an ARM64 board
> > running a mainline 6.8.0-rc7 kernel:
> > 
> >   trace-cmd record -e snd_soc_dapm_path ./my-play
> >   trace-cmd report
> > 
> > While this produces perfectly valid traces for other asoc events,
> > the snd_soc_dapm_path produces:
> > 
> >   snd_soc_dapm_path:    >c<* MIC1_EN <- (direct) <-
> > 
> > instead of the expected:
> > 
> >   snd_soc_dapm_path:    *MIC1 <- (direct) <- MIC1_EN
> > 
> > The originating macro is:
> > 
> > 	TP_printk("%c%s %s %s %s %s",
> > 		(int) __entry->path_node &&
> > 		(int) __entry->path_connect ? '*' : ' ',
> > 		__get_str(wname), DAPM_ARROW(__entry->path_dir),
> > 		__get_str(pname), DAPM_ARROW(__entry->path_dir),
> > 		__get_str(pnname))
> > 
> > It appears as if the %c placeholder always produces the three ">c<"
> > characters, the '*' or ' ' char is printed as the first %s, all the
> > other strings are shifted right by one position and the last string is
> > never printed.
> > 
> > On my x86_64 laptop running the default Ubuntu kernel (6.5) I'm able to
> > trace a few events having a '%c' in their TP_printk() macros and the
> > result is:
> > 
> >   intel_pipe_update_start: dev 0000:00:02.0, pipe >c<, frame=1,
> >   scanline=107856, min=2208, max=2154
> >   
> 
> What does /sys/kernel/tracing/trace show?

It is correct:

   intel_pipe_update_start: dev 0000:00:02.0, pipe B, frame=377644, scanline=1466, min=2154, max=2159

> If that's fine, then the bug is in libtraceevent and not the kernel.
> 
> I'm testing it out now, and I see %c not being processed properly by
> libtraceevent. I'll take a deeper look.

Thanks.

> > originating from:
> > 
> >   TP_printk("dev %s, pipe %c, frame=%u, scanline=%u, min=%u, max=%u",
> > 
> > Here it looks like the %c produced ">c<" again, but apparently without
> > any shifting.
> > 
> > Back on the ARM64 board I found a couple interesting clues.
> > 
> > First, using the <debugfs>/tracing/ interface instead of trace-cmd, I'm
> > getting correctly formatted strings:
> > 
> > trace-cmd: snd_soc_dapm_path: >c<* HPOUT_L -> (direct) ->
> > debugfs:   snd_soc_dapm_path: *HPOUT_L <- (direct) <- HPOUT_POP_SOUND_L
> > 
> > Notice the arrows pointing to the opposite direction though. The correct
> > arrow is the one in the debugfs run.

This other issue appears a separate bug however.

Luca

-- 
Luca Ceresoli, Bootlin
Embedded Linux and Kernel engineering
https://bootlin.com

Re: TP_printk() bug with %c, and more?

[Steven Rostedt]

On Fri, 15 Mar 2024 19:03:12 +0100
Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:

> > > 
> > > I've come across an unexpected behaviour in the kernel tracing
> > > infrastructure that looks like a bug, or maybe two.
> > > 
> > > Cc-ing ASoC maintainers for as it appeared using ASoC traces, but it
> > > does not look ASoC-specific.
> > > 
> > > It all started when using this trace-cmd sequence on an ARM64 board
> > > running a mainline 6.8.0-rc7 kernel:
> > > 
> > >   trace-cmd record -e snd_soc_dapm_path ./my-play
> > >   trace-cmd report
> > > 
> > > While this produces perfectly valid traces for other asoc events,
> > > the snd_soc_dapm_path produces:
> > > 
> > >   snd_soc_dapm_path:    >c<* MIC1_EN <- (direct) <-
> > > 
> > > instead of the expected:
> > > 
> > >   snd_soc_dapm_path:    *MIC1 <- (direct) <- MIC1_EN
> > > 
> > > The originating macro is:
> > > 
> > > 	TP_printk("%c%s %s %s %s %s",
> > > 		(int) __entry->path_node &&
> > > 		(int) __entry->path_connect ? '*' : ' ',
> > > 		__get_str(wname), DAPM_ARROW(__entry->path_dir),
> > > 		__get_str(pname), DAPM_ARROW(__entry->path_dir),
> > > 		__get_str(pnname))
> > > 
> > > It appears as if the %c placeholder always produces the three ">c<"
> > > characters, the '*' or ' ' char is printed as the first %s, all the
> > > other strings are shifted right by one position and the last string is
> > > never printed.
> > > 
> > > On my x86_64 laptop running the default Ubuntu kernel (6.5) I'm able to
> > > trace a few events having a '%c' in their TP_printk() macros and the
> > > result is:
> > > 
> > >   intel_pipe_update_start: dev 0000:00:02.0, pipe >c<, frame=1,
> > >   scanline=107856, min=2208, max=2154
> > >     
> > 
> > What does /sys/kernel/tracing/trace show?  
> 
> It is correct:
> 
>    intel_pipe_update_start: dev 0000:00:02.0, pipe B, frame=377644, scanline=1466, min=2154, max=2159
> 
> > If that's fine, then the bug is in libtraceevent and not the kernel.
> > 
> > I'm testing it out now, and I see %c not being processed properly by
> > libtraceevent. I'll take a deeper look.  
> 
> Thanks.
> 
> > > originating from:
> > > 
> > >   TP_printk("dev %s, pipe %c, frame=%u, scanline=%u, min=%u, max=%u",
> > > 
> > > Here it looks like the %c produced ">c<" again, but apparently without
> > > any shifting.
> > > 
> > > Back on the ARM64 board I found a couple interesting clues.
> > > 
> > > First, using the <debugfs>/tracing/ interface instead of trace-cmd, I'm
> > > getting correctly formatted strings:
> > > 
> > > trace-cmd: snd_soc_dapm_path: >c<* HPOUT_L -> (direct) ->
> > > debugfs:   snd_soc_dapm_path: *HPOUT_L <- (direct) <- HPOUT_POP_SOUND_L
> > > 
> > > Notice the arrows pointing to the opposite direction though. The correct
> > > arrow is the one in the debugfs run.  
> 
> This other issue appears a separate bug however.

Can you make user you have the latest libtraceevent from:

   git://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git

And apply this patch.

Thanks,

-- Steve

diff --git a/src/event-parse.c b/src/event-parse.c
index d607556..61b0966 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -3732,8 +3732,19 @@ process_arg_token(struct tep_event *event, struct tep_print_arg *arg,
 		arg->atom.atom = atom;
 		break;
 
-	case TEP_EVENT_DQUOTE:
 	case TEP_EVENT_SQUOTE:
+		arg->type = TEP_PRINT_ATOM;
+		/* Make characters into numbers */
+		if (asprintf(&arg->atom.atom, "%d", token[0]) < 0) {
+			free_token(token);
+			*tok = NULL;
+			arg->atom.atom = NULL;
+			return TEP_EVENT_ERROR;
+		}
+		free_token(token);
+		type = read_token_item(event->tep, &token);
+		break;
+	case TEP_EVENT_DQUOTE:
 		arg->type = TEP_PRINT_ATOM;
 		arg->atom.atom = token;
 		type = read_token_item(event->tep, &token);

Re: TP_printk() bug with %c, and more?

[Luca Ceresoli]

Hello Steven,

On Fri, 15 Mar 2024 14:58:52 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 15 Mar 2024 19:03:12 +0100
> Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:
> 
> > > > 
> > > > I've come across an unexpected behaviour in the kernel tracing
> > > > infrastructure that looks like a bug, or maybe two.
> > > > 
> > > > Cc-ing ASoC maintainers for as it appeared using ASoC traces, but it
> > > > does not look ASoC-specific.
> > > > 
> > > > It all started when using this trace-cmd sequence on an ARM64 board
> > > > running a mainline 6.8.0-rc7 kernel:
> > > > 
> > > >   trace-cmd record -e snd_soc_dapm_path ./my-play
> > > >   trace-cmd report
> > > > 
> > > > While this produces perfectly valid traces for other asoc events,
> > > > the snd_soc_dapm_path produces:
> > > > 
> > > >   snd_soc_dapm_path:    >c<* MIC1_EN <- (direct) <-
> > > > 
> > > > instead of the expected:
> > > > 
> > > >   snd_soc_dapm_path:    *MIC1 <- (direct) <- MIC1_EN
> > > > 
> > > > The originating macro is:
> > > > 
> > > > 	TP_printk("%c%s %s %s %s %s",
> > > > 		(int) __entry->path_node &&
> > > > 		(int) __entry->path_connect ? '*' : ' ',
> > > > 		__get_str(wname), DAPM_ARROW(__entry->path_dir),
> > > > 		__get_str(pname), DAPM_ARROW(__entry->path_dir),
> > > > 		__get_str(pnname))
> > > > 
> > > > It appears as if the %c placeholder always produces the three ">c<"
> > > > characters, the '*' or ' ' char is printed as the first %s, all the
> > > > other strings are shifted right by one position and the last string is
> > > > never printed.
> > > > 
> > > > On my x86_64 laptop running the default Ubuntu kernel (6.5) I'm able to
> > > > trace a few events having a '%c' in their TP_printk() macros and the
> > > > result is:
> > > > 
> > > >   intel_pipe_update_start: dev 0000:00:02.0, pipe >c<, frame=1,
> > > >   scanline=107856, min=2208, max=2154
> > > >       
> > > 
> > > What does /sys/kernel/tracing/trace show?    
> > 
> > It is correct:
> > 
> >    intel_pipe_update_start: dev 0000:00:02.0, pipe B, frame=377644, scanline=1466, min=2154, max=2159
> >   
> > > If that's fine, then the bug is in libtraceevent and not the kernel.
> > > 
> > > I'm testing it out now, and I see %c not being processed properly by
> > > libtraceevent. I'll take a deeper look.    
> > 
> > Thanks.
> >   
> > > > originating from:
> > > > 
> > > >   TP_printk("dev %s, pipe %c, frame=%u, scanline=%u, min=%u, max=%u",
> > > > 
> > > > Here it looks like the %c produced ">c<" again, but apparently without
> > > > any shifting.
> > > > 
> > > > Back on the ARM64 board I found a couple interesting clues.
> > > > 
> > > > First, using the <debugfs>/tracing/ interface instead of trace-cmd, I'm
> > > > getting correctly formatted strings:
> > > > 
> > > > trace-cmd: snd_soc_dapm_path: >c<* HPOUT_L -> (direct) ->
> > > > debugfs:   snd_soc_dapm_path: *HPOUT_L <- (direct) <- HPOUT_POP_SOUND_L
> > > > 
> > > > Notice the arrows pointing to the opposite direction though. The correct
> > > > arrow is the one in the debugfs run.    
> > 
> > This other issue appears a separate bug however.  
> 
> Can you make user you have the latest libtraceevent from:
> 
>    git://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git
> 
> And apply this patch.
> 
> Thanks,
> 
> -- Steve
> 
> diff --git a/src/event-parse.c b/src/event-parse.c
> index d607556..61b0966 100644
> --- a/src/event-parse.c
> +++ b/src/event-parse.c
> @@ -3732,8 +3732,19 @@ process_arg_token(struct tep_event *event, struct tep_print_arg *arg,
>  		arg->atom.atom = atom;
>  		break;
>  
> -	case TEP_EVENT_DQUOTE:
>  	case TEP_EVENT_SQUOTE:
> +		arg->type = TEP_PRINT_ATOM;
> +		/* Make characters into numbers */
> +		if (asprintf(&arg->atom.atom, "%d", token[0]) < 0) {
> +			free_token(token);
> +			*tok = NULL;
> +			arg->atom.atom = NULL;
> +			return TEP_EVENT_ERROR;
> +		}
> +		free_token(token);
> +		type = read_token_item(event->tep, &token);
> +		break;
> +	case TEP_EVENT_DQUOTE:
>  		arg->type = TEP_PRINT_ATOM;
>  		arg->atom.atom = token;
>  		type = read_token_item(event->tep, &token);

Indeed I was on an older version, apologies.

I upgraded both libtraceevent and trace-cmd to master and applied your
patch, now the %c is formatted correctly.

However the arrows are still reversed.

Is this what you were expecting?

Luca

-- 
Luca Ceresoli, Bootlin
Embedded Linux and Kernel engineering
https://bootlin.com

Re: TP_printk() bug with %c, and more?

[Steven Rostedt]

On Mon, 18 Mar 2024 16:43:07 +0100
Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:

> Indeed I was on an older version, apologies.
> 
> I upgraded both libtraceevent and trace-cmd to master and applied your
> patch, now the %c is formatted correctly.
> 
> However the arrows are still reversed.
> 
> Is this what you were expecting?

No, I didn't look at the arrows, just the %c issue. I'll try to get some
time to do that.

-- Steve

Re: TP_printk() bug with %c, and more?

[Steven Rostedt]

On Mon, 18 Mar 2024 16:43:07 +0100
Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:

> However the arrows are still reversed.

This requires a kernel change. The problem is that the print fmt has:

print fmt: "%c%s %s %s %s %s", (int) REC->path_node && (int) REC->path_connect ? '*' : ' ', __get_str(wname), (((REC->path_dir) == SND_SOC_DAPM_DIR_OUT) ? "->" : "<-"), __get_str(pname), (((REC->path_dir) == SND_SOC_DAPM_DIR_OUT) ? "->" : "<-"), __get_str(pnname)

User space (trace-cmd and perf) have no idea what SND_SOC_DAPM_DIR_OUT
is. The kernel needs to convert that, otherwise the parsing will fail,
or it will default it to zero.

-- Steve

Re: TP_printk() bug with %c, and more?

[Luca Ceresoli]

Hello Steven,

On Mon, 15 Apr 2024 04:44:30 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Mon, 18 Mar 2024 16:43:07 +0100
> Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:
> 
> > However the arrows are still reversed.  
> 
> This requires a kernel change. The problem is that the print fmt has:
> 
> print fmt: "%c%s %s %s %s %s", (int) REC->path_node && (int) REC->path_connect ? '*' : ' ', __get_str(wname), (((REC->path_dir) == SND_SOC_DAPM_DIR_OUT) ? "->" : "<-"), __get_str(pname), (((REC->path_dir) == SND_SOC_DAPM_DIR_OUT) ? "->" : "<-"), __get_str(pnname)
> 
> User space (trace-cmd and perf) have no idea what SND_SOC_DAPM_DIR_OUT
> is. The kernel needs to convert that, otherwise the parsing will fail,
> or it will default it to zero.

Thanks for the insight. I'm definitely trying to fix this based on your
hint as soon as I get my hand on a board.

Luca

-- 
Luca Ceresoli, Bootlin
Embedded Linux and Kernel engineering
https://bootlin.com

Re: TP_printk() bug with %c, and more?

[Steven Rostedt]

On Tue, 16 Apr 2024 04:08:46 +0200
Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:

> Thanks for the insight. I'm definitely trying to fix this based on your
> hint as soon as I get my hand on a board.

I have a patch I forgot to send out. Let me do that now.

-- Steve