From d8bb6d54e49896a2d8585a2e4bfe40873b6e802e Mon Sep 17 00:00:00 2001 From: Noah Klayman Date: Sun, 27 Mar 2022 04:50:30 +0000 Subject: [PATCH 1/7] ASoC: SOF: add widget setup/free tracing Enables tracking of use_count during widget setup and free routines. Useful for debugging unbalanced use_counts during suspend/resume. Signed-off-by: Noah Klayman --- 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 00000000000000..94e8e18605e14d --- /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 +// + +#undef TRACE_SYSTEM +#define TRACE_SYSTEM sof + +#if !defined(_TRACE_SOF_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_SOF_H +#include +#include +#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 diff --git a/sound/soc/sof/core.c b/sound/soc/sof/core.c index 5f43adda0b1187..4ff706a4fb01b3 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 + /* 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 8d740635a4bb84..cd41d0599cef2d 100644 --- a/sound/soc/sof/sof-audio.c +++ b/sound/soc/sof/sof-audio.c @@ -9,6 +9,7 @@ // #include +#include #include "sof-audio.h" #include "ops.h" @@ -35,6 +36,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; @@ -85,6 +88,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 0510ea2e38806a3662ad29ce78ed9cd937c8352b Mon Sep 17 00:00:00 2001 From: Noah Klayman Date: Sun, 27 Mar 2022 05:00:14 +0000 Subject: [PATCH 2/7] ASoC: SOF: Intel: add HDA interrupt source tracing 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. Signed-off-by: Noah Klayman --- 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 00000000000000..11b3fc39714260 --- /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 +// + +#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 +#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 diff --git a/sound/soc/sof/intel/hda.c b/sound/soc/sof/intel/hda.c index 61c924ec6df36b..df03bea5e53624 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 + #if IS_ENABLED(CONFIG_SND_SOC_SOF_HDA) #include #endif @@ -828,17 +831,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 66e8371fb81e8d897c0c23640f48283adffdadaf Mon Sep 17 00:00:00 2001 From: Noah Klayman Date: Fri, 8 Apr 2022 19:23:27 +0000 Subject: [PATCH 3/7] ASoC: SOF: Intel: remove unneeded dev_vdbg This patch removes an unneeded dev_vdbg call in hda-stream. Signed-off-by: Noah Klayman --- 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 daeb64c495e402..12468f2d4e0cde 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 b3c9e8b5653884965432cb57466869cf9cadf561 Mon Sep 17 00:00:00 2001 From: Noah Klayman Date: Fri, 8 Apr 2022 19:28:02 +0000 Subject: [PATCH 4/7] ASoC: SOF: remove unneeded dev_vdbg This patch removes some unneeded dev_vdbg calls. Signed-off-by: Noah Klayman --- 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 a3300ecee06282..b6345a7345af7b 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 0e3647405c5a89..410947b139c8a3 100644 --- a/sound/soc/sof/topology.c +++ b/sound/soc/sof/topology.c @@ -1002,9 +1002,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)) @@ -1488,9 +1485,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 */ @@ -1518,9 +1512,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 ed631ff08ff98a895e5a6e774c39a54519be93d2 Mon Sep 17 00:00:00 2001 From: Noah Klayman Date: Fri, 8 Apr 2022 19:29:52 +0000 Subject: [PATCH 5/7] ASoC: SOF: Intel: replace dev_vdbg with tracepoints This patch replaces all dev_vdbg calls with tracepoints to reduce overhead and enable use of trace collection and analysis tools. Signed-off-by: Noah Klayman --- 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 +- 6 files changed, 128 insertions(+), 20 deletions(-) diff --git a/include/trace/events/sof_intel.h b/include/trace/events/sof_intel.h index 11b3fc39714260..1b6fcb547d2f81 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 +#include #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 d1045ee1584c03..7971d752932b63 100644 --- a/sound/soc/sof/intel/cnl.c +++ b/sound/soc/sof/intel/cnl.c @@ -17,6 +17,7 @@ #include #include +#include #include "../ipc4-priv.h" #include "../ops.h" #include "hda.h" @@ -116,9 +117,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, @@ -143,9 +142,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 56dac2d42e2b17..d8775afd909662 100644 --- a/sound/soc/sof/intel/hda-dsp.c +++ b/sound/soc/sof/intel/hda-dsp.c @@ -18,6 +18,7 @@ #include #include #include +#include #include "../sof-audio.h" #include "../ops.h" #include "hda.h" @@ -389,8 +390,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 84fd36d44c6379..08fccf4d9d690b 100644 --- a/sound/soc/sof/intel/hda-ipc.c +++ b/sound/soc/sof/intel/hda-ipc.c @@ -16,6 +16,7 @@ */ #include +#include #include "../ops.h" #include "hda.h" @@ -206,9 +207,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, @@ -244,9 +243,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, @@ -302,7 +299,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 dc1f743730c0d8..da92300ffa0abf 100644 --- a/sound/soc/sof/intel/hda-pcm.c +++ b/sound/soc/sof/intel/hda-pcm.c @@ -18,6 +18,7 @@ #include #include #include +#include #include "../sof-audio.h" #include "../ops.h" #include "hda.h" @@ -268,8 +269,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 12468f2d4e0cde..724b69d36a6937 100644 --- a/sound/soc/sof/intel/hda-stream.c +++ b/sound/soc/sof/intel/hda-stream.c @@ -19,6 +19,7 @@ #include #include #include +#include #include "../ops.h" #include "../sof-audio.h" #include "hda.h" @@ -692,7 +693,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) @@ -730,8 +731,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); From e0f814dc9b521881b2eb1728f0b8ae2cdefb80ff Mon Sep 17 00:00:00 2001 From: Noah Klayman Date: Fri, 8 Apr 2022 19:31:52 +0000 Subject: [PATCH 6/7] ASoC: SOF: replace dev_vdbg with tracepoints 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 --- 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 94e8e18605e14d..363bea00a2fe5a 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 +#include #include #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 a8ffc4f9956506..ab83615657dc28 100644 --- a/sound/soc/sof/ipc3.c +++ b/sound/soc/sof/ipc3.c @@ -9,6 +9,7 @@ #include #include +#include #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; @@ -204,8 +205,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 a76d0b5b2ad950..9f2c77023ba262 100644 --- a/sound/soc/sof/pcm.c +++ b/sound/soc/sof/pcm.c @@ -13,6 +13,7 @@ #include #include #include +#include #include "sof-priv.h" #include "sof-audio.h" #include "sof-utils.h" @@ -383,9 +384,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 6cb90598f42e78651a837ff642c00470a7ce807b Mon Sep 17 00:00:00 2001 From: Noah Klayman Date: Fri, 8 Apr 2022 19:35:54 +0000 Subject: [PATCH 7/7] ASoC: SOF: replace ipc4-loader dev_vdbg with tracepoints This patch replaces dev_vdbg with tracepoints in new ipc4-loader code. Signed-off-by: Noah Klayman --- 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 363bea00a2fe5a..aaef758eef731f 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 9fadae8fd01142..363067072c9e34 100644 --- a/sound/soc/sof/ipc4-loader.c +++ b/sound/soc/sof/ipc4-loader.c @@ -8,6 +8,7 @@ #include #include #include +#include #include "ipc4-priv.h" #include "sof-audio.h" #include "sof-priv.h" @@ -182,13 +183,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); break; default: break;