Global log enable/disable (IDFGH-9712)

[someburner]

Any thoughts on adding a global variable that can be used to enable/disable all logs at runtime?

Use case:

In some applications, it may be desirable to have many logs compiled (e.g. set a high CONFIG_LOG_MAXIMUM_LEVEL), but not impose a performance hit during normal operation, and only do so when instructed. E.g. for remote debugging, or perhaps having conditions in code where you want to start seeing logs.

The log cache seems to be fairly performant, but as an example, in my project if I compile in logs at LOG_LEVEL_DEBUG, but disable them at runtime with esp_log_level_set("*", ESP_LOG_NONE);, there is enough of a performance hit that it warrants looking into.

const int64_t MEASUREMENTS = 1000;

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);

For me, this results in

1000 iterations took 9069 microseconds (9 microseconds per invocation)

Not too bad but if you have a lot of logs, it can start to add up.

If instead we add a global log variable and do something like this:

// log.c
bool g_logs_enabled = true;

// esp_log.h
extern bool g_logs_enabled;

#define ESP_LOG_LEVEL_LOCAL(level, tag, format, ...) do {               \
        if ( (g_logs_enabled) && (LOG_LOCAL_LEVEL >= level) ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \
    } while(0)

And switch that on/off each time with the test code:

g_logs_enabled = !g_logs_enabled;

You get:

# g_logs_enabled = false
1000 iterations took 90 microseconds (0 microseconds per invocation)
# g_logs_enabled = true (but log_level enabled)
1000 iterations took 9069 microseconds (9 microseconds per invocation)

Which is much more acceptable, but adds about 15KB to program size in my case. Any pitfalls with this / is this a bad idea? Should I be measuring differently?

[atanisoft]

Have you tried setting the maximum log level via menuconfig? Similarly have you tried calling something like esp_log_level_set("*", ESP_LOG_ERROR); (perhaps with ESP_LOG_NONE)

[someburner]

Yes that's what I described. With lots of logs compiled in but few enabled, you incur a performance hit as each log is checked to see if it's enabled.

[atanisoft]

There is also the KConfig setting for logs to disable all logs that are below a certain level, they simply will not be available in the compiled binary.

But having a bit more control to disable logs (such as a NDEBUG build) would speed it up considerably.

[someburner]

The stated use case is to make all logs available and run-time select-able, but without the performance hit. I understand you can simply not compile them in but that's not what I want.

[atanisoft]

I don't think it is feasible to have everything compiled in without having a performance hit, at least for lower level components built into IDF itself.

[someburner]

I benchmarked it, rudimentary, but clearly very feasible. I'm suggesting this as an optional feature for certain use cases and asking for feedback about pitfalls of doing things this way.

The performance difference is 100x. If it were not so great I wouldn't be suggesting this.

[chipweinberger]

You're right. There is going to be a big perf difference.

ESP_LOG_X supports a different log level per tag, so it does not do the runtime check later until this code:

void esp_log_writev(esp_log_level_t level, const char *tag, const char *format, va_list args)
{
    if (!esp_log_impl_lock_timeout()) {
        return;
    }
    esp_log_level_t level_for_tag = s_log_level_get_and_unlock(tag);
    if (!should_output(level, level_for_tag)) {
        return;
    }

    (*s_log_print_func)(format, args);
}

Which is already after we've done all this code too:

#define ESP_LOG_LEVEL(level, tag, format, ...) do {                     \
        if (level==ESP_LOG_ERROR )          { esp_log_write(ESP_LOG_ERROR,      tag, LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
        else if (level==ESP_LOG_WARN )      { esp_log_write(ESP_LOG_WARN,       tag, LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
        else if (level==ESP_LOG_DEBUG )     { esp_log_write(ESP_LOG_DEBUG,      tag, LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
        else if (level==ESP_LOG_VERBOSE )   { esp_log_write(ESP_LOG_VERBOSE,    tag, LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
        else                                { esp_log_write(ESP_LOG_INFO,       tag, LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
    } while(0)

I think it's reasonable to speed this up. I'd open a PR with your changes. But instead of a bool, I would do this:

#define ESP_LOG_LEVEL_LOCAL(level, tag, format, ...) do {               \
        if ( (level >= g_master_log_level) && (LOG_LOCAL_LEVEL >= level) ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \
    } while(0)

And perhaps add a new function:

void esp_log_level_master_set(esp_log_level_t level);

[someburner]

I think going that route it would have to be

#define ESP_LOG_LEVEL_LOCAL(level, tag, format, ...) do {               \
        if ( (g_master_log_level >= level) && (LOG_LOCAL_LEVEL >= level) ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \
    } while(0)

And a slight performance hit with the compare.

1000 iterations took 8674 microseconds (8 microseconds per invocation)
1000 iterations took 94 microseconds (0 microseconds per invocation)

Not sure why compiled-in but set to none perf is better, you'd think it'd be worse. But I like that approach- if you only want say, INFO level then you retain perf of not hitting the cache for DEBUG, etc.

[kriegste]

+1 Compiling with log level "debug" and despite disabling log output at run-time makes the SPI LCD routines slow. I noticed that, too, a few days ago. So there is a lot of optimization potential for speed and saving energy.

[chipweinberger]

@someburner your comments are hard to follow. What numbers are you comparing here?

And a slight performance hit with the compare.

1000 iterations took 8674 microseconds (8 microseconds per invocation)
1000 iterations took 94 microseconds (0 microseconds per invocation)

Not sure why compiled-in but set to none perf is better

Can you clarify - in this statement how are you setting it to none? Using my approach, yours, esp_log_level_set? And better than what?

[someburner]

@chipweinberger

In both cases I'm benching with max+default log level set to debug. The slow-running (8us / invocation) is when g_master_log_level = ESP_LOG_DEBUG;. And the faster running is when g_master_log_level = ESP_LOG_NONE;. And in these cases, I am calling esp_log_level_set("*", ESP_LOG_NONE); after init.

And the comment is saying it's strange that the "slow" case is oddly a little faster than when using the boolean check that I suggested in OP vs your recommendation.

But actually I think what might be happening is depending on when you do g_master_log_level = ESP_LOG_NONE;, some logs in IDF/your application will never esp_log_writev, so those tags wont be in the cache at all, and result in a little more perf when the master level is re-enabled and the cache is smaller. IDK I haven't been doing 1-1 comparisons, it's probably not a big deal.

[chipweinberger]

Got it.

So the esp_log_level_master_set(esp_log_level_t level) approach solves your perf issue too. Integer comparisons are basically the same perf as bool comparisons. I think it's worth opening a PR with the master level approach. I would like to have this perf improvement too!

[someburner]

Yeah I will open a PR soon. We'll see how it's received though. The API can be a little strange if you make it optional, and making it required adds a decent chunk to code size. They will want test cases added too and I'm lazy. But I can start with just the PR.

[chipweinberger]

adds a decent chunk to code size.

Perhaps put the g_master_log_level check in esp_log_writev? As opposed to putting it in the macro.

[someburner]

I think I tried that and it had worse perf. But I can double check before opening a PR. I don't think that would make any difference in terms of API though. Basically you either compile this in there and have the master_log_level and esp_log_level_master_set method do something, and increase code size, or you don't, and define esp_log_level_master_set as a do nothing macro. I'm sure they will have opinions.

For now I'm just adding a Kconfig option.

[someburner]

Here is my current 5.1 edits against 5.0. Some other stuff in there I added that might be useful for others too. Espressif is good about integrating PRs quickly but until they add the feature to use more dram as iram I have to maintain my own idf patch set.

esp_log.patch.txt

Might also want to add this to ESP_LOG_EARLY_IMPL.

[someburner]

Running a few more checks here:

1. confirmed placing the check in esp_log_write is slower, only 10x perf vs 100x

1000 iterations took 828 microseconds (0 microseconds per invocation)
1000 iterations took 7252 microseconds (7 microseconds per invocation)

Not surprising at all since this still doesn't skip timestamps if enabled and has to call a function. Placing in IRAM doesn't help much. I suppose there could be an argument for a 10x perf bonus with a bit smaller code size but IMO 5-20K ish is not a big deal if you really want perf.

[chipweinberger]

but IMO 5-20K ish is not a big deal if you really want perf.

My concern is IRAM functions that call ESP_LOGX will also be larger - many apps have little IRAM to spare. So of course, we should put this behind a KConfig.

CONFIG_ESP_LOG_FAST_MASTER_LEVEL - increase perf of master level ignore at the cost of code size and internal ram

We should also keep a check in esp_log_write. It should be checked in both places IMO, since that is still a 10x speedup even if you don't use the config.

[someburner]

More discussion in the PR:

https://github.com/espressif/esp-idf/pull/11057

I am pretty sure most components dont put debug macros into IRAM methods. Although I should probably check my IRAM usage with/without this to see.

Edit: Checked

# iram remaining without master_level check
4730
# iram remaining with with master_level check
4662

So there are a few log macros hiding in IRAM somewhere it would seem. I dont think they are in my project.

Essentially maintainer is asking to make this an optional feature but transparent to the API. From my perspective that adds a lot of "what ifs" to how I would like this feature to be used. Unless I can be sure that IDF components and closed source libraries are only using ESP_LOGx macros guarded by KConfig macros that always default to being off, then making it transparent to API is problematic for me.

[KonstantinKondrashov]

Hi! Since we have a PR https://github.com/espressif/esp-idf/pull/11057 for this issue I close this issue. Further discussion can be done there.