ESP32 doesn't seem to keep up with UART when using uart_enable_pattern_det_intr

JeffWilliams
Posts: 17
Joined: Thu Mar 09, 2017 2:06 am

ESP32 doesn't seem to keep up with UART when using uart_enable_pattern_det_intr

Postby JeffWilliams » Tue Mar 06, 2018 5:50 pm

Hello,

I am parsing GPS NMEA data inbound on UART2 at 115200 baud. The GPS is capable of 50Hz updates though I have it set to 25Hz currently. Module does not have any flow control, it just streams the NMEA sentences.

I am using current master of IDF from git and planned to use uart_enable_pattern_det_intr to detect the LF in the inbound data as then I can process each line as they come in. I have set the character to detect as a single LF. I will then use the new uart_pattern_pop_pos call to get the position in the buffer of the LF to get each line as I go.

I am currently using the uart_events_example from the IDF to test things. Only change is to detect a single ASCII 10 vs '+++'. (code copied below at end)

What I am seeing though is that the ESP32 can't keep up. Its the only thing the ESP32 is doing but yet by the 5 line in it's behind 1 line and by the 10th line or so it's about 2 lines behind. The log message for the pattern detection continues to show the total buffered size growing faster than it can keep up. 115200 isn't all that fast. Is there a performance hit in using the pattern detection? Would I be better to just read the data as it comes in and split the lines out myself? I figured the event mechanism would be more efficient.
[UART PATTERN DETECTED] pos: 71, buffered size: 842
I guess I expected the pattern detection log message and the total buffered size to stay at a pretty constant size around 1 lines worth. I was actually expecting the ESP to handle more data and possibly change the GPS to 230400 though with these results I suspect that will just overload things faster.

I suspect I am missing something simple.

Thoughts? Thanks, Jeff

Log where you can see ii growing from first message:

Code: Select all

I (12) uart: queue free spaces: 50
I (32) uart_events: uart[2] event:
I (32) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (32) uart_events: read data: $GPGGA,172114.840,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*68
I (42) uart_events: read pat : 

I (42) uart_events: uart[2] event:
I (42) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (52) uart_events: read data: $GPRMC,172114.840,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*7A
I (62) uart_events: read pat : 

I (72) uart_events: uart[2] event:
I (72) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (82) uart_events: read data: $GPGGA,172114.880,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*64
I (92) uart_events: read pat : 

I (92) uart_events: uart[2] event:
I (102) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (102) uart_events: read data: $GPRMC,172114.880,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*76
I (112) uart_events: read pat : 

I (122) uart_events: uart[2] event:
I (122) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 150
I (132) uart_events: read data: $GPGGA,172114.920,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*6F
I (142) uart_events: read pat : 

I (142) uart_events: uart[2] event:
I (152) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 150
I (162) uart_events: read data: $GPRMC,172114.920,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*7D
I (172) uart_events: read pat : 

I (172) uart_events: uart[2] event:
I (172) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 150
I (182) uart_events: read data: $GPGGA,172114.960,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*6B
I (192) uart_events: read pat : 

I (202) uart_events: uart[2] event:
I (202) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 222
I (212) uart_events: read data: $GPRMC,172114.960,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*79
I (222) uart_events: read pat : 

I (222) uart_events: uart[2] event:
I (232) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 150
I (232) uart_events: read data: $GPGGA,172115.000,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*65
I (242) uart_events: read pat : 

I (252) uart_events: uart[2] event:
I (252) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 222
I (262) uart_events: read data: $GPRMC,172115.000,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*77
I (272) uart_events: read pat : 

I (272) uart_events: uart[2] event:
I (282) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 300
I (282) uart_events: read data: $GPGGA,172115.040,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*61
I (302) uart_events: read pat : 

I (302) uart_events: uart[2] event:
I (302) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 222
I (312) uart_events: read data: $GPRMC,172115.040,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*73
I (322) uart_events: read pat : 

I (322) uart_events: uart[2] event:
I (332) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 300
I (342) uart_events: read data: $GPGGA,172115.080,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*6D
I (352) uart_events: read pat : 

I (352) uart_events: uart[2] event:
I (362) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 372
I (362) uart_events: read data: $GPRMC,172115.080,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*7F
I (372) uart_events: read pat : 

I (382) uart_events: uart[2] event:
I (382) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 300
I (392) uart_events: read data: $GPGGA,172115.120,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*66
I (402) uart_events: read pat : 

I (402) uart_events: uart[2] event:
I (412) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 372
I (412) uart_events: read data: $GPRMC,172115.120,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*74
I (422) uart_events: read pat : 

I (432) uart_events: uart[2] event:
I (432) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 450
I (442) uart_events: read data: $GPGGA,172115.160,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*62
I (452) uart_events: read pat : 

I (452) uart_events: uart[2] event:
I (462) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 372
I (472) uart_events: read data: $GPRMC,172115.160,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*70
I (482) uart_events: read pat : 

I (482) uart_events: uart[2] event:
I (482) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 450
I (492) uart_events: read data: $GPGGA,172115.200,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*67
I (502) uart_events: read pat : 

I (512) uart_events: uart[2] event:
I (512) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 450
I (522) uart_events: read data: $GPRMC,172115.200,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*75
I (532) uart_events: read pat : 

I (532) uart_events: uart[2] event:
I (542) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 450
I (542) uart_events: read data: $GPGGA,172115.240,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*63
I (552) uart_events: read pat : 

I (562) uart_events: uart[2] event:
I (562) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 522
I (572) uart_events: read data: $GPRMC,172115.240,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*71
I (582) uart_events: read pat : 

I (582) uart_events: uart[2] event:
I (592) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 528
I (602) uart_events: read data: $GPGGA,172115.280,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*6F
I (612) uart_events: read pat : 

I (612) uart_events: uart[2] event:
I (612) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 522
I (622) uart_events: read data: $GPRMC,172115.280,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*7D
I (632) uart_events: read pat : 

I (642) uart_events: uart[2] event:
I (642) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 600
I (652) uart_events: read data: $GPGGA,172115.320,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*64
I (662) uart_events: read pat : 

I (662) uart_events: uart[2] event:
I (672) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 600
I (672) uart_events: read data: $GPRMC,172115.320,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*76
I (682) uart_events: read pat : 

I (692) uart_events: uart[2] event:
I (692) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 600
I (702) uart_events: read data: $GPGGA,172115.360,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*60
I (712) uart_events: read pat : 

I (712) uart_events: uart[2] event:
I (722) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 672
I (732) uart_events: read data: $GPRMC,172115.360,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*72
I (742) uart_events: read pat : 

I (742) uart_events: uart[2] event:
I (742) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 600
I (752) uart_events: read data: $GPGGA,172115.400,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*61
I (762) uart_events: read pat : 

I (772) uart_events: uart[2] event:
I (772) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 842
I (782) uart_events: read data: $GPRMC,172115.400,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*73
I (792) uart_events: read pat : 

I (792) uart_events: uart[2] event:
I (802) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 1056
I (802) uart_events: read data: $GPGGA,172115.440,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*65
I (812) uart_events: read pat : 

I (822) uart_events: uart[2] event:
I (822) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 1050
I (832) uart_events: read data: $GPRMC,172115.440,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*77
I (842) uart_events: read pat : 

I (842) uart_events: uart[2] event:
I (852) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 1128
I (862) uart_events: read data: $GPGGA,172115.480,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*69
I (872) uart_events: read pat : 

I (872) uart_events: uart[2] event:
I (872) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 1200
I (882) uart_events: read data: $GPRMC,172115.480,A,4358.1013,N,07916.3057,W,000.0,146.4,060318,,,A*7B
I (892) uart_events: read pat : 

I (902) uart_events: uart[2] event:
I (902) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 1128
I (912) uart_events: read data: $GPGGA,172115.520,4358.1013,N,07916.3057,W,1,06,1.6,311.0,M,-34.3,M,,0000*62
I (922) uart_events: read pat : 


Code: Select all

/* UART Events Example

   This example code is in the Public Domain (or CC0 licensed, at your option.)

   Unless required by applicable law or agreed to in writing, this
   software is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR
   CONDITIONS OF ANY KIND, either express or implied.
*/
#include <stdio.h>
#include <string.h>
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "freertos/queue.h"
#include "driver/uart.h"
#include "esp_log.h"

static const char *TAG = "uart_events";

/**
 * This example shows how to use the UART driver to handle special UART events.
 *
 * It also reads data from UART0 directly, and echoes it to console.
 *
 * - Port: UART0
 * - Receive (Rx) buffer: on
 * - Transmit (Tx) buffer: off
 * - Flow control: off
 * - Event queue: on
 * - Pin assignment: TxD (default), RxD (default)
 */

#define EX_UART_NUM UART_NUM_2
#define PATTERN_CHR_NUM    (1)         /*!< Set the number of consecutive and identical characters received by receiver which defines a UART pattern*/

#define BUF_SIZE (1024)
#define RD_BUF_SIZE (BUF_SIZE)
static QueueHandle_t uart0_queue;

static void uart_event_task(void *pvParameters)
{
    uart_event_t event;
    size_t buffered_size;
    uint8_t* dtmp = (uint8_t*) malloc(RD_BUF_SIZE);
    for(;;) {
        //Waiting for UART event.
        if(xQueueReceive(uart0_queue, (void * )&event, (portTickType)portMAX_DELAY)) {
            bzero(dtmp, RD_BUF_SIZE);
            ESP_LOGI(TAG, "uart[%d] event:", EX_UART_NUM);
            switch(event.type) {
                //Event of UART receving data
                /*We'd better handler data event fast, there would be much more data events than
                other types of events. If we take too much time on data event, the queue might
                be full.*/
                case UART_DATA:
                    ESP_LOGI(TAG, "[UART DATA]: %d", event.size);
                    uart_read_bytes(EX_UART_NUM, dtmp, event.size, portMAX_DELAY);
                    ESP_LOGI(TAG, "[DATA EVT]:");
                    uart_write_bytes(EX_UART_NUM, (const char*) dtmp, event.size);
                    break;
                //Event of HW FIFO overflow detected
                case UART_FIFO_OVF:
                    ESP_LOGI(TAG, "hw fifo overflow");
                    // If fifo overflow happened, you should consider adding flow control for your application.
                    // The ISR has already reset the rx FIFO,
                    // As an example, we directly flush the rx buffer here in order to read more data.
                    uart_flush_input(EX_UART_NUM);
                    xQueueReset(uart0_queue);
                    break;
                //Event of UART ring buffer full
                case UART_BUFFER_FULL:
                    ESP_LOGI(TAG, "ring buffer full");
                    // If buffer full happened, you should consider encreasing your buffer size
                    // As an example, we directly flush the rx buffer here in order to read more data.
                    uart_flush_input(EX_UART_NUM);
                    xQueueReset(uart0_queue);
                    break;
                //Event of UART RX break detected
                case UART_BREAK:
                    ESP_LOGI(TAG, "uart rx break");
                    break;
                //Event of UART parity check error
                case UART_PARITY_ERR:
                    ESP_LOGI(TAG, "uart parity error");
                    break;
                //Event of UART frame error
                case UART_FRAME_ERR:
                    ESP_LOGI(TAG, "uart frame error");
                    break;
                //UART_PATTERN_DET
                case UART_PATTERN_DET:
                    uart_get_buffered_data_len(EX_UART_NUM, &buffered_size);
                    int pos = uart_pattern_pop_pos(EX_UART_NUM);
                    ESP_LOGI(TAG, "[UART PATTERN DETECTED] pos: %d, buffered size: %d", pos, buffered_size);
                    if (pos == -1) {
                        // There used to be a UART_PATTERN_DET event, but the pattern position queue is full so that it can not
                        // record the position. We should set a larger queue size.
                        // As an example, we directly flush the rx buffer here.
                        uart_flush_input(EX_UART_NUM);
                    } else {
                        uart_read_bytes(EX_UART_NUM, dtmp, pos, 100 / portTICK_PERIOD_MS);
                        uint8_t pat[PATTERN_CHR_NUM + 1];
                        memset(pat, 0, sizeof(pat));
                        uart_read_bytes(EX_UART_NUM, pat, PATTERN_CHR_NUM, 100 / portTICK_PERIOD_MS);
                        ESP_LOGI(TAG, "read data: %s", dtmp);
                        ESP_LOGI(TAG, "read pat : %s", pat);
                    }
                    break;
                //Others
                default:
                    ESP_LOGI(TAG, "uart event type: %d", event.type);
                    break;
            }
        }
    }
    free(dtmp);
    dtmp = NULL;
    vTaskDelete(NULL);
}

void app_main()
{
    esp_log_level_set(TAG, ESP_LOG_INFO);

    /* Configure parameters of an UART driver,
     * communication pins and install the driver */
    uart_config_t uart_config = {
        .baud_rate = 115200,
        .data_bits = UART_DATA_8_BITS,
        .parity = UART_PARITY_DISABLE,
        .stop_bits = UART_STOP_BITS_1,
        .flow_ctrl = UART_HW_FLOWCTRL_DISABLE
    };
    uart_param_config(EX_UART_NUM, &uart_config);

    //Set UART log level
    esp_log_level_set(TAG, ESP_LOG_INFO);
    //Set UART pins (using UART0 default pins ie no changes.)
    uart_set_pin(EX_UART_NUM, GPIO_NUM_17, GPIO_NUM_16, UART_PIN_NO_CHANGE, UART_PIN_NO_CHANGE);
    //Install UART driver, and get the queue.
    uart_driver_install(EX_UART_NUM, BUF_SIZE * 2, BUF_SIZE * 2, 50, &uart0_queue, 0);

    //Set uart pattern detect function.
    uart_enable_pattern_det_intr(EX_UART_NUM, 10, PATTERN_CHR_NUM, 10000, 10, 10);
    //Reset the pattern queue length to record at most 20 pattern positions.
    uart_pattern_queue_reset(EX_UART_NUM, 20);

    //Create a task to handler UART event from ISR
    xTaskCreate(uart_event_task, "uart_event_task", 2048, NULL, 12, NULL);
}

WiFive
Posts: 3529
Joined: Tue Dec 01, 2015 7:35 am

Re: ESP32 doesn't seem to keep up with UART when using uart_enable_pattern_det_intr

Postby WiFive » Wed Mar 07, 2018 3:23 am

The buffer count jumps 242 bytes in 30ms when the update frequency is 40ms? Seems like some other driver bug in processing the received data.

JeffWilliams
Posts: 17
Joined: Thu Mar 09, 2017 2:06 am

Re: ESP32 doesn't seem to keep up with UART when using uart_enable_pattern_det_intr

Postby JeffWilliams » Wed Mar 07, 2018 4:40 pm

By accident I have it working better. All I did was change the logging. I removed all logging from the code except for

Code: Select all

ESP_LOGI(TAG, "[UART PATTERN DETECTED] pos: %d, buffered size: %d", pos, buffered_size);
Now things work fine. It seems my previous experience has to do with logging output to UART0. Have not dug any deeper to see if it's any logging of something specific in the logging of that app. Added to my todo to look a bit deeper and test it a bit more when I have a bit of time

Now I get a consistent buffer usage:

Code: Select all

I (22) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (32) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (62) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (72) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (112) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (112) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (142) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (152) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (192) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (192) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (222) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (232) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (262) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (272) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (312) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (312) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (342) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (352) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (382) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (392) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (422) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (432) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (462) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (472) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (512) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (512) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (542) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (552) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72
I (592) uart_events: [UART PATTERN DETECTED] pos: 77, buffered size: 78
I (602) uart_events: [UART PATTERN DETECTED] pos: 71, buffered size: 72

Who is online

Users browsing this forum: kaxx1975 and 117 guests