Fix data loss in cdc-acm

Since acm_process_read_urb does not check the return value of tty_insert_flip_string, it can happen that not all data is copied from the urb to the tty if the tty buffer is full and throttling does not set in quickly enough. This problem is very evident for devices with high data throughput; for a device with ~12 MB/s of data transfer, I get a few missing kB of data every few MB transferred randomly.

To solve this problem, a check is introduced which verifies that indeed all data was copied from the urb to the tty buffer. If that is not the case, the urb is held in a queue instead of resubmitting it to the USB subsystem right away. When new data arrives or the tty is unthrottled, the queue is emptied again (as far as possible).

Effectively, this change will force the transmitting USB device to wait until the tty buffer can accept new data again, instead of discarding the data in this case.

Please excuse the poor code quality, I have no experience whatsoever in kernel development.

---
 drivers/usb/class/cdc-acm.c | 93 +++++++++++++++++++++++++++++++++++++++++----
 drivers/usb/class/cdc-acm.h |  3 ++
 2 files changed, 89 insertions(+), 7 deletions(-)

index 5c8f581..eafe64c 100644
@@ -402,14 +402,68 @@ static int acm_submit_read_urbs(struct acm *acm, gfp_t mem_flags)
 	return 0;
 }
 
-static void acm_process_read_urb(struct acm *acm, struct urb *urb)
+static int acm_process_read_urb(struct acm *acm, struct urb *urb)
 {
+	int size;
+
 	if (!urb->actual_length)
-		return;
+		return 0;
 
-	tty_insert_flip_string(&acm->port, urb->transfer_buffer,
-			urb->actual_length);
+	size = tty_insert_flip_string(&acm->port, urb->transfer_buffer,
+		urb->actual_length);
 	tty_flip_buffer_push(&acm->port);
+	return size;
+}
+
+static bool acm_push_leftover_data_to_tty(struct acm *acm) {
+	int j, k;
+	int urb_index;
+	unsigned long remaining, offset;
+	int written;
+	struct urb *urb;
+	struct acm_rb *rb;
+	bool may_submit_new = true;
+
+	/* TODO: Does this locking mechanism make any sense? I don't know.
+	         Some sort of lock is certainly required. */
+	unsigned long flags;
+	spin_lock_irqsave(&acm->resubmit_lock, flags);
+
+	/* Loop over the queued read urbs, and submit as much data as possible to the tty. */
+	for (j = 0; j < ACM_NR; j++) {
+		urb_index = acm->held_urbs[j];
+		remaining = acm->remaining_data_in_read_urbs[urb_index];
+		if (remaining == 0)
+			continue;
+
+		urb = acm->read_urbs[urb_index];
+		rb = urb->context;
+		offset = urb->actual_length - remaining;
+		written = tty_insert_flip_string(&acm->port, (char*) (urb->transfer_buffer) + offset,
+			remaining);
+		tty_flip_buffer_push(&acm->port);
+		acm->remaining_data_in_read_urbs[urb_index] = remaining - written;
+		if (remaining == written) {
+			/* The urb's buffer was fully submitted to the tty, it can be passed
+			 * to the USB subsystem again. */
+			set_bit(rb->index, &acm->read_urbs_free);
+			acm_submit_read_urb(acm, rb->index, GFP_ATOMIC);
+			acm->num_held_urbs--;
+		}
+		else {
+			/* There is no point in continuing now, the buffer is full */
+			may_submit_new = false;
+			break;
+		}
+	}
+	/* Move the remaining queued urbs to the beginning of the queue */
+	for (k = 0; k < acm->num_held_urbs; k++) {
+		acm->held_urbs[k] = acm->held_urbs[k+j];
+	}
+
+	spin_unlock_irqrestore(&acm->resubmit_lock, flags);
+
+	return may_submit_new;
 }
 
 static void acm_read_bulk_callback(struct urb *urb)

@@ -418,6 +472,11 @@ static void acm_read_bulk_callback(struct urb *urb)
 	struct acm *acm = rb->instance;
 	unsigned long flags;
 	int status = urb->status;
+	int size;
+	bool may_resubmit, may_submit_new;
+
+	/* First look if any filled urbs are still in the queue */
+	may_submit_new = acm_push_leftover_data_to_tty(acm);
 
 	dev_vdbg(&acm->data->dev, "%s - urb %d, len %d\n", __func__,
 					rb->index, urb->actual_length);

@@ -437,20 +496,36 @@ static void acm_read_bulk_callback(struct urb *urb)
 
 	usb_mark_last_busy(acm->dev);
 
-	acm_process_read_urb(acm, urb);
+	/*
+	 * Only try to post data of this new urb if the queue is empty,
+	 * otherwise put it to the end of the queue.
+	 */
+	size = may_submit_new ? acm_process_read_urb(acm, urb) : 0;
+
+	may_resubmit = true;
 	/*
 	 * Unthrottle may run on another CPU which needs to see events
 	 * in the same order. Submission has an implict barrier
 	 */
 	smp_mb__before_atomic();
-	set_bit(rb->index, &acm->read_urbs_free);
+	if (size != urb->actual_length) {
+		/* do not resubmit the urb, but mark it as filled instead */
+		acm->remaining_data_in_read_urbs[rb->index] = urb->actual_length - size;
+		acm->held_urbs[acm->num_held_urbs++] = rb->index;
+		may_resubmit = false;
+	}
+	else {
+		set_bit(rb->index, &acm->read_urbs_free);
+	}
 
 	/* throttle device if requested by tty */
 	spin_lock_irqsave(&acm->read_lock, flags);
 	acm->throttled = acm->throttle_req;
 	if (!acm->throttled) {
 		spin_unlock_irqrestore(&acm->read_lock, flags);
-		acm_submit_read_urb(acm, rb->index, GFP_ATOMIC);
+		if ( may_resubmit ) {
+			acm_submit_read_urb(acm, rb->index, GFP_ATOMIC);
+		}
 	} else {
 		spin_unlock_irqrestore(&acm->read_lock, flags);
 	}

@@ -774,6 +849,8 @@ static void acm_tty_unthrottle(struct tty_struct *tty)
 	acm->throttle_req = 0;
 	spin_unlock_irq(&acm->read_lock);
 
+	acm_push_leftover_data_to_tty(acm);
+
 	if (was_throttled)
 		acm_submit_read_urbs(acm, GFP_KERNEL);
 }

@@ -1367,6 +1444,8 @@ made_compressed_probe:
 		struct acm_rb *rb = &(acm->read_buffers[i]);
 		struct urb *urb;
 
+		acm->remaining_data_in_read_urbs[i] = 0;
+
 		rb->base = usb_alloc_coherent(acm->dev, readsize, GFP_KERNEL,
 								&rb->dma);
 		if (!rb->base)

index ffeb3c8..0946b0a 100644
@@ -93,6 +93,9 @@ struct acm {
 	struct acm_wb wb[ACM_NW];
 	unsigned long read_urbs_free;
 	struct urb *read_urbs[ACM_NR];
+	int held_urbs[ACM_NR+1], num_held_urbs; /* fixed-size queue for not-yet-processed read urbs */
+	unsigned long remaining_data_in_read_urbs[ACM_NR]; /* amount of bytes in each held urb */
+	spinlock_t resubmit_lock;
 	struct acm_rb read_buffers[ACM_NR];
 	int rx_buflimit;
 	int rx_endpoint;

2.4.6

[ +CC: Alan, Oliver, Peter, Toby, linux-serial, linux-usb ]

What kernel version are you using?

The idea of adding another layer of buffering in the cdc-acm driver has been suggested in the past but was rejected (or at least questioned). See for example this thread:

	https://lkml.kernel.org/r/[email protected]

The tty buffers are quite large these days, but could possibly be bumped further if needed to give the ldisc some more time to throttle the device at very high speeds.

Johan

I'm using linux 4.1.2.

Yes, that is indeed pretty much the same problem and the same solution. Answering to the questions brought up in that thread:

As far as I understand, the throttle happens only when there's less than 128 bytes of free space in the tty buffer. Data can already be lost before the tty even decides it should start throttling, simply because the throttle threshold is smaller than the amount of data potentially in each urb. Also (excuse my cluelessness) it seems that when exactly the throttling happens depends on some scheduling "jitter" as well. Additionally, the response of the cdc_acm driver to a throttle request is not very prompt; it might have a queue of up to 16kB (16 urbs) pending.

This I cannot answer, I don't know enough about the architecture or standards. I can just say that for my case, there's a lot of losses; this it not an issue which happens after hours when the system is under heavy load, it happens after just a few seconds reproducably.

I do not like this solution. It will again be based on luck, and you will still be unable to rely on the delivery guarantee made by the USB stack (at least when using bulk).
My suggestion instead stops the host system from accepting any more data from the device when its buffers are full, forcing the device to wait before sending out more data (which many kinds of devices might very well be able to do).

Also note that this patch does not introduce an extra layer of buffering. The buffers are already there; this change just alters the process which decides when to submit the buffers to the tty, and when to free them for more input data from the device.

Sven

Not really. The n_tty ldisc throttles when *its* buffer space is low, but there should still be plenty of room in the tty buffers.

Looks like the ldisc processing is being starved.

In general if data isn't being consumed fast enough we eventually need to drop it (unless we can throttle the producer).

But this isn't necessarily the case in your setup.

See above.

This is what we are supposed to do today, but by relying on the ldisc and tty buffers rather than forcing every driver to implement another custom throttling mechanism.

But something obviously isn't working as intended.

Johan

Hi Sven,

Just to expand on Johan's explanation somewhat.

The tty buffers are separate from the fixed 4KB n_tty line discipline read buffer. The 4KB read buffer holds data which has already been processed as input based on the current termios settings.

The tty buffers hold unprocessed rx data; because the cdc-acm driver does not use per-char flags, the default tty buffer limit amounts to a 128KB buffer, which is roughly 10ms at your line rate of 96Mb/s.

10ms is a long time for a kworker thread (which would indicate throttle) to not be running once scheduled, so I doubt scheduler latency is actually the problem.

More likely suspects are:
1. Because most drivers don't properly handle concurrent throttle/unthrottle, the n_tty line discipline excludes one while the other is in-progress. acm_tty_unthrottle() first clears throttle state, thus letting input proceed, and then continues to submit previously in-flight urbs. During this time, the driver cannot receive throttle notification (ie., acm_tty_throttle() will not be called).

2. The reader/consumer can't process at that line rate, or related, the reader/consumer can't catch up once it has fallen behind.

Some interesting experiments would be:
1. Instrument acm_read_bulk_callback with tty_buffer_space_avail() to track the (approx) fill level of the tty buffers. I would use ftrace/trace_printk() to record this.
2. Similarly instrument acm_tty_throttle/acm_tty_unthrottle.

A driver can set the upper limit of tty buffers on a per-tty basis with tty_buffer_set_limit(). The default limit is 64KB. This limit must be set before the tty can receive input.

Let me know if you need help instrumenting the tty buffers/throttling to help figure out what the actual problem is.

Regarding the patch itself, I have no opinion on the suitability of simply not resubmitting urbs. However, that is exactly how the throttle mechanism works, and the tty buffer API is specifically designed to allow drivers to manage flow via that interface as well (especially for high-throughput drivers).

The n_tty throttle/unthrottle is a very indirect method for restricting flow, and at extremely high bit rates may not be appropriate. (It's mostly a historical vestige from pre-tty buffer days).

Regards,
Peter Hurley

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Could you please expand on how this is supposed to work? For once how does one learn that room is available again?

Regards
Oliver

There are basically 3 mechanisms for managing rx data:
1. Allocate space when the data arrives; drop data if no space is avail and indicate buf_overrun. This is what most drivers do.
2. Allocate space when the data arrives; try to buffer uncopied data and resubmit the data later. Some high-throughput drivers (in the wild) do this (but less so now that the tty buffer space is configurable).
3. Pre-allocate space _before_ the data arrives (with tty_buffer_request_room()); this is applicable to subsystems which know how much data can be in-flight at any one time. This guarantees that when rx data arrives buffer space is available (since it has already been allocated).

Drivers that use method 2 typically attempt to recopy the buffered data when either new data arrives or @ unthrottle. I've seen others use deferred work as well.

AFAIK no driver/subsystem is using method 3 for guaranteed delivery of in-flight data, but it seems ideally suited to usb serial.

Regards,
Peter Hurley

Indeed. But flow control is still done by throttle/unthrottle, isn't it?

Regards
Oliver

Oliver, somehow I never saw this. Please accept my apologies.

Well, input flow control from the driver would be implicitly limited by a failure to allocate new buffer space after the old buffer was inserted and pushed. In the case of urbs, this would simply mean that the urb could not be resubmitted yet, and would have to be deferred. So preventing buffer overrun wouldn't rely on throttle.

WRT flow control, method 3 only needs to know when to resume. As with method 2, this could be @ unthrottle or by retry in deferred work (essentially polling). At least that's what's currently available.

Regardless, tty drivers should still respond to throttle/unthrottle requests so as to limit input data when there is no active reader.

All that being said, unthrottle behaves degenerately at very high line rates and throughput, which needs to be resolved.

The central issue is that the wrong thread is evaluating the wrong conditions for restart. A further complication is that unthrottle is guaranteed race-free reads of struct termios which limit the contexts from which unthrottle can be called.

So to recap; the tty buffer api already provides the necessary interface for preventing buffer overrun and drivers/subsystems with very high line rates should be utilizing that interface instead of relying on throttle.

In addition, a more reliable/appropriate method of restart is required (preferably by fixing when/why unthrottle is invoked). I'll look into that.

Regards,
Peter Hurley
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Yes, but that was not really a modem. The stuff on the other end doesn't come over an external conection.

Then there is a problem in the tty code. Now it may not have enough information, but there is no point of turning the buffers of cdc-acm into an inofficial buffer.

Then the tty layer needs to throttle earlier. In the general case we must be ready to throw away data.

But others won't and we'd preserve stale data in preference over fresh data.

It does. It turns those buffers from temporary scratch buffers into a queue.

Regards
Oliver

Hi,

Thank you for your comments.

If that is important for your device, you should be using an isochronous endpoint, not bulk, no?
Also note that the driver currently does this anyways. It loses a few kB of data, and _then_ it throttles the producer and forces it to wait.

Yes, maybe this is the first thing which should be cleared up: Is "throttle the producer" always preferable over "lose data"? I'd say yes for bulk transfers, no for isochronous. It is in principle easy enough to throttle the producer, that is what e.g. my patch does. Whether a different approach may be more appropriate than the "don't resubmit the urbs" thing is then of course open to debate.

As far as I can see, throttling the producer is the only way to guarantee data delivery. So if we want that (and I certainly want it for my application, I don't know about the general case), I think all changes to the tty buffers or throttling mechanisms are "just" performance optimization, since no such modification will ever guarantee delivery if the producer is not throttled in time.
And, this I want to mention again, if your producer is timing-sensitive you would not be using bulk anyways. The USB controller could just decide that your device cannot send data for the next five seconds, and it will have to handle that case as well. Thus I see no reason to not throttle the producer if necessary.

I already did this while debugging. For a while, the buffer is almost empty (fluctuates by a few kB), then it rapidly drops to zero bytes free. Only after a few urbs where submitted (or rather, not submitted) into the full buffer, the throttle flag gets set.

Thank you for your offer to help figuring out what exactly goes wrong with the throttling mechanism. If it turns out we should actually look for a fix there, I'll be happy to make use of it.

Best,
Sven

It's unclear to me that you haven't hit some other bug (buffer miscalc, failure to progress, etc.) which is affecting other users but just not to the extent you're experiencing.

For example, I made changes to the conditions required to restart the input worker; I may have omitted some necessary condition which you've triggered.

I'd like to see that data, if you can, which will help me understand at least the timing.

Regards,
Peter Hurley

Hey,

Sure, please see below for the code which produced the output and the actual output. Let me know if you need anything else. This was run with the unmodified version of the driver, i.e. without my patch.

Sven
------

Code which produced the output:

index 5c8f581..3d26c87 100644
@@ -404,12 +404,16 @@ static int acm_submit_read_urbs(struct acm *acm, gfp_t mem_flags)
 
 static void acm_process_read_urb(struct acm *acm, struct urb *urb)
 {
+    int written;
+
        if (!urb->actual_length)
                return;
 
-       tty_insert_flip_string(&acm->port, urb->transfer_buffer,
+       written = tty_insert_flip_string(&acm->port, urb->transfer_buffer,
                        urb->actual_length);
        tty_flip_buffer_push(&acm->port);
+    printk("cdc-acm: acm_process_read_urb: processed %d of %d (free space left: %d)\n",
+           written, urb->actual_length, tty_buffer_space_avail(&acm->port));
 }
 
 static void acm_read_bulk_callback(struct urb *urb)

@@ -448,6 +452,9 @@ static void acm_read_bulk_callback(struct urb *urb)
        /* throttle device if requested by tty */
        spin_lock_irqsave(&acm->read_lock, flags);
        acm->throttled = acm->throttle_req;
+    if (acm->throttle_req) {
+        printk("cdc-acm: acm_read_bulk_callback: throttle requested\n");
+    }
        if (!acm->throttled) {
                spin_unlock_irqrestore(&acm->read_lock, flags);
                acm_submit_read_urb(acm, rb->index, GFP_ATOMIC);

@@ -758,6 +765,9 @@ static void acm_tty_throttle(struct tty_struct *tty)
 {
        struct acm *acm = tty->driver_data;
 
+    printk("cdc-acm: acm_tty_throttle: called; free space in tty: %d\n",
+           tty_buffer_space_avail(&acm->port));
+
        spin_lock_irq(&acm->read_lock);
        acm->throttle_req = 1;
        spin_unlock_irq(&acm->read_lock);

@@ -768,6 +778,9 @@ static void acm_tty_unthrottle(struct tty_struct *tty)
        struct acm *acm = tty->driver_data;
        unsigned int was_throttled;
 
+    printk("cdc-acm: acm_tty_unthrottle: called; free space in tty: %d\n",
+           tty_buffer_space_avail(&acm->port));
+
        spin_lock_irq(&acm->read_lock);
        was_throttled = acm->throttled;
        acm->throttled = 0;

______________________________
Output from dmesg (cut a bit in the beginning):

[...]

[62517.602478] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.602480] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.602483] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.602485] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.602487] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61184)
[62517.602489] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61184)
[62517.602494] cdc-acm: acm_tty_throttle: called; free space in tty: 63488
[62517.602600] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.602602] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602603] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.602604] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602606] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.602607] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602609] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.602610] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602612] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 60416)
[62517.602613] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602726] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.602727] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602729] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.602730] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602731] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.602732] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602734] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.602735] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602737] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.602738] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.602959] cdc-acm: acm_tty_unthrottle: called; free space in tty: 64512
[62517.603852] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 64256)
[62517.603856] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.603858] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.603976] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.603979] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.603981] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.603983] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.603985] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.603991] cdc-acm: acm_tty_throttle: called; free space in tty: 63488
[62517.604101] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 64512)
[62517.604103] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.604105] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.604105] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.604107] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.604108] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.604110] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.604111] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.604113] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.604115] cdc-acm: acm_tty_unthrottle: called; free space in tty: 62464
[62517.604121] cdc-acm: acm_tty_throttle: called; free space in tty: 64512
[62517.604227] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.604228] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.604230] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.604231] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.604233] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.604234] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.604235] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.604236] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.604375] cdc-acm: acm_tty_unthrottle: called; free space in tty: 64512
[62517.605355] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 64256)
[62517.605358] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.605360] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.605362] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.605364] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.605371] cdc-acm: acm_tty_throttle: called; free space in tty: 64512
[62517.605478] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.605479] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605481] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.605482] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605484] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.605485] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605487] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.605488] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605490] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.605491] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605602] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.605603] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605605] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.605606] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605608] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.605609] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605610] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.605611] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605613] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.605614] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605726] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.605728] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605729] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.605730] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.605891] cdc-acm: acm_tty_unthrottle: called; free space in tty: 64512
[62517.606858] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 64256)
[62517.606862] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.606864] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.606866] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.606868] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.606871] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61184)
[62517.606873] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61184)
[62517.606881] cdc-acm: acm_tty_throttle: called; free space in tty: 63488
[62517.606978] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.606980] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.606982] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.606983] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.606985] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.606986] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.606987] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.606988] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.606990] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 60416)
[62517.606991] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.607102] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.607104] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.607106] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.607107] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.607108] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.607109] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.607111] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 60416)
[62517.607112] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.607114] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 60416)
[62517.607115] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.607414] cdc-acm: acm_tty_unthrottle: called; free space in tty: 64512
[62517.608229] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 64256)
[62517.608232] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.608234] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.608236] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.608353] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 64512)
[62517.608356] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.608358] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.608361] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.608363] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.608401] cdc-acm: acm_tty_throttle: called; free space in tty: 64512
[62517.608480] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.608481] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.608483] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.608484] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.608485] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.608486] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.608488] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62464)
[62517.608489] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.608491] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61440)
[62517.608492] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.608603] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 64512)
[62517.608604] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.608606] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.608607] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.608609] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63488)
[62517.608610] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.608691] cdc-acm: acm_tty_unthrottle: called; free space in tty: 64512
[62517.609738] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 64256)
[62517.609743] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.609747] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 63232)
[62517.609750] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.609754] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 62208)
[62517.609757] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61184)
[62517.609855] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 61184)
[62517.609859] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 60160)
[62517.609862] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 60160)
[62517.609866] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 59136)
[62517.610023] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 59136)
[62517.610030] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 58112)
[62517.610035] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 58112)
[62517.610040] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 57088)
[62517.610106] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 57088)
[62517.610110] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 56064)
[62517.610113] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 56064)
[62517.611115] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 55808)
[62517.611119] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 54784)
[62517.611231] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 54784)
[62517.611236] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 53760)
[62517.611240] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 53760)
[62517.611243] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 52736)
[62517.611247] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 52736)
[62517.611386] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 51712)
[62517.611391] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 51712)
[62517.611396] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 50688)
[62517.611401] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 50688)
[62517.611406] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 49664)
[62517.611482] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 49664)
[62517.611489] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 48640)
[62517.611493] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 48640)
[62517.611606] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 47616)
[62517.611609] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 47616)
[62517.612610] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 47360)
[62517.612615] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 46336)
[62517.612618] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 46336)
[62517.612622] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 45312)
[62517.612734] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 45312)
[62517.612738] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 44288)
[62517.612741] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 44288)
[62517.612745] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 43264)
[62517.612859] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 43264)
[62517.612862] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 42240)
[62517.612866] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 42240)
[62517.612869] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 41216)
[62517.612981] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 41216)
[62517.612984] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 40192)
[62517.612987] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 40192)
[62517.612991] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 39168)
[62517.613106] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 39168)
[62517.614111] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 38912)
[62517.614116] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 37888)
[62517.614119] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 37888)
[62517.614124] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 36864)
[62517.614127] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 36864)
[62517.614130] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 35840)
[62517.614232] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 35840)
[62517.614235] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 34816)
[62517.614239] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 34816)
[62517.614247] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 33792)
[62517.614359] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 33792)
[62517.614363] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 32768)
[62517.614366] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 32768)
[62517.614369] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 31744)
[62517.614483] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 31744)
[62517.614486] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 30720)
[62517.614489] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 30720)
[62517.615485] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 30464)
[62517.615489] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 29440)
[62517.615492] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 29440)
[62517.615611] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 28416)
[62517.615614] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 28416)
[62517.615617] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 27392)
[62517.615734] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 27392)
[62517.615737] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 26368)
[62517.615741] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 26368)
[62517.615746] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 25344)
[62517.615749] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 25344)
[62517.615858] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 24320)
[62517.615861] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 24320)
[62517.615864] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 23296)
[62517.615867] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 23296)
[62517.615983] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 22272)
[62517.615986] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 22272)
[62517.616989] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 22016)
[62517.616994] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 20992)
[62517.616997] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 20992)
[62517.617001] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 19968)
[62517.617110] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 19968)
[62517.617114] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 18944)
[62517.617117] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 18944)
[62517.617120] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 17920)
[62517.617233] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 17920)
[62517.617240] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 16896)
[62517.617243] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 16896)
[62517.617246] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 15872)
[62517.617362] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 15872)
[62517.617366] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 14848)
[62517.617369] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 14848)
[62517.617372] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 13824)
[62517.617484] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 13824)
[62517.618487] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 13568)
[62517.618491] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 12544)
[62517.618494] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 12544)
[62517.618498] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 11520)
[62517.618501] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 11520)
[62517.618504] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 10496)
[62517.618507] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 10496)
[62517.618613] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 9472)
[62517.618616] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 9472)
[62517.618621] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 8448)
[62517.618625] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 8448)
[62517.618737] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 7424)
[62517.618740] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 7424)
[62517.618744] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 6400)
[62517.618747] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 6400)
[62517.618859] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 5376)
[62517.618862] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 5376)
[62517.619863] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 5120)
[62517.619867] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 4096)
[62517.619870] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 4096)
[62517.619874] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 3072)
[62517.620022] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 3072)
[62517.620028] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2048)
[62517.620033] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2048)
[62517.620037] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 1024)
[62517.620113] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2048)
[62517.620118] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 1024)
[62517.620121] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 1024)
[62517.620126] cdc-acm: acm_tty_throttle: called; free space in tty: 2304
[62517.620245] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2304)
[62517.620247] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.620250] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2304)
[62517.620251] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.620253] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 1280)
[62517.620255] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.620257] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 1280)
[62517.620258] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.620264] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 256)
[62517.620265] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.620267] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 256)
[62517.620269] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.620318] cdc-acm: acm_tty_unthrottle: called; free space in tty: 256
[62517.621367] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 0)
[62517.621372] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 0)
[62517.621375] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 0)
                  ------- FAILURE HAPPENS HERE --------
[62517.621378] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621381] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621489] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621492] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621495] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621618] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621622] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621626] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621744] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621747] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621750] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621862] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621865] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.621867] cdc-acm: acm_process_read_urb: processed 0 of 1024 (free space left: 0)
[62517.622357] cdc-acm: acm_tty_throttle: called; free space in tty: 1024
[62517.622746] cdc-acm: acm_process_read_urb: processed 16 of 16 (free space left: 6144)
[62517.622748] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622750] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 5120)
[62517.622751] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622753] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 5120)
[62517.622754] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622863] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 4096)
[62517.622864] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622866] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 4096)
[62517.622867] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622869] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 3072)
[62517.622870] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622872] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 3072)
[62517.622873] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622875] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2048)
[62517.622876] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622989] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 4096)
[62517.622991] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622993] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 3072)
[62517.622994] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622996] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 3072)
[62517.622997] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.622999] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2048)
[62517.623000] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.623002] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2048)
[62517.623003] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.623116] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 3072)
[62517.623118] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.623119] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 3072)
[62517.623120] cdc-acm: acm_read_bulk_callback: throttle requested
[62517.623122] cdc-acm: acm_process_read_urb: processed 1024 of 1024 (free space left: 2048)
[62517.623123] cdc-acm: acm_read_bulk_callback: throttle requested

Hi Sven,

Thanks for this, which confirms that roughly 10.4ms elapses from kworker schedule (of input into nearly empty tty buffers) to throttle notification.

The premature unthrottle actually leads to the data loss but the throttling with a mere 2K left is _way too late_.

10ms is a _really_ long time for a cpu not to attend to a kworker. Which raises 2 questions:
1. What are the termios settings of the tty receiving input? Is it 'raw' mode or typical terminal mode (icanon, echo, etc.) or something else?
2. Are there RT threads that are hogging cpu time?

Regards,
Peter Hurley

Hi,

Ok, yes, I think so too.

In my test code, I open the tty like
fd = open("/dev/ttyACM0", O_RDWR | O_NOCTTY | O_NONBLOCK);
I don't make any other changes to the default settings. To be honest, I'm not sure in which mode it is operating then (I was assuming raw, but I might be wrong?).

I can't see any, I think the only thing which occasionally goes to RT is pulseaudio (but during at least some of the tests I wasn't even playing audio, so that sounds very unplausible to me). I also cannot see a correlation between failure rate and CPU load.

Best regards,
Sven

You should explicitly set a mode if you need a particular mode, otherwise the port might be in another mode. This sets raw. Add error checking.

struct termios t;

tcgetattr(fd, &t);
cfmakeraw(&t);
cfsetspeed(&t, B115200);
tcsetattr(fd, 0, &t);

//Peter

I haven't forgotten about this problem and I still plan to look into why the long delay, particularly focusing on the scheduling latency from tty_flip_buffer_push() => flush_to_ldisc().

Regards,
Peter Hurley

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

I made some changes wrt which CPU is scheduled for the flush_to_ldisc() input worker, which should reduce the kworker latency. The changes are on the tty-next branch of Greg's tty.git tree; please test at your earliest convenience.

ECHO is on by default and the cdc-acm driver does not implement the put_char() and flush_chars() tty driver methods, which made the problem _way worse_, since every echoed char is sent as it's own URB.

Since echoing is performed by the input worker, this seems the likely cause for the significant delay in ldisc processing.

Echo processing should probably be performed by a separate kworker rather than by the input kworker.

Regards,
Peter Hurley

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

That can be fixed. How can I test this? Will the tty layer use write() and put_char()?

Regards
Oliver

From: Oliver Neukum <[email protected]>
Date: Wed, 21 Oct 2015 12:10:07 +0200
Subject: [PATCH] cdc-acm: implement put_char() and flush_chars()

This should cut down latencies and waste if the tty layer writes single bytes.

---
 drivers/usb/class/cdc-acm.c | 58 +++++++++++++++++++++++++++++++++++++++++++++
 drivers/usb/class/cdc-acm.h |  1 +
 2 files changed, 59 insertions(+)

index b30e742..262f179 100644
@@ -725,6 +725,62 @@ static int acm_tty_write(struct tty_struct *tty,
 	return count;
 }
 
+static void acm_tty_flush_chars(struct tty_struct *tty)
+{
+	struct acm *acm = tty->driver_data;
+	struct acm_wb *cur = acm->putbuffer;
+	int err;
+	unsigned long flags;
+
+	acm->putbuffer = NULL;
+	err = usb_autopm_get_interface_async(acm->control);
+	spin_lock_irqsave(&acm->write_lock, flags);
+	if (err < 0) {
+		cur->use = 0;
+		goto out;
+	}
+
+	if (acm->susp_count) {
+		usb_anchor_urb(cur->urb, &acm->delayed);
+		goto out;
+	}
+
+	acm_start_wb(acm, cur);
+out:
+	spin_unlock_irqrestore(&acm->write_lock, flags);
+	return;
+}
+
+static int acm_tty_put_char(struct tty_struct *tty, unsigned char ch)
+{
+	struct acm *acm = tty->driver_data;
+	struct acm_wb *cur;
+	int wbn;
+	unsigned long flags;
+
+overflow:
+	cur = acm->putbuffer;
+	if (!cur) {
+		spin_lock_irqsave(&acm->write_lock, flags);
+		wbn = acm_wb_alloc(acm);
+		if (wbn >= 0) {
+			cur = &acm->wb[wbn];
+			acm->putbuffer = cur;
+		}
+		spin_unlock_irqrestore(&acm->write_lock, flags);
+		if (!cur)
+			return 0;
+	}
+
+	if (cur->len == acm->writesize) {
+		acm_tty_flush_chars(tty);
+		goto overflow;
+	}
+
+	cur->buf[cur->len++] = ch;
+	return 1;
+}
+
 static int acm_tty_write_room(struct tty_struct *tty)
 {
 	struct acm *acm = tty->driver_data;

@@ -1888,6 +1944,8 @@ static const struct tty_operations acm_ops = {
 	.cleanup =		acm_tty_cleanup,
 	.hangup =		acm_tty_hangup,
 	.write =		acm_tty_write,
+	.put_char =		acm_tty_put_char,
+	.flush_chars =		acm_tty_flush_chars,
 	.write_room =		acm_tty_write_room,
 	.ioctl =		acm_tty_ioctl,
 	.throttle =		acm_tty_throttle,

index dd9af38..648a6f7 100644
@@ -94,6 +94,7 @@ struct acm {
 	unsigned long read_urbs_free;
 	struct urb *read_urbs[ACM_NR];
 	struct acm_rb read_buffers[ACM_NR];
+	struct acm_wb *putbuffer;			/* for acm_tty_put_char() */
 	int rx_buflimit;
 	int rx_endpoint;
 	spinlock_t read_lock;

2.1.4

I'm working on getting my tty tests organized for upstreaming, but it's not there yet. Let me see if I can get you a standalone test for accuracy, at least.

Echoing uses put_char() + flush_chars() for echoing, if the driver supports it; otherwise, it uses write().

Be aware that while the N_TTY line discipline ensures that put_char() and write() usage will not be interleaved without flush_chars(), other line disciplines might not, so at least be sure that driver won't crash if that happens.

Regards,
Peter Hurley

Sorry, I take that back: certain echoes are output via write() in OPOST mode, specifically for O_ONLCR and XTABS.