From: Luca Ceresoli <luca.ceresoli@bootlin.com>
To: Steven Rostedt <rostedt@goodmis.org>,
Masami Hiramatsu <mhiramat@kernel.org>,
Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org
Cc: Liam Girdwood <lgirdwood@gmail.com>,
Mark Brown <broonie@kernel.org>,
Thomas Petazzoni <thomas.petazzoni@bootlin.com>
Subject: TP_printk() bug with %c, and more?
Date: Fri, 15 Mar 2024 17:49:00 +0100 [thread overview]
Message-ID: <20240315174900.14418f22@booty> (raw)
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
next reply other threads:[~2024-03-15 16:49 UTC|newest]
Thread overview: 9+ messages / expand[flat|nested] mbox.gz Atom feed top
2024-03-15 16:49 Luca Ceresoli [this message]
2024-03-15 17:21 ` TP_printk() bug with %c, and more? Steven Rostedt
2024-03-15 18:03 ` Luca Ceresoli
2024-03-15 18:58 ` Steven Rostedt
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=20240315174900.14418f22@booty \
--to=luca.ceresoli@bootlin.com \
--cc=broonie@kernel.org \
--cc=lgirdwood@gmail.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-trace-kernel@vger.kernel.org \
--cc=mathieu.desnoyers@efficios.com \
--cc=mhiramat@kernel.org \
--cc=rostedt@goodmis.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.