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). 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. >
