Unverified Commit 5ba3522c authored by Mark Brown's avatar Mark Brown
Browse files

ASoC: SOF: start using tracing instead of dev_dbg 

Merge series from Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>:

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_scripts/suspend_resume_time.bt
parents 717a8ff2 794cd3bd

include/trace/events/sof.h

0 → 100644
+121 −0
Original line number Diff line number Diff line 
/* 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 <linux/types.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)

);



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

);



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 */

#include <trace/define_trace.h>

include/trace/events/sof_intel.h

0 → 100644
+148 −0
Original line number Diff line number Diff line 
/* 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/hdaudio.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))

);



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 */

#include <trace/define_trace.h>

sound/soc/sof/core.c

+3 −0
Original line number Diff line number Diff line
@@ -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);

sound/soc/sof/intel/cnl.c

+3 −6
Original line number Diff line number Diff line
@@ -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) {

sound/soc/sof/intel/hda-dsp.c

+2 −2
Original line number Diff line number Diff line
@@ -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;

}