Throttled log messages

[jasonbeach]

Is there a way to implement a "throttled" log message? i.e. say if I don't want a log message to be actually published more than once a second (or some desired frequency) even though the actual log function may be called more frequently? I've racked my head on how to do this without macros and haven't come up with anything. One implementation with macros would be something like:

#define LOG_THROTTLE(rate, level, ...) \
  do \
  { \
    static std::chrono::steady_clock::timepoint last_hit{0.0}; \
    auto now = std::chrono::steady_clock::now(); \
    if (last_hit + rate <= now ) \
    { \
      last_hit = now; \
      spdlog::log(level,__VA_ARGS__); \
    } \
  } while(0)

[tt4g]

There is not support but you can create custom sink.
spdlog::sinks::dist_sink is reference implementation: https://github.com/gabime/spdlog/blob/v1.9.2/include/spdlog/sinks/dist_sink.h

Example implementation

throttle_sink.hpp

#include <spdlog/details/log_msg.h>
#include <spdlog/details/null_mutex.h>
#include <spdlog/details/os.h>
#include <spdlog/pattern_formatter.h>
#include <spdlog/sinks/base_sink.h>

#include <algorithm>
#include <chrono>
#include <memory>
#include <mutex>
#include <utility>
#include <vector>

template <typename Mutex, typename BaseDuration = std::chrono::milliseconds>
class throttle_sink : public spdlog::sinks::base_sink<Mutex>
{
    using BaseSink = spdlog::sinks::base_sink<Mutex>;

public:
    explicit throttle_sink(BaseDuration rate)
        : rate_(std::move(rate)), sinks_(),
          last_(spdlog::log_clock::time_point(BaseDuration::min())) {}

    explicit throttle_sink(BaseDuration rate,
                           std::vector<std::shared_ptr<sink>> sinks)
        : rate_(std::move(rate)),
          sinks_(std::move(sinks)),
          last_(spdlog::log_clock::time_point(BaseDuration::min())) {}

    throttle_sink(const throttle_sink &) = delete;
    throttle_sink &operator=(const throttle_sink &) = delete;

    void add_sink(std::shared_ptr<sink> sink)
    {
        std::lock_guard<Mutex> lock(BaseSink::mutex_);
        sinks_.push_back(sink);
    }

    void remove_sink(std::shared_ptr<sink> sink)
    {
        std::lock_guard<Mutex> lock(BaseSink::mutex_);
        sinks_.erase(std::remove(sinks_.begin(), sinks_.end(), sink), sinks_.end());
    }

    void set_sinks(std::vector<std::shared_ptr<sink>> sinks)
    {
        std::lock_guard<Mutex> lock(BaseSink::mutex_);
        sinks_ = std::move(sinks);
    }

    std::vector<std::shared_ptr<sink>> &sinks() { return sinks_; }

protected:
    void sink_it_(const spdlog::details::log_msg &msg) override
    {
        // Throttling.
        auto diff = msg.time - last_;
        if (diff >= rate_) {
            last_ = msg.time;
        } else {
            return;
        }

        for (auto &sink : sinks_) {
            if (sink->should_log(msg.level)) {
                sink->log(msg);
            }
        }
    }

    void flush_() override
    {
        for (auto &sink : sinks_) {
            sink->flush();
        }
    }

    void set_pattern_(const std::string &pattern) override
    {
        set_formatter_(
            spdlog::details::make_unique<spdlog::pattern_formatter>(pattern));
    }

    void
    set_formatter_(std::unique_ptr<spdlog::formatter> sink_formatter) override
    {
        BaseSink::formatter_ = std::move(sink_formatter);
        for (auto &sink : sinks_) {
            sink->set_formatter(BaseSink::formatter_->clone());
        }
    }

private:
    BaseDuration rate_;

    std::vector<std::shared_ptr<spdlog::sinks::sink>> sinks_;

    spdlog::log_clock::time_point last_;
};

using throttle_sink_mt = throttle_sink<std::mutex>;
using throttle_sink_st = throttle_sink<spdlog::details::null_mutex>;

main.cpp

#include "throttle_sink.hpp"
#include <spdlog/sinks/stdout_color_sinks.h>
#include <spdlog/spdlog.h>

#include <chrono>
#include <memory>
#include <thread>

void main()
{
    auto stdout_color_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();
    std::vector<spdlog::sink_ptr> sinks;
    sinks.push_back(stdout_color_sink);
    auto throttle_sink =
        std::make_shared<throttle_sink_mt>(std::chrono::milliseconds(100), sinks);

    auto logger = std::make_shared<spdlog::logger>("throttle_logger", throttle_sink);

    logger->info("foo");
    logger->info("bar"); // Drop
    logger->info("baz"); // Drop

    std::this_thread::sleep_for(std::chrono::milliseconds(100));
    logger->info("qux");

    std::this_thread::sleep_for(std::chrono::milliseconds(20));
    logger->info("quux"); // Drop

    std::this_thread::sleep_for(std::chrono::milliseconds(20));
    logger->info("corge"); // Drop

    std::this_thread::sleep_for(std::chrono::milliseconds(60));
    logger->info("grault");
}

[jasonbeach]

That wouldn't work as I'm thinking...that would throttle all messages that go to that sink not a specific instance of a log message. Sorry if I wasn't clear that my intended goal would be to throttle a specific log message and not effect any other log messages. The idea is that if you have a message in a hot loop and the data in the message doesn't change rapidly (think position or velocity, etc.) you get the gist of what is happening or if you're polling waiting for some condition and want to log something without completely spamming a log.

[tt4g]

If you can't throttle all messages, you should be able to create a proxy class for spdlog;::logger (like throttle_sink).
The requirement can be met by using a proxy logger only to output specific log messages.

[gabime]

There is also the dup_filter_sink that you might find useful.