From: Steven Rostedt <rostedt@goodmis.org>
To: Luca Ceresoli <luca.ceresoli@bootlin.com>
Cc: Masami Hiramatsu <mhiramat@kernel.org>,
Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org,
Liam Girdwood <lgirdwood@gmail.com>,
Mark Brown <broonie@kernel.org>,
Thomas Petazzoni <thomas.petazzoni@bootlin.com>
Subject: Re: TP_printk() bug with %c, and more?
Date: Fri, 15 Mar 2024 14:58:52 -0400 [thread overview]
Message-ID: <20240315145852.46125ac5@gandalf.local.home> (raw)
In-Reply-To: <20240315190312.2bd6a198@booty>
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);
next prev parent reply other threads:[~2024-03-15 18:56 UTC|newest]
Thread overview: 9+ messages / expand[flat|nested] mbox.gz Atom feed top
2024-03-15 16:49 TP_printk() bug with %c, and more? Luca Ceresoli
2024-03-15 17:21 ` Steven Rostedt
2024-03-15 18:03 ` Luca Ceresoli
2024-03-15 18:58 ` Steven Rostedt [this message]
2024-03-18 15:43 ` Luca Ceresoli
2024-03-18 15:53 ` Steven Rostedt
2024-04-15 8:44 ` Steven Rostedt
2024-04-16 2:08 ` Luca Ceresoli
2024-04-16 4:01 ` Steven Rostedt
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20240315145852.46125ac5@gandalf.local.home \
--to=rostedt@goodmis.org \
--cc=broonie@kernel.org \
--cc=lgirdwood@gmail.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-trace-kernel@vger.kernel.org \
--cc=luca.ceresoli@bootlin.com \
--cc=mathieu.desnoyers@efficios.com \
--cc=mhiramat@kernel.org \
--cc=thomas.petazzoni@bootlin.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.