linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH 0/2] ratelimit: Do not lose messages under limit
@ 2018-05-10 12:52 Dmitry Safonov
  2018-05-10 12:52 ` [PATCH 1/2] random: Omit double-printing ratelimit messages Dmitry Safonov
  2018-05-10 12:52 ` [PATCH 2/2] lib/ratelimit: Lockless ratelimiting Dmitry Safonov
  0 siblings, 2 replies; 12+ messages in thread
From: Dmitry Safonov @ 2018-05-10 12:52 UTC (permalink / raw)
  To: linux-kernel
  Cc: 0x7f454c46, Dmitry Safonov, Arnd Bergmann, Theodore Ts'o,
	David Airlie, Greg Kroah-Hartman, Jani Nikula, Joonas Lahtinen,
	Rodrigo Vivi, Thomas Gleixner, intel-gfx, dri-devel

There are two issues with ratelimiting as far a I can see:
1. Messages may be lost even if their amount fit burst limit;
2. "suppressed" message may not be printed if there is no call to
   ___ratelimit() after interval ends.

I address (1) issue in the second patch.
While the (2) issue will require adding timers to print "suppressed"
message and care if ratelimit is on stack and no more exists. Which
looks too much at this point.

Dmitry Safonov (2):
  random: Omit double-printing ratelimit messages
  lib/ratelimit: Lockless ratelimiting

 drivers/char/random.c            | 22 +++++++--------
 drivers/gpu/drm/i915/i915_perf.c |  4 +--
 include/linux/ratelimit.h        | 34 ++++++++++++++---------
 lib/ratelimit.c                  | 59 +++++++++++++++++++---------------------
 4 files changed, 61 insertions(+), 58 deletions(-)

-- 
2.13.6

^ permalink raw reply	[flat|nested] 12+ messages in thread

* [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-10 12:52 [PATCH 0/2] ratelimit: Do not lose messages under limit Dmitry Safonov
@ 2018-05-10 12:52 ` Dmitry Safonov
  2018-05-10 18:19   ` Theodore Y. Ts'o
  2018-05-10 12:52 ` [PATCH 2/2] lib/ratelimit: Lockless ratelimiting Dmitry Safonov
  1 sibling, 1 reply; 12+ messages in thread
From: Dmitry Safonov @ 2018-05-10 12:52 UTC (permalink / raw)
  To: linux-kernel; +Cc: 0x7f454c46, Dmitry Safonov, Arnd Bergmann, Theodore Ts'o

Currently "suppressed" messages will be printed once in a second for
unseeded/urandom warnings, but there is already custom message which
says how many warnings are missing. So, let's skip suppressed messages
until crng_init == 2.

P.S.: not sure if there is a value in custom messages, maybe we can just
remove them instead.

Cc: Arnd Bergmann <arnd@arndb.de>
Cc: Theodore Ts'o <tytso@mit.edu>
Signed-off-by: Dmitry Safonov <dima@arista.com>
---
 drivers/char/random.c     |  6 ++++--
 include/linux/ratelimit.h | 10 +++++++---
 2 files changed, 11 insertions(+), 5 deletions(-)

diff --git a/drivers/char/random.c b/drivers/char/random.c
index cd888d4ee605..c1c40c7ed0e8 100644
--- a/drivers/char/random.c
+++ b/drivers/char/random.c
@@ -440,9 +440,9 @@ static void process_random_ready_list(void);
 static void _get_random_bytes(void *buf, int nbytes);
 
 static struct ratelimit_state unseeded_warning =
-	RATELIMIT_STATE_INIT("warn_unseeded_randomness", HZ, 3);
+	RATELIMIT_STATE_INIT_FLAGS("warn_unseeded_randomness", HZ, 3, RATELIMIT_MSG_ON_RELEASE);
 static struct ratelimit_state urandom_warning =
-	RATELIMIT_STATE_INIT("warn_urandom_randomness", HZ, 3);
+	RATELIMIT_STATE_INIT_FLAGS("warn_urandom_randomness", HZ, 3, RATELIMIT_MSG_ON_RELEASE);
 
 static int ratelimit_disable __read_mostly;
 
@@ -949,12 +949,14 @@ static void crng_reseed(struct crng_state *crng, struct entropy_store *r)
 				  unseeded_warning.missed);
 			unseeded_warning.missed = 0;
 		}
+		unseeded_warning.flags = 0;
 		if (urandom_warning.missed) {
 			pr_notice("random: %d urandom warning(s) missed "
 				  "due to ratelimiting\n",
 				  urandom_warning.missed);
 			urandom_warning.missed = 0;
 		}
+		urandom_warning.flags = 0;
 	}
 }
 
diff --git a/include/linux/ratelimit.h b/include/linux/ratelimit.h
index 8ddf79e9207a..e9a14a7641e0 100644
--- a/include/linux/ratelimit.h
+++ b/include/linux/ratelimit.h
@@ -23,12 +23,16 @@ struct ratelimit_state {
 	unsigned long	flags;
 };
 
-#define RATELIMIT_STATE_INIT(name, interval_init, burst_init) {		\
+#define RATELIMIT_STATE_INIT_FLAGS(name, _interval, _burst, _flags) {	\
 		.lock		= __RAW_SPIN_LOCK_UNLOCKED(name.lock),	\
-		.interval	= interval_init,			\
-		.burst		= burst_init,				\
+		.interval	= _interval,				\
+		.burst		= _burst,				\
+		.flags		= _flags,				\
 	}
 
+#define RATELIMIT_STATE_INIT(name, _interval, _burst)			\
+	RATELIMIT_STATE_INIT_FLAGS(name, _interval, _burst, 0)
+
 #define RATELIMIT_STATE_INIT_DISABLED					\
 	RATELIMIT_STATE_INIT(ratelimit_state, 0, DEFAULT_RATELIMIT_BURST)
 
-- 
2.13.6

^ permalink raw reply	[flat|nested] 12+ messages in thread

* [PATCH 2/2] lib/ratelimit: Lockless ratelimiting
  2018-05-10 12:52 [PATCH 0/2] ratelimit: Do not lose messages under limit Dmitry Safonov
  2018-05-10 12:52 ` [PATCH 1/2] random: Omit double-printing ratelimit messages Dmitry Safonov
@ 2018-05-10 12:52 ` Dmitry Safonov
  1 sibling, 0 replies; 12+ messages in thread
From: Dmitry Safonov @ 2018-05-10 12:52 UTC (permalink / raw)
  To: linux-kernel
  Cc: 0x7f454c46, Dmitry Safonov, Arnd Bergmann, David Airlie,
	Greg Kroah-Hartman, Jani Nikula, Joonas Lahtinen, Rodrigo Vivi,
	Theodore Ts'o, Thomas Gleixner, intel-gfx, dri-devel

Currently ratelimit_state is protected with spin_lock. If the .lock is
taken at the moment of ___ratelimit() call, the message is suppressed to
make ratelimiting robust.

That results in the following issue issue:
      CPU0                          CPU1
------------------           ------------------
printk_ratelimit()           printk_ratelimit()
        |                             |
  try_spin_lock()              try_spin_lock()
        |                             |
time_is_before_jiffies()          return 0; // suppress

So, concurrent call of ___ratelimit() results in silently suppressing
one of the messages, regardless if the limit is reached or not.
And rc->missed is not increased in such case so the issue is covered
from user.

Convert ratelimiting to use atomic counters and drop spin_lock.

Note: in the rare corner-case when (rs->burst == 0) and concurrent
access suppressed message might be printed from both (several) CPUs,
that are accessing ratelimit.

Note: That might be unexpected, but with the first interval of messages
storm one can print up to burst*2 messages. So, it doesn't guarantee
that in *any* interval amount of messages is lesser than burst.
But, that differs lightly from previous behavior where one can start
burst=5 interval and print 4 messages on the last milliseconds of
interval + new 5 messages from new interval (totally 9 messages in
lesser than interval value).

Cc: Arnd Bergmann <arnd@arndb.de>
Cc: David Airlie <airlied@linux.ie>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: Jani Nikula <jani.nikula@linux.intel.com>
Cc: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
Cc: Rodrigo Vivi <rodrigo.vivi@intel.com>
Cc: "Theodore Ts'o" <tytso@mit.edu>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: intel-gfx@lists.freedesktop.org
Cc: dri-devel@lists.freedesktop.org
Signed-off-by: Dmitry Safonov <dima@arista.com>
---
 drivers/char/random.c            | 16 ++++-------
 drivers/gpu/drm/i915/i915_perf.c |  4 +--
 include/linux/ratelimit.h        | 24 +++++++++-------
 lib/ratelimit.c                  | 59 +++++++++++++++++++---------------------
 4 files changed, 50 insertions(+), 53 deletions(-)

diff --git a/drivers/char/random.c b/drivers/char/random.c
index c1c40c7ed0e8..3694cbcb04a0 100644
--- a/drivers/char/random.c
+++ b/drivers/char/random.c
@@ -937,25 +937,21 @@ static void crng_reseed(struct crng_state *crng, struct entropy_store *r)
 	crng->init_time = jiffies;
 	spin_unlock_irqrestore(&crng->lock, flags);
 	if (crng == &primary_crng && crng_init < 2) {
+		int unseeded_miss, urandom_miss;
+
 		invalidate_batched_entropy();
 		numa_crng_init();
 		crng_init = 2;
 		process_random_ready_list();
 		wake_up_interruptible(&crng_init_wait);
 		pr_notice("random: crng init done\n");
-		if (unseeded_warning.missed) {
+		if ((unseeded_miss = atomic_xchg(&unseeded_warning.missed, 0)))
 			pr_notice("random: %d get_random_xx warning(s) missed "
-				  "due to ratelimiting\n",
-				  unseeded_warning.missed);
-			unseeded_warning.missed = 0;
-		}
+				  "due to ratelimiting\n", unseeded_miss);
 		unseeded_warning.flags = 0;
-		if (urandom_warning.missed) {
+		if ((urandom_miss = atomic_xchg(&urandom_warning.missed, 0)))
 			pr_notice("random: %d urandom warning(s) missed "
-				  "due to ratelimiting\n",
-				  urandom_warning.missed);
-			urandom_warning.missed = 0;
-		}
+				  "due to ratelimiting\n", urandom_miss);
 		urandom_warning.flags = 0;
 	}
 }
diff --git a/drivers/gpu/drm/i915/i915_perf.c b/drivers/gpu/drm/i915/i915_perf.c
index abaca6edeb71..a8e00913bdb9 100644
--- a/drivers/gpu/drm/i915/i915_perf.c
+++ b/drivers/gpu/drm/i915/i915_perf.c
@@ -1316,9 +1316,9 @@ static void i915_oa_stream_destroy(struct i915_perf_stream *stream)
 
 	put_oa_config(dev_priv, stream->oa_config);
 
-	if (dev_priv->perf.oa.spurious_report_rs.missed) {
+	if (atomic_read(&dev_priv->perf.oa.spurious_report_rs.missed)) {
 		DRM_NOTE("%d spurious OA report notices suppressed due to ratelimiting\n",
-			 dev_priv->perf.oa.spurious_report_rs.missed);
+			 atomic_read(&dev_priv->perf.oa.spurious_report_rs.missed));
 	}
 }
 
diff --git a/include/linux/ratelimit.h b/include/linux/ratelimit.h
index e9a14a7641e0..ddc572389f08 100644
--- a/include/linux/ratelimit.h
+++ b/include/linux/ratelimit.h
@@ -4,7 +4,6 @@
 
 #include <linux/param.h>
 #include <linux/sched.h>
-#include <linux/spinlock.h>
 
 #define DEFAULT_RATELIMIT_INTERVAL	(5 * HZ)
 #define DEFAULT_RATELIMIT_BURST		10
@@ -13,21 +12,21 @@
 #define RATELIMIT_MSG_ON_RELEASE	BIT(0)
 
 struct ratelimit_state {
-	raw_spinlock_t	lock;		/* protect the state */
+	atomic_t	printed;
+	atomic_t	missed;
 
 	int		interval;
 	int		burst;
-	int		printed;
-	int		missed;
 	unsigned long	begin;
 	unsigned long	flags;
 };
 
 #define RATELIMIT_STATE_INIT_FLAGS(name, _interval, _burst, _flags) {	\
-		.lock		= __RAW_SPIN_LOCK_UNLOCKED(name.lock),	\
 		.interval	= _interval,				\
 		.burst		= _burst,				\
 		.flags		= _flags,				\
+		.printed	= ATOMIC_INIT(0),			\
+		.missed		= ATOMIC_INIT(0),			\
 	}
 
 #define RATELIMIT_STATE_INIT(name, _interval, _burst)			\
@@ -46,9 +45,10 @@ static inline void ratelimit_state_init(struct ratelimit_state *rs,
 {
 	memset(rs, 0, sizeof(*rs));
 
-	raw_spin_lock_init(&rs->lock);
 	rs->interval	= interval;
 	rs->burst	= burst;
+	atomic_set(&rs->printed, 0);
+	atomic_set(&rs->missed, 0);
 }
 
 static inline void ratelimit_default_init(struct ratelimit_state *rs)
@@ -57,16 +57,20 @@ static inline void ratelimit_default_init(struct ratelimit_state *rs)
 					DEFAULT_RATELIMIT_BURST);
 }
 
+/*
+ * Keeping It Simple: not reenterable and not safe for concurrent
+ * ___ratelimit() call as used only by devkmsg_release().
+ */
 static inline void ratelimit_state_exit(struct ratelimit_state *rs)
 {
+	int missed;
+
 	if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE))
 		return;
 
-	if (rs->missed) {
+	if ((missed = atomic_xchg(&rs->missed, 0)))
 		pr_warn("%s: %d output lines suppressed due to ratelimiting\n",
-			current->comm, rs->missed);
-		rs->missed = 0;
-	}
+			current->comm, missed);
 }
 
 static inline void
diff --git a/lib/ratelimit.c b/lib/ratelimit.c
index d01f47135239..c99305e9239f 100644
--- a/lib/ratelimit.c
+++ b/lib/ratelimit.c
@@ -13,6 +13,18 @@
 #include <linux/jiffies.h>
 #include <linux/export.h>
 
+static void ratelimit_end_interval(struct ratelimit_state *rs, const char *func)
+{
+	rs->begin = jiffies;
+
+	if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
+		unsigned missed = (unsigned)atomic_xchg(&rs->missed, 0);
+
+		if (missed)
+			pr_warn("%s: %u callbacks suppressed\n", func, missed);
+	}
+}
+
 /*
  * __ratelimit - rate limiting
  * @rs: ratelimit_state data
@@ -27,45 +39,30 @@
  */
 int ___ratelimit(struct ratelimit_state *rs, const char *func)
 {
-	unsigned long flags;
-	int ret;
-
 	if (!rs->interval)
 		return 1;
 
-	/*
-	 * If we contend on this state's lock then almost
-	 * by definition we are too busy to print a message,
-	 * in addition to the one that will be printed by
-	 * the entity that is holding the lock already:
-	 */
-	if (!raw_spin_trylock_irqsave(&rs->lock, flags))
+	if (unlikely(!rs->burst)) {
+		atomic_add_unless(&rs->missed, 1, -1);
+		if (time_is_before_jiffies(rs->begin + rs->interval))
+			ratelimit_end_interval(rs, func);
+
 		return 0;
+	}
 
-	if (!rs->begin)
-		rs->begin = jiffies;
+	if (atomic_add_unless(&rs->printed, 1, rs->burst))
+		return 1;
 
 	if (time_is_before_jiffies(rs->begin + rs->interval)) {
-		if (rs->missed) {
-			if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
-				printk_deferred(KERN_WARNING
-						"%s: %d callbacks suppressed\n",
-						func, rs->missed);
-				rs->missed = 0;
-			}
-		}
-		rs->begin   = jiffies;
-		rs->printed = 0;
-	}
-	if (rs->burst && rs->burst > rs->printed) {
-		rs->printed++;
-		ret = 1;
-	} else {
-		rs->missed++;
-		ret = 0;
+		if (atomic_cmpxchg(&rs->printed, rs->burst, 0))
+			ratelimit_end_interval(rs, func);
 	}
-	raw_spin_unlock_irqrestore(&rs->lock, flags);
 
-	return ret;
+	if (atomic_add_unless(&rs->printed, 1, rs->burst))
+		return 1;
+
+	atomic_add_unless(&rs->missed, 1, -1);
+
+	return 0;
 }
 EXPORT_SYMBOL(___ratelimit);
-- 
2.13.6

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-10 12:52 ` [PATCH 1/2] random: Omit double-printing ratelimit messages Dmitry Safonov
@ 2018-05-10 18:19   ` Theodore Y. Ts'o
  2018-05-10 18:37     ` Dmitry Safonov
  0 siblings, 1 reply; 12+ messages in thread
From: Theodore Y. Ts'o @ 2018-05-10 18:19 UTC (permalink / raw)
  To: Dmitry Safonov; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Thu, May 10, 2018 at 01:52:10PM +0100, Dmitry Safonov wrote:
> Currently "suppressed" messages will be printed once in a second for
> unseeded/urandom warnings, but there is already custom message which
> says how many warnings are missing. So, let's skip suppressed messages
> until crng_init == 2.

I'm not sure what you are trying to fix?  The whole point of the
ratelimit system is to nly allow no more than <burst> packages in a
particular time interval.  Once that time interval has expired,
messages allowed again until they exceed the burst limit.  So printing
messages once a second is, in fact, working as intended.

	      	       	      	    	    - Ted

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-10 18:19   ` Theodore Y. Ts'o
@ 2018-05-10 18:37     ` Dmitry Safonov
  2018-05-10 19:40       ` Theodore Y. Ts'o
  0 siblings, 1 reply; 12+ messages in thread
From: Dmitry Safonov @ 2018-05-10 18:37 UTC (permalink / raw)
  To: Theodore Y. Ts'o; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Thu, 2018-05-10 at 14:19 -0400, Theodore Y. Ts'o wrote:
> On Thu, May 10, 2018 at 01:52:10PM +0100, Dmitry Safonov wrote:
> > Currently "suppressed" messages will be printed once in a second
> > for
> > unseeded/urandom warnings, but there is already custom message
> > which
> > says how many warnings are missing. So, let's skip suppressed
> > messages
> > until crng_init == 2.
> 
> I'm not sure what you are trying to fix?  The whole point of the
> ratelimit system is to nly allow no more than <burst> packages in a
> particular time interval.  Once that time interval has expired,
> messages allowed again until they exceed the burst limit.  So
> printing
> messages once a second is, in fact, working as intended.


Ok, then what's the purpose of those messages?
:        pr_notice("random: %d get_random_xx warning(s) missed "
:                  "due to ratelimiting\n",
:                  unseeded_warning.missed);
:        pr_notice("random: %d urandom warning(s) missed "
:                  "due to ratelimiting\n",
:                  urandom_warning.missed);

I thought you want to print the summary after initializing random,
not once per second?

-- 
Thanks,
             Dmitry

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-10 18:37     ` Dmitry Safonov
@ 2018-05-10 19:40       ` Theodore Y. Ts'o
  2018-05-10 19:50         ` Dmitry Safonov
  0 siblings, 1 reply; 12+ messages in thread
From: Theodore Y. Ts'o @ 2018-05-10 19:40 UTC (permalink / raw)
  To: Dmitry Safonov; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Thu, May 10, 2018 at 07:37:40PM +0100, Dmitry Safonov wrote:
> 
> Ok, then what's the purpose of those messages?
> :        pr_notice("random: %d get_random_xx warning(s) missed "
> :                  "due to ratelimiting\n",
> :                  unseeded_warning.missed);
> :        pr_notice("random: %d urandom warning(s) missed "
> :                  "due to ratelimiting\n",
> :                  urandom_warning.missed);
> 
> I thought you want to print the summary after initializing random,
> not once per second?

Yes, and that's what is happening today.  The "output lines suppressed
due to ratelimiting" message is only printed out by printk_ratelimit()
function, which we are *not* using.

So I'm not sure what you are unhappy about?  What are you trying to fix?

>From my testing, it is *NOT* double-printing ratelimit messages today.
Are you seeing something that I am not?

       	   	     	     	     	     	  - Ted

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-10 19:40       ` Theodore Y. Ts'o
@ 2018-05-10 19:50         ` Dmitry Safonov
  2018-05-11  3:51           ` Theodore Y. Ts'o
  0 siblings, 1 reply; 12+ messages in thread
From: Dmitry Safonov @ 2018-05-10 19:50 UTC (permalink / raw)
  To: Theodore Y. Ts'o; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Thu, 2018-05-10 at 15:40 -0400, Theodore Y. Ts'o wrote:
> On Thu, May 10, 2018 at 07:37:40PM +0100, Dmitry Safonov wrote:
> > 
> > Ok, then what's the purpose of those messages?
> > :        pr_notice("random: %d get_random_xx warning(s) missed "
> > :                  "due to ratelimiting\n",
> > :                  unseeded_warning.missed);
> > :        pr_notice("random: %d urandom warning(s) missed "
> > :                  "due to ratelimiting\n",
> > :                  urandom_warning.missed);
> > 
> > I thought you want to print the summary after initializing random,
> > not once per second?
> 
> Yes, and that's what is happening today.  The "output lines
> suppressed
> due to ratelimiting" message is only printed out by
> printk_ratelimit()
> function, which we are *not* using.

random uses __ratelimit() which calls ___ratelimit() with a function
name. Depending on !RATELIMIT_MSG_ON_RELEASE it prints how many
messages were suppressed every ratelimit interval (1 second for random)
and flushes ratelimit_state::missed:

:if (time_is_before_jiffies(rs->begin + rs->interval)) {
:    if (rs->missed) {
:        if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
:            printk_deferred(KERN_WARNING
:                            "%s: %d callbacks suppressed\n",
:                            func, rs->missed);
:            rs->missed = 0;
:        }
:    }
:    rs->begin   = jiffies;
:    rs->printed = 0;
:}

-- 
Thanks,
             Dmitry

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-10 19:50         ` Dmitry Safonov
@ 2018-05-11  3:51           ` Theodore Y. Ts'o
  2018-05-11 12:41             ` Dmitry Safonov
  0 siblings, 1 reply; 12+ messages in thread
From: Theodore Y. Ts'o @ 2018-05-11  3:51 UTC (permalink / raw)
  To: Dmitry Safonov; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Thu, May 10, 2018 at 08:50:07PM +0100, Dmitry Safonov wrote:
> random uses __ratelimit() which calls ___ratelimit() with a function
> name. Depending on !RATELIMIT_MSG_ON_RELEASE it prints how many
> messages were suppressed every ratelimit interval (1 second for random)
> and flushes ratelimit_state::missed:

So the thing about the ratelimit system is that if you have a burst of
1,000,000 within the one second burst window, and then nothing ever
again, you will never see a message accounting for those 1,000,000
"callbacks" (which is a terrible wording; it just confuses people).

If you have a burst of 1,000,000 calls to ratelimit, and then a month
goes by, and *then* a single call to __ratelimit is called by printk,
only *the* does the message about the suppressed "callback" get
printed.

So in the case of the random driver, once the random driver is fully
intialized, there will never be a call to __ratelimit() for the
urandom ratelimit structures, so we manually print out the final
number of suppressed message so there is proper accounting for them.

It is not a double-count.  If we didn't do that, those suppressed
warnings would never be mentioned by the kernel.

Cheers,

						- Ted

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-11  3:51           ` Theodore Y. Ts'o
@ 2018-05-11 12:41             ` Dmitry Safonov
  2018-05-16 15:46               ` Dmitry Safonov
  0 siblings, 1 reply; 12+ messages in thread
From: Dmitry Safonov @ 2018-05-11 12:41 UTC (permalink / raw)
  To: Theodore Y. Ts'o; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Thu, 2018-05-10 at 23:51 -0400, Theodore Y. Ts'o wrote:
> On Thu, May 10, 2018 at 08:50:07PM +0100, Dmitry Safonov wrote:
> > random uses __ratelimit() which calls ___ratelimit() with a
> > function
> > name. Depending on !RATELIMIT_MSG_ON_RELEASE it prints how many
> > messages were suppressed every ratelimit interval (1 second for
> > random)
> > and flushes ratelimit_state::missed:
> 
> So the thing about the ratelimit system is that if you have a burst
> of
> 1,000,000 within the one second burst window, and then nothing ever
> again, you will never see a message accounting for those 1,000,000
> "callbacks" (which is a terrible wording; it just confuses people).
> 
> If you have a burst of 1,000,000 calls to ratelimit, and then a month
> goes by, and *then* a single call to __ratelimit is called by printk,
> only *the* does the message about the suppressed "callback" get
> printed.

Yes, if the initialization time of driver is lesser than a second.
If it's 1.1 sec - you'll have prints from ___ratelimit() and from your
driver too. And they differ in format.

> So in the case of the random driver, once the random driver is fully
> intialized, there will never be a call to __ratelimit() for the
> urandom ratelimit structures, so we manually print out the final
> number of suppressed message so there is proper accounting for them.

So, there is this flag, AFAICS, which perfectly fits your purpose
RATELIMIT_MSG_ON_RELEASE which will omit printing how many messages
were suppressed every interval of ___ratelimit(). And that will allow
you to print total in the end.

> It is not a double-count.  If we didn't do that, those suppressed
> warnings would never be mentioned by the kernel.

Yeah, but what you print is not total sum, it's since the last interval
because without mentioned flag ___ratelimit() will flush missed counter
and print "suppressed" message.
They might even double if say other proccess has called
get_random_bytes() got to ___ratelimit() and got preempted. This thread
finishes initializing random driver and prints this not-proper-sum
statistics, and when the code flow is back in the first context, it
will print statistics again from ___ratelimit() function. 

-- 
Thanks,
             Dmitry

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-11 12:41             ` Dmitry Safonov
@ 2018-05-16 15:46               ` Dmitry Safonov
  2018-05-16 20:54                 ` Theodore Y. Ts'o
  0 siblings, 1 reply; 12+ messages in thread
From: Dmitry Safonov @ 2018-05-16 15:46 UTC (permalink / raw)
  To: Theodore Y. Ts'o; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Fri, 2018-05-11 at 13:41 +0100, Dmitry Safonov wrote:
> On Thu, 2018-05-10 at 23:51 -0400, Theodore Y. Ts'o wrote:
> > On Thu, May 10, 2018 at 08:50:07PM +0100, Dmitry Safonov wrote:
> > > random uses __ratelimit() which calls ___ratelimit() with a
> > > function
> > > name. Depending on !RATELIMIT_MSG_ON_RELEASE it prints how many
> > > messages were suppressed every ratelimit interval (1 second for
> > > random)
> > > and flushes ratelimit_state::missed:
> > 
> > So the thing about the ratelimit system is that if you have a burst
> > of
> > 1,000,000 within the one second burst window, and then nothing ever
> > again, you will never see a message accounting for those 1,000,000
> > "callbacks" (which is a terrible wording; it just confuses people).
> > 
> > If you have a burst of 1,000,000 calls to ratelimit, and then a
> > month
> > goes by, and *then* a single call to __ratelimit is called by
> > printk,
> > only *the* does the message about the suppressed "callback" get
> > printed.
> 
> Yes, if the initialization time of driver is lesser than a second.
> If it's 1.1 sec - you'll have prints from ___ratelimit() and from
> your
> driver too. And they differ in format.
> 
> > So in the case of the random driver, once the random driver is
> > fully
> > intialized, there will never be a call to __ratelimit() for the
> > urandom ratelimit structures, so we manually print out the final
> > number of suppressed message so there is proper accounting for
> > them.
> 
> So, there is this flag, AFAICS, which perfectly fits your purpose
> RATELIMIT_MSG_ON_RELEASE which will omit printing how many messages
> were suppressed every interval of ___ratelimit(). And that will allow
> you to print total in the end.
> 
> > It is not a double-count.  If we didn't do that, those suppressed
> > warnings would never be mentioned by the kernel.
> 
> Yeah, but what you print is not total sum, it's since the last
> interval
> because without mentioned flag ___ratelimit() will flush missed
> counter
> and print "suppressed" message.
> They might even double if say other proccess has called
> get_random_bytes() got to ___ratelimit() and got preempted. This
> thread
> finishes initializing random driver and prints this not-proper-sum
> statistics, and when the code flow is back in the first context, it
> will print statistics again from ___ratelimit() function. 

So, does it make sense to you, Theodore?
If not - I'll just resend second patch rebasing and dropping this one.

-- 
Thanks,
             Dmitry

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-16 15:46               ` Dmitry Safonov
@ 2018-05-16 20:54                 ` Theodore Y. Ts'o
  2018-05-16 22:11                   ` Dmitry Safonov
  0 siblings, 1 reply; 12+ messages in thread
From: Theodore Y. Ts'o @ 2018-05-16 20:54 UTC (permalink / raw)
  To: Dmitry Safonov; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Wed, May 16, 2018 at 04:46:13PM +0100, Dmitry Safonov wrote:
> > Yeah, but what you print is not total sum, it's since the last
> > interval because without mentioned flag ___ratelimit() will flush
> > missed counter and print "suppressed" message.  They might even
> > double if say other proccess has called get_random_bytes() got to
> > ___ratelimit() and got preempted. This thread finishes
> > initializing random driver and prints this not-proper-sum
> > statistics, and when the code flow is back in the first context,
> > it will print statistics again from ___ratelimit() function.
> 
> So, does it make sense to you, Theodore?
> If not - I'll just resend second patch rebasing and dropping this one.

Yes, it's correct that it's not the total sum.  I guess your complaint
is that some of the messages are using the "callbacks suppressed"
message, and the last one is using the random drvier's custom message
which I think is much more user-friendly.  That being said, although I
think "callbacks suppressed is a terrible message, I agree that using
a single message makes more sense.  So setting the
RATELIMIT_MSG_ON_RELEASE and then calling ratelimit_state_exit() from
crng_reseed() does make sense.

In the future I'd like to push for some way to customize --- or
perhaps just fix --- "callbacks suppressed" to something more sane
like, "messages ratelimited", but that's more of an aesthetics issue.

						- Ted

^ permalink raw reply	[flat|nested] 12+ messages in thread

* Re: [PATCH 1/2] random: Omit double-printing ratelimit messages
  2018-05-16 20:54                 ` Theodore Y. Ts'o
@ 2018-05-16 22:11                   ` Dmitry Safonov
  0 siblings, 0 replies; 12+ messages in thread
From: Dmitry Safonov @ 2018-05-16 22:11 UTC (permalink / raw)
  To: Theodore Y. Ts'o; +Cc: linux-kernel, 0x7f454c46, Arnd Bergmann

On Wed, 2018-05-16 at 16:54 -0400, Theodore Y. Ts'o wrote:
> On Wed, May 16, 2018 at 04:46:13PM +0100, Dmitry Safonov wrote:
> > > Yeah, but what you print is not total sum, it's since the last
> > > interval because without mentioned flag ___ratelimit() will flush
> > > missed counter and print "suppressed" message.  They might even
> > > double if say other proccess has called get_random_bytes() got to
> > > ___ratelimit() and got preempted. This thread finishes
> > > initializing random driver and prints this not-proper-sum
> > > statistics, and when the code flow is back in the first context,
> > > it will print statistics again from ___ratelimit() function.
> > 
> > So, does it make sense to you, Theodore?
> > If not - I'll just resend second patch rebasing and dropping this
> > one.
> 
> Yes, it's correct that it's not the total sum.  I guess your
> complaint
> is that some of the messages are using the "callbacks suppressed"
> message, and the last one is using the random drvier's custom message
> which I think is much more user-friendly.  That being said, although
> I
> think "callbacks suppressed is a terrible message, I agree that using
> a single message makes more sense.  So setting the
> RATELIMIT_MSG_ON_RELEASE and then calling ratelimit_state_exit() from
> crng_reseed() does make sense.
> 
> In the future I'd like to push for some way to customize --- or
> perhaps just fix --- "callbacks suppressed" to something more sane
> like, "messages ratelimited", but that's more of an aesthetics issue.

Thanks, Ted.
As you've looked inside lib/ratelimit, care to review 2 patch from the
series maybe?

-- 
Thanks,
             Dmitry

^ permalink raw reply	[flat|nested] 12+ messages in thread

end of thread, other threads:[~2018-05-16 22:12 UTC | newest]

Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-05-10 12:52 [PATCH 0/2] ratelimit: Do not lose messages under limit Dmitry Safonov
2018-05-10 12:52 ` [PATCH 1/2] random: Omit double-printing ratelimit messages Dmitry Safonov
2018-05-10 18:19   ` Theodore Y. Ts'o
2018-05-10 18:37     ` Dmitry Safonov
2018-05-10 19:40       ` Theodore Y. Ts'o
2018-05-10 19:50         ` Dmitry Safonov
2018-05-11  3:51           ` Theodore Y. Ts'o
2018-05-11 12:41             ` Dmitry Safonov
2018-05-16 15:46               ` Dmitry Safonov
2018-05-16 20:54                 ` Theodore Y. Ts'o
2018-05-16 22:11                   ` Dmitry Safonov
2018-05-10 12:52 ` [PATCH 2/2] lib/ratelimit: Lockless ratelimiting Dmitry Safonov

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).