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.
