On 5/11/2023 5:58 PM, Takashi Iwai wrote:
On Thu, 11 May 2023 17:31:37 +0200,
Amadeusz Sławiński wrote:
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)
Sofar, that's the expected behavior. The driver initially mutes the
mixers explicitly. But, something else must unmute the mixer
afterwards for allowing recording.
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.
So far, so good. The mixer amp update during the codec power down
changes only the cache. And, this modified cached value must be
written to the hardware at the codec power up. But...
Then capture stream starts and seems to assume that
registers were already set, so it doesn't write them to hw.
... it seems this didn't happen, and that's the inconsistency.
So the further question is:
At the point just before you start recording, is the codec in runtime
suspended? Or it's running?
If it's runtime-suspended, snd_hda_regmap_sync() must be called from
alc269_resume() via runtime-resume, and this must write out the
cached values. Then the bug can be along with that line.
Or if it's running, it means that the previous check of
snd_hdac_keep_power_up() was bogus (or racy).
Well, it is in... let's call it semi powered state. When snd_hda_intel
driver is loaded with power_save=X option it sets timeout to X seconds
and problem only happens when I start the stream before those X seconds
pass and it runs first runtime suspend. After it suspends it then uses
standard pm_runtime_resume and works correctly. That's why the
pm_runtime_force_suspend(&codec->core.dev); mentioned in first email in
thread "fixes" the problem, as it forces it to be instantly suspended
instead of waiting for timeout and then later normal
resume-play/record-suspend flow can be followed.
Takashi
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.
