printk ratelimiting #472

foxhlchen · 2021-07-31T12:15:16Z

Features:

Add pr_*_ratelimited macros (not including pr_debug_ratelimited)
Add printk_ratelimit

Implementation:

pr_*_ratelimit are macros that define a static local ratelimit_state and use Atomic and CAS to guard its initialization. That ratelimit_state will be used later by ___ratelimit() to decide if to suppress the printk or not.
printk_ratelimit wraps around kernel's __printk_ratelimit which calls __ratelimit() with a globally shared ratelimit_state

Future:

pr_debug_ratelimited is special and more complicated, will implement it in future PRs.

Issues:

Complete printing support #122

rust/kernel/print.rs

nbdd0121 · 2021-07-31T19:01:37Z

I think it's probably better to use similar approach to once that I do in 0f02826 (which is once part of #300) but dropped from that PR because it was considered low priority for upstreaming).

I.e. use pr_info!(once, "{}", "blah") or pr_info!(ratelimited, "{}", "blah") instead of pr_info_once("{}", "blah") or pr_info_ratelimited("{}", "blah").

nbdd0121 · 2021-07-31T19:28:19Z

rust/kernel/print.rs

+        static mut PRINTK_RS: core::mem::MaybeUninit<$crate::print::ratelimit_state> =
+            core::mem::MaybeUninit::<$crate::print::ratelimit_state>::uninit();
+        static mut PRINTK_RS_PTR: core::sync::atomic::AtomicPtr<$crate::print::ratelimit_state> =
+            core::sync::atomic::AtomicPtr::<$crate::print::ratelimit_state>::new(core::ptr::null_mut());
+        static mut PRINTK_RS_AVAILABLE: core::sync::atomic::AtomicBool =
+            core::sync::atomic::AtomicBool::new(false);
+
+        // SAFETY: [`PRINTK_RS_AVAILABLE`] and [`PRINTK_RS_PTR`] is used to
+        // control the intialization of [`PRINTK_RS`] - a local
+        // [`ratelimit_state`] initialized with [`DEFAULT_RATELIMIT_INTERVAL`]
+        // and [`DEFAULT_RATELIMIT_BURST`]. All of these three variables are
+        // static local variables to avoid dynamic memory allocation and no
+        // lock is used because printk can be used in any circumstance.
+        //
+        // The hidden macro [`call_printk`] should only be called by the
+        // documented printing macros which ensure the format string is one of
+        // the fixed ones.
+        // All `__LOG_PREFIX`s are null-terminated as they are generated
+        // by the `module!` proc macro or fixed values defined in a kernel
+        // crate.
+        unsafe {
+            if PRINTK_RS_AVAILABLE.compare_exchange(
+                false,
+                true,
+                core::sync::atomic::Ordering::SeqCst,
+                core::sync::atomic::Ordering::SeqCst
+            ).is_ok() {
+                // Zero out [`PRINTK_RS`] then initialize it using
+                // [`rust_helper_ratelimit_state_init`] helper function.
+                *PRINTK_RS.as_mut_ptr() = $crate::print::ratelimit_state::default();
+                $crate::print::rust_helper_ratelimit_state_init(PRINTK_RS.as_mut_ptr());
+
+                // Make PRINTK_RS_PTR point at PRINTK_RS so later we can call
+                // [`___ratelimit`] with it.
+                if PRINTK_RS_PTR.load(
+                    core::sync::atomic::Ordering::SeqCst
+                ).is_null() {
+                    PRINTK_RS_PTR.store(
+                        PRINTK_RS.as_mut_ptr(),
+                        core::sync::atomic::Ordering::SeqCst
+                    );
+                }
+            }
+
+            // [`PRINTK_RS`] can be uninitialized under concurrent situation,
+            // if so, we print message without ratelimit control.
+            // Otherwise we call __ratelimit to decide if
+            // enforce ratelimit.
+            if PRINTK_RS_PTR.load(core::sync::atomic::Ordering::SeqCst).is_null() ||
+                $crate::print::___ratelimit(
+                    PRINTK_RS_PTR.load(core::sync::atomic::Ordering::SeqCst),
+                    $crate::c_str!($where).as_char_ptr()
+                ) != 0 {
+                $crate::print::call_printk(


I think a better approach might be providing an abstraction of the ratelimiter instead of having these macro expanded each time.

There is a problem, we need a static local ratelimite_state at each occurrence. Can we do this without macros??

You can have a Ratelimiter that wraps ratelimit_state and call a method on it each time.

But how can we preserve the state??
Can you elaborate further?

You'll still need a static variable, but just static RATERLIMITER: Ratelimiter = Ratelimiter::new(); (or perhaps Lazy<Ratelimiter>).

I might need to use Lazy.
Does it work well in multithreading??

There are SyncLazy in std (but not core) and once_cell::sync::Lazy. We probably need to implement our own Lazy in kernel.

foxhlchen · 2021-08-01T03:13:50Z

I think it's probably better to use similar approach to once that I do in 0f02826 (which is once part of #300) but dropped from that PR because it was considered low priority for upstreaming).

I.e. use pr_info!(once, "{}", "blah") or pr_info!(ratelimited, "{}", "blah") instead of pr_info_once("{}", "blah") or pr_info_ratelimited("{}", "blah").

I don't think merging them into one will be better. Because:

They are fundamentally different.

pr_* expands to
printk(log_level, fmt, ....)

while pr_*_ratelimited:

<delcare a static local ratelimit_state and initialize it in the first run>
if ___ratelimit(ratelimit_state)
      printk(log_level, fmt, ...)

pr_* is more basic & used way more often than pr_*_ratelimited
The kernel has separate pr_* and pr_*_ratelimited. Doing this consistently makes it easier to navigate between rust & c code.

nbdd0121 · 2021-08-01T03:18:40Z

The C code has pr_* and pr_*_ratelimited due to the limitation of C macros. You can't do pattern matching in C macros but Rust allows that.

The semantics is really just how often do you want the print to be executed. So essentially:

pr_* is if (true) printk(...)
pr_*_once is if (first time) printk(...)
pr_*_ratelimited is if (__ratelimit(ratelimit_state)) printk(...)

foxhlchen · 2021-08-01T03:31:25Z

The C code has pr_* and pr_*_ratelimited due to the limitation of C macros. You can't do pattern matching in C macros but Rust allows that.

The semantics is really just how often do you want the print to be executed. So essentially:

pr_* is if (true) printk(...)

pr_*_once is if (first time) printk(...)

pr_*_ratelimited is if (__ratelimit(ratelimit_state)) printk(...)

Ok, then that makes sense to me.

I can turn this into inner implementation and write a universal pr_* as a dispatcher.

ojeda · 2021-08-01T11:54:26Z

What users gain by writing pr_info!(once, vs. pr_info_once!?

foxhlchen · 2021-08-02T01:19:46Z

What users gain by writing pr_info!(once, vs. pr_info_once!?

For me, pr_info!(once...) makes semantics more "intact" (as Gary mentioned above) while pr_info_once is more consistent with the C side.

nbdd0121 · 2021-08-02T01:30:34Z

Some reasons related how macros are namespaced in Rust:

Namespace pollution: macros are always defined in the crate root, so if we follow C style then eventually we will have a huge list of macros in crate root doc, which isn't nice to navigate through
Importing: either they are all re-exported via the prelude, adding once to ratelimited will require changing the import
Documentation: having these functionalities in a single macro allows doc reader to see all the options together without needing to navigate through links and having documentations duplicated

Also, for me once/ratelimited are just "modifiers" to the print, so having them as options for pr_* macros feels more natural.

ojeda · 2021-08-02T14:12:36Z

The same discussion could be had about the level itself, i.e. we could argue that a single pr! macro that does everything is best. Same for assert! and its variations, as well as functions if we had e.g. overloading, like read_*().

I do not particularly mind one way or the other, and the documentation can indeed look funny with so many variations. However, we were asked to keep names as close to the C side as possible, thus if we do not have a strong reason otherwise, we should go with the C scheme.

In fact, I think the best way to approach these changes is that we have a talk with potential improvements to common APIs for the Rust side, and see what is the input from kernel developers. We have accumulated quite a few of these ideas, thus we could put all together in a small talk and ask for feedback. If one of you is up to give such a talk in September, let me know.

ojeda · 2021-10-14T15:00:23Z

In fact, I think the best way to approach these changes is that we have a talk with potential improvements to common APIs for the Rust side, and see what is the input from kernel developers. We have accumulated quite a few of these ideas, thus we could put all together in a small talk and ask for feedback. If one of you is up to give such a talk in September, let me know.

Well, in the end there was no discussion at LPC in the end about naming :(

We can go with either.

nbdd0121 · 2021-10-14T15:03:17Z

I think we should have them implemented together in the print_macro, and then we can decide/change later about how it is exposed.

foxhlchen · 2021-10-14T15:48:14Z

I think we should have them implemented together in the print_macro, and then we can decide/change later about how it is exposed.

Yeah, probably with a more universal design

Oh, it's been a while, sorry I'm busy recently... sigh.

foxhlchen · 2021-10-22T04:14:25Z

I think we should have them implemented together in the print_macro, and then we can decide/change later about how it is exposed.

Hi Gary, Does your 'together' mean what you proposed before:
pr_info!(once, "{}", "blah") or pr_info!(ratelimited, "{}", "blah")?

I will take a look at the weekend.

This commit adds equivalent pr_*_ratelimited to kernel crate. They are macros that define a static local `ratelimit_state` and uses Atomic and CAS to guard its initialization. That `ratelimit_state` will be used later by `___ratelimit()` to decide if to suppress the `printk` or not. Because we use Atomic & CAS to help initialize `ratelimit_state`, in concurrent situation some thread may reach `__ratelimit()` before `ratelimit_state` is initialized. If that happens, we call `printk` anyway. This commit does not implement pr_debug_ratelimited since it's special and way more complicated and deserves another dedicated commit. `printk_ratelimit` is also implemented in this commit Signed-off-by: Fox Chen <[email protected]>

foxhlchen · 2021-11-01T06:20:51Z

I rebased the pr to the latest.

I think @nbdd0121 's proposal can be implemented later in other PR when we have decided how to approach print_macro (probably related to #300) and have a more universal design. For now, I stick to what we have and use pr_*_ratelimited.

ojeda · 2021-11-08T18:20:33Z

rust/kernel/print.rs

+    /// This function initializes ratelimit_state with DEFAULT_RATELIMIT_INTERVAL
+    /// and DEFAULT_RATELIMIT_BURST.


Suggested change

/// This function initializes ratelimit_state with DEFAULT_RATELIMIT_INTERVAL

/// and DEFAULT_RATELIMIT_BURST.

/// Initializes the parameter with `DEFAULT_RATELIMIT_INTERVAL`

/// and `DEFAULT_RATELIMIT_BURST`.

ojeda · 2021-11-08T18:28:20Z

rust/kernel/print.rs

+/// [`pr_emerg`]: https://www.kernel.org/doc/html/latest/core-api/printk-basics.html#c.pr_emerg
+/// [`std::print!`]: https://doc.rust-lang.org/std/macro.print.html
+///
+/// [`where`] parameter is a string literal that will be used as an


where cannot be a link (rustdoc warns); same for the others:

Suggested change

/// [`where`] parameter is a string literal that will be used as an

/// `where` parameter is a string literal that will be used as an

ojeda · 2021-11-08T18:30:53Z

rust/kernel/print.rs

+/// identifier when ratelimite is triggered. In C this is populated with
+/// __function__.


Suggested change

/// identifier when ratelimite is triggered. In C this is populated with

/// __function__.

/// identifier when the ratelimit is triggered. In C this is populated with

/// `__function__`.

ojeda · 2021-11-08T18:33:18Z

rust/kernel/print.rs

+macro_rules! print_macro_ratelimited (
+    // The non-continuation cases (most of them, e.g. `INFO`).
+    ($format_string:path, false, $where:literal, $($arg:tt)+) => ({
+        static mut PRINTK_RS: core::mem::MaybeUninit<$crate::print::ratelimit_state> =


Perhaps use MaybeUninit, AtomicPtr, SeqCst, etc. to make this more readable?

ojeda · 2021-11-08T18:37:28Z

samples/rust/rust_print.rs

+            if printk_ratelimit!("RustPrint::init") {
+                pr_warn!("Inside printk_ratelimit {}", i);
+            }


Could you please add a test for this in the CI? (we are testing for other messages too)

ojeda · 2021-11-08T18:42:41Z

rust/kernel/print.rs

+/// identifier when ratelimite is triggered. In C this is populated with
+/// __function__.


Suggested change

/// identifier when ratelimite is triggered. In C this is populated with

/// __function__.

/// identifier when the ratelimit is triggered. In C this is populated with

/// `__function__`.

ojeda · 2021-11-08T18:45:07Z

rust/kernel/print.rs

+        // All `__LOG_PREFIX`s are null-terminated as they are generated
+        // by the `module!` proc macro or fixed values defined in a kernel
+        // crate.
+        unsafe {


It would be best to reduce the scope of unsafe.

ojeda · 2021-11-08T18:46:03Z

rust/kernel/print.rs

+        // SAFETY: [`PRINTK_RS_AVAILABLE`] and [`PRINTK_RS_PTR`] is used to
+        // control the intialization of [`PRINTK_RS`] - a local


Do we want all these as intradoc links?

ojeda · 2021-11-08T18:48:47Z

rust/kernel/print.rs

@@ -190,6 +203,90 @@ macro_rules! print_macro (
    );
 );

+/// Same as [`print_macro`], but ratelimites messages with local ratelimit_state.


Suggested change

/// Same as [`print_macro`], but ratelimites messages with local ratelimit_state.

/// Same as [`print_macro`], but ratelimits messages with a local `ratelimit_state`.

ojeda · 2021-11-08T18:50:22Z

rust/kernel/print.rs

+pub use bindings::___ratelimit;
+pub use bindings::__printk_ratelimit;
+pub use bindings::ratelimit_state;


I think it is best to avoid useng things from bindings to make it clear to the reader it comes from the C side.

ojeda · 2021-11-08T18:52:07Z

I think Gary's suggestion is worth doing -- it will be useful elsewhere (similarly, a Once one) and will make the code here much easier to review.

foxhlchen · 2021-11-09T01:35:22Z

I think Gary's suggestion is worth doing -- it will be useful elsewhere (similarly, a Once one) and will make the code here much easier to review.

Ok, let me change interfaces to pr_info!(once, "{}", "blah") pr_info!(ratelimited, "{}", "blah")

ojeda · 2021-11-09T10:33:29Z

Ok, let me change interfaces to pr_info!(once, "{}", "blah") pr_info!(ratelimited, "{}", "blah")

Sorry, I meant the one about factoring out the rate limiting into its own abstraction. Please leave the interfaces as they were for the moment.

bjorn3 reviewed Jul 31, 2021

View reviewed changes

rust/kernel/print.rs Show resolved Hide resolved

foxhlchen force-pushed the pr-printk-ratelimited branch from 726b9c4 to 3807c6f Compare July 31, 2021 13:07

nbdd0121 reviewed Jul 31, 2021

View reviewed changes

foxhlchen force-pushed the pr-printk-ratelimited branch from 3807c6f to 45c3e2f Compare November 1, 2021 06:06

ojeda reviewed Nov 8, 2021

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

printk ratelimiting #472

printk ratelimiting #472

foxhlchen commented Jul 31, 2021

nbdd0121 commented Jul 31, 2021

nbdd0121 Jul 31, 2021

foxhlchen Aug 1, 2021

nbdd0121 Aug 1, 2021

foxhlchen Aug 1, 2021

nbdd0121 Aug 1, 2021

foxhlchen Aug 1, 2021

nbdd0121 Aug 1, 2021

foxhlchen commented Aug 1, 2021

nbdd0121 commented Aug 1, 2021

foxhlchen commented Aug 1, 2021

ojeda commented Aug 1, 2021

foxhlchen commented Aug 2, 2021

nbdd0121 commented Aug 2, 2021

ojeda commented Aug 2, 2021

ojeda commented Oct 14, 2021

nbdd0121 commented Oct 14, 2021

foxhlchen commented Oct 14, 2021

foxhlchen commented Oct 22, 2021

foxhlchen commented Nov 1, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda Nov 8, 2021

ojeda commented Nov 8, 2021

foxhlchen commented Nov 9, 2021

ojeda commented Nov 9, 2021

		/// This function initializes ratelimit_state with DEFAULT_RATELIMIT_INTERVAL
		/// and DEFAULT_RATELIMIT_BURST.

	/// [`where`] parameter is a string literal that will be used as an
	/// `where` parameter is a string literal that will be used as an

		/// identifier when ratelimite is triggered. In C this is populated with
		/// __function__.

		// SAFETY: [`PRINTK_RS_AVAILABLE`] and [`PRINTK_RS_PTR`] is used to
		// control the intialization of [`PRINTK_RS`] - a local

	/// Same as [`print_macro`], but ratelimites messages with local ratelimit_state.
	/// Same as [`print_macro`], but ratelimits messages with a local `ratelimit_state`.

printk ratelimiting #472

Are you sure you want to change the base?

printk ratelimiting #472

Conversation

foxhlchen commented Jul 31, 2021

nbdd0121 commented Jul 31, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

foxhlchen commented Aug 1, 2021

nbdd0121 commented Aug 1, 2021

foxhlchen commented Aug 1, 2021

ojeda commented Aug 1, 2021

foxhlchen commented Aug 2, 2021

nbdd0121 commented Aug 2, 2021

ojeda commented Aug 2, 2021

ojeda commented Oct 14, 2021

nbdd0121 commented Oct 14, 2021

foxhlchen commented Oct 14, 2021

foxhlchen commented Oct 22, 2021

foxhlchen commented Nov 1, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ojeda commented Nov 8, 2021

foxhlchen commented Nov 9, 2021

ojeda commented Nov 9, 2021