User:MarcusMueller/Logging

This page describes the logging system, as it is in GNU Radio 3.10 and later. For the logging as realized in earlier versions, see Legacy Logging.

Usage

Log what you think might be useful. Some fundamental change occurred that you think you'd like to know about later on? Log. An error occurred? Definitely log! A setter method got a value that looks strange, but it's not an error, while probably still worth investigating? Log!

GNU Radio's logging system is very flexible and pretty fast. If you think it makes sense to be able to reconstruct what happened later on, that might be something you want to log (maybe with a low priority, see the section on Levels**.

Never use standard output for logging. GNU Radio's logging system allows for anyone who has special logging needs (e.g. forward all log messages to a central log server, have logs in a graphical environment) to attach to it. Can't do that with std::cout, std::cerror, printf, or Python's print.

Log Message Categories / Levels

The GNU Radio logging system is based on spdlog and hence exposes the same log levels. Use these to denote the severity of your logging message. For example, use info for things that might be interesting for someone observing the operation of your flow graph, use warn to notify that something might reasonably be assumed to be wrong and that they need to look into it, and error if something really is wrong and needs to be fixed.

The log levels are ordered, so when you tell the logging system "I don't care about anything less than a warning", you will not get info messages (and anything below in severity).

The levels are:

• trace: Tracing your code's operation. This is mostly for when you're developing an algorithm and need to log specific values that it calculates
• debug: Used for debugging purposes, and should not be visible under usual usage.
• info: Information that does not require immediate attention, but might be of interest to someone observing the operation
• warn: A warning. Means something might be wrong and it's probably worth looking into it.
• error: An error has occurred. Meaning something definitely is wrong.
• critical: An error that cannot be recovered from. For all that concerns your block/functional unit, execution cannot continue sensibly.

Logging in Python

In GNU Radio 3.10, you construct your own logger from gr.logger. For example, in a block context:

import numpy as np
import gnuradio as gr
class my_block(gr.sync_block):
    def __init__(self, foo = 1, bar = False):
        gr.sync_block.__init__(
            self,
            name="My fancy block",
            in_sig=[np.float32],
            out_sig=[np.float32])
        self.foo = foo
        self.bar = bar
        self.my_log = gr.logger(self.alias())
    def work(self, input_items, output_ites):
        if max(input_items) > self.foo:
            self.my_log.warn(f"maximum of input {max(input_items)} larger than foo ({self.foo})")
        output_items[0][:] = input_items[0][:]
        return len(output_items[0])

or outside a block

from gnuradio import gr
…
logging_mc_logface = gr.logger("prime searcher")
…
if number % potential_factor == 0:
    logging_mc_logface.info(f"{number} is not a prime, as it can be divided by {potential_factor}")
    return False

As you can see, we're using the fact that Python has formatted string literals (f"something {} more") to embed values in log messages. The Python format string syntax f"Some string {python expression}" defines how to embed values.

It's generally very straightforward: A formatted string is f"content", where content can contain {}, which in turn contain an expression (e.g., a variable name like number, or also formatting instructions):

f"The received int32 is {rx_value:b}"

will apply the b format to the variable rx_value. b prints a binary representation of the value. x prints a hexadecimal representation, wheras e can be used on floating point numbers to express them in exponential notation (f"{1/90000:e}" becomes 1.111111e-05). For more information on formats, see the format string syntax.

Logging in C++

If you're writing a block, you will already find d_logger as a member of your block. It is a smart pointer to a logger object. This logger is already set up correctly to log messages with a prefix that quotes your block's alias.

The different log levels are member functions of the logger, so you can log an error using d_logger->error(…) and a debug message using d_logger->debug(…).

So, in case you need to log a warning, e.g., when a value is invalid and has been replaced, you would follow this example

void my_block::gain_msg_handler(const pmt::pmt_t& message) {
    constexpr float min_gain = 1.0;
    d_gain = pmt::to_double(message);
    if (d_gain <= 0.0) {
        d_logger->warn("Attempted to set non-positive gain {}; clipping to {}.", d_gain, min_gain);
        d_gain = min_gain;
    }
}

Outside of blocks, you will have to create your own logger. You simply instantiate a gr::logger with the name of the logging "thing" as constructor parameter. An example of that is show below:

#include <gnuradio/logger.h>

class my_thing
{
private:
    gr::logger _logger;

public:
    my_thing(const std::string& name)
        : _logger("my thing " + name)
    {
        _logger.info("constructed");
    }
    ~my_thing() { _logger.warn("I don't like being destructed!"); }
};

int main() { my_thing thing("gizmo"); }

Logging Values

Since gr::logger is a wrapper around spdlog's logging facilities, it offers the same fmt-based string formatting.

An example of that was shown in gain_msg_handler above:

d_logger->warn("Attempted to set non-positive gain {}; clipping to {}.", d_gain, min_gain);

The {} get replaced (in their respective order) by the arguments to the logging function.

You can also set the format of fields by using a format specifier syntax very close to Python's format string syntax. For the actual full syntax definition, refer to fmt's specification.

This being C++, the type of the argument specifies already what type of conversion to use (unlike e.g. libc's printf, where you need to tell printf that an integer needs to be interpreted as an integer), so in most cases, you do not need to specify a format. However, sometimes enforcing a specific notation can be helpful for interpretation.

The format specification follows a colon :. Common examples of things that you might want:

• Formatting floating point in scientific notation: logger.warn("Amplitude {:e} out of range", value); Here, e causes the number passed in to be represented in scientific notation. Use g instead to only apply for large numbers.
• Formatting a value with fixed width: logger.warn("Count {: +15} out of range", count); Here, the format specification consists of a space , which is the fill character to be used to pad to the specified length of 15 characters, and + denotes that the sign should always be printed (not only for negative numbers). Works with numbers just as well as with strings.
• Formatting data in hexadecimal: logger.info("Got data {:X}", data_as_integer_of_any_width): Print using uppercase hexadecimal (13CAFE37). Use :x for lower case, and use :#x or :#X to get a 0x prefix.
• Formatting integers as binary: logger.warn("Value {:b} is not a valid code word. Corrected to {:b}.", rx_word, code_word);. Use :#b to get a 0b prefix.

Performance Considerations

Logger Construction Cost

While constructing a logger is not very expensive, it's still not something you want to do within a hot loop, as it requires inter-thread coordination. Ideally, you want your entity to hold onto a logger object once it's been created. (This is solved through the d_logger member if you're writing a GNU Radio block. Elsewhere, define your own member if in a class context.)

Logging Cost – Disabled Logging

It's possible to disable logging at compile time (it's not recommended, logging is universally quite useful). Or, that the minimum log level was set to higher than a message's log level, so that, for example d_logger->trace("val: {: +15g}"); shouldn't actually do anything.

There is an integer comparison at run time that will be incurred by having this logging in the code. Notice, however, that modern CPUs tend to predict that to be false if it happens more often, and even if they didn't, such a comparison is quite cheap (and speculative execution would have continued after the logging in the meantime). Benchmarking showed negligible overhead unless used in tight arithmetic loops. If you are in the rare case that you want to log from such a compute-intense place, you would want to wrap the logging in some preprocessor #if magic (or figure out a less invasive place to log).

The format string evaluation only happens when the logging actually takes place. So, even complex logging formats (aside from the code size) do not affect the runtime. (It might, however, affect life time of some values, so it's not free of side effects.)

Logging Cost – Active Logging

fmt is seriously fast. In fact, it beats things like std::stringstream << by orders of magnitude. Especially when logging things that should not happen often (warn, error or critical), it's probably a good idea to rather log more useful information than less.