ijeffsc
Posts: 5
Joined: Thu Mar 26, 2015 12:15 pm

/dev/ACM0 long turnaround time waiting on EAGAIN

Wed Apr 01, 2015 11:05 am

RTFM's welcome.

Hi all,

For the last few years I've been running a pair of raspberrypi model b's to do some temperature collection. I use a Canakit UK1104 http://www.canakit.com/4-port-usb-relay-controller.html usb ADC/Relay board for this along with a simple custom signal conditioner for the thermistors I'm using. It has been running reliably up until ~ mid February when I did a pretty standard apt-get update/upgrade. I'm assuming a 3.18 kernel or device change of some kind has occurred.

The systems continued to work but with frequent (60%) but random failure in serial communications. I have isolated my problem to a section of code that sends and receives ascii commands to the UK1104. For example:

Sending:
ch2.getanalog\n

Returns (more or less):
ch2.getanalog\n470\n\n::\n

What I was initially seeing was a frequent but random error 11 EAGAIN - device temporarily unavailable. This error occurred after the command write and a usleep(10000) (10 ms) during the subsequent read. The port is opened at 115kbps.

I ended up checking for this error and waiting - this is my workaround. However the turnaround time is sometimes enormous and even with a one second timeout (retrying read every 10ms) between writes and reads the port sometimes ( < 0.5% of the time) continues to report temporarily unavailable and the routine fails.



Some relevant details below.

dmesg:

[ 3.494660] usb 1-1.3: new full-speed USB device number 4 using dwc_otg
[ 3.656055] usb 1-1.3: New USB device found, idVendor=04d8, idProduct=fc73
[ 3.667461] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 3.682389] usb 1-1.3: Product: CANA KIT UK1104
[ 3.691865] usb 1-1.3: Manufacturer: CANAKIT.COM
[ 4.458744] udevd[159]: starting version 175
[ 5.909295] cdc_acm 1-1.3:1.0: This device cannot do calls on its own. It is not a modem.
[ 6.021221] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
[ 6.157936] usbcore: registered new interface driver cdc_acm
[ 6.295214] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters

ijeffsc@raspberrypi ~ $ uname -a
Linux raspberrypi 3.18.7+ #755 PREEMPT Thu Feb 12 17:14:31 GMT 2015 armv6l GNU/Linux

ijeffsc
Posts: 5
Joined: Thu Mar 26, 2015 12:15 pm

Re: /dev/ACM0 long turnaround time waiting on EAGAIN

Sat Apr 18, 2015 11:04 am

Hi all,

Well I see 70 or so folks have reviewed my post without comment. I'm working on a code snippet that can be posted and demonstrates the behaviour I'm seeing. In the mean time I'm still digging around the forums. The code I used for the USB serial IO is based on snippets I found in this thread: viewtopic.php?f=33&t=7500.

The turnaround is so slow that I expected to be able to reproduce the problem in minicom but was unable to. So now I'm suspecting some error in my code that was tolerated in the previous kernel but isn't in this one.

Has anyone else seen USB Serial (ttysACM0) problems arise after a kernel upgrade?

rkanton
Posts: 9
Joined: Tue Apr 30, 2013 4:05 pm

Re: /dev/ACM0 long turnaround time waiting on EAGAIN

Mon Apr 27, 2015 5:54 pm

Just want to let you know that I've been experiencing some similar issues with /dev/ttyACM devices. Unlike you however, I'm only seeing the issue with Raspberry Pi 2 and not the B+. I'm running the same kernel version number on both rPi 2 and B+.

Linux rp1 3.18.7+ #755 PREEMPT Thu Feb 12 17:14:31 GMT 2015 armv6l GNU/Linux

I have a biometric reader that appears as a /dev/ttyACM device. It sends 400 bytes of data to the rPi when a finger is registered. On the rPi 2 I'm only seeing about 250 bytes come through with the B+ it's as expected 400 bytes.

Don't know if it matters but I have Device Tree Overlays disabled via a "device_tree= " entry in /boot/config.txt.

- rkanton

rkanton
Posts: 9
Joined: Tue Apr 30, 2013 4:05 pm

Re: /dev/ACM0 long turnaround time waiting on EAGAIN

Mon Apr 27, 2015 10:57 pm

A followup to my previous post. Turns out that I had a bug in my read() code that was uncovered when using the rPi 2 and not the B+. I have a multi-threaded app and maybe the issue was exposed because of the quad core architecture in the rPi 2 - it ended being a timing related problem.

Anyway, /dev/ACM0 is working just fine for both my rPi 2 and B+.

ijeffsc
Posts: 5
Joined: Thu Mar 26, 2015 12:15 pm

Re: /dev/ACM0 long turnaround time waiting on EAGAIN

Sat May 02, 2015 3:38 pm

Huh,

Well problems persist but I can work around them. Attached is a code snippet to play with if you are interested. This is based on http://tldp.org/HOWTO/Serial-Programmin ... /x115.html.

The interesting things to play with in this example are:

If MIN > 0 and TIME = 0, or If MIN > 0 and TIME > 0 - I/O is blocked and the program succeeds in all cases *however* there is ~ 25% of the time a visible delay in the read response. The timeout in these cases is only inter-character. Per the link above "The timer is restarted every time a character is received and only becomes active after the first character has been received."

If MIN = 0 and TIME = 1, I/O is still blocked but with a timeout. Per the link above "The read will be satisfied if a single character is read, or TIME is exceeded (t = TIME *0.1 s). If TIME is exceeded, no character will be returned." This behaviour is what I'm seeing so in about ~25% of the cases I will get no characters back.

So now I think I'm back to saying my original code is OK but has exposed a bug introduced in 3.18.7 or so that really robust serial IO code can overcome. The turnaround time occasionally is unreasonably high. I don't write really robust code typically. :)

By my estimation at 115kbps I should be > 10,000 characters per second so I'd expect turnaround times of << 1 ms and preferably =~ 0.1 ms. not 1000X that.

Am I thinking clearly?

The workaround for me is to use a blocking read of a single character. This works but interferes with my IO speeds. If I was really interested in high speed IO I'd be sunk.

Code: Select all

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <fcntl.h>
#include <termios.h>

int main(int argc, char* argv[]) {

    struct termios serial, oldserial;
    int fd;
    char* str = "\r\n";
    char* str2 = "ch1.getanalog\r\n";
    char buffer[1024];

    if (argc == 1) {
        printf("Usage: %s [device]\n\n", argv[0]);
        return -1;
    }

    printf("Opening %s\n", argv[1]);

    fd = open(argv[1], O_RDWR | O_NOCTTY );
    if (fd <0) {perror(argv[1]); exit(-1); }
    
    tcgetattr(fd,&oldserial); /* save current port settings */
    
    bzero(&serial, sizeof(serial));
    serial.c_cflag = B115200 | CRTSCTS | CS8 | CLOCAL | CREAD;
    serial.c_iflag = IGNPAR;
    serial.c_oflag = 0;
    
    /* set input mode (non-canonical, no echo,...) */
    serial.c_lflag = 0;
    
    serial.c_cc[VTIME]    = 1;   /* inter-character timer in 0.1 secs */
    serial.c_cc[VMIN]     = 0;   /* blocking read until n chars received */
    
    tcflush(fd, TCIFLUSH);
    tcsetattr(fd,TCSANOW,&serial);
    // Attempt to send and receive
    printf("Sending: %s\n", str);

    int wcount = write(fd, str, strlen(str));
    if (wcount < 0) {
        perror("Write");
        tcsetattr(fd,TCSANOW,&oldserial);
        close(fd);
        return -1;
    }
    else {
        printf("Sent %d characters\n", wcount);
    }

    usleep(100000);
    int rcount = read(fd, buffer, sizeof(buffer));
    if (rcount < 0) {
        perror("Read");
        tcsetattr(fd,TCSANOW,&oldserial);
        close(fd);
        return -1;
    }
    else {
        printf("Received %d characters\n", rcount);
    }
    printf("Received: %s\n", buffer);

    wcount = write(fd, str2, strlen(str2));
    if (wcount < 0) {
        perror("Write");
        tcsetattr(fd,TCSANOW,&oldserial);
        close(fd);
        return -1;
    }
    else {
        printf("Sent %d characters\n", wcount);
    }

    usleep(100000);
    rcount = read(fd, buffer, sizeof(buffer));
    if (rcount < 0) {
        perror("Read");
        return -1;
    }
    else {
        printf("Received %d characters\n", rcount);
    }

    buffer[rcount] = '\0';

    printf("Received: %s\n", buffer);
    tcsetattr(fd,TCSANOW,&oldserial);
    close(fd);
    return(0);
}


rkanton
Posts: 9
Joined: Tue Apr 30, 2013 4:05 pm

Re: /dev/ACM0 long turnaround time waiting on EAGAIN

Wed May 06, 2015 4:33 pm

ijeffsc,

I use a select() call to block if there is no read data. Below code is just a snippet. The code is enclosed in a while loop which tries to read up to the expected receive data. At some point it gives up and returns if the expected len is less then received length. The bug I had earlier is that I was not waiting long enough to receive all the data from the peripheral device - this was the "timing issue" with the rPi 2 and not rPi B+.

There is an open(fd, O_RDWR | O_NOCTTY | O_NDELAY) command prior to the code below

Code: Select all


		tv->tv_sec = 0;
		tv->tv_usec = 500000;
	
				
		FD_ZERO(&rfds);
		FD_SET(fd,&rfds);
				
		retval = select(fd+1, &rfds, NULL, NULL, tv);
			
		if(retval == -1) {
			perror("d_read: select()");
			goto exit;
		}
		else if(retval == 0) {
			printf("Timeout waiting for read data\n";		
			goto exit;			
		}
			
		if((n = read(fd, &buf[t], len)) < 0) {
			printf("Read failed\n");
			goto exit;
		}


ijeffsc
Posts: 5
Joined: Thu Mar 26, 2015 12:15 pm

Re: /dev/ACM0 long turnaround time waiting on EAGAIN

Sat May 09, 2015 3:47 pm

I got curious wondering if this behaviour of long turnaround time was a device driver issue of cdc-acm or if it was something else. Somewhere in my reading I found several threads about using usbserial.ko instead of cdc-acm.ko. I tried loading the usbserial module instead of cdc-acm. In my testing code above I got the same behaviour in my last post against the /dev/ttyUSB0 device.

To drop cdc-acm (/dev/ttysACM0) and use usbserial (/dev/ttysUSB0) I followed this thread:

https://bbs.archlinux.org/viewtopic.php?id=129884
which references:
https://wiki.archlinux.org/index.php/Hu ... 0_3G_modem

More or less what I tried is below.

Code: Select all


root@raspberrypi:~# dmesg | grep -i usb
[3728302.205368] usb 1-1.3: new full-speed USB device number 5 using dwc_otg
[3728302.335402] usb 1-1.3: New USB device found, idVendor=04d8, idProduct=fc73
[3728302.335442] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[3728302.335461] usb 1-1.3: Product: CANA KIT UK1104
[3728302.335478] usb 1-1.3: Manufacturer: CANAKIT.COM
[3728302.396289] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device

or

root@raspberrypi:~# lsusb
Bus 001 Device 002: ID 0424:9512 Standard Microsystems Corp. 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp. 
Bus 001 Device 005: ID 04d8:fc73 Microchip Technology, Inc. 

Then

root@raspberrypi:~# modeprobe -r cdc_acm
root@raspberrypi:~# modprobe usbserial vendor=0x04d8 product=0xfc73
root@raspberrypi:~# ls /dev/ttyA* /dev/ttyU*
/dev/ttyAMA0  /dev/ttyUSB0
Besides making my code a bit more robust I think my next step will be to to quantify the turnaround jitter on my "good old" kernel and the new one.

ijeffsc
Posts: 5
Joined: Thu Mar 26, 2015 12:15 pm

Re: /dev/ACM0 long turnaround time waiting on EAGAIN

Sat May 09, 2015 4:20 pm

<snip>
rkanton wrote:ijeffsc,

The bug I had earlier is that I was not waiting long enough to receive all the data from the peripheral device - this was the "timing issue" with the rPi 2 and not rPi B+.
<snip>

OK interesting approach. I didn't know about select(). Two questions:
  • Do you have multiple threads competing for the same serial device? i.e. are you using semaphores or mutex or something?
  • Have you quantified the "waiting long enough"?
I think quantifying the response time is probably my 2nd next step. The 1st will be to modify my code so it works reliably with the current kernel/device I'm using. By modern standards (lacklustre performance and bloat) I suppose I'm obsessing but I'm unsatisfied and I don't think I should be seeing these long turnaround times. Perhaps your code is more robust already and in a general sense what you are doing with select() I'm now (well, will be real soon now) doing with tweaks to a blocking read (i.e. waiting until there is something available).

One other observation - I believe that it is only the first character on the minority of responses that exhibit this behaviour so the device is really just not ready and/or has nothing for me on that first character. Once the device becomes available/has data subsequent characters on the response are all available. - I'll have to confirm this but it looks like it with short timeouts I get the complete response or nothing (timeout) in about a 4:1 ration.

Happily I'm learning more about serial ports.

Ian

Return to “C/C++”