[PATCH 0/7] ASoC: SOF: start using tracing instead of dev_dbg
Multiple maintainers have told us to start using the tracing subsystem. Wish granted, this patchset suggested by Noah Klayman removes a number of verbose and arguably useless dev_dbg or dev_vdbg logs.
Beyond higher efficiency and less intrusive instrumentation, the use of bpftrace scripts bring new functionality and helps gather statistics on usage count on a running system, see how we can get information on suspend/resume times with [1]
[1] https://github.com/thesofproject/sof-test/blob/main/kernel_tracing/bpftrace_...
Bard Liao (2): ASoC: SOF: add widget setup/free tracing ASoC: SOF: Intel: replace dev_vdbg with tracepoints
Noah Klayman (5): ASoC: SOF: Intel: add HDA interrupt source tracing ASoC: SOF: Intel: remove unneeded dev_vdbg ASoC: SOF: remove unneeded dev_vdbg ASoC: SOF: replace dev_vdbg with tracepoints ASoC: SOF: replace ipc4-loader dev_vdbg with tracepoints
include/trace/events/sof.h | 121 +++++++++++++++++++++++++ include/trace/events/sof_intel.h | 148 +++++++++++++++++++++++++++++++ sound/soc/sof/core.c | 3 + sound/soc/sof/intel/cnl.c | 9 +- sound/soc/sof/intel/hda-dsp.c | 4 +- sound/soc/sof/intel/hda-ipc.c | 11 +-- sound/soc/sof/intel/hda-pcm.c | 4 +- sound/soc/sof/intel/hda-stream.c | 9 +- sound/soc/sof/intel/hda.c | 19 +++- sound/soc/sof/intel/mtl.c | 3 +- sound/soc/sof/ipc3.c | 12 +-- sound/soc/sof/ipc4-loader.c | 7 +- sound/soc/sof/pcm.c | 5 +- sound/soc/sof/sof-audio.c | 5 ++ sound/soc/sof/sof-utils.c | 2 - sound/soc/sof/topology.c | 9 -- 16 files changed, 320 insertions(+), 51 deletions(-) create mode 100644 include/trace/events/sof.h create mode 100644 include/trace/events/sof_intel.h
From: Bard Liao yung-chuan.liao@linux.intel.com
Enables tracking of use_count during widget setup and free routines. Useful for debugging unbalanced use_counts during suspend/resume.
Reviewed-by: Péter Ujfalusi peter.ujfalusi@linux.intel.com Signed-off-by: Noah Klayman noah.klayman@intel.com Signed-off-by: Bard Liao yung-chuan.liao@linux.intel.com Signed-off-by: Pierre-Louis Bossart pierre-louis.bossart@linux.intel.com --- include/trace/events/sof.h | 44 ++++++++++++++++++++++++++++++++++++++ sound/soc/sof/core.c | 3 +++ sound/soc/sof/sof-audio.c | 5 +++++ 3 files changed, 52 insertions(+) create mode 100644 include/trace/events/sof.h
diff --git a/include/trace/events/sof.h b/include/trace/events/sof.h new file mode 100644 index 0000000000000..f25eef6c95c09 --- /dev/null +++ b/include/trace/events/sof.h @@ -0,0 +1,44 @@ +/* SPDX-License-Identifier: GPL-2.0-only */ +/* + * Copyright(c) 2022 Intel Corporation. All rights reserved. + * + * Author: Noah Klayman noah.klayman@intel.com + */ + +#undef TRACE_SYSTEM +#define TRACE_SYSTEM sof + +#if !defined(_TRACE_SOF_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_SOF_H +#include <linux/tracepoint.h> +#include <sound/sof/stream.h> +#include "../../../sound/soc/sof/sof-audio.h" + +DECLARE_EVENT_CLASS(sof_widget_template, + TP_PROTO(struct snd_sof_widget *swidget), + TP_ARGS(swidget), + TP_STRUCT__entry( + __string(name, swidget->widget->name) + __field(int, use_count) + ), + TP_fast_assign( + __assign_str(name, swidget->widget->name); + __entry->use_count = swidget->use_count; + ), + TP_printk("name=%s use_count=%d", __get_str(name), __entry->use_count) +); + +DEFINE_EVENT(sof_widget_template, sof_widget_setup, + TP_PROTO(struct snd_sof_widget *swidget), + TP_ARGS(swidget) +); + +DEFINE_EVENT(sof_widget_template, sof_widget_free, + TP_PROTO(struct snd_sof_widget *swidget), + TP_ARGS(swidget) +); + +#endif /* _TRACE_SOF_H */ + +/* This part must be outside protection */ +#include <trace/define_trace.h> diff --git a/sound/soc/sof/core.c b/sound/soc/sof/core.c index c99b5e6c026c1..3e6141d03770f 100644 --- a/sound/soc/sof/core.c +++ b/sound/soc/sof/core.c @@ -15,6 +15,9 @@ #include "sof-priv.h" #include "ops.h"
+#define CREATE_TRACE_POINTS +#include <trace/events/sof.h> + /* see SOF_DBG_ flags */ static int sof_core_debug = IS_ENABLED(CONFIG_SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE); module_param_named(sof_debug, sof_core_debug, int, 0444); diff --git a/sound/soc/sof/sof-audio.c b/sound/soc/sof/sof-audio.c index ea9663d448eb8..a3d3dd7a00375 100644 --- a/sound/soc/sof/sof-audio.c +++ b/sound/soc/sof/sof-audio.c @@ -9,6 +9,7 @@ //
#include <linux/bitfield.h> +#include <trace/events/sof.h> #include "sof-audio.h" #include "sof-of-dev.h" #include "ops.h" @@ -36,6 +37,8 @@ int sof_widget_free(struct snd_sof_dev *sdev, struct snd_sof_widget *swidget) if (!swidget->private) return 0;
+ trace_sof_widget_free(swidget); + /* only free when use_count is 0 */ if (--swidget->use_count) return 0; @@ -86,6 +89,8 @@ int sof_widget_setup(struct snd_sof_dev *sdev, struct snd_sof_widget *swidget) if (!swidget->private) return 0;
+ trace_sof_widget_setup(swidget); + /* widget already set up */ if (++swidget->use_count > 1) return 0;
From: Noah Klayman noah.klayman@intel.com
The Intel HDaudio controller relies on a single interrupt line which wire-ORs multiple interrupt sources, such as stream, IPC, SoundWire and wakes. This patch adds the ability to trace each event occurrence.
Reviewed-by: Bard Liao yung-chuan.liao@linux.intel.com Reviewed-by: Péter Ujfalusi peter.ujfalusi@linux.intel.com Signed-off-by: Noah Klayman noah.klayman@intel.com Signed-off-by: Pierre-Louis Bossart pierre-louis.bossart@linux.intel.com --- include/trace/events/sof_intel.h | 34 ++++++++++++++++++++++++++++++++ sound/soc/sof/intel/hda.c | 19 ++++++++++++++---- 2 files changed, 49 insertions(+), 4 deletions(-) create mode 100644 include/trace/events/sof_intel.h
diff --git a/include/trace/events/sof_intel.h b/include/trace/events/sof_intel.h new file mode 100644 index 0000000000000..37a9b92d494ef --- /dev/null +++ b/include/trace/events/sof_intel.h @@ -0,0 +1,34 @@ +/* SPDX-License-Identifier: GPL-2.0-only */ +/* + * Copyright(c) 2022 Intel Corporation. All rights reserved. + * + * Author: Noah Klayman noah.klayman@intel.com + */ + +#undef TRACE_SYSTEM +#define TRACE_SYSTEM sof_intel + +#if !defined(_TRACE_SOF_INTEL_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_SOF_INTEL_H +#include <linux/tracepoint.h> +#include "../../../sound/soc/sof/sof-audio.h" + +TRACE_EVENT(sof_intel_hda_irq, + TP_PROTO(struct snd_sof_dev *sdev, char *source), + TP_ARGS(sdev, source), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __string(source, source) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __assign_str(source, source); + ), + TP_printk("device_name=%s source=%s", + __get_str(device_name), __get_str(source)) +); + +#endif /* _TRACE_SOF_INTEL_H */ + +/* This part must be outside protection */ +#include <trace/define_trace.h> diff --git a/sound/soc/sof/intel/hda.c b/sound/soc/sof/intel/hda.c index dfb3b424fb5e3..eec54c8bb0e9a 100644 --- a/sound/soc/sof/intel/hda.c +++ b/sound/soc/sof/intel/hda.c @@ -31,6 +31,9 @@ #include "../ops.h" #include "hda.h"
+#define CREATE_TRACE_POINTS +#include <trace/events/sof_intel.h> + #if IS_ENABLED(CONFIG_SND_SOC_SOF_HDA) #include <sound/soc-acpi-intel-match.h> #endif @@ -954,17 +957,25 @@ static irqreturn_t hda_dsp_interrupt_thread(int irq, void *context) struct sof_intel_hda_dev *hdev = sdev->pdata->hw_pdata;
/* deal with streams and controller first */ - if (hda_dsp_check_stream_irq(sdev)) + if (hda_dsp_check_stream_irq(sdev)) { + trace_sof_intel_hda_irq(sdev, "stream"); hda_dsp_stream_threaded_handler(irq, sdev); + }
- if (hda_check_ipc_irq(sdev)) + if (hda_check_ipc_irq(sdev)) { + trace_sof_intel_hda_irq(sdev, "ipc"); sof_ops(sdev)->irq_thread(irq, sdev); + }
- if (hda_dsp_check_sdw_irq(sdev)) + if (hda_dsp_check_sdw_irq(sdev)) { + trace_sof_intel_hda_irq(sdev, "sdw"); hda_dsp_sdw_thread(irq, hdev->sdw); + }
- if (hda_sdw_check_wakeen_irq(sdev)) + if (hda_sdw_check_wakeen_irq(sdev)) { + trace_sof_intel_hda_irq(sdev, "wakeen"); hda_sdw_process_wakeen(sdev); + }
hda_check_for_state_change(sdev);
From: Noah Klayman noah.klayman@intel.com
This patch removes an unneeded dev_vdbg call in hda-stream.
Reviewed-by: Bard Liao yung-chuan.liao@linux.intel.com Reviewed-by: Péter Ujfalusi peter.ujfalusi@linux.intel.com Signed-off-by: Noah Klayman noah.klayman@intel.com Signed-off-by: Pierre-Louis Bossart pierre-louis.bossart@linux.intel.com --- sound/soc/sof/intel/hda-stream.c | 3 --- 1 file changed, 3 deletions(-)
diff --git a/sound/soc/sof/intel/hda-stream.c b/sound/soc/sof/intel/hda-stream.c index b58662faa4aad..8344363beec09 100644 --- a/sound/soc/sof/intel/hda-stream.c +++ b/sound/soc/sof/intel/hda-stream.c @@ -93,9 +93,6 @@ static int hda_setup_bdle(struct snd_sof_dev *sdev, bdl++; hstream->frags++; offset += chunk; - - dev_vdbg(sdev->dev, "bdl, frags:%d, chunk size:0x%x;\n", - hstream->frags, chunk); }
*bdlp = bdl;
From: Noah Klayman noah.klayman@intel.com
This patch removes some unneeded dev_vdbg calls.
Reviewed-by: Bard Liao yung-chuan.liao@linux.intel.com Reviewed-by: Péter Ujfalusi peter.ujfalusi@linux.intel.com Signed-off-by: Noah Klayman noah.klayman@intel.com Signed-off-by: Pierre-Louis Bossart pierre-louis.bossart@linux.intel.com --- sound/soc/sof/sof-utils.c | 2 -- sound/soc/sof/topology.c | 9 --------- 2 files changed, 11 deletions(-)
diff --git a/sound/soc/sof/sof-utils.c b/sound/soc/sof/sof-utils.c index a3300ecee0628..b6345a7345af7 100644 --- a/sound/soc/sof/sof-utils.c +++ b/sound/soc/sof/sof-utils.c @@ -45,8 +45,6 @@ int snd_sof_create_page_table(struct device *dev, u32 pfn = snd_sgbuf_get_addr(dmab, i * PAGE_SIZE) >> PAGE_SHIFT; u8 *pg_table;
- dev_vdbg(dev, "pfn i %i idx %d pfn %x\n", i, idx, pfn); - pg_table = (u8 *)(page_table + idx);
/* diff --git a/sound/soc/sof/topology.c b/sound/soc/sof/topology.c index 9273a70fec25c..6087483deb48e 100644 --- a/sound/soc/sof/topology.c +++ b/sound/soc/sof/topology.c @@ -1011,9 +1011,6 @@ static int sof_connect_dai_widget(struct snd_soc_component *scomp, }
list_for_each_entry(rtd, &card->rtd_list, list) { - dev_vdbg(scomp->dev, "tplg: check widget: %s stream: %s dai stream: %s\n", - w->name, w->sname, rtd->dai_link->stream_name); - /* does stream match DAI link ? */ if (!rtd->dai_link->stream_name || strcmp(w->sname, rtd->dai_link->stream_name)) @@ -1537,9 +1534,6 @@ static int sof_dai_load(struct snd_soc_component *scomp, int index,
stream = SNDRV_PCM_STREAM_PLAYBACK;
- dev_vdbg(scomp->dev, "tplg: pcm %s stream tokens: playback d0i3:%d\n", - spcm->pcm.pcm_name, spcm->stream[stream].d0i3_compatible); - caps = &spcm->pcm.caps[stream];
/* allocate playback page table buffer */ @@ -1567,9 +1561,6 @@ static int sof_dai_load(struct snd_soc_component *scomp, int index, if (!spcm->pcm.capture) return ret;
- dev_vdbg(scomp->dev, "tplg: pcm %s stream tokens: capture d0i3:%d\n", - spcm->pcm.pcm_name, spcm->stream[stream].d0i3_compatible); - caps = &spcm->pcm.caps[stream];
/* allocate capture page table buffer */
From: Bard Liao yung-chuan.liao@linux.intel.com
This patch replaces all dev_vdbg calls with tracepoints to reduce overhead and enable use of trace collection and analysis tools.
Reviewed-by: Péter Ujfalusi peter.ujfalusi@linux.intel.com Signed-off-by: Noah Klayman noah.klayman@intel.com Signed-off-by: Bard Liao yung-chuan.liao@linux.intel.com Signed-off-by: Pierre-Louis Bossart pierre-louis.bossart@linux.intel.com --- include/trace/events/sof_intel.h | 114 +++++++++++++++++++++++++++++++ sound/soc/sof/intel/cnl.c | 9 +-- sound/soc/sof/intel/hda-dsp.c | 4 +- sound/soc/sof/intel/hda-ipc.c | 11 ++- sound/soc/sof/intel/hda-pcm.c | 4 +- sound/soc/sof/intel/hda-stream.c | 6 +- sound/soc/sof/intel/mtl.c | 3 +- 7 files changed, 130 insertions(+), 21 deletions(-)
diff --git a/include/trace/events/sof_intel.h b/include/trace/events/sof_intel.h index 37a9b92d494ef..2a77f9d26c0bf 100644 --- a/include/trace/events/sof_intel.h +++ b/include/trace/events/sof_intel.h @@ -11,6 +11,7 @@ #if !defined(_TRACE_SOF_INTEL_H) || defined(TRACE_HEADER_MULTI_READ) #define _TRACE_SOF_INTEL_H #include <linux/tracepoint.h> +#include <sound/hdaudio.h> #include "../../../sound/soc/sof/sof-audio.h"
TRACE_EVENT(sof_intel_hda_irq, @@ -28,6 +29,119 @@ TRACE_EVENT(sof_intel_hda_irq, __get_str(device_name), __get_str(source)) );
+DECLARE_EVENT_CLASS(sof_intel_ipc_firmware_template, + TP_ARGS(struct snd_sof_dev *sdev, u32 msg, u32 msg_ext), + TP_PROTO(sdev, msg, msg_ext), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __field(u32, msg) + __field(u32, msg_ext) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __entry->msg = msg; + __entry->msg_ext = msg_ext; + ), + TP_printk("device_name=%s msg=%#x msg_ext=%#x", + __get_str(device_name), __entry->msg, __entry->msg_ext) +); + +DEFINE_EVENT(sof_intel_ipc_firmware_template, sof_intel_ipc_firmware_response, + TP_PROTO(struct snd_sof_dev *sdev, u32 msg, u32 msg_ext), + TP_ARGS(sdev, msg, msg_ext) +); + +DEFINE_EVENT(sof_intel_ipc_firmware_template, sof_intel_ipc_firmware_initiated, + TP_PROTO(struct snd_sof_dev *sdev, u32 msg, u32 msg_ext), + TP_ARGS(sdev, msg, msg_ext) +); + +TRACE_EVENT(sof_intel_D0I3C_updated, + TP_PROTO(struct snd_sof_dev *sdev, u8 reg), + TP_ARGS(sdev, reg), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __field(u8, reg) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __entry->reg = reg; + ), + TP_printk("device_name=%s register=%#x", + __get_str(device_name), __entry->reg) +); + +TRACE_EVENT(sof_intel_hda_irq_ipc_check, + TP_PROTO(struct snd_sof_dev *sdev, u32 irq_status), + TP_ARGS(sdev, irq_status), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __field(u32, irq_status) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __entry->irq_status = irq_status; + ), + TP_printk("device_name=%s irq_status=%#x", + __get_str(device_name), __entry->irq_status) +); + +TRACE_EVENT(sof_intel_hda_dsp_pcm, + TP_PROTO(struct snd_sof_dev *sdev, + struct hdac_stream *hstream, + struct snd_pcm_substream *substream, + snd_pcm_uframes_t pos + ), + TP_ARGS(sdev, hstream, substream, pos), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __field(u32, hstream_index) + __field(u32, substream) + __field(unsigned long, pos) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __entry->hstream_index = hstream->index; + __entry->substream = substream->stream; + __entry->pos = pos; + ), + TP_printk("device_name=%s hstream_index=%d substream=%d pos=%lu", + __get_str(device_name), __entry->hstream_index, + __entry->substream, __entry->pos) +); + +TRACE_EVENT(sof_intel_hda_dsp_stream_status, + TP_PROTO(struct device *dev, struct hdac_stream *s, u32 status), + TP_ARGS(dev, s, status), + TP_STRUCT__entry( + __string(device_name, dev_name(dev)) + __field(u32, stream) + __field(u32, status) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(dev)); + __entry->stream = s->index; + __entry->status = status; + ), + TP_printk("device_name=%s stream=%d status=%#x", + __get_str(device_name), __entry->stream, __entry->status) +); + +TRACE_EVENT(sof_intel_hda_dsp_check_stream_irq, + TP_PROTO(struct snd_sof_dev *sdev, u32 status), + TP_ARGS(sdev, status), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __field(u32, status) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __entry->status = status; + ), + TP_printk("device_name=%s status=%#x", + __get_str(device_name), __entry->status) +); + #endif /* _TRACE_SOF_INTEL_H */
/* This part must be outside protection */ diff --git a/sound/soc/sof/intel/cnl.c b/sound/soc/sof/intel/cnl.c index 0bb91df272805..180001d0a38ae 100644 --- a/sound/soc/sof/intel/cnl.c +++ b/sound/soc/sof/intel/cnl.c @@ -17,6 +17,7 @@
#include <sound/sof/ext_manifest4.h> #include <sound/sof/ipc4/header.h> +#include <trace/events/sof_intel.h> #include "../ipc4-priv.h" #include "../ops.h" #include "hda.h" @@ -121,9 +122,7 @@ irqreturn_t cnl_ipc_irq_thread(int irq, void *context) msg_ext = hipci & CNL_DSP_REG_HIPCIDR_MSG_MASK; msg = hipcida & CNL_DSP_REG_HIPCIDA_MSG_MASK;
- dev_vdbg(sdev->dev, - "ipc: firmware response, msg:0x%x, msg_ext:0x%x\n", - msg, msg_ext); + trace_sof_intel_ipc_firmware_response(sdev, msg, msg_ext);
/* mask Done interrupt */ snd_sof_dsp_update_bits(sdev, HDA_DSP_BAR, @@ -153,9 +152,7 @@ irqreturn_t cnl_ipc_irq_thread(int irq, void *context) msg = hipctdr & CNL_DSP_REG_HIPCTDR_MSG_MASK; msg_ext = hipctdd & CNL_DSP_REG_HIPCTDD_MSG_MASK;
- dev_vdbg(sdev->dev, - "ipc: firmware initiated, msg:0x%x, msg_ext:0x%x\n", - msg, msg_ext); + trace_sof_intel_ipc_firmware_initiated(sdev, msg, msg_ext);
/* handle messages from DSP */ if ((hipctdr & SOF_IPC_PANIC_MAGIC_MASK) == SOF_IPC_PANIC_MAGIC) { diff --git a/sound/soc/sof/intel/hda-dsp.c b/sound/soc/sof/intel/hda-dsp.c index 671c3e02d7df8..1319c8e34021b 100644 --- a/sound/soc/sof/intel/hda-dsp.c +++ b/sound/soc/sof/intel/hda-dsp.c @@ -18,6 +18,7 @@ #include <linux/module.h> #include <sound/hdaudio_ext.h> #include <sound/hda_register.h> +#include <trace/events/sof_intel.h> #include "../sof-audio.h" #include "../ops.h" #include "hda.h" @@ -397,8 +398,7 @@ static int hda_dsp_update_d0i3c_register(struct snd_sof_dev *sdev, u8 value) return ret; }
- dev_vdbg(bus->dev, "D0I3C updated, register = 0x%x\n", - snd_hdac_chip_readb(bus, VS_D0I3C)); + trace_sof_intel_D0I3C_updated(sdev, snd_hdac_chip_readb(bus, VS_D0I3C));
return 0; } diff --git a/sound/soc/sof/intel/hda-ipc.c b/sound/soc/sof/intel/hda-ipc.c index 65e688f749eaf..c597ef491d383 100644 --- a/sound/soc/sof/intel/hda-ipc.c +++ b/sound/soc/sof/intel/hda-ipc.c @@ -16,6 +16,7 @@ */
#include <sound/sof/ipc4/header.h> +#include <trace/events/sof_intel.h> #include "../ops.h" #include "hda.h"
@@ -212,9 +213,7 @@ irqreturn_t hda_dsp_ipc_irq_thread(int irq, void *context) msg = hipci & HDA_DSP_REG_HIPCI_MSG_MASK; msg_ext = hipcie & HDA_DSP_REG_HIPCIE_MSG_MASK;
- dev_vdbg(sdev->dev, - "ipc: firmware response, msg:0x%x, msg_ext:0x%x\n", - msg, msg_ext); + trace_sof_intel_ipc_firmware_response(sdev, msg, msg_ext);
/* mask Done interrupt */ snd_sof_dsp_update_bits(sdev, HDA_DSP_BAR, @@ -255,9 +254,7 @@ irqreturn_t hda_dsp_ipc_irq_thread(int irq, void *context) msg = hipct & HDA_DSP_REG_HIPCT_MSG_MASK; msg_ext = hipcte & HDA_DSP_REG_HIPCTE_MSG_MASK;
- dev_vdbg(sdev->dev, - "ipc: firmware initiated, msg:0x%x, msg_ext:0x%x\n", - msg, msg_ext); + trace_sof_intel_ipc_firmware_initiated(sdev, msg, msg_ext);
/* mask BUSY interrupt */ snd_sof_dsp_update_bits(sdev, HDA_DSP_BAR, @@ -312,7 +309,7 @@ bool hda_dsp_check_ipc_irq(struct snd_sof_dev *sdev)
/* store status */ irq_status = snd_sof_dsp_read(sdev, HDA_DSP_BAR, HDA_DSP_REG_ADSPIS); - dev_vdbg(sdev->dev, "irq handler: irq_status:0x%x\n", irq_status); + trace_sof_intel_hda_irq_ipc_check(sdev, irq_status);
/* invalid message ? */ if (irq_status == 0xffffffff) diff --git a/sound/soc/sof/intel/hda-pcm.c b/sound/soc/sof/intel/hda-pcm.c index 6888e0a4665d2..0a9c80216a8c2 100644 --- a/sound/soc/sof/intel/hda-pcm.c +++ b/sound/soc/sof/intel/hda-pcm.c @@ -18,6 +18,7 @@ #include <linux/moduleparam.h> #include <sound/hda_register.h> #include <sound/pcm_params.h> +#include <trace/events/sof_intel.h> #include "../sof-audio.h" #include "../ops.h" #include "hda.h" @@ -196,8 +197,7 @@ snd_pcm_uframes_t hda_dsp_pcm_pointer(struct snd_sof_dev *sdev, found: pos = bytes_to_frames(substream->runtime, pos);
- dev_vdbg(sdev->dev, "PCM: stream %d dir %d position %lu\n", - hstream->index, substream->stream, pos); + trace_sof_intel_hda_dsp_pcm(sdev, hstream, substream, pos); return pos; }
diff --git a/sound/soc/sof/intel/hda-stream.c b/sound/soc/sof/intel/hda-stream.c index 8344363beec09..be60e7785da94 100644 --- a/sound/soc/sof/intel/hda-stream.c +++ b/sound/soc/sof/intel/hda-stream.c @@ -19,6 +19,7 @@ #include <sound/hdaudio_ext.h> #include <sound/hda_register.h> #include <sound/sof.h> +#include <trace/events/sof_intel.h> #include "../ops.h" #include "../sof-audio.h" #include "hda.h" @@ -697,7 +698,7 @@ bool hda_dsp_check_stream_irq(struct snd_sof_dev *sdev) spin_lock_irq(&bus->reg_lock);
status = snd_hdac_chip_readl(bus, INTSTS); - dev_vdbg(bus->dev, "stream irq, INTSTS status: 0x%x\n", status); + trace_sof_intel_hda_dsp_check_stream_irq(sdev, status);
/* if Register inaccessible, ignore it.*/ if (status != 0xffffffff) @@ -736,8 +737,7 @@ static bool hda_dsp_stream_check(struct hdac_bus *bus, u32 status) if (status & BIT(s->index) && s->opened) { sd_status = snd_hdac_stream_readb(s, SD_STS);
- dev_vdbg(bus->dev, "stream %d status 0x%x\n", - s->index, sd_status); + trace_sof_intel_hda_dsp_stream_status(bus->dev, s, sd_status);
snd_hdac_stream_writeb(s, SD_STS, sd_status);
diff --git a/sound/soc/sof/intel/mtl.c b/sound/soc/sof/intel/mtl.c index efc91feb83e9e..5408c34b04ef7 100644 --- a/sound/soc/sof/intel/mtl.c +++ b/sound/soc/sof/intel/mtl.c @@ -11,6 +11,7 @@
#include <linux/firmware.h> #include <sound/sof/ipc4/header.h> +#include <trace/events/sof_intel.h> #include "../ipc4-priv.h" #include "../ops.h" #include "hda.h" @@ -63,7 +64,7 @@ static bool mtl_dsp_check_ipc_irq(struct snd_sof_dev *sdev) hfintipptr = snd_sof_dsp_read(sdev, HDA_DSP_BAR, MTL_HFINTIPPTR) & MTL_HFINTIPPTR_PTR_MASK; irq_status = snd_sof_dsp_read(sdev, HDA_DSP_BAR, hfintipptr + MTL_DSP_IRQSTS);
- dev_vdbg(sdev->dev, "irq handler: irq_status:0x%x\n", irq_status); + trace_sof_intel_hda_irq_ipc_check(sdev, irq_status);
if (irq_status != U32_MAX && (irq_status & MTL_DSP_IRQSTS_IPC)) return true;
From: Noah Klayman noah.klayman@intel.com
This patch removes unneeded dev_vdbg calls and replaces remaining ones with tracepoints to reduce overhead and enable use of trace collection and analysis tools.
Signed-off-by: Noah Klayman noah.klayman@intel.com Reviewed-by: Pierre-Louis Bossart pierre-louis.bossart@linux.intel.com Reviewed-by: Bard Liao yung-chuan.liao@linux.intel.com Reviewed-by: Péter Ujfalusi peter.ujfalusi@linux.intel.com --- include/trace/events/sof.h | 60 ++++++++++++++++++++++++++++++++++++++ sound/soc/sof/ipc3.c | 12 ++++---- sound/soc/sof/pcm.c | 5 ++-- 3 files changed, 68 insertions(+), 9 deletions(-)
diff --git a/include/trace/events/sof.h b/include/trace/events/sof.h index f25eef6c95c09..03751323aaa84 100644 --- a/include/trace/events/sof.h +++ b/include/trace/events/sof.h @@ -11,6 +11,7 @@ #if !defined(_TRACE_SOF_H) || defined(TRACE_HEADER_MULTI_READ) #define _TRACE_SOF_H #include <linux/tracepoint.h> +#include <linux/types.h> #include <sound/sof/stream.h> #include "../../../sound/soc/sof/sof-audio.h"
@@ -38,6 +39,65 @@ DEFINE_EVENT(sof_widget_template, sof_widget_free, TP_ARGS(swidget) );
+TRACE_EVENT(sof_ipc3_period_elapsed_position, + TP_PROTO(struct snd_sof_dev *sdev, struct sof_ipc_stream_posn *posn), + TP_ARGS(sdev, posn), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __field(u64, host_posn) + __field(u64, dai_posn) + __field(u64, wallclock) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __entry->host_posn = posn->host_posn; + __entry->dai_posn = posn->dai_posn; + __entry->wallclock = posn->wallclock; + ), + TP_printk("device_name=%s host_posn=%#llx dai_posn=%#llx wallclock=%#llx", + __get_str(device_name), __entry->host_posn, __entry->dai_posn, + __entry->wallclock) +); + +TRACE_EVENT(sof_pcm_pointer_position, + TP_PROTO(struct snd_sof_dev *sdev, + struct snd_sof_pcm *spcm, + struct snd_pcm_substream *substream, + snd_pcm_uframes_t dma_posn, + snd_pcm_uframes_t dai_posn + ), + TP_ARGS(sdev, spcm, substream, dma_posn, dai_posn), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __field(u32, pcm_id) + __field(int, stream) + __field(unsigned long, dma_posn) + __field(unsigned long, dai_posn) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __entry->pcm_id = le32_to_cpu(spcm->pcm.pcm_id); + __entry->stream = substream->stream; + __entry->dma_posn = dma_posn; + __entry->dai_posn = dai_posn; + ), + TP_printk("device_name=%s pcm_id=%d stream=%d dma_posn=%lu dai_posn=%lu", + __get_str(device_name), __entry->pcm_id, __entry->stream, + __entry->dma_posn, __entry->dai_posn) +); + +TRACE_EVENT(sof_stream_position_ipc_rx, + TP_PROTO(struct device *dev), + TP_ARGS(dev), + TP_STRUCT__entry( + __string(device_name, dev_name(dev)) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(dev)); + ), + TP_printk("device_name=%s", __get_str(device_name)) +); + #endif /* _TRACE_SOF_H */
/* This part must be outside protection */ diff --git a/sound/soc/sof/ipc3.c b/sound/soc/sof/ipc3.c index 82fa320253bef..b28af3a48b707 100644 --- a/sound/soc/sof/ipc3.c +++ b/sound/soc/sof/ipc3.c @@ -9,6 +9,7 @@
#include <sound/sof/stream.h> #include <sound/sof/control.h> +#include <trace/events/sof.h> #include "sof-priv.h" #include "sof-audio.h" #include "ipc3-priv.h" @@ -23,7 +24,7 @@ static void ipc3_log_header(struct device *dev, u8 *text, u32 cmd) u8 *str2 = NULL; u32 glb; u32 type; - bool vdbg = false; + bool is_sof_ipc_stream_position = false;
glb = cmd & SOF_GLB_TYPE_MASK; type = cmd & SOF_CMD_TYPE_MASK; @@ -118,7 +119,7 @@ static void ipc3_log_header(struct device *dev, u8 *text, u32 cmd) case SOF_IPC_STREAM_TRIG_XRUN: str2 = "TRIG_XRUN"; break; case SOF_IPC_STREAM_POSITION: - vdbg = true; + is_sof_ipc_stream_position = true; str2 = "POSITION"; break; case SOF_IPC_STREAM_VORBIS_PARAMS: str2 = "VORBIS_PARAMS"; break; @@ -206,8 +207,8 @@ static void ipc3_log_header(struct device *dev, u8 *text, u32 cmd) }
if (str2) { - if (vdbg) - dev_vdbg(dev, "%s: 0x%x: %s: %s\n", text, cmd, str, str2); + if (is_sof_ipc_stream_position) + trace_sof_stream_position_ipc_rx(dev); else dev_dbg(dev, "%s: 0x%x: %s: %s\n", text, cmd, str, str2); } else { @@ -852,8 +853,7 @@ static void ipc3_period_elapsed(struct snd_sof_dev *sdev, u32 msg_id) return; }
- dev_vdbg(sdev->dev, "posn : host 0x%llx dai 0x%llx wall 0x%llx\n", - posn.host_posn, posn.dai_posn, posn.wallclock); + trace_sof_ipc3_period_elapsed_position(sdev, &posn);
memcpy(&stream->posn, &posn, sizeof(posn));
diff --git a/sound/soc/sof/pcm.c b/sound/soc/sof/pcm.c index 49f7cb049f62d..14571b821ecac 100644 --- a/sound/soc/sof/pcm.c +++ b/sound/soc/sof/pcm.c @@ -13,6 +13,7 @@ #include <linux/pm_runtime.h> #include <sound/pcm_params.h> #include <sound/sof.h> +#include <trace/events/sof.h> #include "sof-of-dev.h" #include "sof-priv.h" #include "sof-audio.h" @@ -384,9 +385,7 @@ static snd_pcm_uframes_t sof_pcm_pointer(struct snd_soc_component *component, dai = bytes_to_frames(substream->runtime, spcm->stream[substream->stream].posn.dai_posn);
- dev_vdbg(component->dev, - "PCM: stream %d dir %d DMA position %lu DAI position %lu\n", - spcm->pcm.pcm_id, substream->stream, host, dai); + trace_sof_pcm_pointer_position(sdev, spcm, substream, host, dai);
return host; }
From: Noah Klayman noah.klayman@intel.com
This patch replaces dev_vdbg with tracepoints in new ipc4-loader code.
Reviewed-by: Bard Liao yung-chuan.liao@linux.intel.com Reviewed-by: Péter Ujfalusi peter.ujfalusi@linux.intel.com Signed-off-by: Noah Klayman noah.klayman@intel.com Signed-off-by: Pierre-Louis Bossart pierre-louis.bossart@linux.intel.com --- include/trace/events/sof.h | 17 +++++++++++++++++ sound/soc/sof/ipc4-loader.c | 7 ++++--- 2 files changed, 21 insertions(+), 3 deletions(-)
diff --git a/include/trace/events/sof.h b/include/trace/events/sof.h index 03751323aaa84..21c2a1efb9f6e 100644 --- a/include/trace/events/sof.h +++ b/include/trace/events/sof.h @@ -98,6 +98,23 @@ TRACE_EVENT(sof_stream_position_ipc_rx, TP_printk("device_name=%s", __get_str(device_name)) );
+TRACE_EVENT(sof_ipc4_fw_config, + TP_PROTO(struct snd_sof_dev *sdev, char *key, u32 value), + TP_ARGS(sdev, key, value), + TP_STRUCT__entry( + __string(device_name, dev_name(sdev->dev)) + __string(key, key) + __field(u32, value) + ), + TP_fast_assign( + __assign_str(device_name, dev_name(sdev->dev)); + __assign_str(key, key); + __entry->value = value; + ), + TP_printk("device_name=%s key=%s value=%d", + __get_str(device_name), __get_str(key), __entry->value) +); + #endif /* _TRACE_SOF_H */
/* This part must be outside protection */ diff --git a/sound/soc/sof/ipc4-loader.c b/sound/soc/sof/ipc4-loader.c index c678f05d0ef55..e635ae515fa9f 100644 --- a/sound/soc/sof/ipc4-loader.c +++ b/sound/soc/sof/ipc4-loader.c @@ -8,6 +8,7 @@ #include <linux/firmware.h> #include <sound/sof/ext_manifest4.h> #include <sound/sof/ipc4/header.h> +#include <trace/events/sof.h> #include "ipc4-priv.h" #include "sof-audio.h" #include "sof-priv.h" @@ -194,13 +195,13 @@ static int sof_ipc4_query_fw_configuration(struct snd_sof_dev *sdev) fw_ver->build); break; case SOF_IPC4_FW_CFG_DL_MAILBOX_BYTES: - dev_vdbg(sdev->dev, "DL mailbox size: %u\n", *tuple->value); + trace_sof_ipc4_fw_config(sdev, "DL mailbox size", *tuple->value); break; case SOF_IPC4_FW_CFG_UL_MAILBOX_BYTES: - dev_vdbg(sdev->dev, "UL mailbox size: %u\n", *tuple->value); + trace_sof_ipc4_fw_config(sdev, "UL mailbox size", *tuple->value); break; case SOF_IPC4_FW_CFG_TRACE_LOG_BYTES: - dev_vdbg(sdev->dev, "Trace log size: %u\n", *tuple->value); + trace_sof_ipc4_fw_config(sdev, "Trace log size", *tuple->value); ipc4_data->mtrace_log_bytes = *tuple->value; break; default:
On Mon, 19 Sep 2022 14:21:01 +0200, Pierre-Louis Bossart wrote:
Multiple maintainers have told us to start using the tracing subsystem. Wish granted, this patchset suggested by Noah Klayman removes a number of verbose and arguably useless dev_dbg or dev_vdbg logs.
Beyond higher efficiency and less intrusive instrumentation, the use of bpftrace scripts bring new functionality and helps gather statistics on usage count on a running system, see how we can get information on suspend/resume times with [1]
[...]
Applied to
broonie/sound.git for-next
Thanks!
[1/7] ASoC: SOF: add widget setup/free tracing commit: fa6e73d69193d0ba3b794f7c303beae498732f40 [2/7] ASoC: SOF: Intel: add HDA interrupt source tracing commit: baedc6300b3d52c71a06f4bddd426488ec243c2b [3/7] ASoC: SOF: Intel: remove unneeded dev_vdbg commit: 032e7c68bb4f4d977d2dd7f7629771973131f15e [4/7] ASoC: SOF: remove unneeded dev_vdbg commit: 4a232cc910b943947a52da363bce1265911555f7 [5/7] ASoC: SOF: Intel: replace dev_vdbg with tracepoints commit: d272b65704bbbb9c054093c8c7dffb7b1793539f [6/7] ASoC: SOF: replace dev_vdbg with tracepoints commit: bcd2cc350ded769963970c4b0074b38bc9240a64 [7/7] ASoC: SOF: replace ipc4-loader dev_vdbg with tracepoints commit: 794cd3bd69315f724532e35fbc1c45dfad9a79e6
All being well this means that it will be integrated into the linux-next tree (usually sometime in the next 24 hours) and sent to Linus during the next merge window (or sooner if it is a bug fix), however if problems are discovered then the patch may be dropped or reverted.
You may get further e-mails resulting from automated or manual testing and review of the tree, please engage with people reporting problems and send followup patches addressing any issues that are reported if needed.
If any updates are required or you are submitting further changes they should be sent as incremental updates against current git, existing patches will not be replaced.
Please add any relevant lists and maintainers to the CCs when replying to this mail.
Thanks, Mark
participants (2)
-
Mark Brown -
Pierre-Louis Bossart