Tracing ASoC with trace events

Kernel 2.6.38 will add support for tracing ASoC using trace points. Previously all logging for ASoC had been done using printk(), meaning that changing the active logging required a kernel rebuild and that when trace was enabled the volume of trace could easily become very disruptive to other logging within the system. Trace points solve these problems by providing a framework for enabling and disabling individual traces dynamically and separate logging infrastructure designed for easy filtering and post-processing. When using trace points it’s reasonable to leave them enabled all the time, making life much easier especially when debugging intermittent problems.

There’s a bunch of existing documentation out there for the trace subsystem, including some in the kernel under Documentation/trace, which I won’t repeat here. The ASoC events are grouped together under ‘asoc’. The raw log can be viewed by looking at the file tracing/trace in debugfs. Here’s a sample output from starting playback of an MP3 on a Samsung SMDK6410 reference system using WM8580, a high performance six channel CODEC with a very simple software interface:

mplayer-1673  [000]   183.920000: snd_soc_dapm_start: card=SMDK-I2S
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=Rear val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=Center+Sub val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=Front val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=VOUT3R val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=VOUT3L val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=VOUT2R val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=VOUT2L val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=VOUT1R val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=VOUT1L val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=DAC3 val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=DAC2 val=1
mplayer-1673  [000]   183.920000: snd_soc_dapm_widget_power: widget=DAC1 val=1
mplayer-1673  [000]   183.920000: snd_soc_bias_level_start: card=SMDK-I2S val=2
mplayer-1673  [000]   183.920000: snd_soc_bias_level_done: card=SMDK-I2S val=2
mplayer-1673  [000]   183.920000: snd_soc_reg_read: codec=wm8580-codec.0-001b.27 reg=32 val=1e
mplayer-1673  [000]   183.920000: snd_soc_reg_write: codec=wm8580-codec.0-001b.27 reg=32 val=2
mplayer-1673  [000]   183.920000: snd_soc_bias_level_start: card=SMDK-I2S val=3
mplayer-1673  [000]   183.920000: snd_soc_bias_level_done: card=SMDK-I2S val=3
mplayer-1673  [000]   183.920000: snd_soc_dapm_done: card=SMDK-I2S
mplayer-1673  [000]   183.920000: snd_soc_reg_read: codec=wm8580-codec.0-001b.27 reg=13 val=10
mplayer-1673  [000]   183.920000: snd_soc_reg_write: codec=wm8580-codec.0-001b.27 reg=13 val=0

Each line represents a trace event, showing the process that initiated the event, the CPU it ran on and the time it was recorded at together with event-specific details. On this system the time is reported with 10ms accuracy and the CODEC is very simple so the timing information is not terribly informative, but more accurate timers can be really helpful in analysing what’s going on with more complex CODECs. The set of events available will change over time, the key ones currently present in the kernel are:

• snd_soc_dapm_start and snd_soc_dapm_done: These events show the start and stop of the DAPM algorithms, showing the time spent on power management decisions.
• snd_soc_dapm_widget_power events are generated for each of the widgets which DAPM has determined needs to change state. The ‘val=1’ means that all these widgets are being powered up, val=0 would show power down.
• snd_soc_reg_write events show values written to registers.
• snd_soc_reg_read events show values read from registers – these reads may be done from the register cache, or may be from the hardware.
• snd_soc_dapm_widget_event_start and snd_soc_dapm_widget_event_done show the time spent in per-widget event callbacks.

The set of events traced will change as the subsystem develops and as people gain more experience with using the trace API.