Request for improvement on driver for ttyS_ (or help to do it myself)



  • Hi folks. I have a situation using poll() in C code, with /dev/ttyS0.

    I'd like to either make poll() a lot faster (seems unlikely), or find a way to increase the size of the read buffer for each ttyS_ device. I figure this means rebuilding the kernel.

    I'm sending packets over ttyS0 -- not characters. Serial packet protocols are not uncommon, but they won't work very well with Omega2/LEDE because poll() can't really be used.

    By the time poll() returns, the tty buffer is already long gone.

    Based on what I can glean from testing dozens of different poll/read configurations, I think the tty driver keeps a buffer of only 8 bytes (which is probably just the hardware FIFO).

    Anyway, that's it. I have a fully working buildroot cross-compilation setup for the Omega2 platform, if that helps. Thanks.



  • hi @JP-Norair,

    I am using ttyS* devices myself for very similar purposes (packet sending/receiving, high baudrates), with no problems so far.

    So I wonder what exactly could be the problem your're seeing.

    You wrote:

    By the time poll() returns, the tty buffer is already long gone.

    What exactly do you mean by that? Are you loosing incoming data?

    IMHO the ttyS0 driver can buffer a lot of incoming data, so poll() speed should not be an issue, as long as you read() enough data at a time.

    ttyS0 on the Omega2 is using the standard 8250 driver including the buffering mechanisms of the tty core. These buffers are dynamically allocated but can grow very large, the limit seems to be 2*64 = 128 kBytes (see TTYB_DEFAULT_MEM_LIMIT)

    Based on what I can glean from testing dozens of different poll/read configurations, I think the tty driver keeps a buffer of only 8 bytes (which is probably just the hardware FIFO).

    The device tree source for the mt76x8 (the target/linux/ramips/dts/mt7628an.dtsi file in your buildroot) shows the uarts specify ne16550a compatibility:

    uartlite: uartlite@c00 {
        compatible = "ns16550a";
        reg = <0xc00 0x100>;
        ....
    

    This will select the PORT_16550A configuration, with a FIFO size of 16 bytes.

    But the hardware FIFO size should not matter for your problem - the interrupt response time of the Omega2 (~5uS) is way fast enough to empty that FIFO into the large tty driver buffers without loosing any data.

    So I guess it must be something else than the serial driver's buffer size.

    Maybe you can post a code snippet showing how your poll() / read() loop looks like?



  • @luz

    • Are you using poll()?
    • Are you using a binary packet (i.e. NOT character transmissions)?
    • What baud rate are you using?

    I'm sending a binary packet with 0xFF55 as a two-byte syncword that prepends each frame. If I wait on a poll(), The data I receive will start quite a bit after 0xFF55 in the packet.

    Sometime a packet will be received correctly, but usually it will not be. There are gaps in the packet where-ever there are poll() calls.

    Here is the polling code. It works quite well on other platforms. I should point-out that on Onion Omega there is only one interface that is being polled, so the fds list is a list of size 1.

        // Handle timeout (return 0).
        // Timeouts only occur when there is a job to reconnect to some lost
        // connections.
        ready_fds = poll(fds, num_fds, polltimeout);
        if (ready_fds == 0) {
            int num_dc = 0;
            int connfail;
            
            for (i=0; i<num_fds; i++) {
                if (fds[i].fd < 0) {
                    VERBOSE_PRINTF("Attempting to reconnect on %s\n", mpipe_file_get(mph, i));
                    connfail = (mpipe_reopen(mph, i) != 0);
                    num_dc  += connfail;
                    if (connfail == 0) {
                        fds[i].fd = ((mpipe_tab_t*)mph)->intf[i].fd.in;
                        fds[i].events = (POLLIN | POLLNVAL | POLLHUP);
                    }
                }
            }
            if (num_dc == 0) {
                polltimeout = -1;
            }
            else if (polltimeout >= 30000) {
                polltimeout = 60000;
            }
            else {
                polltimeout *= 2;
            }
            continue;
        }
        
        // Handle fatal errors
        if (ready_fds < 0) {
            ERR_PRINTF("Polling failure in %s, line %i\n", __FUNCTION__, __LINE__);
            goto mpipe_reader_TERM;
        }
        
        for (i=0; i<num_fds; i++) {
            // Handle Errors
            ///@todo change 100ms fixed wait on hangup to a configurable amount
            if (fds[i].revents & (POLLNVAL|POLLHUP)) {
                usleep(100 * 1000);
                errcode = 5;
                goto mpipe_reader_ERR;
            }
        
            // Verify that POLLIN is high.  This should be implicit, but we check explicitly here
            if ((fds[i].revents & POLLIN) == 0) {
                mpipe_flush(mph, i, 0, TCIFLUSH);
                continue;
            }
    
            // Find FF, the first sync byte
            mpipe_reader_SYNC0:
            new_bytes = (int)read(fds[i].fd, &syncinput, 1);
            if (new_bytes < 1) {
                errcode = 1;        // flushable
                goto mpipe_reader_ERR;
            }
            if (syncinput != 0xFF) {
                goto mpipe_reader_SYNC0;
            }
            TTY_PRINTF("Sync FF Received\n");
            
            // Now wait for a 55, ignoring FFs
            mpipe_reader_SYNC1:
            pollcode = poll(&fds[i], 1, 50);
            if (pollcode <= 0) {
                errcode = 4;        // flushable
                goto mpipe_reader_ERR;
            }
            else if (fds[0].revents & (POLLERR | POLLHUP | POLLNVAL)) {
                errcode = 5;        // flushable
                goto mpipe_reader_ERR;
            }
            new_bytes = (int)read(fds[i].fd, &syncinput, 1);
            if (new_bytes < 1) {
                errcode = 1;        // flushable
                goto mpipe_reader_ERR;
            }
            if (syncinput == 0xFF) {
                goto mpipe_reader_SYNC1;
            }
            if (syncinput != 0x55) {
                goto mpipe_reader_SYNC0;
            }
            TTY_PRINTF("Sync 55 Received\n");
            
            // At this point, FF55 was detected.  We get the next 6 bytes of the
            // header, which is the rest of the header.
            /// @todo Make header length dynamic based on control field (last byte).
            ///           However, control field is not yet defined.
            new_bytes       = 0;
            payload_left    = 6;
            rbuf_cursor     = rbuf;
            while (payload_left > 0) {
                pollcode = poll(&fds[i], 1, 50);
                if (pollcode <= 0) {
                    errcode = 4;
                    goto mpipe_reader_ERR;
                }
                else if (fds[0].revents & (POLLERR | POLLHUP | POLLNVAL)) {
                    errcode = 5;
                    goto mpipe_reader_ERR;
                }
            
                new_bytes       = (int)read(fds[i].fd, rbuf_cursor, payload_left);
                rbuf_cursor    += new_bytes;
                payload_left   -= new_bytes;
                TTY_PRINTF("header new_bytes = %d\n", new_bytes);
            }
    
            // Bytes 0:1 are the CRC16 checksum.  The controlling app can decide what
            // to do about those.  They are in the buffer.
            // Bytes 2:3 are the Length of the Payload, in big endian.  It can be up
            // to 65535 bytes, but CRC16 won't be great help for more than 250 bytes.
            payload_length  = rbuf[2] * 256;
            payload_length += rbuf[3];
            
            // Byte 4 is a sequence number, which the controlling app can decide what
            // to do with.  Byte 5 is RFU, but in the future it can be used to
            // expand the header.  That logic would go below (currently trivial).
            header_length = 6 + 0;
            
            // Now do some checks to prevent malformed packets.
            if (((unsigned int)payload_length == 0) \
            || ((unsigned int)payload_length > (1024-header_length))) {
                errcode = 2;
                goto mpipe_reader_ERR;
            }
    
            // Receive the remaining payload bytes
            payload_left    = payload_length;
            rbuf_cursor     = &rbuf[6];
            while (payload_left > 0) {
                pollcode = poll(&fds[i], 1, 50);
                if (pollcode <= 0) {
                    errcode = 4;
                    goto mpipe_reader_ERR;
                }
                else if (fds[0].revents & (POLLERR | POLLHUP | POLLNVAL)) {
                    errcode = 5;
                    goto mpipe_reader_ERR;
                }
            
                new_bytes       = (int)read(fds[i].fd, rbuf_cursor, payload_left);
                // Debugging output
                TTY_PRINTF("payload new_bytes = %d\n", new_bytes);
                HEX_DUMP(rbuf_cursor, new_bytes, "read(): ");
                
                rbuf_cursor    += new_bytes;
                payload_left   -= new_bytes;
            }


  • Update:

    I've written a stateful read implementation that does not use poll at all (posted at the bottom).

    From this implementation, I've been able to determine that I'm losing exactly 16 bytes. So the first load of the 16 byte HW buffer seems to be getting discarded. If the buffer is already partially full, and read is blocking on new bytes, the next packet that arrives will be read successfully.

    So with this implementation, I lose every other packet. This is not workable, and I will need to find a fix, but nonetheless it is a step forward in diagnosing and solving the problem. Clearly, it's either the driver or some HW issue. I'll need to scope the lines next.

    Here's an output of the program ("otter") being run in interactive mode. The second packet is correctly received. On the first packet, the first 15 or 16 bytes are being discarded.

    First packet: the first 15/16 bytes are discarded
    DEBUG: read(): 00
    DEBUG: read(): 0A
    DEBUG: read(): 00
    DEBUG: read(): 00
    DEBUG: read(): 11
    DEBUG: read(): 11
    DEBUG: read(): 04
    DEBUG: read(): 36
    DEBUG: read(): 00
    DEBUG: read(): 00
    DEBUG: read(): 00
    DEBUG: read(): 02

    Second packet: received correctly from partially full buffer.
    DEBUG: read(): FF
    DEBUG: read(): FF
    DEBUG: read(): 55
    DEBUG: read(): 3D 8E 00 13 02 00
    DEBUG: read(): C0 0F 01 35 00 00 00
    DEBUG: read(): 00 0A 00 00 11 11 04 36 00 00 00 02
    DEBUG: pkt : C0 0F 01 35 00 00 00 00 0A 00 00 11 11 04 36 00 00 00 02
    DEBUG: 25 Bytes Queued
    3D 8E 00 13 02 00 C0 0F 01 35 00 00 00 00 0A 00 00 11 11 04 36 00 00 00 02

    In case anyone is curious, here is the total hack I used to get around poll() incurring too much delay. The problem may be HW, in which case if I fix the HW (i.e. the other device sending data), the polling code might work again. Nonetheless, for using a single interface, this code below is probably slightly more performant -- albeit sloppy.

        {   int unused_bytes;
            struct timespec ref;
            struct timespec test;
            
            mpipe_reader_INIT:
            rbuf_cursor     = rbuf;
            unused_bytes    = 0;
            payload_left    = 1;
            
            while (1) {
                /// Check size of bytes in the hopper, and compare with payload_left (requested bytes)
                /// Only do read() if we need more bytes
                
                // Read from interface, and time how long it takes to return
                if (clock_gettime(CLOCK_MONOTONIC, &ref) != 0) {
                    errcode = -1;
                    goto mpipe_reader_ERR;
                }
                new_bytes = (int)read(fds[0].fd, rbuf_cursor, payload_left);
                if (new_bytes <= 0) {
                    errcode = 5 - (new_bytes == 0);
                    goto mpipe_reader_ERR;
                }
                if (clock_gettime(CLOCK_MONOTONIC, &test) != 0) {
                    errcode = -1;
                    goto mpipe_reader_ERR;
                }
                
                // If read took longer than 50ms (should be configurable ms),
                // we need to restart the reception state machine.
                if (timespec_diffms(ref, test) > 50) {
                    errcode = 0;
                    for (; (new_bytes>0)&&(*rbuf_cursor!=0xFF); new_bytes--, rbuf_cursor++);
                    if (new_bytes == 0) {
                        goto mpipe_reader_INIT;
                    }
                    unused_bytes = new_bytes-1;
                    new_bytes = 1;
                }
                else {
                    unused_bytes = 0;
                }
                
                mpipe_reader_STATEHANDLER:
                syncinput       = *rbuf_cursor;
                rbuf_cursor    += new_bytes;
                unused_bytes   -= new_bytes;
                payload_left   -= new_bytes;
                
                switch (errcode) {
                case 0: payload_left = 1;
                        if (syncinput != 0xFF) {
                            break;
                        }
                        errcode = 1;
                        break;
                
                case 1: payload_left = 1;
                        if (syncinput == 0xFF) {
                            break;
                        }
                        if (syncinput != 0x55) {
                            errcode = 0;
                            break;
                        }
                        // Sync-Found: realign rbuf if necessary
                        for (int j=0; j<unused_bytes; j++) {
                            rbuf[j] = rbuf_cursor[j];
                        }
                        rbuf_cursor = rbuf;
                        errcode = 2;
                        payload_left = 6;
                        break;
                
                // Header (6 bytes)
                case 2: if (payload_left > 0) {
                            break;
                        }
                        errcode = 3;
                        payload_length  = rbuf[2] * 256;
                        payload_length += rbuf[3];
                        payload_left    = payload_length;
                        header_length   = 6 + 0;
                        if ((payload_length == 0) || (payload_length > (1024-header_length))) {
                            errcode = 2;
                            goto mpipe_reader_ERR;
                        }
                        break;
                
                // Payload (N bytes)
                case 3: if (payload_left <= 0) {
                            goto mpipe_reader_READDONE;
                        }
                        break;
                
               default: rbuf_cursor = rbuf;
                        payload_left = 1;
                        errcode = 0;
                        unused_bytes = 0;
                        break;
                }
                
                if (unused_bytes > 0) {
                    new_bytes = (payload_left < unused_bytes) ? payload_left : unused_bytes;
                    goto mpipe_reader_STATEHANDLER;
                }
            }
       }


  • I've not done any work on the TTY device but what you are describing looks like a handshaking issue, does the TTY do handshaking?



  • @crispyoz
    No, it's just direct TX/RX without usage of tcflow()



  • Update:

    I found the problem. tcflush() does not appear to work properly on this platform. I will investigate further, submit a bug report, and perhaps fix it. Right now I'm 2 weeks behind schedule, though, so it will need to wait.

    I worked-around the problem by removing all calls to tcflush(). This is suboptimal, but there won't be any packet loss unless the other end is sending packets with incorrect framing. For this project, that's something I don't really need to worry about.

    So, I finally got around to scoping the TX & RX signals. You can see the TX and RX packets. If I transmit a packet after calling tcflush(fd, TCIFLUSH), the tty driver will:

    1: discard the first 16 bytes of the received response -- this is one frame of the HW FIFO.
    2: At ~3.5ms after the request transmission, Onion will transmit a giant, erroneous packet that contains some clobbered data -- the data, here, is in part the request (tx) and in part the response (rx).

    This smells so much like a driver bug.

    0_1562977372839_Screen Shot 2019-07-12 at 17.07.52 .png



  • @JP-Norair thx for posting your findings! That's very useful to know.

    Regarding your questions above: yes, I've been using poll(), yes I've transmitted binary packets with all values 0..0xFF. And the baudrate was 115200bd.

    But, obviously, I haven't used TCIFLUSH.

    I agree this looks like a driver bug.

    But still I am surprised such a significant bug would be in Linux' 8250 standard driver without somebody having noticed and fixed it loooong ago...

    Maybe I'm missing something and it's not the standard 8250 driver that is included in OnionOS builds?



  • @luz there are so many flavors of Linux (onion uses musl libraries) that it’s very easy for bugs to slip through the cracks for a specific platform. I’ve run the original code on other platforms using the same kernel version and ostensibly same serial driver, and it works great.

    Anyway, I will plod on.



  • Just a note that the issues I have are re-occurring. The removal of tcflush() calls oddly worked the day of testing, but it no longer works. The same error has returned. My conclusion for the moment is that Onion Omega 2 is buggy and not suitable for usage with binary serial port.

    Notes:

    1. Using poll() and/or tcflush() results in nearly 100% failure.
    2. Using the read loop without poll results in less failure, but still far too much failure.

  • administrators

    @JP-Norair @luz We took a look and confirmed that the default Omega2 firmware uses the standard Linux 8250 serial driver included with kernel 4.14, with the DTS file setting NS16550A for the port type for all 3 UARTs.

    Questions:

    1. You mentioned the polling code works well on other platforms. Which platforms did you try out? Did they have NS16550A serial ports and were they running Linux kernel 4.14?
    2. Can you try using a USB-to-Serial adapter (connected to the Omega2's USB Host port) to check if the same problem appears?


  • @Lazar-Demin
    Here is the list of issues I've encountered with the Omega2+ serial port. I'm a big fan of the Onion project, and I'd like to help if possible. I can send you hardware and software to replicate this, if you'd like.

    Current workarounds:

    • Do not use poll() or tcflush()!
    • Use read(fd, buf, 1) only. That is, size param = 1.
    1. Receiver on UART0 seems to have a lot of capacitance on it. This can be overcome with a strong pull-up, but I thought I'd mention this in any case.

    2. I have a half-duplex binary packet protocol. It's much like SLIP or PPP. If I send a Request TX packet to the endpoint, and it generates a Response RX packet, problems can occur during the RX.
      A. If poll() is used during reception of the Response RX Packet, the serial port will spew a bunch of data on the TX line (see behavior in logic analyzer capture).
      B. If tcflush(..., TCIFLUSH) is used after the packet is fully received and read (via read()), similar behavior as in (2A) will ensue.
      C. Usage of tcflush(), in any way, anywhere in the program seems to cause issues with the fd it is used-on.

    3. There is another issue with reception. When I'm receiving a binary packet, the 16th byte is often dropped.
      A. When I scope the lines, I can verify that the 16th byte is always on the line.
      B. Here's an example of a correct packet. Bytes 0:1, sync. Bytes 2:7, header. Bytes 8:..., payload. This packet has 0x39 payload size (57 bytes).
      [FF 55] [F9 F4 00 39 08 00] [C0 35 01 35 01 00 00 00 30 00 00 36 00 4A 30 06 ...]
      C. Here's the same packet, with byte 16 missing. The last byte of the payload will be read as FF, because this is the idle state of the serial lines.
      [FF 55] [F9 F4 00 39 08 00] [C0 35 01 35 01 00 00 30 00 00 36 00 4A 30 06 ... FF]
      D. If I change the way read() is done (i.e. changing the size boundary to smaller values), this often causes more bytes to be dropped. HOWEVER, if I use size=1, and only size=1, reception generally works without dropping bytes. This is one workaround I'm using.

    4. tcdrain(...) does not appear to cause any problems, although I'm skeptical if it actually blocks program flow as it should.

    5. tcdrain() and tcflush() both return 0 (no errors)

    Final notes.
    I've run the original SW over USB-serial (ttyUSBx) and USB-CDCACM (ttyACMx) interface without issue.
    I've run the original SW on ttySx, with a 4.x kernel (might have been 4.4.xxx) on an OrangePi without issue. Not sure what HW they have, but definitely it is a 32 bit ARM Cortex A7, and definitely it's NOT running musl. So the libc is different. I expect the problems are probably not so much in the driver but in musl, but that's just my guess.



  • @JP-Norair I'm still wondering what could be the difference between your Omega2 setup and mine.

    Because in my current project (means: I heavily using the code every day), I am using poll() all the time. I also found that the library I'm using even occasionaly uses tcflush(TCIFLUSH) and tcflush(TCIOFLUSH) - I thought it didn't, in my previous post.

    The read code is simple, when poll() returns a POLLIN, a single read() reads everything currently available. tcflush() is used only after detecting receiving errors (unexpected message lengths, crc errors).

    What kernel, musl and openwrt version are you using?

    My versions are linux 4.14.95, musl 1.1.19 and openwrt 18.06.2

    All openwrt v18.06.x use musl 1.1.19. LEDE v17.01 was using musl 1.1.16, upcoming openwrt v19.07 will use musl 1.1.23, but I found no commit in musl since 1.1.19 I could relate to anything fixed regarding serial ports.

    From the fact that @Lazar-Demin confirms the use of the standard 8250 driver, and the MIPS platform is not an obscure corner case for linux, I would agree that the problem is more likely a musl thing.



  • @luz said in Request for improvement on driver for ttyS_ (or help to do it myself):

    My versions are linux 4.14.95, musl 1.1.19 and openwrt 18.06.2

    I compiled the buildroot in June, but I will try to rebuild it with whatever is the latest commit from GitHub. I'm wondering now if I was using the master branch, which would be the wrong branch to use by the looks of it. I added some of libs from the OpenWRT universe (libfts, libtalloc), but I don't think these would impact anything.

    I was following the instructions here. There isn't an instruction about changing branches, so unless I built HEAD, it probably was master. I think Onion team should update the docs, if so.
    https://docs.onion.io/omega2-docs/cross-compiling.html

    Update:
    No, the buildroot is from the 18.06 branch.

    @luz are you cross-compiling or building on the onion? Maybe you could share your tty configuration. I've attached mine at the bottom of this post.

    Another crazy thing I noticed on Onion is that signal(SIGINT, &handler_fn) will return non-zero if the process is launched from within a shell script. If process is launched from tty, it's fine. I ported my code to use SIGTERM instead, and to ignore the SIGINT handler. I'm curious if, somehow, this may lead to the issues.

    static int sub_opentty(mpipe_intf_t* ttyintf) {
        mpipe_tty_t* ttyparams = (mpipe_tty_t*)ttyintf->params;
        struct termios tio;
        int i_par;
        int rc = 0;
    
        // first open with O_NONBLOCK
        ttyintf->fd.in = open(ttyparams->path, O_RDWR | /*O_NDELAY*/ O_NONBLOCK | O_EXCL);
        if (ttyintf->fd.in < 0 ) {
            rc = -1;
            goto sub_opentty_EXIT;
        }
        
        if ( !isatty(ttyintf->fd.in) ) {
            rc = -2;
            goto sub_opentty_ERR;
        }
        
        // TTY device has output and input on the same file descriptor
        ttyintf->fd.out = ttyintf->fd.in;
        
        // then reset O_NDELAY
        if ( fcntl(ttyintf->fd.in, F_SETFL, O_RDWR) )  {
            rc = -3;
            goto sub_opentty_ERR;
        }
        
        // clear the datastruct just in case
        bzero(&tio, sizeof(struct termios));
        
        // Framing parameters are derived in mpipe_opentty()
        ///@todo Currently ignores parity on RX (IGNPAR)
        i_par           = IGNPAR;
        tio.c_cflag     = ttyparams->data_bits | ttyparams->stop_bits | ttyparams->parity | CREAD | CLOCAL | ttyparams->flowctl;
        tio.c_iflag     = IGNBRK | i_par;
        tio.c_oflag     = CR0 | TAB0 | BS0 | VT0 | FF0;
        tio.c_lflag     = 0;
        
        tio.c_cc[VMIN]  = 1;        // smallest read is one character
        tio.c_cc[VTIME] = 0;        // Inter-character timeout (after VMIN) is 0.1sec
        
        tcflush( ttyintf->fd.in, TCIOFLUSH );
        
        cfsetospeed(&tio, ttyparams->baud);
        cfsetispeed(&tio, ttyparams->baud);
        
        // Using TCSANOW will do [something]
        if (tcsetattr(ttyintf->fd.in, TCSANOW, &tio) != 0)  {
            rc = -4;
            goto sub_opentty_ERR;
        }
        
        // RTS/CTS are not available at this moment (may never be)
        //if( flowctrl != FLOW_HW )  {
        //    if (rts)    tiocmbis(table->intf[id].fd.in,TIOCM_RTS);
        //    else        tiocmbic(table->intf[id].fd.in,TIOCM_RTS);
        //}
        
        // DTR is not available at this moment (may never be)
        //if (dtr)    tiocmbis(table->intf[id].fd.in,TIOCM_DTR);
        //else        tiocmbic(table->intf[id].fd.in,TIOCM_DTR);
        
        sub_opentty_EXIT:
        return rc;
        
        sub_opentty_ERR:
        close(ttyintf->fd.in);
        return rc;
    }
    

  • administrators

    @JP-Norair What does your hardware setup look like? Is using a USB-to-Serial chip with the Omega an option?



  • @Lazar-Demin

    No: for size, cost, and power reasons we need to use the built-in UART(s).

    I'm interested that @luz is having no trouble doing basically the same thing. It would be nice to know what he/she is doing that is different from what I am doing.

    I will rebuild buildroot and see if this makes a difference.



Looks like your connection to Community was lost, please wait while we try to reconnect.