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;
Date:   Tue, 12 Nov 2019 17:25:13 +0100
Message-ID: <s5hzhh1njti.wl-tiwai@suse.de>
From:   Takashi Iwai <tiwai@suse.de>
To:     Henry Lin <henryl@nvidia.com>
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
In-Reply-To: <MN2PR12MB33897DF3AED495FCAF1F421AAC770@MN2PR12MB3389.namprd12.prod.outlook.com>
References: <20191112065108.7766-1-henryl@nvidia.com>
User-Agent: Wanderlust/2.15.9 (Almost Unreal) SEMI/1.14.6 (Maruoka)
 FLIM/1.14.9 (=?UTF-8?B?R29qxY0=?=) APEL/10.8 Emacs/25.3
 (x86_64-suse-linux-gnu) MULE/6.0 (HANACHIRUSATO)
MIME-Version: 1.0 (generated by SEMI 1.14.6 - "Maruoka")
Content-Type: text/plain; charset=US-ASCII
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

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

Ah, I see.  Then you don't have to write up the full stack trace like
the above.  It's confusing as if it were some kernel Oops or WARNING.

BTW, with your patch, is the error in the first line ("timeout: still
1 active urbs on EP #1") also fixed?


thanks,

Takashi