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;}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/soun...), 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/soun... 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().