pw_log: Add rate limit log statements

Adds a PW_LOG_EVERY_N and PW_LOG_EVERY_N_DURATION macro
for rate limited logging.

Change-Id: Ia22da728f5f9b88f00c492e7742542ccf2c370bd
Reviewed-on: https://pigweed-review.googlesource.com/c/pigweed/pigweed/+/183870
Reviewed-by: Keir Mierle <keir@google.com>
Commit-Queue: Jordan Brauer <jtbrauer@google.com>
Reviewed-by: Ewout van Bekkum <ewout@google.com>
Presubmit-Verified: CQ Bot Account <pigweed-scoped@luci-project-accounts.iam.gserviceaccount.com>
This commit is contained in:
Jordan Brauer 2024-03-21 17:59:18 +00:00 committed by CQ Bot Account
parent f39e03d8ec
commit 9109c0d863
7 changed files with 256 additions and 0 deletions

View File

@ -51,6 +51,22 @@ pw_facade(
],
)
cc_library(
name = "rate_limited",
srcs = [
"rate_limited.cc",
],
hdrs = [
"public/pw_log/rate_limited.h",
],
includes = ["public"],
deps = [
":config_override",
":pw_log",
"//pw_chrono:system_clock",
],
)
label_flag(
name = "config_override",
build_setting_default = "//pw_build:default_module_config",
@ -151,6 +167,7 @@ pw_cc_test(
deps = [
":pw_log",
":pw_log.facade",
":rate_limited",
"//pw_preprocessor",
"//pw_unit_test",
],

View File

@ -59,6 +59,17 @@ pw_facade("pw_log") {
require_link_deps = [ ":impl" ]
}
pw_source_set("rate_limited") {
public_configs = [ ":public_include_path" ]
public = [ "public/pw_log/rate_limited.h" ]
public_deps = [
":config",
":pw_log",
"$dir_pw_chrono:system_clock",
]
sources = [ "rate_limited.cc" ]
}
pw_source_set("args") {
public_configs = [ ":public_include_path" ]
public_deps = [ dir_pw_tokenizer ]

View File

@ -45,6 +45,18 @@ pw_add_facade(pw_log INTERFACE
pw_log.config
)
pw_add_library(pw_log.rate_limited STATIC
HEADERS
public/pw_log/rate_limited.h
PUBLIC_INCLUDES
public
PUBLIC_DEPS
pw_log
pw_chrono.system_clock
SOURCES
rate_limited.cc
)
pw_add_library(pw_log.glog_adapter INTERFACE
HEADERS
public/pw_log/glog_adapter.h

View File

@ -133,6 +133,57 @@ system, intended to be used directly.
Shorthand for ``PW_LOG(<level>, PW_LOG_MODULE_NAME, PW_LOG_FLAGS, fmt, ...)``.
.. c:macro:: PW_LOG_EVERY_N(level, rate, ...)
A simple rate limit logger which will simply log one out of every N logs.
*level* - An integer level as defined by ``pw_log/levels.h``.
*rate* - Rate to reduce logs to, every ``rate``-th log will complete, others
will be suppressed.
.. c:macro:: PW_LOG_EVERY_N_DURATION(level, min_interval_between_logs, msg, ...)
This is a rate-limited form of logging, especially useful for progressive
or chatty logs that should be logged periodically, but not on each instance
of the logger being called.
*level* - An integer level as defined by ``pw_log/levels.h``.
*min_interval_between_logs* - A ``std::chrono::duration`` of the minimum time
between logs. Logs attempted before this time duration will be completely
dropped.
Dropped logs will be counted to add a drop count and calculated rate of the
logs.
*msg* - Formattable log message, as you would pass to the above ``PW_LOG``
macro.
.. note::
``PW_LOG_EVERY_N`` is simpler, if you simply need to reduce uniformly
periodic logs by a fixed or variable factor not based explicitly on a
duration. Each call to the macro will incur a static ``uint32_t`` within
the calling context.
``PW_LOG_EVERY_N_DURATION`` is able to suppress all logs based on a time
interval, suppressing logs logging faster than the desired time interval.
Each call to the duration macro will incur a static 16 byte object to
track the time interval within the calling context.
Example:
.. code-block:: cpp
// Ensure at least 500ms between transfer parameter logs.
chrono::SystemClock::duration rate_limit_ =
chrono::SystemClock::for_at_least(std::chrono::milliseconds(500));
PW_LOG_EVERY_N_DURATION(PW_LOG_LEVEL_INFO,
rate_limit_,
"Transfer %u sending transfer parameters!"
static_cast<unsigned>(session_id_));
--------------------
Module configuration
--------------------

View File

@ -101,6 +101,19 @@
PW_LOG(PW_LOG_LEVEL_CRITICAL, PW_LOG_MODULE_NAME, PW_LOG_FLAGS, __VA_ARGS__)
#endif // PW_LOG_CRITICAL
#ifndef PW_LOG_EVERY_N
#define PW_LOG_EVERY_N(level, rate, ...) \
do { \
static uint32_t _pw_log_suppressor##__LINE__ = 0; \
if (_pw_log_suppressor##__LINE__ == 0) { \
PW_LOG(level, PW_LOG_MODULE_NAME, PW_LOG_FLAGS, __VA_ARGS__); \
_pw_log_suppressor##__LINE__ = rate; \
} else { \
_pw_log_suppressor##__LINE__--; \
} \
} while (0)
#endif // PW_LOG_EVERY_N
// Default: Number of bits available for the log flags
//
// All log statements have a flags field, and this define is the number of bits

View File

@ -0,0 +1,101 @@
// Copyright 2024 The Pigweed Authors
//
// Licensed under the Apache License, Version 2.0 (the "License"); you may not
// use this file except in compliance with the License. You may obtain a copy of
// the License at
//
// https://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
// WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
// License for the specific language governing permissions and limitations under
// the License.
#pragma once
#include "pw_chrono/system_clock.h"
#include "pw_log/log.h"
// rate_limited adds a wrapper around a normal PW_LOG call to provide a rate
// limitor parameter to suppress chatty logs and provide info on how many logs
// were suppressed
// PW_LOG_EVERY_N_DURATION(level, min_interval_between_logs, msg, ...)
// - Required.
// level - An integer level as defined by pw_log/levels.h
// min_interval_between_logs - A std::chrono::duration of the minimum
// interval between
// two of the same logs.
// msg - Formattable message, same as you would use for PW_LOG or variants
//
// Does not check that input parameters have changed to un-suppress logs.
namespace pw::log::internal {
class RateLimiter {
public:
struct PollResult {
uint16_t count;
uint16_t logs_per_s;
};
explicit RateLimiter() {}
~RateLimiter() = default;
PollResult Poll(chrono::SystemClock::duration min_interval_between_logs);
private:
uint32_t count_ = 0;
chrono::SystemClock::time_point last_timestamp_;
};
} // namespace pw::log::internal
// PW_LOG_EVERY_N_DURATION(level, min_interval_between_logs, msg, ...)
//
// Logs a message at the given level, only it hasn't been logged within
// `min_interval_between_logs`.
//
// Inputs:
// level - An integer level as devifen by pw_log/levels.h
// min_interval_between_logs - A pw::chrono::SystemClock::duration that
// defines the minimum time interval between unsuppressed logs
// msg - Formattable message, same as you would use for PW_LOG or variants
//
// Includes a summary of how many logs were skipped, and a rough rate in
// integer seconds.
//
// NOTE: This macro is NOT threadsafe. The underlying object being modified by
// multiple threads calling the macro context may result in undefined behavior.
//
// Intended to supplement and replace widespread use of EVERY_N for logging. The
// main benefit this provides is responsiveness for bursty logs.
// LOG_RATE_LIMITED will log as soon as a burst starts - provided the
// `min_interval_between_logs` has elapsed - while EVERY_N may sit idle for a
// full period depending on the count state.
//
// Note that this will not log until called again, so the summary may include
// skipped logs from a prior burst.
#define PW_LOG_EVERY_N_DURATION(level, min_interval_between_logs, msg, ...) \
do { \
static pw::log::internal::RateLimiter rate_limiter; \
\
if (auto result = rate_limiter.Poll(min_interval_between_logs); \
result.count == std::numeric_limits<uint16_t>::max()) { \
PW_LOG(level, \
PW_LOG_MODULE_NAME, \
PW_LOG_FLAGS, \
msg " (skipped %d or more, %d/s)", \
##__VA_ARGS__, \
static_cast<unsigned>(result.count), \
static_cast<unsigned>(result.logs_per_s)); \
} else if (result.count != 0) { \
PW_LOG(level, \
PW_LOG_MODULE_NAME, \
PW_LOG_FLAGS, \
msg " (skipped %d, %d/s)", \
##__VA_ARGS__, \
static_cast<unsigned>(result.count - 1), \
static_cast<unsigned>(result.logs_per_s)); \
} \
} while (0)

51
pw_log/rate_limited.cc Normal file
View File

@ -0,0 +1,51 @@
// Copyright 2024 The Pigweed Authors
//
// Licensed under the Apache License, Version 2.0 (the "License"); you may not
// use this file except in compliance with the License. You may obtain a copy of
// the License at
//
// https://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
// WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
// License for the specific language governing permissions and limitations under
// the License.
#include "pw_log/rate_limited.h"
namespace pw::log::internal {
RateLimiter::PollResult RateLimiter::Poll(
chrono::SystemClock::duration min_interval_between_logs) {
PollResult result({
.count = 0,
.logs_per_s = 0,
});
const chrono::SystemClock::time_point now = chrono::SystemClock::now();
const chrono::SystemClock::duration elapsed = now - last_timestamp_;
if (count_ < std::numeric_limits<uint16_t>::max()) {
count_++;
}
if (last_timestamp_.time_since_epoch().count() != 0 &&
elapsed < min_interval_between_logs) {
return result;
}
// Add half to round not floor.
uint16_t elapsed_ms =
std::chrono::duration_cast<std::chrono::milliseconds>(elapsed).count();
if (elapsed_ms != 0) {
result.logs_per_s = (count_ * 1000 + 500) / elapsed_ms;
}
result.count = count_;
last_timestamp_ = now;
count_ = 0;
return result;
}
} // namespace pw::log::internal