On Tue, Apr 15, 2014 at 04:24:10PM +0800, Xiao Jin wrote:
> On 04/15/2014 03:58 AM, Johan Hovold wrote:
> > Jin, did you check what closing_wait setting your application is using?
>
> I check the closing_wait is 30s by default. Below is the trace we get
> when reproduced problem.
>
> <...>-1360 [003] d.s5 1843.061418: acm_tty_write:
> acm_tty_write - write 65
> <...>-1360 [003] d.s5 1843.061425: acm_write_start:
> acm_write_start - susp_count 2
> <...>-2535 [002] .... 1843.180687: acm_tty_close:
> acm_tty_close
> <...>-2535 [002] .... 1843.181217: acm_wb_is_avail: avail n=15
> <...>-2535 [002] .... 1843.181238: acm_port_shutdown:
> acm_port_shutdown
> <...>-438 [003] .... 1843.182803: acm_wb_is_avail: avail n=16
> <...>-438 [003] d..1 1843.182817: acm_tty_write:
> acm_tty_write - write 11
> <...>-438 [003] d..1 1843.182826: acm_write_start:
> acm_write_start - susp_count 2
> <...>-37 [003] .... 1843.202884: acm_resume: wgq[acm_resume]
> <...>-37 [003] .... 1843.202892: acm_resume: wgq[acm_resume]
> <...>-37 [003] d..1 1843.203195: acm_resume: send
> d_wb-1046297992
> <...>-37 [003] .... 1843.203199: acm_start_wb:
> acm_start_wb, acm->transmitting=0
> <idle>-0 [000] d.h2 1843.203343: acm_write_done.isra.11:
> acm_write_done, acm->transmitting=1
> <...>-1989 [001] .... 1843.207197: acm_tty_cleanup:
> acm_tty_cleanup
>
> There are two acms in the case, acm0 and acm3. acm0 have delayed 65
> bytes before close. When acm0 close, ASYNCB_INITIALIZED flag is cleared,
> that lead to acm0 have no chance to start delayed wb during acm resume.
The ASYNCB_INITIALIZED flag is not cleared until chars_in_buffer returns
0 (or closing_wait times out), so this should not be a problem.
What kernel are you using here?
Can you try to reproduce this using a single ACM device with the
diagnostic patch below applied (on top of v3.14 and my autosuspend fix)?
> acm3 delayed 11 bytes send out because it still is opened.
> It looks closing_wait didn't take effect at that time. I am not sure the
> reason why because we have no more debug log. Now We are checking the
> issue again.
>
> > Could you give this patch a try as well?
>
> I try the write and resume part of this patch, anchor urb works well.
Thanks for testing.
Johan
>From 3c622243c33a815f66e606531edd3a7ff4e579bf Mon Sep 17 00:00:00 2001
From: Johan Hovold <jhovold@xxxxxxxxx>
Date: Tue, 15 Apr 2014 10:44:59 +0200
Subject: [PATCH] USB: cdc-acm: add and enable some extra debugging
---
drivers/usb/class/cdc-acm.c | 35 ++++++++++++++++++++++++++++-------
1 file changed, 28 insertions(+), 7 deletions(-)
diff --git a/drivers/usb/class/cdc-acm.c b/drivers/usb/class/cdc-acm.c
index ebbcc7a6a7c8..44aa8a620f89 100644
--- a/drivers/usb/class/cdc-acm.c
+++ b/drivers/usb/class/cdc-acm.c
@@ -28,8 +28,8 @@
* Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
*/
-#undef DEBUG
-#undef VERBOSE_DEBUG
+#define DEBUG
+#define VERBOSE_DEBUG
#include <linux/kernel.h>
#include <linux/errno.h>
@@ -175,6 +175,7 @@ static int acm_wb_is_avail(struct acm *acm)
spin_lock_irqsave(&acm->write_lock, flags);
for (i = 0; i < ACM_NW; i++)
n -= acm->wb[i].use;
+ dev_dbg(&acm->data->dev, "%s - %d\n", __func__, n);
spin_unlock_irqrestore(&acm->write_lock, flags);
return n;
}
@@ -433,6 +434,8 @@ static void acm_write_bulk(struct urb *urb)
struct acm *acm = wb->instance;
unsigned long flags;
+ dev_dbg(&acm->data->dev, "%s\n", __func__);
+
if (urb->status || (urb->actual_length != urb->transfer_buffer_length))
dev_vdbg(&acm->data->dev, "%s - len %d/%d, status %d\n",
__func__,
@@ -632,11 +635,11 @@ static int acm_tty_write(struct tty_struct *tty,
int wbn;
struct acm_wb *wb;
+ dev_vdbg(&acm->data->dev, "%s - count %d, data = %*ph\n", __func__,
+ count, count, buf);
if (!count)
return 0;
- dev_vdbg(&acm->data->dev, "%s - count %d\n", __func__, count);
-
spin_lock_irqsave(&acm->write_lock, flags);
wbn = acm_wb_alloc(acm);
if (wbn < 0) {
@@ -658,6 +661,8 @@ static int acm_tty_write(struct tty_struct *tty,
usb_autopm_get_interface_async(acm->control);
if (acm->susp_count) {
+ dev_dbg(&acm->data->dev, "%s - suspended", __func__);
+
usb_anchor_urb(wb->urb, &acm->delayed);
spin_unlock_irqrestore(&acm->write_lock, flags);
return count;
@@ -675,26 +680,38 @@ static int acm_tty_write(struct tty_struct *tty,
static int acm_tty_write_room(struct tty_struct *tty)
{
struct acm *acm = tty->driver_data;
+ int room;
+
/*
* Do not let the line discipline to know that we have a reserve,
* or it might get too enthusiastic.
*/
- return acm_wb_is_avail(acm) ? acm->writesize : 0;
+ room = acm_wb_is_avail(acm) ? acm->writesize : 0;
+
+ dev_dbg(&acm->data->dev, "%s - %d\n", __func__, room);
+
+ return room;
}
static int acm_tty_chars_in_buffer(struct tty_struct *tty)
{
struct acm *acm = tty->driver_data;
+ int chars = 0;
+
/*
* if the device was unplugged then any remaining characters fell out
* of the connector ;)
*/
if (acm->disconnected)
- return 0;
+ goto out;
/*
* This is inaccurate (overcounts), but it works.
*/
- return (ACM_NW - acm_wb_is_avail(acm)) * acm->writesize;
+ chars = (ACM_NW - acm_wb_is_avail(acm)) * acm->writesize;
+out:
+ dev_dbg(&acm->data->dev, "%s - %d\n", __func__, chars);
+
+ return chars;
}
static void acm_tty_throttle(struct tty_struct *tty)
@@ -1522,6 +1539,8 @@ static int acm_suspend(struct usb_interface *intf, pm_message_t message)
struct acm *acm = usb_get_intfdata(intf);
int cnt;
+ dev_dbg(&intf->dev, "%s\n", __func__);
+
if (PMSG_IS_AUTO(message)) {
int b;
@@ -1554,6 +1573,8 @@ static int acm_resume(struct usb_interface *intf)
int rv = 0;
int cnt;
+ dev_dbg(&intf->dev, "%s\n", __func__);
+
spin_lock_irq(&acm->read_lock);
acm->susp_count -= 1;
cnt = acm->susp_count;
--
1.8.3.2
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
