USB Serial starts going slow if buffer on PC is not emptied

RogerClark
Fri Aug 07, 2015 3:51 am
Hi Guys,

I was testing some code that writes to a ILI9341 display and also sends the same debug information to Serial.

I left it doing a soak test and after about sending several thousand chars to the serial without the serial console being open, I get a strange effect where Serial.print seems to start taking a noticeable amount of time to write something like “Sending ….” ( around 250ms)

If I open the Serial monitor, the issue goes away, but if I close the serial monitor and wait a for a few more thousand characters to be sent, the problem comes back.

I’ve written a test program yet to investigate what the issue is, but there does appear to be a problem.

The only other test I did so far is to run my test rig from a USB PSU and in this case there isn’t an issue.

i.e I’t only seems to occur if there is USB host.


victor_pv
Fri Aug 07, 2015 4:18 am
RogerClark wrote:Hi Guys,

I was testing some code that writes to a ILI9341 display and also sends the same debug information to Serial.

I left it doing a soak test and after about sending several thousand chars to the serial without the serial console being open, I get a strange effect where Serial.print seems to start taking a noticeable amount of time to write something like “Sending ….” ( around 250ms)

If I open the Serial monitor, the issue goes away, but if I close the serial monitor and wait a for a few more thousand characters to be sent, the problem comes back.

I’ve written a test program yet to investigate what the issue is, but there does appear to be a problem.

The only other test I did so far is to run my test rig from a USB PSU and in this case there isn’t an issue.

i.e I’t only seems to occur if there is USB host.


RogerClark
Fri Aug 07, 2015 7:35 am
Hi Victor,

I’m not writing data that fast, I have a “ping” test on some wireless modules (NRF905) which I’m running, that sends data once a second, and displays a small amount of text each time (approx 60 chars)

After around 150 secs it starts to go very slow.

So that puts the number at 9000 characters, so I agree there is no way that the USB stack in libmaple has a 8k buffer as it would be taking almost half the usable RAM.

Perhaps the driver on the PC has a really small buffer, but 8k sounds small for a system like Windows,

I’ll need to write some sort of really simple test that writes chars one by one to the USB Serial and flashes the LED each time its written 128 chars, and see if the flash rate suddenly drops off after a certain number of writes

I guess I should also test hardware serial, however I can’t really see how that could have the same issue.


fredbox
Fri Aug 07, 2015 7:13 pm
Create a blink sketch with the led blinking at a fairly good pace:#include <Streaming.h>
#define mySerial Serial
const byte ledPin=33;
boolean led;
void setup() {
pinMode(ledPin, OUTPUT);
mySerial.begin(9600);
}
void loop() {
led=1-led;
digitalWrite(ledPin,led);
mySerial << (("Serial: Led is ")) << led << endl;
delay(100);
}

RogerClark
Fri Aug 07, 2015 8:34 pm
Thanks @fredbox

hopefully we can find a simple fix for this.

I’ve not delved into the USB serial code before, but i will take a look this weekend.


victor_pv
Fri Aug 07, 2015 9:22 pm
RogerClark wrote:Thanks @fredbox

hopefully we can find a simple fix for this.

I’ve not delved into the USB serial code before, but i will take a look this weekend.


RogerClark
Fri Aug 07, 2015 9:34 pm
victor

No. It seems fine when running from a external power source.

I have taken a quick look in the code and I suspect the cause is in this function

size_t USBSerial::write(const void *buf, uint32 len) {
size_t n = 0;
if (!this->isConnected() || !buf) {
return 0;
}

uint32 txed = 0;
uint32 old_txed = 0;
uint32 start = millis();

uint32 sent = 0;

while (txed < len && (millis() - start < USB_TIMEOUT)) {
sent = usb_cdcacm_tx((const uint8*)buf + txed, len - txed);
txed += sent;
if (old_txed != txed) {
start = millis();
}
old_txed = txed;
}

if (sent == USB_CDCACM_TX_EPSIZE) {
while (usb_cdcacm_is_transmitting() != 0) {
}
/* flush out to avoid having the pc wait for more data */
usb_cdcacm_tx(NULL, 0);
}
return n;
}


victor_pv
Fri Aug 07, 2015 10:43 pm
I was about to post the same, but you beat me to it :)

So the code waits to make sure the peripheral has already sent what’s in the buffer, and if not, waits up to 50ms.

I see 2 posibilities:
-Reduce that time out
-Check what is the peripheral supposed to do if the PC is not getting data.

I haven’t checked yet why would the peripheral hold on to data if the PC is not caring to receive it.
Is it desirable having that behaviour? I would think it is not. If you usb buffer fills in the PC, then you sketch is slowed down a lot.
50ms seems excesive, that would result in a lower limit from the PC of about 20 bytes per second. So as long as the PC can get about 180 bits per second or more, the Serial driver will not dump anything, new or old, and if it is slower than that, then it seems to drops the latest data, rather than the oldest one.

Personally, I would have expected that if the buffer fills faster than the PC can process the data, it just overwrites the oldest and goes on.


RogerClark
Sat Aug 08, 2015 12:11 am
Victor,

I’m just testing on the Mac and I get the same effect, so its not limited to the PC.

However I’m getting very odd results with my test program.

const byte ledPin=PB1;
boolean led;
void setup() {
pinMode(ledPin, OUTPUT);
// delay(1000);
}
void loop() {
long s;
int c=0;
long d;
bool broken=false;

while(!broken)
{
c++;
s=millis();
Serial.print("X");
d=millis()-s;
if (d >= 50)
{
broken=true;
}
// delay(100);
}
digitalWrite(ledPin,HIGH);

while(1)
{
Serial.println(c);
delay(500);
}
}


fredbox
Sat Aug 08, 2015 3:46 pm
RogerClark wrote:Thanks @fredbox

hopefully we can find a simple fix for this.

I’ve not delved into the USB serial code before, but i will take a look this weekend.


RogerClark
Sat Aug 08, 2015 10:17 pm
@fredbox

actually, there is some code that can check whether the serial console is open.

Ray used it quite a lot, and its very useful when debugging what happens in startup(),

I’m not at my main computer at the moment, but i will try to post the code later in case you cant find it.


ahull
Sun Aug 09, 2015 8:21 pm
For what its worth, the USB and CAN peripherals have their own ram…

0x4000 6400 Shared 512 byte
USB/CAN SRAM
0x4000 6000 USB Registers
0x4000 5C00 ……………

… this may be what is filling up.


mrburnette
Sun Aug 09, 2015 8:34 pm
ahull wrote:For what its worth, the USB and CAN peripherals have their own ram…

… this may be what is filling up.


RogerClark
Sun Aug 09, 2015 9:32 pm
Thanks Andy,

I think, I wasn’t aware of those blocks of RAM.

I haven’t had time to look at the issue again, over the weekend, but I will try to look during the week.

Its failure mode is very odd, i.e it doesn’t appear to be a fixed buffer size, as in my test sketches, I can write different number of characters before it goes wrong, depending on how quickly / often I write a character..

Which is very odd. But as we know where in the code, the Timeout value is being tested, It probably makes more sense to track down why its timing out, and if possible make a distinction between the USB connection to the host going slow, and the USB connection to the host accepting any more characters.


victor_pv
Mon Aug 10, 2015 1:42 am
RogerClark wrote:Thanks Andy,

I think, I wasn’t aware of those blocks of RAM.

I haven’t had time to look at the issue again, over the weekend, but I will try to look during the week.

Its failure mode is very odd, i.e it doesn’t appear to be a fixed buffer size, as in my test sketches, I can write different number of characters before it goes wrong, depending on how quickly / often I write a character..

Which is very odd. But as we know where in the code, the Timeout value is being tested, It probably makes more sense to track down why its timing out, and if possible make a distinction between the USB connection to the host going slow, and the USB connection to the host accepting any more characters.


RogerClark
Mon Aug 10, 2015 1:46 am
Victor

I’ll need to double check, but I didn’t think the issue occurred if I ran from a USB charger supply


fredbox
Wed Aug 19, 2015 2:58 am
actually, there is some code that can check whether the serial console is open.

Ray used it quite a lot, and its very useful when debugging what happens in startup(),
I believe this is it:
// wait for serial monitor to be connected.
while (!(Serial.isConnected() && (Serial.getDTR() || Serial.getRTS())))
{
digitalWrite(33,!digitalRead(33));// Turn the LED from off to on, or on to off
delay(100); // fast blink
}


victor_pv
Wed Aug 19, 2015 4:01 am
fredbox wrote:actually, there is some code that can check whether the serial console is open.

Ray used it quite a lot, and its very useful when debugging what happens in startup(),
I believe this is it:
// wait for serial monitor to be connected.
while (!(Serial.isConnected() && (Serial.getDTR() || Serial.getRTS())))
{
digitalWrite(33,!digitalRead(33));// Turn the LED from off to on, or on to off
delay(100); // fast blink
}


RogerClark
Wed Aug 19, 2015 4:09 am
Victor

Thats worth a try.

I’m not sure what happens however if you open the terminal then close it, i.e does DTR remain set.

However it could be better than the current situation


fredbox
Sun Sep 13, 2015 10:42 pm
On my Linux Mint 17.2 system, I believe I have a solution for the Maple Mini taking a long time (~30 seconds) to make the USB serial port available. I noticed this warning in syslog after the port became available:
ModemManager: <warn> Couldn't create modem for device at '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-1': Failed to find primary AT port

ahull
Sun Sep 13, 2015 11:34 pm
fredbox wrote:On my Linux Mint 17.2 system, I believe I have a solution for the Maple Mini taking a long time (~30 seconds) to make the USB serial port available. I noticed this warning in syslog after the port became available:
ModemManager: <warn> Couldn't create modem for device at '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-1': Failed to find primary AT port

fredbox
Mon Sep 14, 2015 3:27 am
I may also have a shot at blacklisting the maple device so modemmangler doesn’t attempt to enumerate it. That would provide a more general solution. See https://mail.gnome.org/archives/network … 00038.html and http://cgit.freedesktop.org/ModemManage … list.rules for a head start with this idea.
That also works. I reinstalled modemmanager and created /lib/udev/rules.d/77-mm-usb-custom.rules with this line:
ATTRS{idVendor}=="1eaf", ATTRS{idProduct}=="0004", ENV{ID_MM_DEVICE_IGNORE}="1"

RogerClark
Mon Sep 14, 2015 5:46 am
HI fredbox

I dont think its the same issue, but thankyou for letting us know of the problem and the solution.

I think I may need to start a “Not so frequently asked questions” section in the wiki ;-)


Leave a Reply

Your email address will not be published. Required fields are marked *