Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1458402 > unrolled thread

[PATCH 1/1] usb: misc: usbtest: add fix for driver hang

Started byLu Baolu <baolu.lu@linux.intel.com>
First post2016-08-09 07:10 +0200
Last post2016-08-10 20:50 +0200
Articles 4 — 3 participants

Back to article view | Back to linux.kernel

Contents

  [PATCH 1/1] usb: misc: usbtest: add fix for driver hang Lu Baolu <baolu.lu@linux.intel.com> - 2016-08-09 07:10 +0200
    Re: [PATCH 1/1] usb: misc: usbtest: add fix for driver hang Felipe Balbi <felipe.balbi@linux.intel.com> - 2016-08-09 11:20 +0200
      Re: [PATCH 1/1] usb: misc: usbtest: add fix for driver hang Alan Stern <stern@rowland.harvard.edu> - 2016-08-09 16:20 +0200
        Re: [PATCH 1/1] usb: misc: usbtest: add fix for driver hang Lu Baolu <baolu.lu@linux.intel.com> - 2016-08-10 20:50 +0200

#1458402 — [PATCH 1/1] usb: misc: usbtest: add fix for driver hang

FromLu Baolu <baolu.lu@linux.intel.com>
Date2016-08-09 07:10 +0200
Subject[PATCH 1/1] usb: misc: usbtest: add fix for driver hang
Message-ID<s47sC-36N-11@gated-at.bofh.it>
In sg_timeout(), req->status is set to "-ETIMEDOUT" before calling
into usb_sg_cancel(). usb_sg_cancel() will do nothing and return
directly if req->status has been set to a non-zero value. This will
cause driver hang as soon as transfer time out is triggered.

In my test case, below system log shows when port reset happens after
urb being submitted.

[55099.746213] usb 2-3: USB disconnect, device number 2
[55321.955451] INFO: task kworker/6:0:59 blocked for more than 120 seconds.
[55321.955463]       Not tainted 4.7.0-rc6+ #19
[55321.955466] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[55321.955472] kworker/6:0     D ffff88045ad3bbf8     0    59      2 0x00000000
[55321.955489] Workqueue: usb_hub_wq hub_event
[55321.955493]  ffff88045ad3bbf8 ffff880400000030 ffff88045ad30f40 ffff88045ad3bbd0
[55321.955499]  ffff88045ad3c000 ffff8804590920fc ffff88045ad30f40 00000000ffffffff
[55321.955505]  ffff880459092100 ffff88045ad3bc10 ffffffff817b5925 ffff8804590920f8
[55321.955511] Call Trace:
[55321.955521]  [<ffffffff817b5925>] schedule+0x35/0x80
[55321.955527]  [<ffffffff817b5c1e>] schedule_preempt_disabled+0xe/0x10
[55321.955533]  [<ffffffff817b7505>] __mutex_lock_slowpath+0x95/0x110
[55321.955538]  [<ffffffff817b759f>] mutex_lock+0x1f/0x2f
[55321.955544]  [<ffffffff815b28a3>] usb_disconnect+0x53/0x270
[55321.955550]  [<ffffffff815b4521>] hub_port_connect+0x71/0x900
[55321.955556]  [<ffffffff815b08be>] ? hub_port_reset+0x3de/0x630
[55321.955562]  [<ffffffff815b53ee>] hub_event+0x63e/0xb20
[55321.955569]  [<ffffffff810ae675>] ? put_prev_entity+0x35/0x730
[55321.955577]  [<ffffffff810921f3>] process_one_work+0x153/0x3f0
[55321.955583]  [<ffffffff810929ab>] worker_thread+0x12b/0x4b0
[55321.955590]  [<ffffffff81092880>] ? rescuer_thread+0x340/0x340
[55321.955595]  [<ffffffff810981c9>] kthread+0xc9/0xe0
[55321.955601]  [<ffffffff817b961f>] ret_from_fork+0x1f/0x40
[55321.955606]  [<ffffffff81098100>] ? kthread_park+0x60/0x60
[55321.955638] INFO: task testusb:3011 blocked for more than 120 seconds.
[55321.955643]       Not tainted 4.7.0-rc6+ #19
[55321.955647] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[55321.955651] testusb         D ffff880449a079f8     0  3011   2367 0x00000000
[55321.955657]  ffff880449a079f8 0000000000000002 ffff88045754cc40 ffffffff815b91b9
[55321.955663]  ffff880449a08000 7fffffffffffffff ffff880449a07cb0 ffff88045754cc40
[55321.955668]  0000000000000000 ffff880449a07a10 ffffffff817b5925 ffff880449a07cb8
[55321.955673] Call Trace:
[55321.955680]  [<ffffffff815b91b9>] ? usb_hcd_submit_urb+0xa9/0xba0
[55321.955685]  [<ffffffff817b5925>] schedule+0x35/0x80
[55321.955691]  [<ffffffff817b8661>] schedule_timeout+0x231/0x2d0
[55321.955698]  [<ffffffff8117a592>] ? __alloc_pages_nodemask+0x112/0x2b0
[55321.955703]  [<ffffffff817b62e4>] wait_for_completion+0xa4/0x110
[55321.955709]  [<ffffffff810a2cb0>] ? wake_up_q+0x80/0x80
[55321.955713]  [<ffffffff815bcf78>] usb_sg_wait+0x138/0x190
[55321.955722]  [<ffffffffc01b6fdf>] perform_sglist+0xef/0x180 [usbtest]
[55321.955728]  [<ffffffffc01b6020>] ? usbtest_resume+0x10/0x10 [usbtest]
[55321.955734]  [<ffffffffc01b9648>] usbtest_do_ioctl+0x898/0x1520 [usbtest]
[55321.955740]  [<ffffffff815ba2a5>] ? usb_hcd_reset_endpoint+0x25/0x60
[55321.955745]  [<ffffffff815bd4f5>] ? usb_enable_endpoint+0x85/0x90
[55321.955751]  [<ffffffffc01ba3f3>] usbtest_ioctl+0x123/0x26e [usbtest]
[55321.955756]  [<ffffffff81172335>] ? filemap_map_pages+0x295/0x310
[55321.955763]  [<ffffffff815c5cc8>] ? proc_ioctl+0x48/0x210
[55321.955769]  [<ffffffff815c5db0>] proc_ioctl+0x130/0x210
[55321.955776]  [<ffffffff815c7d4a>] usbdev_do_ioctl+0x50a/0x1170
[55321.955782]  [<ffffffff815c89de>] usbdev_ioctl+0xe/0x20
[55321.955789]  [<ffffffff81207786>] do_vfs_ioctl+0x96/0x590
[55321.955794]  [<ffffffff81203723>] ? putname+0x53/0x60
[55321.955800]  [<ffffffff81207cf9>] SyS_ioctl+0x79/0x90
[55321.955806]  [<ffffffff817b93f6>] entry_SYSCALL_64_fastpath+0x1e/0xa

This patch fixes this driver hang. It should be back-ported to stable
kernel with version after v3.15.

Cc: stable@vger.kernel.org
Cc: Alan Stern <stern@rowland.harvard.edu>
Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
---
 drivers/usb/misc/usbtest.c | 1 -
 1 file changed, 1 deletion(-)

diff --git a/drivers/usb/misc/usbtest.c b/drivers/usb/misc/usbtest.c
index 6b978f0..6c6586d 100644
--- a/drivers/usb/misc/usbtest.c
+++ b/drivers/usb/misc/usbtest.c
@@ -585,7 +585,6 @@ static void sg_timeout(unsigned long _req)
 {
 	struct usb_sg_request	*req = (struct usb_sg_request *) _req;
 
-	req->status = -ETIMEDOUT;
 	usb_sg_cancel(req);
 }
 
-- 
2.1.4

[toc] | [next] | [standalone]

#1458533

FromFelipe Balbi <felipe.balbi@linux.intel.com>
Date2016-08-09 11:20 +0200
Message-ID<s4bmx-5B6-19@gated-at.bofh.it>
In reply to#1458402

[Multipart message — attachments visible in raw view] — view raw

Hi,

Lu Baolu <baolu.lu@linux.intel.com> writes:
> In sg_timeout(), req->status is set to "-ETIMEDOUT" before calling
> into usb_sg_cancel(). usb_sg_cancel() will do nothing and return
> directly if req->status has been set to a non-zero value. This will
> cause driver hang as soon as transfer time out is triggered.
>
> In my test case, below system log shows when port reset happens after
> urb being submitted.
>
> [55099.746213] usb 2-3: USB disconnect, device number 2
> [55321.955451] INFO: task kworker/6:0:59 blocked for more than 120 seconds.
> [55321.955463]       Not tainted 4.7.0-rc6+ #19
> [55321.955466] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [55321.955472] kworker/6:0     D ffff88045ad3bbf8     0    59      2 0x00000000
> [55321.955489] Workqueue: usb_hub_wq hub_event
> [55321.955493]  ffff88045ad3bbf8 ffff880400000030 ffff88045ad30f40 ffff88045ad3bbd0
> [55321.955499]  ffff88045ad3c000 ffff8804590920fc ffff88045ad30f40 00000000ffffffff
> [55321.955505]  ffff880459092100 ffff88045ad3bc10 ffffffff817b5925 ffff8804590920f8
> [55321.955511] Call Trace:
> [55321.955521]  [<ffffffff817b5925>] schedule+0x35/0x80
> [55321.955527]  [<ffffffff817b5c1e>] schedule_preempt_disabled+0xe/0x10
> [55321.955533]  [<ffffffff817b7505>] __mutex_lock_slowpath+0x95/0x110
> [55321.955538]  [<ffffffff817b759f>] mutex_lock+0x1f/0x2f
> [55321.955544]  [<ffffffff815b28a3>] usb_disconnect+0x53/0x270
> [55321.955550]  [<ffffffff815b4521>] hub_port_connect+0x71/0x900
> [55321.955556]  [<ffffffff815b08be>] ? hub_port_reset+0x3de/0x630
> [55321.955562]  [<ffffffff815b53ee>] hub_event+0x63e/0xb20
> [55321.955569]  [<ffffffff810ae675>] ? put_prev_entity+0x35/0x730
> [55321.955577]  [<ffffffff810921f3>] process_one_work+0x153/0x3f0
> [55321.955583]  [<ffffffff810929ab>] worker_thread+0x12b/0x4b0
> [55321.955590]  [<ffffffff81092880>] ? rescuer_thread+0x340/0x340
> [55321.955595]  [<ffffffff810981c9>] kthread+0xc9/0xe0
> [55321.955601]  [<ffffffff817b961f>] ret_from_fork+0x1f/0x40
> [55321.955606]  [<ffffffff81098100>] ? kthread_park+0x60/0x60
> [55321.955638] INFO: task testusb:3011 blocked for more than 120 seconds.
> [55321.955643]       Not tainted 4.7.0-rc6+ #19
> [55321.955647] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [55321.955651] testusb         D ffff880449a079f8     0  3011   2367 0x00000000
> [55321.955657]  ffff880449a079f8 0000000000000002 ffff88045754cc40 ffffffff815b91b9
> [55321.955663]  ffff880449a08000 7fffffffffffffff ffff880449a07cb0 ffff88045754cc40
> [55321.955668]  0000000000000000 ffff880449a07a10 ffffffff817b5925 ffff880449a07cb8
> [55321.955673] Call Trace:
> [55321.955680]  [<ffffffff815b91b9>] ? usb_hcd_submit_urb+0xa9/0xba0
> [55321.955685]  [<ffffffff817b5925>] schedule+0x35/0x80
> [55321.955691]  [<ffffffff817b8661>] schedule_timeout+0x231/0x2d0
> [55321.955698]  [<ffffffff8117a592>] ? __alloc_pages_nodemask+0x112/0x2b0
> [55321.955703]  [<ffffffff817b62e4>] wait_for_completion+0xa4/0x110
> [55321.955709]  [<ffffffff810a2cb0>] ? wake_up_q+0x80/0x80
> [55321.955713]  [<ffffffff815bcf78>] usb_sg_wait+0x138/0x190
> [55321.955722]  [<ffffffffc01b6fdf>] perform_sglist+0xef/0x180 [usbtest]
> [55321.955728]  [<ffffffffc01b6020>] ? usbtest_resume+0x10/0x10 [usbtest]
> [55321.955734]  [<ffffffffc01b9648>] usbtest_do_ioctl+0x898/0x1520 [usbtest]
> [55321.955740]  [<ffffffff815ba2a5>] ? usb_hcd_reset_endpoint+0x25/0x60
> [55321.955745]  [<ffffffff815bd4f5>] ? usb_enable_endpoint+0x85/0x90
> [55321.955751]  [<ffffffffc01ba3f3>] usbtest_ioctl+0x123/0x26e [usbtest]
> [55321.955756]  [<ffffffff81172335>] ? filemap_map_pages+0x295/0x310
> [55321.955763]  [<ffffffff815c5cc8>] ? proc_ioctl+0x48/0x210
> [55321.955769]  [<ffffffff815c5db0>] proc_ioctl+0x130/0x210
> [55321.955776]  [<ffffffff815c7d4a>] usbdev_do_ioctl+0x50a/0x1170
> [55321.955782]  [<ffffffff815c89de>] usbdev_ioctl+0xe/0x20
> [55321.955789]  [<ffffffff81207786>] do_vfs_ioctl+0x96/0x590
> [55321.955794]  [<ffffffff81203723>] ? putname+0x53/0x60
> [55321.955800]  [<ffffffff81207cf9>] SyS_ioctl+0x79/0x90
> [55321.955806]  [<ffffffff817b93f6>] entry_SYSCALL_64_fastpath+0x1e/0xa
>
> This patch fixes this driver hang. It should be back-ported to stable
> kernel with version after v3.15.
>
> Cc: stable@vger.kernel.org
> Cc: Alan Stern <stern@rowland.harvard.edu>
> Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
> ---
>  drivers/usb/misc/usbtest.c | 1 -
>  1 file changed, 1 deletion(-)
>
> diff --git a/drivers/usb/misc/usbtest.c b/drivers/usb/misc/usbtest.c
> index 6b978f0..6c6586d 100644
> --- a/drivers/usb/misc/usbtest.c
> +++ b/drivers/usb/misc/usbtest.c
> @@ -585,7 +585,6 @@ static void sg_timeout(unsigned long _req)
>  {
>  	struct usb_sg_request	*req = (struct usb_sg_request *) _req;
>  
> -	req->status = -ETIMEDOUT;
>  	usb_sg_cancel(req);
>  }

IMO, req->status = -ETIMEDOUT should still be done, but perhaps after
usb_sg_cancel(). Alan?

-- 
balbi

[toc] | [prev] | [next] | [standalone]

#1458793

FromAlan Stern <stern@rowland.harvard.edu>
Date2016-08-09 16:20 +0200
Message-ID<s4g2R-fu-13@gated-at.bofh.it>
In reply to#1458533
On Tue, 9 Aug 2016, Felipe Balbi wrote:

> 
> Hi,
> 
> Lu Baolu <baolu.lu@linux.intel.com> writes:
> > In sg_timeout(), req->status is set to "-ETIMEDOUT" before calling
> > into usb_sg_cancel(). usb_sg_cancel() will do nothing and return
> > directly if req->status has been set to a non-zero value. This will
> > cause driver hang as soon as transfer time out is triggered.

...

> > This patch fixes this driver hang. It should be back-ported to stable
> > kernel with version after v3.15.
> >
> > Cc: stable@vger.kernel.org
> > Cc: Alan Stern <stern@rowland.harvard.edu>
> > Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
> > ---
> >  drivers/usb/misc/usbtest.c | 1 -
> >  1 file changed, 1 deletion(-)
> >
> > diff --git a/drivers/usb/misc/usbtest.c b/drivers/usb/misc/usbtest.c
> > index 6b978f0..6c6586d 100644
> > --- a/drivers/usb/misc/usbtest.c
> > +++ b/drivers/usb/misc/usbtest.c
> > @@ -585,7 +585,6 @@ static void sg_timeout(unsigned long _req)
> >  {
> >  	struct usb_sg_request	*req = (struct usb_sg_request *) _req;
> >  
> > -	req->status = -ETIMEDOUT;
> >  	usb_sg_cancel(req);
> >  }
> 
> IMO, req->status = -ETIMEDOUT should still be done, but perhaps after
> usb_sg_cancel(). Alan?

That would race with sg_complete(), perhaps causing a bunch of error
messages.  A better approach would be to delete the assignment as
above and then change perform_sglist():

 		usb_sg_wait(req);
-		del_timer_sync(&sg_timer);
 		retval = req->status;
+		if (!del_timer_sync(&sg_timer))
+			retval = -ETIMEDOUT;

Alan Stern

[toc] | [prev] | [next] | [standalone]

#1459516

FromLu Baolu <baolu.lu@linux.intel.com>
Date2016-08-10 20:50 +0200
Message-ID<s4GJI-j6-65@gated-at.bofh.it>
In reply to#1458793
Hi,

On 08/09/2016 10:18 PM, Alan Stern wrote:
> On Tue, 9 Aug 2016, Felipe Balbi wrote:
>
>> Hi,
>>
>> Lu Baolu <baolu.lu@linux.intel.com> writes:
>>> In sg_timeout(), req->status is set to "-ETIMEDOUT" before calling
>>> into usb_sg_cancel(). usb_sg_cancel() will do nothing and return
>>> directly if req->status has been set to a non-zero value. This will
>>> cause driver hang as soon as transfer time out is triggered.
> ...
>
>>> This patch fixes this driver hang. It should be back-ported to stable
>>> kernel with version after v3.15.
>>>
>>> Cc: stable@vger.kernel.org
>>> Cc: Alan Stern <stern@rowland.harvard.edu>
>>> Signed-off-by: Lu Baolu <baolu.lu@linux.intel.com>
>>> ---
>>>  drivers/usb/misc/usbtest.c | 1 -
>>>  1 file changed, 1 deletion(-)
>>>
>>> diff --git a/drivers/usb/misc/usbtest.c b/drivers/usb/misc/usbtest.c
>>> index 6b978f0..6c6586d 100644
>>> --- a/drivers/usb/misc/usbtest.c
>>> +++ b/drivers/usb/misc/usbtest.c
>>> @@ -585,7 +585,6 @@ static void sg_timeout(unsigned long _req)
>>>  {
>>>  	struct usb_sg_request	*req = (struct usb_sg_request *) _req;
>>>  
>>> -	req->status = -ETIMEDOUT;
>>>  	usb_sg_cancel(req);
>>>  }
>> IMO, req->status = -ETIMEDOUT should still be done, but perhaps after
>> usb_sg_cancel(). Alan?
> That would race with sg_complete(), perhaps causing a bunch of error
> messages.  A better approach would be to delete the assignment as
> above and then change perform_sglist():
>
>  		usb_sg_wait(req);
> -		del_timer_sync(&sg_timer);
>  		retval = req->status;
> +		if (!del_timer_sync(&sg_timer))
> +			retval = -ETIMEDOUT;

I agree. I will send v2 with this change included.

I am afraid that req->status is managed by usb core. A spin lock
is used to serialize the change of it. The driver could check the
value of req->status, but should not change it (especially change
it without the hold of the lock). Otherwise, it could cause race or
errors in usb core.

This happens in another driver implemented in drivers/mfd/rtsx_usb.c.

static void rtsx_usb_sg_timed_out(unsigned long data)
{
        struct rtsx_ucr *ucr = (struct rtsx_ucr *)data;

        dev_dbg(&ucr->pusb_intf->dev, "%s: sg transfer timed out", __func__);
        usb_sg_cancel(&ucr->current_sg);

        /* we know the cancellation is caused by time-out */
        ucr->current_sg.status = -ETIMEDOUT;
                                   (^^^^ status being changed by driver without hold of lock)
}

I will send another patch to enhance this later.

Best regards,
Lu Baolu

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web