On Fri, 15 Mar 2024 19:03:12 +0100
Luca Ceresoli [off-list ref] wrote:

quoted

quoted

quoted

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
  

quoted

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.
  

quoted

quoted

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);