Re: HDA, power saving and recording

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

On 5/15/2023 3:02 PM, Takashi Iwai wrote:
> On Mon, 15 May 2023 13:19:29 +0200,
> Amadeusz Sławiński wrote:
>>
>> On 5/12/2023 2:24 PM, Takashi Iwai wrote:
>>> On Fri, 12 May 2023 14:00:54 +0200,
>>> Amadeusz Sławiński wrote:
>>>>
>>>> On 5/12/2023 1:33 PM, Takashi Iwai wrote:
>>>>> On Fri, 12 May 2023 13:23:49 +0200,
>>>>> Takashi Iwai wrote:
>>>>>>
>>>>>> On Thu, 11 May 2023 19:20:17 +0200,
>>>>>> Amadeusz Sławiński wrote:
>>>>>>>
>>>>>>> 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:
>>>>>>>>> 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.
>>>>>>
>>>>>> Hm, then maybe it's a bad idea to rely on the usage count there.
>>>>>> Even if the usage is 0, the device can be still active, and the update
>>>>>> can be missed.
>>>>>>
>>>>>> How about the patch like below?
>>>>>
>>>>> Scratch that, it returns a wrong value.
>>>>> A simpler version like below works instead?
>>>>>
>>>>
>>>> Yes it was broken, arecord didn't even start capturing ;)
>>>>
>>>>>
>>>>> Takashi
>>>>>
>>>>> --- a/sound/hda/hdac_device.c
>>>>> +++ b/sound/hda/hdac_device.c
>>>>> @@ -611,10 +611,9 @@ EXPORT_SYMBOL_GPL(snd_hdac_power_up_pm);
>>>>>     int snd_hdac_keep_power_up(struct hdac_device *codec)
>>>>>     {
>>>>>     	if (!atomic_inc_not_zero(&codec->in_pm)) {
>>>>> -		int ret = pm_runtime_get_if_in_use(&codec->dev);
>>>>> -		if (!ret)
>>>>> +		if (!pm_runtime_active(&codec->dev))
>>>>>     			return -1;
>>>>> -		if (ret < 0)
>>>>> +		if (pm_runtime_get_sync(&codec->dev) < 0)
>>>>>     			return 0;
>>>>>     	}
>>>>>     	return 1;
>>>>
>>>>
>>>> This one seems to work, as in I'm able to record before first suspend
>>>> hits. However device stays in D0 when no stream is running...
>>>> # cat /sys/devices/pci0000\:00/0000\:00\:0e.0/power_state
>>>> D0
>>>
>>> OK, one step forward.  The previous change was bad in anyway, as we
>>> shouldn't sync there at all.
>>>
>>> So, the problem becomes clearer now: it's in the lazy update mechanism
>>> that misses the case that has to be written.
>>>
>>> Scratch the previous one again, and could you try the following one
>>> instead?
>>>
>>>
>>> Takashi
>>>
>>> --- a/sound/hda/hdac_regmap.c
>>> +++ b/sound/hda/hdac_regmap.c
>>> @@ -293,8 +293,17 @@ static int hda_reg_write(void *context, unsigned int reg, unsigned int val)
>>>      	if (verb != AC_VERB_SET_POWER_STATE) {
>>>    		pm_lock = codec_pm_lock(codec);
>>> -		if (pm_lock < 0)
>>> -			return codec->lazy_cache ? 0 : -EAGAIN;
>>> +		if (pm_lock < 0) {
>>> +			/* skip the actual write if it's in lazy-update mode
>>> +			 * and only if the device is actually suspended;
>>> +			 * the usage count can be zero at transition phase
>>> +			 * (either suspending/resuming or auto-suspend sleep)
>>> +			 */
>>> +			if (codec->lazy_cache &&
>>> +			    pm_runtime_suspended(&codec->dev))
>>> +				return 0;
>>> +			return -EAGAIN;
>>> +		}
>>>    	}
>>>      	if (is_stereo_amp_verb(reg)) {
>>>
>>
>> With this one we are back to same behavior as without it. When capture
>> is started before first suspend it records silence. After waiting for
>> timeout and suspend it records correctly.
> 
> Hm, interesting.  Does it mean that the pm_runtime_get_if_in_use() (in
> snd_hdac_keep_power_up()) returns a non-zero value?
> Or is pm_runtime_suspended() returns really true there?
> 
> 

So I've tested with vanilla kernel, where pm_runtime_get_if_in_use 
returns -22 until loaded and then 13 times "0" until arecord.

With above patch it returns 13 times "0" and then one more time "1".

pm_runtime_suspended() returns 0 (needed to modify patch a bit)

Patch:

diff --git a/sound/hda/hdac_device.c b/sound/hda/hdac_device.c
index 035b720bf602..62880952e398 100644
--- a/sound/hda/hdac_device.c
+++ b/sound/hda/hdac_device.c
@@ -612,6 +612,7 @@ int snd_hdac_keep_power_up(struct hdac_device *codec)
  {
         if (!atomic_inc_not_zero(&codec->in_pm)) {
                 int ret = pm_runtime_get_if_in_use(&codec->dev);
+               pr_err("DEBUG:%s:%d %s ret=%d\n", __FILE__, __LINE__, 
__func__, ret);
                 if (!ret)
                         return -1;
                 if (ret < 0)
diff --git a/sound/hda/hdac_regmap.c b/sound/hda/hdac_regmap.c
index fe3587547cfe..d6cf3fa2d4e7 100644
--- a/sound/hda/hdac_regmap.c
+++ b/sound/hda/hdac_regmap.c
@@ -293,8 +293,19 @@ static int hda_reg_write(void *context, unsigned 
int reg, unsigned int val)

         if (verb != AC_VERB_SET_POWER_STATE) {
                 pm_lock = codec_pm_lock(codec);
-               if (pm_lock < 0)
-                       return codec->lazy_cache ? 0 : -EAGAIN;
+               if (pm_lock < 0) {
+                       bool x;
+                       /* skip the actual write if it's in lazy-update mode
+                        * and only if the device is actually suspended;
+                        * the usage count can be zero at transition phase
+                        * (either suspending/resuming or auto-suspend 
sleep)
+                        */
+                       x = pm_runtime_suspended(&codec->dev);
+                       pr_err("DEBUG: %s:%d x = %d\n", __FILE__, 
__LINE__, x);
+                       if (codec->lazy_cache && x)
+                               return 0;
+                       return -EAGAIN;
+               }
         }

         if (is_stereo_amp_verb(reg)) {


Part of vanilla dmesg (contains only first chunk):

[   85.152514] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=-22
[   85.153698] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=-22
[   85.162216] snd_hda_core:snd_hdac_display_power: snd_hda_intel 
0000:00:0e.0: display power enable
[   85.166311] input: HDA Intel PCH Mic as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input4
[   85.168075] input: HDA Intel PCH Headphone as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input5
[   85.168867] input: HDA Intel PCH HDMI/DP,pcm=3 as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input6
[   85.169615] input: HDA Intel PCH HDMI/DP,pcm=7 as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input7
[   85.170620] input: HDA Intel PCH HDMI/DP,pcm=8 as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input8
[   85.172761] snd_hda_core:snd_hdac_display_power: snd_hda_intel 
0000:00:0e.0: display power disable
[   85.302102] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302142] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302162] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302181] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302241] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302261] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302282] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302300] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302778] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302800] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302845] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.302864] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   85.340127] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   86.724945] PRE ARECORD
[   86.746549] snd_hda_codec:snd_hda_codec_setup_stream: 
snd_hda_codec_realtek hdaudioC0D0: hda_codec_setup_stream: NID=0x9, 
stream=0x1, channel=0, format=0x11
[   90.805536] snd_hda_core:snd_hdac_display_power: snd_hda_intel 
0000:00:0e.0: display power disable


Part of fully patched dmesg:

[   79.418123] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=-22
[   79.419102] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=-22
[   79.425939] snd_hda_core:snd_hdac_display_power: snd_hda_intel 
0000:00:0e.0: display power enable
[   79.433261] input: HDA Intel PCH Mic as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input4
[   79.436524] input: HDA Intel PCH Headphone as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input5
[   79.437992] input: HDA Intel PCH HDMI/DP,pcm=3 as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input6
[   79.438742] input: HDA Intel PCH HDMI/DP,pcm=7 as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input7
[   79.442223] input: HDA Intel PCH HDMI/DP,pcm=8 as 
/devices/pci0000:00/0000:00:0e.0/sound/card0/input8
[   79.443541] snd_hda_core:snd_hdac_display_power: snd_hda_intel 
0000:00:0e.0: display power disable
[   79.556191] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.556234] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.556256] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.556276] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.556340] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.556362] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.556383] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.556403] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.559139] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.559174] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.559221] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.559243] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.587950] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=0
[   79.588013] DEBUG:sound/hda/hdac_device.c:615 snd_hdac_keep_power_up 
ret=1
[   80.975460] PRE ARECORD
[   80.998701] snd_hda_codec:snd_hda_codec_setup_stream: 
snd_hda_codec_realtek hdaudioC0D0: hda_codec_setup_stream: NID=0x9, 
stream=0x1, channel=0, format=0x11
[   85.674194] snd_hda_core:snd_hdac_display_power: snd_hda_intel 
0000:00:0e.0: display power disable
[   92.229492] snd_hda_codec:__snd_hda_codec_cleanup_stream: 
snd_hda_codec_realtek hdaudioC0D0: hda_codec_cleanup_stream: NID=0x9



I think there are two problems:

1. After probe codec is powered down 
(https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/sound/pci/hda/hda_codec.c#n833), 
even though according to power management it is still running

2. When stream is started before first suspend, resume function doesn't 
run and it is a function which syncs cached registers. By resume 
function I mean 
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/sound/pci/hda/hda_codec.c#n2899 
which calls snd_hda_regmap_sync() or through in case of the platform I 
test it on codec->patch_ops.resume(codec) -> alc269_resume, which also 
calls snd_hda_regmap_sync().