Re: HDA, power saving and recording

["Amadeusz Sławiński" <amadeuszx.slawinski@linux.intel.com>]

On 5/10/2023 2:21 PM, Takashi Iwai wrote:
> On Tue, 09 May 2023 12:10:06 +0200,
> Amadeusz Sławiński wrote:
>>
>> Hi Takashi,
>>
>> I have a question related to HDA codecs, power saving and sending verb
>> configuration. In our tests we test avs driver with HDA codec
>> configuration and we see problem when arecord is started before codec
>> goes to first sleep.
>>
>> In ASoC code we set power save timeout to 2 seconds [1], if we start
>> recording before codec goes to sleep, we record only silence.
>>
>> Now I've spend some time investigating the issue and as far as I can
>> tell, when codec is being initialized channels are being set to mute
>> and when one starts stream before first "sleep" it never sends proper
>> configuration to codec.
> 
> Who does set channels to mute?  Or do you mean that the hardware
> initial value set on the codec is muted?  If yes, anyone should have
> unmuted.  Was it tracked?
> 

It is done on probe, first two backtraces in my dmesg show it (one for 
left and other for right channel). It is something along the lines of:
hda_codec_driver_probe -> snd_hda_codec_build_controls -> alc_init -> 
snd_hda_codec_amp_init_stereo and then it writes mute verbs (0x00935080 
and 0x00936080)

>> However if one allows codec to go to sleep
>> proper configuration is being send on resume.
> 
> We need to track down in which level the inconsistency happens.
> First of all, we need to check whether the HD-audio regmap holds the
> right value (unmuted) at the time of the first arecord, as well as the
> actual (raw) value from the codec.
> 
> 

Well, my first idea was that some interaction between power management 
and regmap goes awry somehow.

>> I've also managed to reproduce it with non DSP configuration (using
>> snd_hda_intel driver). One needs to set power_save to non zero value
>> and start recording, before it first goes into first sleep.
>>
>> Here are the steps:
>> 1. Add following to /etc/modprobe.d/test.conf
>> options snd_intel_dspcfg dsp_driver=1
>> options snd_hda_intel power_save=5
>> blacklist snd_hda_intel
>> 2. Reboot the machine
>> 3. Run something like (it is time sensitive, so I just run it all in
>> one line):
>> echo "PRE MODPROBE" > /dev/kmsg; modprobe snd_hda_intel; echo "POST
>> MODPROBE" > /dev/kmsg; sleep 1; echo "PRE ARECORD" > /dev/kmsg;
>> arecord -Dhw:PCH,0 -r48 -c2 -fS16_LE -d 20 -vvv /tmp/cap.wav; echo
>> "POST ARECORD" > /dev/kmsg;
>> 4. Observe silence in above file
>> 5. Run after waiting more than 5 seconds:
>> echo "PRE SECOND ARECORD" > /dev/kmsg; arecord -Dhw:PCH,0 -r48 -c2
>> -fS16_LE -d 20 -vvv /tmp/cap.wav; echo "POST SECOND ARECORD" >
>> /dev/kmsg;
>>
>> I'm also attaching logs from my reproduction with debug.diff (also
>> attached) applied. Main purpose of debug.diff is to log when
>> snd_hdac_exec_verb() is called and to log backtraces for when record
>> input is muted on load and set on startup.
>>
>> When looking at attached dmesg, it is easy to see that when first
>> arecord is being run almost no configuration happens.
> 
> The driver itself doesn't unmute.  It should be alsactl or PA/PW that
> unmutes.  At the initialization, HDA codec driver calls
> snd_hda_codec_amp_init() for each codec amp, and this reads the
> current value from the chip and updates *only* the regmap cache.
> When a program like alsactl/PA/PW updates the mute/volume, it's
> checked with the regmap cache and updated only if the value differs.
> 
> So, the inconsistency may happen at this level, too.  By some reason,
> it might believe the values unchanged, hence the registers might be
> left untouched.
> 
> This needs further checks, obviously...
> 

And playing with controls is good suggestion, it made it a bit easier to 
debug. Seems like hda_reg_write() exits early here:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/sound/hda/hdac_regmap.c#n297
this happens because codec_pm_lock returns -1. While in working case it 
goes through whole hda_reg_write() function.

So codec_pm_lock() calls snd_hdac_keep_power_up(), according to comment 
snd_hdac_keep_power_up() returns -1 when codec is not powered up.

With additional logs I see that when snd_hdac_keep_power_up() is called 
codec->dev->power.usage_count indeed is 0.


The call to snd_hda_power_down() which seems to set power to off, seems 
to be in:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/sound/pci/hda/hda_codec.c#n833


So broken order of operations seems to be:
snd_hda_intel driver gets loaded, it initializes codec. While it 
initializes it sets amplifier to mute. It finishes initialization and 
powers off. Then control gets set from alsactl, but as power is off it 
gets cached. Then capture stream starts and seems to assume that 
registers were already set, so it doesn't write them to hw. Also using 
alsamixer while "broken" stream is running doesn't result in any writes 
being done.

Contrasted with working case:
Codec is being brought up from sleep, registers get set to proper value 
via call to snd_hda_regmap_sync(). Capture stream gets started (and 
assumes that registers were set, and they were this time, as runtime 
resume sets them) and continues with working volume set.


However when I tried to put snd_hda_regmap_sync() in few places while 
stream is started it doesn't seem to help :/ I will continue looking 
tomorrow, but any suggestions are still welcome.