PATCH] tracing: ALSA: hda: Remove string manipulation out of the fast path
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,
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
participants (2)
-
Steven Rostedt
-
Takashi Iwai