Skip to content

Commit af51a7c

Browse files
committed
logging: Add ratelimited variants
These are helpful for logging in data-path, not to overwhelm the console but still keep the user informed about the issues. This is similar to printk_ratelimited in Linux kernel. Signed-off-by: Chaitanya Tata <[email protected]>
1 parent 1f69b91 commit af51a7c

File tree

9 files changed

+967
-88
lines changed

9 files changed

+967
-88
lines changed

doc/releases/release-notes-4.3.rst

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -65,6 +65,23 @@ New APIs and options
6565
6666
.. zephyr-keep-sorted-start re(^\* \w)
6767
68+
* :c:macro:`LOG_ERR_RATELIMITED` - Rate-limited error logging macro (convenience)
69+
* :c:macro:`LOG_WRN_RATELIMITED` - Rate-limited warning logging macro (convenience)
70+
* :c:macro:`LOG_INF_RATELIMITED` - Rate-limited info logging macro (convenience)
71+
* :c:macro:`LOG_DBG_RATELIMITED` - Rate-limited debug logging macro (convenience)
72+
* :c:macro:`LOG_HEXDUMP_ERR_RATELIMITED` - Rate-limited error hexdump macro (convenience)
73+
* :c:macro:`LOG_HEXDUMP_WRN_RATELIMITED` - Rate-limited warning hexdump macro (convenience)
74+
* :c:macro:`LOG_HEXDUMP_INF_RATELIMITED` - Rate-limited info hexdump macro (convenience)
75+
* :c:macro:`LOG_HEXDUMP_DBG_RATELIMITED` - Rate-limited debug hexdump macro (convenience)
76+
* :c:macro:`LOG_ERR_RATELIMITED_RATE` - Rate-limited error logging macro (explicit rate)
77+
* :c:macro:`LOG_WRN_RATELIMITED_RATE` - Rate-limited warning logging macro (explicit rate)
78+
* :c:macro:`LOG_INF_RATELIMITED_RATE` - Rate-limited info logging macro (explicit rate)
79+
* :c:macro:`LOG_DBG_RATELIMITED_RATE` - Rate-limited debug logging macro (explicit rate)
80+
* :c:macro:`LOG_HEXDUMP_ERR_RATELIMITED_RATE` - Rate-limited error hexdump macro (explicit rate)
81+
* :c:macro:`LOG_HEXDUMP_WRN_RATELIMITED_RATE` - Rate-limited warning hexdump macro (explicit rate)
82+
* :c:macro:`LOG_HEXDUMP_INF_RATELIMITED_RATE` - Rate-limited info hexdump macro (explicit rate)
83+
* :c:macro:`LOG_HEXDUMP_DBG_RATELIMITED_RATE` - Rate-limited debug hexdump macro (explicit rate)
84+
6885
.. zephyr-keep-sorted-stop
6986
7087
New Boards
@@ -90,9 +107,27 @@ New Samples
90107
Same as above for boards and drivers, this will also be recomputed at the time of the release.
91108
Just link the sample, further details go in the sample documentation itself.
92109
110+
Libraries / Subsystems
111+
**********************
112+
113+
* Logging:
114+
115+
* Added hybrid rate-limited logging macros to prevent log flooding when messages are generated frequently.
116+
The system provides both convenience macros (using default rate from :kconfig:option:`CONFIG_LOG_RATELIMIT_INTERVAL_MS`)
117+
and explicit rate macros (with custom rate parameter). This follows Linux's ``printk_ratelimited`` pattern
118+
while providing more flexibility. The rate limiting is per-macro-call-site, meaning that each unique call
119+
to a rate-limited macro has its own independent rate limit. Rate-limited logging can be globally enabled/disabled
120+
via :kconfig:option:`CONFIG_LOG_RATELIMIT_ENABLE`. For more details, see :ref:`logging_ratelimited`.
121+
93122
Other notable changes
94123
*********************
95124

125+
* Added rate-limited logging functionality to prevent log flooding when messages are generated frequently.
126+
This includes 16 new macros (8 convenience macros using default rate and 8 explicit rate macros)
127+
for all log levels and hexdump variants. The feature can be globally enabled/disabled via
128+
``CONFIG_LOG_RATELIMIT_ENABLE`` and the default rate configured via
129+
``CONFIG_LOG_RATELIMIT_INTERVAL_MS``. For more details, see :ref:`logging_ratelimited`.
130+
96131
..
97132
Any more descriptive subsystem or driver changes. Do you really want to write
98133
a paragraph or is it enough to link to the api/driver/Kconfig/board page above?

doc/services/logging/index.rst

Lines changed: 95 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ Summary of the logging features:
3232
- Support for logging floating point variables and long long arguments.
3333
- Built-in copying of transient strings used as arguments.
3434
- Support for multi-domain logging.
35+
- Rate-limited logging macros to prevent log flooding when messages are generated frequently.
3536

3637
Logging API is highly configurable at compile time as well as at run time. Using
3738
Kconfig options (see :ref:`logging_kconfig`) logs can be gradually removed from
@@ -59,6 +60,16 @@ The warning level also exposes the following additional macro:
5960

6061
- :c:macro:`LOG_WRN_ONCE` for warnings where only the first occurrence is of interest.
6162

63+
Rate-limited logging macros are also available for all severity levels to prevent log flooding:
64+
65+
- ``LOG_X_RATELIMITED`` for rate-limited standard printf-like messages using default rate, e.g. :c:macro:`LOG_ERR_RATELIMITED`.
66+
- ``LOG_X_RATELIMITED_RATE`` for rate-limited standard printf-like messages with custom rate, e.g. :c:macro:`LOG_ERR_RATELIMITED_RATE`.
67+
- ``LOG_HEXDUMP_X_RATELIMITED`` for rate-limited data dumping using default rate, e.g. :c:macro:`LOG_HEXDUMP_WRN_RATELIMITED`.
68+
- ``LOG_HEXDUMP_X_RATELIMITED_RATE`` for rate-limited data dumping with custom rate, e.g. :c:macro:`LOG_HEXDUMP_WRN_RATELIMITED_RATE`.
69+
70+
The convenience macros use the default rate specified by ``CONFIG_LOG_RATELIMIT_INTERVAL_MS``,
71+
while the explicit rate macros take a rate parameter (in milliseconds) that specifies the minimum interval between log messages.
72+
6273
There are two configuration categories: configurations per module and global
6374
configuration. When logging is enabled globally, it works for modules. However,
6475
modules can disable logging locally. Every module can specify its own logging
@@ -341,6 +352,88 @@ If logs are processed from a thread (user or internal) then it is possible to en
341352
a feature which will wake up processing thread when certain amount of log messages are
342353
buffered (see :kconfig:option:`CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD`).
343354

355+
.. _logging_ratelimited:
356+
357+
Rate-limited logging
358+
********************
359+
360+
Rate-limited logging macros provide a way to prevent log flooding when messages are
361+
generated frequently. These macros ensure that log messages are not output more
362+
frequently than a specified interval, similar to Linux's ``printk_ratelimited``
363+
functionality.
364+
365+
The rate-limited logging system provides two types of macros:
366+
367+
**Convenience macros (using default rate):**
368+
- :c:macro:`LOG_ERR_RATELIMITED` - Rate-limited error messages
369+
- :c:macro:`LOG_WRN_RATELIMITED` - Rate-limited warning messages
370+
- :c:macro:`LOG_INF_RATELIMITED` - Rate-limited info messages
371+
- :c:macro:`LOG_DBG_RATELIMITED` - Rate-limited debug messages
372+
- :c:macro:`LOG_HEXDUMP_ERR_RATELIMITED` - Rate-limited error hexdump
373+
- :c:macro:`LOG_HEXDUMP_WRN_RATELIMITED` - Rate-limited warning hexdump
374+
- :c:macro:`LOG_HEXDUMP_INF_RATELIMITED` - Rate-limited info hexdump
375+
- :c:macro:`LOG_HEXDUMP_DBG_RATELIMITED` - Rate-limited debug hexdump
376+
377+
**Explicit rate macros (with custom rate):**
378+
- :c:macro:`LOG_ERR_RATELIMITED_RATE` - Rate-limited error messages with custom rate
379+
- :c:macro:`LOG_WRN_RATELIMITED_RATE` - Rate-limited warning messages with custom rate
380+
- :c:macro:`LOG_INF_RATELIMITED_RATE` - Rate-limited info messages with custom rate
381+
- :c:macro:`LOG_DBG_RATELIMITED_RATE` - Rate-limited debug messages with custom rate
382+
- :c:macro:`LOG_HEXDUMP_ERR_RATELIMITED_RATE` - Rate-limited error hexdump with custom rate
383+
- :c:macro:`LOG_HEXDUMP_WRN_RATELIMITED_RATE` - Rate-limited warning hexdump with custom rate
384+
- :c:macro:`LOG_HEXDUMP_INF_RATELIMITED_RATE` - Rate-limited info hexdump with custom rate
385+
- :c:macro:`LOG_HEXDUMP_DBG_RATELIMITED_RATE` - Rate-limited debug hexdump with custom rate
386+
387+
The convenience macros use the default rate specified by :kconfig:option:`CONFIG_LOG_RATELIMIT_INTERVAL_MS`
388+
(5000ms by default). The explicit rate macros take a rate parameter (in milliseconds) that specifies
389+
the minimum interval between log messages. The rate limiting is per-macro-call-site, meaning
390+
that each unique call to a rate-limited macro has its own independent rate limit.
391+
392+
Example usage:
393+
394+
.. code-block:: c
395+
396+
#include <zephyr/logging/log.h>
397+
#include <zephyr/kernel.h>
398+
399+
LOG_MODULE_REGISTER(my_module, CONFIG_LOG_DEFAULT_LEVEL);
400+
401+
void process_data(void)
402+
{
403+
/* Convenience macros using default rate (CONFIG_LOG_RATELIMIT_INTERVAL_MS) */
404+
LOG_WRN_RATELIMITED("Data processing warning: %d", error_code);
405+
LOG_ERR_RATELIMITED("Critical error occurred: %s", error_msg);
406+
LOG_INF_RATELIMITED("Processing status: %d items", item_count);
407+
LOG_HEXDUMP_WRN_RATELIMITED(data_buffer, data_len, "Data buffer:");
408+
409+
/* Explicit rate macros with custom intervals */
410+
LOG_WRN_RATELIMITED_RATE(1000, "Fast rate warning: %d", error_code);
411+
LOG_ERR_RATELIMITED_RATE(30000, "Slow rate error: %s", error_msg);
412+
LOG_INF_RATELIMITED_RATE(2000, "Custom rate status: %d items", item_count);
413+
LOG_HEXDUMP_ERR_RATELIMITED_RATE(5000, data_buffer, data_len, "Error data:");
414+
}
415+
416+
Rate-limited logging is particularly useful for:
417+
418+
- Error conditions that might occur frequently but don't need to flood the logs
419+
- Status updates in tight loops or high-frequency callbacks
420+
- Debug information that could overwhelm the logging system
421+
- Network or I/O operations that might fail repeatedly
422+
423+
Configuration
424+
==============
425+
426+
Rate-limited logging can be configured using the following Kconfig options:
427+
428+
- :kconfig:option:`CONFIG_LOG_RATELIMIT_ENABLE` - Master switch to enable/disable rate-limited logging
429+
- :kconfig:option:`CONFIG_LOG_RATELIMIT_INTERVAL_MS` - Default interval for convenience macros (5000ms)
430+
431+
When :kconfig:option:`CONFIG_LOG_RATELIMIT_ENABLE` is disabled, all rate-limited macros expand to no-ops,
432+
ensuring clean compilation without any runtime overhead.
433+
434+
The rate limiting is implemented using static variables and :c:func:`k_uptime_get_32`
435+
to track the last log time for each call site.
436+
344437
.. _logging_panic:
345438

346439
Logging panic
@@ -790,6 +883,8 @@ Benchmark
790883
Benchmark numbers from :zephyr_file:`tests/subsys/logging/log_benchmark` performed
791884
on ``qemu_x86``. It is a rough comparison to give a general overview.
792885

886+
For testing rate-limited logging functionality, see :zephyr_file:`tests/subsys/logging/log_ratelimited`.
887+
793888
+--------------------------------------------+------------------+
794889
| Feature | |
795890
+============================================+==================+

0 commit comments

Comments
 (0)