PATCH] tracing: ALSA: hda: Remove string manipulation out of the fast path

PATCH] tracing: ALSA: hda: Remove string manipulation out of the fast path

[Steven Rostedt]

From: "Steven Rostedt (Google)" <rostedt@goodmis.org>

The TRACE_EVENT() macro is broken up into various parts to be efficient.
The TP_fast_assign() is just to record the event into the ring buffer, and
is to be done as fast as possible as this occurs during the actual running
of the code. The slower this is, the slower the code that is being traced
becomes.

The TP_printk() is processed when reading the tracing buffer. This is
considered the slow path. Any processing that can be moved from the
TP_fast_assign() to the TP_printk() should do so.

For some reason, the entire string processing of the trace events
hda_send_cmd, hda_get_response, and hda_unsol_event was moved from the
TP_printk() into the TP_fast_assign(). On top of that, the
__dynamic_array() was used with a fixed size of HDAC_MSG_MAX, which is
useless as a dynamic_array as it will always allocate HDAC_MSG_MAX bytes
on the ring buffer and even save that amount into the event (as it expects
the size to be dynamic, which using a fixed size defeats that purpose).

Instead, just save the necessary elements in the TP_fast_assign() and do
the string manipulation in the slow path.

The output should be the same.

Cc: Jaroslav Kysela <perex@perex.cz>
Cc: Takashi Iwai <tiwai@suse.com>
Cc: alsa-devel@alsa-project.org
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
 sound/hda/trace.h | 41 ++++++++++++++++++++++++++---------------
 1 file changed, 26 insertions(+), 15 deletions(-)

diff --git a/sound/hda/trace.h b/sound/hda/trace.h
index 70af6c815089..2cc493434a8f 100644
--- a/sound/hda/trace.h
+++ b/sound/hda/trace.h
@@ -19,37 +19,48 @@ struct hdac_codec;
 TRACE_EVENT(hda_send_cmd,
 	TP_PROTO(struct hdac_bus *bus, unsigned int cmd),
 	TP_ARGS(bus, cmd),
-	TP_STRUCT__entry(__dynamic_array(char, msg, HDAC_MSG_MAX)),
+	TP_STRUCT__entry(
+		__string(name, dev_name((bus)->dev))
+		__field(u32, cmd)
+	),
 	TP_fast_assign(
-		snprintf(__get_str(msg), HDAC_MSG_MAX,
-			 "[%s:%d] val=0x%08x",
-			 dev_name((bus)->dev), (cmd) >> 28, cmd);
+		__assign_str(name, dev_name((bus)->dev));
+		__entry->cmd = cmd;
 	),
-	TP_printk("%s", __get_str(msg))
+	TP_printk("[%s:%d] val=0x%08x", __get_str(name), __entry->cmd >> 28, __entry->cmd)
 );
 
 TRACE_EVENT(hda_get_response,
 	TP_PROTO(struct hdac_bus *bus, unsigned int addr, unsigned int res),
 	TP_ARGS(bus, addr, res),
-	TP_STRUCT__entry(__dynamic_array(char, msg, HDAC_MSG_MAX)),
+	TP_STRUCT__entry(
+		__string(name, dev_name((bus)->dev))
+		__field(u32, addr)
+		__field(u32, res)
+	),
 	TP_fast_assign(
-		snprintf(__get_str(msg), HDAC_MSG_MAX,
-			 "[%s:%d] val=0x%08x",
-			 dev_name((bus)->dev), addr, res);
+		__assign_str(name, dev_name((bus)->dev));
+		__entry->addr = addr;
+		__entry->res = res;
 	),
-	TP_printk("%s", __get_str(msg))
+	TP_printk("[%s:%d] val=0x%08x", __get_str(name), __entry->addr, __entry->res)
 );
 
 TRACE_EVENT(hda_unsol_event,
 	TP_PROTO(struct hdac_bus *bus, u32 res, u32 res_ex),
 	TP_ARGS(bus, res, res_ex),
-	TP_STRUCT__entry(__dynamic_array(char, msg, HDAC_MSG_MAX)),
+	TP_STRUCT__entry(
+		__string(name, dev_name((bus)->dev))
+		__field(u32, res)
+		__field(u32, res_ex)
+	),
 	TP_fast_assign(
-		snprintf(__get_str(msg), HDAC_MSG_MAX,
-			 "[%s:%d] res=0x%08x, res_ex=0x%08x",
-			 dev_name((bus)->dev), res_ex & 0x0f, res, res_ex);
+		__assign_str(name, dev_name((bus)->dev));
+		__entry->res = res;
+		__entry->res_ex = res_ex;
 	),
-	TP_printk("%s", __get_str(msg))
+	TP_printk("[%s:%d] res=0x%08x, res_ex=0x%08x", __get_str(name),
+		  __entry->res_ex & 0x0f, __entry->res, __entry->res_ex)
 );
 
 DECLARE_EVENT_CLASS(hdac_stream,
-- 
2.35.1

Re: PATCH] tracing: ALSA: hda: Remove string manipulation out of the fast path

[Takashi Iwai]

On Sun, 03 Jul 2022 17:06:05 +0200,
Steven Rostedt wrote:
> 
> From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
> 
> The TRACE_EVENT() macro is broken up into various parts to be efficient.
> The TP_fast_assign() is just to record the event into the ring buffer, and
> is to be done as fast as possible as this occurs during the actual running
> of the code. The slower this is, the slower the code that is being traced
> becomes.
> 
> The TP_printk() is processed when reading the tracing buffer. This is
> considered the slow path. Any processing that can be moved from the
> TP_fast_assign() to the TP_printk() should do so.
> 
> For some reason, the entire string processing of the trace events
> hda_send_cmd, hda_get_response, and hda_unsol_event was moved from the
> TP_printk() into the TP_fast_assign(). On top of that, the
> __dynamic_array() was used with a fixed size of HDAC_MSG_MAX, which is
> useless as a dynamic_array as it will always allocate HDAC_MSG_MAX bytes
> on the ring buffer and even save that amount into the event (as it expects
> the size to be dynamic, which using a fixed size defeats that purpose).
> 
> Instead, just save the necessary elements in the TP_fast_assign() and do
> the string manipulation in the slow path.
> 
> The output should be the same.
> 
> Cc: Jaroslav Kysela <perex@perex.cz>
> Cc: Takashi Iwai <tiwai@suse.com>
> Cc: alsa-devel@alsa-project.org
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>

Thanks, applied now to for-next branch.


Takashi