From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from alsa0.perex.cz (alsa0.perex.cz [77.48.224.243]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.lore.kernel.org (Postfix) with ESMTPS id 3D9D3C77B7D for ; Mon, 15 May 2023 14:51:11 +0000 (UTC) Received: from alsa1.perex.cz (alsa1.perex.cz [207.180.221.201]) (using TLSv1.2 with cipher ADH-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by alsa0.perex.cz (Postfix) with ESMTPS id 205511E7; Mon, 15 May 2023 16:50:19 +0200 (CEST) DKIM-Filter: OpenDKIM Filter v2.11.0 alsa0.perex.cz 205511E7 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=alsa-project.org; s=default; t=1684162269; bh=ulHfVzbH+cmHCxYNyNlVgo2oJ//l59SWx7aWt1HJ6PM=; h=Date:Subject:To:Cc:References:From:In-Reply-To:List-Id: List-Archive:List-Help:List-Owner:List-Post:List-Subscribe: List-Unsubscribe:From; b=VdVUl9ccIa5y64H0/Vc322Ykym24tebop85y2UsUFCmVNGtf86vd7Sv2OdYAJdbG8 bFX6VLmv0HZf524v8g92gAAwpwUmYFZkNUne7259i7jwomxOQ0IAs3qtIzxPjH4pH2 72YyJXBhLmLN8KeGg6FW3Kf29Qtn7uHfQLGpxmfE= Received: by alsa1.perex.cz (Postfix, from userid 50401) id 2C6E0F80544; Mon, 15 May 2023 16:50:17 +0200 (CEST) Received: from mailman-core.alsa-project.org (mailman-core.alsa-project.org [10.254.200.10]) by alsa1.perex.cz (Postfix) with ESMTP id 8CBD0F80272; Mon, 15 May 2023 16:50:17 +0200 (CEST) Received: by alsa1.perex.cz (Postfix, from userid 50401) id 6EFB8F80272; Mon, 15 May 2023 16:50:12 +0200 (CEST) Received: from mga14.intel.com (mga14.intel.com [192.55.52.115]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by alsa1.perex.cz (Postfix) with ESMTPS id BC02BF8016D for ; Mon, 15 May 2023 16:49:56 +0200 (CEST) DKIM-Filter: OpenDKIM Filter v2.11.0 alsa1.perex.cz BC02BF8016D Authentication-Results: alsa1.perex.cz; dkim=pass (2048-bit key, unprotected) header.d=intel.com header.i=@intel.com header.a=rsa-sha256 header.s=Intel header.b=OeFi1rkE DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=intel.com; i=@intel.com; q=dns/txt; s=Intel; t=1684162197; x=1715698197; h=message-id:date:mime-version:subject:to:cc:references: from:in-reply-to:content-transfer-encoding; bh=ulHfVzbH+cmHCxYNyNlVgo2oJ//l59SWx7aWt1HJ6PM=; b=OeFi1rkER3ekeCf0ybYugpIJn6g/tFV82Gu5lq74yzzs6qOi884Rs6xL rrOIPddP5kn/FfynwY0vcRmtRSEXJYLDWXbFzi6QWuCO+Z+kVi4xDOwyv rr2ONieafwpvqwtW63zvnKCI7svmWR1GcjOHQwVypKTCaua3qqsoTBdqE TD/qJ5pZkGgk4sXxZX2duALdgGv1Uo+hiMiX4Gon77kGi2BL5N+9LzAPh fO9iYzbGyFoAAJu6bl2FYYr8Bkh0Q3YJdJmrTx184u/vAfWexgIVfq4r0 Y35muJn/XzmJjSl5MbY2BuTKMnZZU+M+9awuXled2BYBmuzF0Rnw+5aE6 A==; X-IronPort-AV: E=McAfee;i="6600,9927,10711"; a="351251863" X-IronPort-AV: E=Sophos;i="5.99,277,1677571200"; d="scan'208";a="351251863" Received: from orsmga006.jf.intel.com ([10.7.209.51]) by fmsmga103.fm.intel.com with ESMTP/TLS/ECDHE-RSA-AES256-GCM-SHA384; 15 May 2023 07:49:52 -0700 X-ExtLoop1: 1 X-IronPort-AV: E=McAfee;i="6600,9927,10711"; a="678465673" X-IronPort-AV: E=Sophos;i="5.99,277,1677571200"; d="scan'208";a="678465673" Received: from aslawinx-mobl.ger.corp.intel.com (HELO [10.99.16.144]) ([10.99.16.144]) by orsmga006-auth.jf.intel.com with ESMTP/TLS/ECDHE-RSA-AES256-GCM-SHA384; 15 May 2023 07:49:50 -0700 Message-ID: <63790c96-215b-bc8c-3ad6-7acbe487d85a@linux.intel.com> Date: Mon, 15 May 2023 16:49:48 +0200 MIME-Version: 1.0 User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.11.0 Subject: Re: HDA, power saving and recording Content-Language: en-US To: Takashi Iwai Cc: Cezary Rojewski , "alsa-devel@alsa-project.org" References: <878rdwjs1s.wl-tiwai@suse.de> <87jzxe5084.wl-tiwai@suse.de> <41417b90-1881-0cbb-52e1-d63923dd8cd6@linux.intel.com> <87ilcxaj3u.wl-tiwai@suse.de> <87fs81ainl.wl-tiwai@suse.de> <7915b40e-a65a-479d-5a2b-062ee3cb432b@linux.intel.com> <87bkipag9z.wl-tiwai@suse.de> <98943bc1-c56c-45aa-06d2-80c618d0585c@linux.intel.com> <878rdplpci.wl-tiwai@suse.de> From: =?UTF-8?Q?Amadeusz_S=c5=82awi=c5=84ski?= In-Reply-To: <878rdplpci.wl-tiwai@suse.de> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit Message-ID-Hash: 5SHVIRZORDGQH4L3YK2JTNOJFCICX77R X-Message-ID-Hash: 5SHVIRZORDGQH4L3YK2JTNOJFCICX77R X-MailFrom: amadeuszx.slawinski@linux.intel.com X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; emergency; loop; banned-address; member-moderation; header-match-alsa-devel.alsa-project.org-0; header-match-alsa-devel.alsa-project.org-1; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header X-Mailman-Version: 3.3.8 Precedence: list List-Id: "Alsa-devel mailing list for ALSA developers - http://www.alsa-project.org" Archived-At: List-Archive: List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: 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().