Received-SPF: pass (google.com: domain of linux-kernel+bounces-104706-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.48.161 as permitted sender) client-ip=147.75.48.161;
Date: Fri, 15 Mar 2024 13:21:46 -0400
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?
Message-ID: <20240315132146.29edf416@gandalf.local.home>
In-Reply-To: <20240315174900.14418f22@booty>
References: <20240315174900.14418f22@booty>
Precedence: bulk
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit

On Fri, 15 Mar 2024 17:49:00 +0100
Luca Ceresoli <luca.ceresoli@bootlin.com> wrote:

> Hello Linux tracing maintainers,

Hi Luca!

> 
> 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?

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 for the report.

-- Steve


> 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]",