[PATCH 1/2] ASoC: Add trace events for ASoC register read/write

[PATCH 1/2] ASoC: Add trace events for ASoC register read/write

[Mark Brown]

The trace subsystem provides a convenient way of instrumenting the kernel
which can be left on all the time with extremely low impact on the system
unlike prints to the kernel log which can be very spammy. Begin adding
support for instrumenting ASoC via this interface by adding trace for the
register access primitives.

Signed-off-by: Mark Brown <broonie@opensource.wolfsonmicro.com>
---
 include/trace/events/asoc.h |   64 +++++++++++++++++++++++++++++++++++++++++++
 sound/soc/soc-core.c        |    5 +++
 2 files changed, 69 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/asoc.h

diff --git a/include/trace/events/asoc.h b/include/trace/events/asoc.h
new file mode 100644
index 0000000..93c3371
--- /dev/null
+++ b/include/trace/events/asoc.h
@@ -0,0 +1,64 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM asoc
+
+#if !defined(_TRACE_ASOC_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_ASOC_H
+
+#include <linux/ktime.h>
+#include <linux/tracepoint.h>
+
+struct snd_soc_codec;
+
+/*
+ * Log register events
+ */
+DECLARE_EVENT_CLASS(snd_soc_reg,
+
+	TP_PROTO(struct snd_soc_codec *codec, unsigned int reg,
+		 unsigned int val),
+
+	TP_ARGS(codec, reg, val),
+
+	TP_STRUCT__entry(
+		__string(	name,		codec->name	)
+		__field(	int,		id		)
+		__field(	unsigned int,	reg		)
+		__field(	unsigned int,	val		)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, codec->name);
+		__entry->id = codec->id;
+		__entry->reg = reg;
+		__entry->val = val;
+	),
+
+	TP_printk("codec=%s.%d reg=%x val=%x", __get_str(name),
+		  (int)__entry->id, (unsigned int)__entry->reg,
+		  (unsigned int)__entry->val)
+);
+
+DEFINE_EVENT(snd_soc_reg, snd_soc_reg_write,
+
+	TP_PROTO(struct snd_soc_codec *codec, unsigned int reg,
+		 unsigned int val),
+
+	TP_ARGS(codec, reg, val)
+
+);
+
+DEFINE_EVENT(snd_soc_reg, snd_soc_reg_read,
+
+	TP_PROTO(struct snd_soc_codec *codec, unsigned int reg,
+		 unsigned int val),
+
+	TP_ARGS(codec, reg, val)
+
+);
+
+
+
+#endif /* _TRACE_ASOC_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/sound/soc/soc-core.c b/sound/soc/soc-core.c
index c18ce1d..700a6d5 100644
--- a/sound/soc/soc-core.c
+++ b/sound/soc/soc-core.c
@@ -39,6 +39,9 @@
 #include <sound/soc-dapm.h>
 #include <sound/initval.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/asoc.h>
+
 #define NAME_SIZE	32
 
 static DEFINE_MUTEX(pcm_mutex);
@@ -1914,6 +1917,7 @@ unsigned int snd_soc_read(struct snd_soc_codec *codec, unsigned int reg)
 
 	ret = codec->driver->read(codec, reg);
 	dev_dbg(codec->dev, "read %x => %x\n", reg, ret);
+	trace_snd_soc_reg_read(codec, reg, ret);
 
 	return ret;
 }
@@ -1923,6 +1927,7 @@ unsigned int snd_soc_write(struct snd_soc_codec *codec,
 			   unsigned int reg, unsigned int val)
 {
 	dev_dbg(codec->dev, "write %x = %x\n", reg, val);
+	trace_snd_soc_reg_write(codec, reg, val);
 	return codec->driver->write(codec, reg, val);
 }
 EXPORT_SYMBOL_GPL(snd_soc_write);
-- 
1.7.1

[PATCH 2/2] ASoC: Add DAPM trace events

[Mark Brown]

Trace events for DAPM allow us to monitor the performance and behaviour
of DAPM with logging which can be built into the kernel permanantly, is
more suited to automated analysis and display and less likely to suffer
interference from other logging activity.

Currently trace events are generated for:

- Start and stop of DAPM processing
- Start and stop of bias level changes
- Power decisions for widgets
- Widget event execution start and stop

giving some view as to what is happening and where latencies occur.

Actual changes in widget power can be seen via the register write trace in
soc-core.

Signed-off-by: Mark Brown <broonie@opensource.wolfsonmicro.com>
---
 include/trace/events/asoc.h |  112 +++++++++++++++++++++++++++++++++++++++++++
 sound/soc/soc-dapm.c        |   14 +++++
 2 files changed, 126 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/asoc.h b/include/trace/events/asoc.h
index 93c3371..9978856 100644
--- a/include/trace/events/asoc.h
+++ b/include/trace/events/asoc.h
@@ -8,6 +8,8 @@
 #include <linux/tracepoint.h>
 
 struct snd_soc_codec;
+struct snd_soc_card;
+struct snd_soc_dapm_widget;
 
 /*
  * Log register events
@@ -56,7 +58,117 @@ DEFINE_EVENT(snd_soc_reg, snd_soc_reg_read,
 
 );
 
+DECLARE_EVENT_CLASS(snd_soc_card,
 
+	TP_PROTO(struct snd_soc_card *card, int val),
+
+	TP_ARGS(card, val),
+
+	TP_STRUCT__entry(
+		__string(	name,		card->name	)
+		__field(	int,		val		)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, card->name);
+		__entry->val = val;
+	),
+
+	TP_printk("card=%s val=%d", __get_str(name), (int)__entry->val)
+);
+
+DEFINE_EVENT(snd_soc_card, snd_soc_bias_level_start,
+
+	TP_PROTO(struct snd_soc_card *card, int val),
+
+	TP_ARGS(card, val)
+
+);
+
+DEFINE_EVENT(snd_soc_card, snd_soc_bias_level_done,
+
+	TP_PROTO(struct snd_soc_card *card, int val),
+
+	TP_ARGS(card, val)
+
+);
+
+DECLARE_EVENT_CLASS(snd_soc_dapm_basic,
+
+	TP_PROTO(struct snd_soc_card *card),
+
+	TP_ARGS(card),
+
+	TP_STRUCT__entry(
+		__string(	name,	card->name	)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, card->name);
+	),
+
+	TP_printk("card=%s", __get_str(name))
+);
+
+DEFINE_EVENT(snd_soc_dapm_basic, snd_soc_dapm_start,
+
+	TP_PROTO(struct snd_soc_card *card),
+
+	TP_ARGS(card)
+
+);
+
+DEFINE_EVENT(snd_soc_dapm_basic, snd_soc_dapm_done,
+
+	TP_PROTO(struct snd_soc_card *card),
+
+	TP_ARGS(card)
+
+);
+
+DECLARE_EVENT_CLASS(snd_soc_dapm_widget,
+
+	TP_PROTO(struct snd_soc_dapm_widget *w, int val),
+
+	TP_ARGS(w, val),
+
+	TP_STRUCT__entry(
+		__string(	name,	w->name		)
+		__field(	int,	val		)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, w->name);
+		__entry->val = val;
+	),
+
+	TP_printk("widget=%s val=%d", __get_str(name),
+		  (int)__entry->val)
+);
+
+DEFINE_EVENT(snd_soc_dapm_widget, snd_soc_dapm_widget_power,
+
+	TP_PROTO(struct snd_soc_dapm_widget *w, int val),
+
+	TP_ARGS(w, val)
+
+);
+
+DEFINE_EVENT(snd_soc_dapm_widget, snd_soc_dapm_widget_event_start,
+
+	TP_PROTO(struct snd_soc_dapm_widget *w, int val),
+
+	TP_ARGS(w, val)
+
+);
+
+DEFINE_EVENT(snd_soc_dapm_widget, snd_soc_dapm_widget_event_done,
+
+	TP_PROTO(struct snd_soc_dapm_widget *w, int val),
+
+	TP_ARGS(w, val)
+
+);
 
 #endif /* _TRACE_ASOC_H */
 
diff --git a/sound/soc/soc-dapm.c b/sound/soc/soc-dapm.c
index 5a5db3f..8352430 100644
--- a/sound/soc/soc-dapm.c
+++ b/sound/soc/soc-dapm.c
@@ -46,6 +46,8 @@
 #include <sound/soc-dapm.h>
 #include <sound/initval.h>
 
+#include <trace/events/asoc.h>
+
 /* dapm power sequences - make this per codec in the future */
 static int dapm_up_seq[] = {
 	[snd_soc_dapm_pre] = 0,
@@ -151,6 +153,8 @@ static int snd_soc_dapm_set_bias_level(struct snd_soc_card *card,
 		return -EINVAL;
 	}
 
+	trace_snd_soc_bias_level_start(card, level);
+
 	if (card && card->set_bias_level)
 		ret = card->set_bias_level(card, level);
 	if (ret == 0) {
@@ -160,6 +164,8 @@ static int snd_soc_dapm_set_bias_level(struct snd_soc_card *card,
 			dapm->bias_level = level;
 	}
 
+	trace_snd_soc_bias_level_done(card, level);
+
 	return ret;
 }
 
@@ -761,7 +767,9 @@ static void dapm_seq_check_event(struct snd_soc_dapm_context *dapm,
 	if (w->event && (w->event_flags & event)) {
 		pop_dbg(dapm->dev, card->pop_time, "pop test : %s %s\n",
 			w->name, ev_name);
+		trace_snd_soc_dapm_widget_event_start(w, event);
 		ret = w->event(w, NULL, event);
+		trace_snd_soc_dapm_widget_event_done(w, event);
 		if (ret < 0)
 			pr_err("%s: %s event failed: %d\n",
 			       ev_name, w->name, ret);
@@ -921,6 +929,8 @@ static int dapm_power_widgets(struct snd_soc_dapm_context *dapm, int event)
 	int power;
 	int sys_power = 0;
 
+	trace_snd_soc_dapm_start(card);
+
 	/* Check which widgets we need to power and store them in
 	 * lists indicating if they should be powered up or down.
 	 */
@@ -947,6 +957,8 @@ static int dapm_power_widgets(struct snd_soc_dapm_context *dapm, int event)
 			if (w->power == power)
 				continue;
 
+			trace_snd_soc_dapm_widget_power(w, power);
+
 			if (power)
 				dapm_seq_insert(w, &up_list, dapm_up_seq);
 			else
@@ -1037,6 +1049,8 @@ static int dapm_power_widgets(struct snd_soc_dapm_context *dapm, int event)
 		"DAPM sequencing finished, waiting %dms\n", card->pop_time);
 	pop_wait(card->pop_time);
 
+	trace_snd_soc_dapm_done(card);
+
 	return 0;
 }
 
-- 
1.7.1

Re: [PATCH 1/2] ASoC: Add trace events for ASoC register read/write

[Liam Girdwood]

On Wed, 2010-11-10 at 16:39 +0000, Mark Brown wrote:
> The trace subsystem provides a convenient way of instrumenting the kernel
> which can be left on all the time with extremely low impact on the system
> unlike prints to the kernel log which can be very spammy. Begin adding
> support for instrumenting ASoC via this interface by adding trace for the
> register access primitives.
> 
> Signed-off-by: Mark Brown <broonie@opensource.wolfsonmicro.com>

Both

Acked-by: Liam Girdwood <lrg@slimlogic.co.uk>
-- 
Freelance Developer, SlimLogic Ltd
ASoC and Voltage Regulator Maintainer.
http://www.slimlogic.co.uk