Specify log level at runtime

[usefulcat]

I'm in the process of migrating from an older logging library to Quill. So far Quill has been able to do almost everything I need, but there is one thing that I still need: the ability to specify the log level at runtime.

I've implemented this feature in a branch. The main change is the addition of a std::optional<LogLevel> to detail::Header. This allows the runtime-specified log level to be propagated to the backend thread so that it can be used when formatting the message (instead of using MacroMetadata::level()).

The downsides are:

• Header is ~8 bytes larger
• You can't just get the log level from the metadata, you have to check the header to see if the optional has a value

This was the least invasive way I could find to do it, but if there is a better way I'm open to suggestions.

[odygrd]

I think probably the best way to do this is to add it to the Header as you said. It can get a bit messy as we would need new log macros for the dynamic log level on the hot path and also change the backend logic and filters to check for it.

You can simulate this behaviour of dynamic log level on the backend with a custom Filter but the hot path will be logging everything

https://github.com/odygrd/quill/blob/master/examples/example_filters.cpp

It’s also safe to adjust the LogLevel of a Logger in runtime on the hot path if you wish for example to switch to debug logging while the application is running

Can you share a use case where you need dynamic log level?

[usefulcat]

I think probably the best way to do this is to add it to the Header as you said. It can get a bit messy as we would need new log macros for the dynamic log level on the hot path and also change the backend logic and filters to check for it.

You can simulate this behaviour of dynamic log level on the backend with a custom Filter but the hot path will be logging everything

https://github.com/odygrd/quill/blob/master/examples/example_filters.cpp

This is interesting but I think that for most of the places I use this I wouldn't want to do that, for reasons of efficiency.

It’s also safe to adjust the LogLevel of a Logger in runtime on the hot path if you wish for example to switch to debug logging while the application is running

This is a good thought, I hadn't thought of that. I'd prefer to avoid modifying Quill if possible, so I'll look into that.

Edit: I've just realized why changing the level of the logger isn't a good solution. The problem is that (without the changes I've made) the log level is still fixed at compile time in the MacroMetadata, so I think the formatter would use the compile time log level, not the dynamic level.

Can you share a use case where you need dynamic log level?

It's for a trading app. Whenever it makes a decision about what to do in response to market data or order-related events, it logs most of the relevant state (currently about 20 different things). For debugging I might set it to debug, in which case it will log every event, but for live trading I would set it to info in which case only the most important events get logged. For some events, the decision about which log level to use can only be made at runtime. Also it's doing this for dozens or hundreds of different symbols, so it adds up quickly.

When I first looked into this I wrote my own macro that did something like:

switch (level) {
    case LogLevel::Debug: LOG_DEBUG(logger, ...); break;
    case LogLevel::Info: LOG_INFO(logger, ...); break;
    case LogLevel::Warning: LOG_WARNING(logger, ...); break;
    case LogLevel::Error: LOG_ERROR(logger, ...); break;
    // etc...
}

..but it seemed like it would add way more code than was really needed, so I never cared for it.

[odygrd]

For some events, the decision about which log level to use can only be made at runtime.

Is it that you want DEBUG for a few symbols and for some others not for example ? Or is it that you want to promote some INFO to ERROR instead ? It would be nice to have the use case do see if I can think of any solutions.

Usually I add all features that are requested. My concerns about adding this to master is that as you said the extra header overhead and the little bit complexity it will add

edit: I think that your macro with the switch statement above isn’t actually a bad solution. I’m tempted to add it to master as a new macro

[usefulcat]

Each symbol (stock) has its own logger (symbol is part of the logger name), so that if needed I can enable additional logging only for specific symbols. Most of the log statements are at debug level most of the time and occasionally at info level. Most of the loggers are set to info level most of the time.

// method that logs a bunch of relevant state
void Strategy::log_state(quill::Logger* logger, quill::LogLevel level) const {
    if (level < logger->log_level()) return;
    // there's actually quite a lot of stuff in place of this comment, gathering
    // up all the relevant information, etc, hence the need for the above check.
    QUILL_LOG_LEVEL(logger, level, "giant format string", many_arguments);
}

// method that handles quote events
void Strategy::on_quote_event() {
    const bool something_important_happened = ...;
    log_state(logger, (something_important_happened ? quill::LogLevel::Info : quill::LogLevel::Debug));
}

// method that handles tradee events
void Strategy::on_trade_event() {
    const bool something_important_happened = ...;
    log_state(logger, (something_important_happened ? quill::LogLevel::Info : quill::LogLevel::Debug));
}

// ...and so on for several other kinds of events

The log_state() method exists because it's logging quite a lot of info, way too much to duplicate at every log_state() call site. It's true I could just do if (something_important_happened) LOG_INFO(...) else LOG_DEBUG(...) inside log_state, and in this particular case that would probably be ok--still some duplication but not too much. But there are also other places where I make use of a LOG_LEVEL type of macro, this is just one particular example.

[odygrd]

I have checked your branch and it was helpful, thank you

I implemented this slightly differently.

There is no overhead on the hot path for the previous macros, except an extra unused argument passed to the log function which should be fine.

When QUILL_DYNAMIC_LOG is used there is some minor overhead on the hot path (1 byte in the queue and the memcpy)

I haven't added the _LIMIT and _NOFN macros to reduce the complexity

Can you have a look at the PR and if it looks good to you too, I can merge it to master

#322

[usefulcat]

This looks good, I like your version better than mine. I've been testing it out this morning and it seems to be working well.

Thanks again for your help!

[usefulcat]

One minor thing, I am seeing this warning (gcc12) when QUILL_ACTIVE_LOG_LEVEL == QUILL_LOG_LEVEL_TRACE_L3:

./quill/Logger.h: In member function ‘bool quill::Logger::should_log(quill::LogLevel) const’:
./quill/Logger.h:101:34: error: comparison is always false due to limited range of data type [-Werror=type-limits]
  101 |       if (QUILL_ACTIVE_LOG_LEVEL > static_cast<uint8_t>(log_statement_level))

It's not a big deal for me, I can selectively disable that warning, but I thought you'd want to know. I couldn't figure out any other way to get rid of it, that's why I had the #ifdef in there originally. The compiler seems to take into account the possible values of log_statement_level, knowing the possible values for that enum type.

[odygrd]

thanks, I believe I have fixed the warning and I have merged this to master.
Let me know if you have any further issues !