ESP-IDF logging library slows down ISR processing

Question

I'm hacking a project with ESP32-WROOM module. I'm running some timers with alarms along with some peripherals triggering ISRs. In the ISR routine I'm sending events to a queue, and receiving them in a task. Normally I'm seeing ~50 micros delay between ISR routine and the task.

I added the esp_log component for logging to UART. If I call some ESP_LOGx in the task after receiving the queue event, the aforementioned delay grows to 25 millis in some cases (depending on the amount of logging).

What's the reason? Does esp_log have longish noInterrupt sections internally? Is there any way to avoid them? Any other remedies?

Those delays are quire troublesome because on one hand I need logging to get things working. On other hand those delays turn all the timings upside down...

I actually switched to esp_log form hand-rolled logger. In my logger I had a 5k fifo queue for log data. The logging calls would format strings and push them into the queue. A low priority task would pop the data and print it to the UART. It was much better in terms of performance. I switched to esp_log for richer functionality, but ... Going back unless there is a fix.

Answer 1

Since your logger uses the UART, you need to take the transmission time into account.

Supposing that you use a 9600 baud line and send about 25 bytes.

A single byte has 10 bits on the wire, start bit, data bits, and at least one stop bit. There are more options to the protocol, but this is it basically.

Each bit takes 1/9600 seconds, this is the definition of 9600 baud. (Actually, this is oversimplified, but nevertheless a correct number here.) 10 bits of one byte take t_Byte = 10 / 9600 s = 1.042 ms.

To send 25 bytes, this sums up to about 25 ms.

Lesson learned: do not log directly to UART in a time critical task. You found the common solution by queuing the bytes to send. Just make sure that the queue will not fill up in the long term.