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:
- 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/soun... 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/soun...
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.