Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
From:   Henry Lin <henryl@nvidia.com>
To:     Takashi Iwai <tiwai@suse.de>
CC:     Jaroslav Kysela <perex@perex.cz>,
        Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        Allison Randal <allison@lohutok.net>,
        "Thomas Gleixner" <tglx@linutronix.de>,
        Richard Fontana <rfontana@redhat.com>,
        "alsa-devel@alsa-project.org" <alsa-devel@alsa-project.org>,
        "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>
Subject: Re: [PATCH] usb-audio: not submit urb for stopped endpoint
Thread-Topic: [PATCH] usb-audio: not submit urb for stopped endpoint
Thread-Index: AQHVmSWhBIS3uSZfiEG540j5JX9w96eHJDUAgACGuvc=
Date:   Tue, 12 Nov 2019 16:13:37 +0000
Message-ID: <MN2PR12MB33897DF3AED495FCAF1F421AAC770@MN2PR12MB3389.namprd12.prod.outlook.com>
References: <20191112065108.7766-1-henryl@nvidia.com>,<s5hzhh15z4n.wl-tiwai@suse.de>
In-Reply-To: <s5hzhh15z4n.wl-tiwai@suse.de>
Accept-Language: en-US, zh-TW
received-spf: None (protection.outlook.com: nvidia.com does not designate
 permitted sender hosts)
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: 57763a81-7a58-4c9b-35af-08d7678b4688
X-MS-Exchange-CrossTenant-originalarrivaltime: 12 Nov 2019 16:13:37.6102
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 43083d15-7273-40c1-b7db-39efd9ccc17a
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: j3O7+DTQsp0UTvPPmbKz7iKfzvIRFPv5fgmWayySQTFHiijPd+cpxlBjkd7fwsx2SGWRrYo3xhbd6nyjoHY4iQ==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: MN2PR12MB3934
X-OriginatorOrg: Nvidia.com
Content-Language: en-US
Content-Type: text/plain; charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=nvidia.com; s=n1;
        t=1573575219; bh=DKrfSK4AVXkdnQFIe5+d+ydR2IP4KMzjnn2tEMMWemE=;
        h=X-PGP-Universal:ARC-Seal:ARC-Message-Signature:
         ARC-Authentication-Results:From:To:CC:Subject:Thread-Topic:
         Thread-Index:Date:Message-ID:References:In-Reply-To:
         Accept-Language:X-MS-Has-Attach:X-MS-TNEF-Correlator:
         authentication-results:x-originating-ip:x-ms-publictraffictype:
         x-ms-office365-filtering-correlation-id:x-ms-traffictypediagnostic:
         x-microsoft-antispam-prvs:x-ms-oob-tlc-oobclassifiers:
         x-forefront-prvs:x-forefront-antispam-report:received-spf:
         x-ms-exchange-senderadcheck:x-microsoft-antispam:
         x-microsoft-antispam-message-info:x-ms-exchange-transport-forked:
         MIME-Version:X-MS-Exchange-CrossTenant-Network-Message-Id:
         X-MS-Exchange-CrossTenant-originalarrivaltime:
         X-MS-Exchange-CrossTenant-fromentityheader:
         X-MS-Exchange-CrossTenant-id:X-MS-Exchange-CrossTenant-mailboxtype:
         X-MS-Exchange-CrossTenant-userprincipalname:
         X-MS-Exchange-Transport-CrossTenantHeadersStamped:X-OriginatorOrg:
         Content-Language:Content-Type:Content-Transfer-Encoding;
        b=EcFYymuIG378jPovUfUTnKIO6h+Kntx/5CeLMH0OkPlUvlC95U6h8AgHArQCM7A5J
         BohVmKeoSZxasnHC+PeXNJAkGn4w+obchC2QlMiPYmAUFqMsKNS0df3i0nmccIooGX
         QPWdJ3+UfCFRprDRXS1Pb5wYXryGn18+RX1pewVxpTICPafFWY468cJNUbGSd29elY
         rKgE3bRcObngnjYqE7Je/hjzRgehHVbcFCfdko627vTRObJmDJEZywBD8Tp1q0SFwV
         hDYHBv/NIAIohhjwd2Th14c5IEFPNjHh/Gq72r9SA9qi8JiKyZkFYSMqZWN8h2yYGQ
         ajx1tPHELd9ug==
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

>On Tue, 12 Nov 2019 07:51:06 +0100,=0A=
>Henry Lin wrote:=0A=
>>=0A=
>> While output urb's snd_complete_urb() is executing, calling=0A=
>> prepare_outbound_urb() may cause endpoint stopped before=0A=
>> prepare_outbound_urb() returns and result in next urb submitted=0A=
>> to stopped endpoint. usb-audio driver cannot re-use it afterwards as=0A=
>> the urb is still hold by usb stack.=0A=
>>=0A=
>> This change checks EP_FLAG_RUNNING flag after prepare_outbound_urb() aga=
in=0A=
>> to let snd_complete_urb() know the endpoint already stopped and does not=
=0A=
>> submit next urb.=0A=
=0A=
>OK, this part looks good and understandable.=0A=
=0A=
=0A=
>> We observed two scenario have this issue:=0A=
>> 1. While executing snd_complete_urb() to complete an output urb, calling=
=0A=
>>    prepare_outbound_urb() let deactive_urbs() get called to unlink all=
=0A=
>>    active urbs.=0A=
>>=0A=
>> [  268.097066] [<ffffffc000af7638>] deactivate_urbs+0xd4/0x108=0A=
>> [  268.102633] [<ffffffc000af87fc>] snd_usb_endpoint_stop+0x30/0x58=0A=
>> [  268.108636] [<ffffffc000b0272c>] snd_usb_substream_playback_trigger+0=
xa4/0xf4=0A=
>> [  268.115765] [<ffffffc000acdbd0>] snd_pcm_do_stop+0x4c/0x58=0A=
>> [  268.121245] [<ffffffc000acda24>] snd_pcm_action_single+0x40/0x88=0A=
>> [  268.127245] [<ffffffc000ace984>] snd_pcm_action+0x30/0xf0=0A=
>> [  268.132632] [<ffffffc000acea68>] snd_pcm_stop+0x24/0x2c=0A=
>> [  268.137851] [<ffffffc000ad5e14>] xrun+0x60/0x6c=0A=
>> [  268.142374] [<ffffffc000ad7a98>] snd_pcm_update_state+0xa8/0x10c=0A=
>> [  268.148374] [<ffffffc000ad7e24>] snd_pcm_update_hw_ptr0+0x328/0x344=
=0A=
>> [  268.154635] [<ffffffc000ad7ed8>] snd_pcm_period_elapsed+0x98/0xb0=0A=
>> [  268.160723] [<ffffffc000b02510>] prepare_playback_urb+0x46c/0x488=0A=
>> [  268.166810] [<ffffffc000af7d60>] prepare_outbound_urb+0x60/0x1d4=0A=
>> [  268.172805] [<ffffffc000af8d60>] snd_complete_urb+0x244/0x264=0A=
>> [  268.178548] [<ffffffc00081fb38>] __usb_hcd_giveback_urb+0x94/0x104=0A=
>> [  268.184721] [<ffffffc00081fbe4>] usb_hcd_giveback_urb+0x3c/0x114=0A=
>> [  268.190724] [<ffffffc00084d4b4>] handle_tx_event+0x1304/0x1434=0A=
>> [  268.196552] [<ffffffc00084dbc0>] xhci_handle_event+0x5dc/0x788=0A=
>> [  268.202378] [<ffffffc00084dee4>] xhci_irq+0x178/0x280=0A=
>>=0A=
>> 2. Userspace application stops playback from sound subsystem with below=
=0A=
>>    call stack:=0A=
>>=0A=
>> [   28.506477] CPU: 5 PID: 1274 Comm: AudioOut_25 Not tainted 4.4.38-teg=
ra #31=0A=
>> [   28.513430] Hardware name: quill (DT)=0A=
>> [   28.517085] Call trace:=0A=
>> [   28.519531] [<ffffffc000089a84>] dump_backtrace+0x0/0xf8=0A=
>> [   28.524837] [<ffffffc000089c44>] show_stack+0x14/0x1c=0A=
>> [   28.529885] [<ffffffc000401c54>] dump_stack+0xac/0xe0=0A=
>> [   28.534931] [<ffffffc000b35f94>] deactivate_urbs+0x148/0x180=0A=
>> [   28.540578] [<ffffffc000b37160>] snd_usb_endpoint_stop+0x30/0x58=0A=
>> [   28.546571] [<ffffffc000b410d8>] snd_usb_substream_playback_trigger+0=
xa4/0xf4=0A=
>> [   28.553699] [<ffffffc000b0c160>] snd_pcm_do_stop+0x4c/0x58=0A=
>> [   28.559179] [<ffffffc000b0bfb4>] snd_pcm_action_single+0x40/0x88=0A=
>> [   28.565178] [<ffffffc000b0cf14>] snd_pcm_action+0x30/0xf0=0A=
>> [   28.570568] [<ffffffc000b0fbc8>] snd_pcm_drop+0xac/0x140=0A=
>> [   28.575873] [<ffffffc000b0fc84>] snd_pcm_release_substream+0x28/0xb0=
=0A=
>> [   28.582212] [<ffffffc000b0fd48>] snd_pcm_release+0x3c/0x98=0A=
>> [   28.587686] [<ffffffc0001e3210>] __fput+0xe0/0x1ac=0A=
>> [   28.592469] [<ffffffc0001e3334>] ____fput+0xc/0x14=0A=
>> [   28.597253] [<ffffffc0000c2904>] task_work_run+0xa0/0xc0=0A=
>> [   28.602558] [<ffffffc0000897bc>] do_notify_resume+0x48/0x60=0A=
>> [   28.608123] [<ffffffc000084ee8>] work_pending+0x1c/0x20=0A=
>>=0A=
>> In the call path, snd_pcm_stream spinlock has been acquired in=0A=
>> snd_pcm_drop(). If an output urb is completed between the spinlock=0A=
>> acquired and deactivate_urbs() clears EP_FLAG_RUNNING for the endpoint,=
=0A=
>> its executing of snd_complete_urb() will be blocked for acquiring=0A=
>> snd_pcm_stream spinlock in snd_pcm_period_elapsed() until the lock is=0A=
>> released in snd_pcm_drop(). When snd_complete_urb() continues, all jobs=
=0A=
>> for deactivate_urbs() are finished.=0A=
=0A=
>... but this part is unclear to me.  Do you mean that we have a=0A=
>deadlock in these two concurrent calls without your patch?=0A=
Above describes two different cases that endpoint is stopped before prepare=
_outbound_urb() returns in details. Listed two call stacks belong to differ=
ent cases. Without this patch, both two cases will result in below error me=
ssages afterwards:=0A=
=0A=
[  213.153103] usb 1-2: timeout: still 1 active urbs on EP #1=0A=
[  213.164121] usb 1-2: cannot submit urb 0, error -16: unknown error=