Hello Steven, On Fri, 15 Mar 2024 14:58:52 -0400 Steven Rostedt <rost...@goodmis.org> wrote:
> On Fri, 15 Mar 2024 19:03:12 +0100 > Luca Ceresoli <luca.ceres...@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