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.


Log in to reply
 

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