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
