[TW#16842] RMT device affected by log output / std::condition_variable logging

[PerMalmberg]

Hi,

I've got a task with the following responsibilities:

• Communicate with three I2C devices over two different channels.
• Control five WS281B RGB LEDs using RMT (each command waits for completation).

This is working splendidly - but only as long as logging is set to "Info" or lower. At debug and especially at verbose level the amount of logging apparently become to much to handle which affects the performance of the RMT, resulting in the timing being wrong and in turn results in corrupt data being sent to the five WS2812B.

As I understand it, the RMT should not be affected by the CPU load and thus be able to do signaling with very tight timing demands, right?

Assuming my understanding is correct, I think there is an issue with how the RMT interacts with the log system, based on the fact that this issue appeared after updating to edb2400 in which std::condition_variable continously spits out a huge amount of log messages like this:

V (427591) esp_pthread: pthread_cond_timedwait 0x3ffc09dc 0x3ffc09d8 0x3ffc07b8
V (427597) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427612) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427619) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427627) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427634) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427641) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427649) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427656) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427664) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8
V (427671) esp_pthread: pthread_cond_timedwait 0x3ffb7fbc 0x3ffb7fb8 0x3ffc93a8

The problem as I see it is that the RMT also logs events and these are, unless I'm mistaken, logged synchronously with all other log messages, which obviously will throw off the timing of the RMT if the log is blocked by another task.

V (543253) esp_pthD (543261) rmt: RMT CH[0]: EVT INTR
D (543261) rmt: RMT CH[0]: EVT INTR
D (543261) rmt: RMT CH[0]: EVT INTR
D (543261) rmt: RMT INTR : TX END
D (543261) rmt: RMT CH[0]: EVT INTR

This theory seems to hold up since when I disable all logging in driver/rmt.c, the RMT device functions perfectly. As such, I propose to either (a) remove logging from RMT entierly, or (b) make logging in RMT configurable separately from other part of the system. It being affected by

Finally, the amount of log output produced by the std::condition_variable actually slows down the entire system by a large factor (I estimate my application runs at about 1/5 of normal speed), so are those log messages actually necessary? I propose to remove these messages entirely.

[chanibal]

I had similar situation with #1167 - there was some instability, but never issues with wrong timings of RMT. What it did cause was breaking another task writing to the UART2 at 100Hz (sometimes UART would block and write two messages concatenated, while I needed to have a distance between them).

Do you have a logic analyzer to verify the timings?

[PerMalmberg]

I have a scope to do the same, but there is no need to look that deep, as either reducing logging or removing logging from the RMT results in a functioning RMT, even with verbose logging enabled. Having a device as the RMT connected to the log system by default is a bad idea and really needs to be changed.

[chanibal]

What exactly is wrong timing - is it a deformation of the signal, or the signal being sent with a delay?

[PerMalmberg]

Have a look at these scope images. The first one shows the result with verbose logging level. The second one shows the same signal with logging set to info-level. The is RMT is activated every 200ms. In the first image, the pulse is 5,23ms, in the second it is 151us. Obviously, the longer one does not function as it should.

[chanibal]

How many 32 bit frames does the signal have?

This is important, because if the signal is short, then maybe it's not the signal timing, but it's looping might be the issue. How are you looping the RMT signal? The loop option in rmt_config_t, or manually (if so, how exactly)?

But if it's long, then maybe you did not allocate enough RMT mem blocks to it and, as far as I remember, RMT can swap it's memory blocks on the run - this might be a reason for a slow down.

[PerMalmberg]

I'm sending out exactly 121 rmt_item32_t items every 200ms. The memory is allocated by the application and since I'm using rmt_write_items(), the RMT uses that same memory to send, i.e. no copying of data according to the docs. And as such I'm not using loop mode; I'm even calling rmt_set_tx_loop_mode(channel, false)

You can see my implementation here: https://github.com/PerMalmberg/Smooth/blob/master/application/rgb_led/RGBLed.cpp
https://github.com/PerMalmberg/Smooth/blob/master/include/smooth/application/rgb_led/RGBLed.h

[chanibal]

You use 121 rmt_item32_t's, but only set up for 1 block of memory - and memory blocks are 64 items each.

Check if setting rmt_set_mem_block_num(channel, 2) will help.

[PerMalmberg]

How would that help? rmt_write_items() does not copy data according to the documentation, so it doesn't use the "internal" buffers, does it?

[chanibal]

RMT works a bit different if the sizes don't match - I have found that looping did not work properly if I don't fit in a mem block - despite the promise of non-copying. Slow memory access could be the cause of your issues. And frankly, if this is not the case, I have no other idea why RMT would slow down.

[PerMalmberg]

Ok, @chanibal, thanks for the info. Lets see if @igrr has some input on this.

[igrr]

@PerMalmberg I can't advise about the issue about RMT blocks mentioned by @chanibal (please report that separately and one of my colleagues will take a look), but i agree that there should be no need for logging in pthread_cond_timedwait or in RMT ISR.

[PerMalmberg]

Thanks for your quick response, @igrr. Do you want me to do a PR to remove the logging?

[igrr]

Closing as fixed in #1450.