log: add master log option (IDFGH-9721)

[someburner]

see #11049

Adds optional LOG_MASTER_LEVEL Kconfig option to log component. Results in 100x performance increase on ESP32 at 240Mhz when logs are compiled in, but disabled at runtime. Useful in cases where you only want log output some of the time. Results in a non-negligible increase in code size with lots of logs enabled, but that is also when you have the most to gain performance-wise.

I have not added test cases pending feedback.

Other things worth considering:

• if this should/could be applied to the early log macros
• Putting this in the noinit section so setting is preserved across boots.

Test it out for yourself:

• Compile with Max/Default = LOG_LEVEL_DEBUG.

#include <stdio.h>
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "esp_log.h"

static const char * TAG = "sometag";

void app_main(void)
{
    ESP_LOGI(TAG, "app_main init");

    esp_log_level_set("*", ESP_LOG_NONE);

    const int64_t MEASUREMENTS = 1000;

    while (true) {
        vTaskDelay( 1000 / portTICK_PERIOD_MS );

        int64_t start = esp_timer_get_time();

        for (int retries = 0; retries < MEASUREMENTS; retries++) {
            ESP_LOGI(TAG, "some test data, %d, %d, %d", retries, MEASUREMENTS-retries, 12);
        }

        int64_t end = esp_timer_get_time();

        printf("%lld iterations took %lld microseconds (%lld microseconds per invocation)\n",
           MEASUREMENTS, (end - start), (end - start)/MEASUREMENTS);

        if (g_master_log_level == ESP_LOG_NONE) {
            g_master_log_level = ESP_LOG_DEBUG;
        } else {
            g_master_log_level = ESP_LOG_NONE;
        }
    }
}

[igrr]

@someburner Thanks for the PR!

This feature seems to have an odd interaction with esp_log_level_set. It essentially overrides the value that can be set using esp_log_level_set, which i think is counter-intuitive, especially if esp_log_level_set is called later than esp_log_level_master_set.

Could we keep the existing API for setting the global log level? esp_log_level_set("*", ...); could set the "global" log level to the desired value. If the user calls esp_log_level_set("any other tag", ...); afterwards would cancel the "global" setting and set the specific level for the desired tag.

Something along these lines:

esp_log_level_set("mytag", ESP_LOG_DEBUG);  // (1) lowers "mytag" level to "DEBUG"
esp_log_level_set("*", ESP_LOG_NONE);  // (2) all logs (including "mytag") now are disabled
esp_log_level_set("mytag", ESP_LOG_DEBUG);  // (3) now "mytag" is enabled, everything else is disabled

If the new Kconfig option is enabled, after point (2) the new "global" "minimal_log_level" variable would be set to ESP_LOG_NONE, and the checks for logs-disabled would be very quick. After point (3), "minimal_log_level" would again be set to ESP_LOG_DEBUG, so the checks would become slower, but the behavior would still be the same as it is now.

This way, the component authors don't need to make assumptions whether the Kconfig option is set and write code accordingly. The behavior would be the same, just the performance/code size tradeoff would be different.

Please let me know if this makes sense!

Edit: corrected a typo in the code snippet

[someburner]

@igrr that makes sense. I did think the API was a bit funky. So in this case you're suggesting to still keep this feature optional? And is it better to do a new PR or just add commits to this one.

[igrr]

I think it should be optional if the global minimal log level is checked inside the log macro — since that leads to a significant increase in binary size.

(If you can tolerate slightly lower performance and check the global log level inside esp_log_write then it doesn't have to be optional.)

You can push more commits to this branch, and eventually squash the commits (git rebase -i) once you are done working on the feature.

[someburner]

I feel like this feature is targeted at performance, the 100x->10x hit is significant so I'll leave it optional.

Regarding your suggestion though- The only issue I see here is that some components call esp_log_level_set themselves. It looks like those are mostly guarded with config definitions and are mostly in the drivers folder.

In particular there is mbedtls_esp_enable_debug_log, and also in esp_wifi/src/wifi_init.c.

So my concern is something else in the SDK calling esp_log_level_set, which then unsets the esp_log_level_set("*", ESP_LOG_NONE);, and then the user can't be sure what state it's in.

It does seem like most of those are done in initialization functions. It would need to be clear in documentation exactly which components/options can undo this setting, and when.

And that is not to mention the potential of closed source libraries calling it..

[someburner]

Another issue, potentially- In my case I want to be able to set various log tags to various levels at runtime, based on a configuration received from a server. But I still don't want the performance hit until I explicitly say "turn on the logs" however that is done.

I suppose for that situation, I would have to set the various tags/levels to the desired configuration, and then call esp_log_level_set("*", ESP_LOG_NONE); afterwards. That isn't so bad, but then what if you really do want to esp_log_level_set("*", ESP_LOG_X); on all tags to reset them to a known state.

That could be achieved by having a esp_log_level_set("**", ESP_LOG_X); or similar, and if the option is disabled, that could simply do the same as esp_log_level_set("*", ESP_LOG_X);..

From the perspective of those using this feature for performance, that all seems to be much more confusing.

[KonstantinKondrashov]

Hi @someburner!
I agree that your feature is useful. Thanks for bringing this issue up.

... Useful in cases where you only want log output some of the time.

It makes me think that you just want to enable and disable all logs. So I think a better solution that fits your needs would be to add APIs: esp_log_enable() and esp_log_disable(), without setting the log level.

So I see the usage like this:

• first, you disable all logs, esp_log_disable()
• then set the correct level using esp_log_level_set("mytag", ESP_LOG_DEBUG)
• then enable the logs according to level settings. esp_log_enable()
  From my perspective, the usage of these APIs (esp_log_level_set and esp_log_enable/disable) getting more clear.
  And I would prefer to put the logic into the log function to skip code size overhead.

FYI, I am working on refactoring the log component so it will be much easier to add your feature after this work will be done.

[igrr]

Regarding esp_log_enable/disable, one remark is that it's difficult to deal with such centralized log control unless you are in control of the entire application code. For example, if one of the components you depend on decides to use esp_log_enable/disable, that might affect logging from other components, and you won't be able to do much about the issue without modifying the component source code.
Ideally, log level settings should be composable and one component should be able to control its own logs without affecting the rest of the system.

[someburner]

Ideally, log level settings should be composable and one component should be able to control its own logs without affecting the rest of the system.

Ideally, yeah. But in an environment of many components, and many logs, each taking 10us to check in cache, those times add up for end users who might have strict timing requirements, but also need visibility sometimes. In the embedded world you really can't have something like logging -not- affect other components unless your application has pretty loose timing requirements.

I don't depend on many 3rd party components, and if I do, I manage them myself. I imagine a lot of people follow this workflow.

I just grepped IDF and it appears only a few places where esp_log_level_set is called. I see where you are coming from though, that this gets more philosophical. I opened this PR for the benefit of other people saying they were interested in such a feature- personally I don't mind maintaining my own patch set.

In any case, I believe it would be to everyone's benefit to have a policy for IDF components regarding esp_log_level_set, explicitly document which components call that, and also document the tags and levels used by closed source libraries. Or if that's not possible, to provide guarantees about the closed source logs or a means to disable them.

[someburner]

@KonstantinKondrashov

Interested to see how the refactor looks. Please do keep in mind performance considerations in the refactor. In my case putting the check in the macro itself is preferred over checking inside a function. Or at least making it possible to hack something like this in but not maintained. For me the 10KB code increase is not a big deal on an 8MB or 16MB chip.

Also- in my case with this PR I get slightly different IRAM sizes from idf.py size when enabled vs disabled. I am pretty sure none of my components have logs in IRAM, and I don't use any 3rd party components. Assertions don't use the ESP_LOGx macros, so it appears there may be a few logs called in IRAM methods somewhere.

• One in spi_bus_lock_acquire_end, but that is verbose
• rmt_driver_isr_default
• npl_freertos_callout_deinit
• controller_sleep_cb
• hci_uart_rx_task
• esp_flash_erase_chip
• get_buffer_malloc

Seems like most of them not a big deal but probably not ideal to have it in hci_uart_rx_task or get_buffer_malloc.

I know this is a separate issue but goes towards my point of performance creep depending on log level.

[chipweinberger]

In my use case, I want to be able to turn on debug logs at runtime, but have them off by default without a big perf hit.

I think a master switch, which is ideally only called by the end user is the best approach.

If we want to make it play nice with other components, use a counting semaphore per log level. +1 on disable, -1 on enable.

[CLAassistant]

Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you sign our Contributor License Agreement before we can accept your contribution.
_{You have signed the CLA already but the status is still pending? Let us recheck it.}