Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Petr Mladek]

On Tue 2016-12-13 10:52:37, Sergey Senozhatsky wrote:
> On (12/12/16 16:58), Petr Mladek wrote:
> > On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
> [..]
> > But not really because we report lost messages from both buffers
> > and from all CPUs here.
> [..]
> > The perfect solution would be to remember the number of lost messages
> > in struct printk_safe_seq_buf. Then we might bump the value directly
> > in printk_safe_log_store() instead of returning the ugly -ENOSPC.
> 
> ok, I can take a look. this won't grow the per-CPU buffers bigger,
> but will shrink the actual message buffer size by sizeof(atomic),
> not that dramatic.

IMHO, the size is a negligible difference. If we are often getting
on the edge of the buffers, we have problems anyway.


> * unrelated, can be done later (if ever) *
> 
> speaking of tha actual message buffer size, we, may be, can move
> `struct irq_work' out of printk_safe_seq_buf. there is already
> a printk-related per-CPU irq_work in place - wake_up_klogd_work.
> so we may be can use it, instead of defining a bunch of new irq_works.
> this will increase the printk-safe/nmi per-CPU message buffer size
> by sizeof(irq_work).

Interesting idea! I think that there is a space for more optimization.
For example, we will not need to schedule the irq work if we are
flushing  the per-CPU buffers from irq work and we know that
we will flush consoles or wake up the kthread right after that.
Also I though about using a global "printk_pending" variable
and queue the irqwork only when the given event was not already set.

I would leave all this optimization for a later patchset.


> > Also we could use an universal message (no "NMI" or "printk-safe")
> > because it could be printed right after flushing the messages
> > that fit the buffer.
> 
> this "context" part probably can be dropped. both printk-safe and
> printk-nmi per-CPU buffer sizes are controlled by a single .config
> option anyway; user can't increase the printk-safe buffer size
> without increasing the printk-nmi buffer size (in case if printk-safe
> buffer is too small).

I agree.

Best Regards,
Petr

Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Petr Mladek]

On Tue 2016-12-13 10:52:37, Sergey Senozhatsky wrote:
> On (12/12/16 16:58), Petr Mladek wrote:
> > On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
> [..]
> > But not really because we report lost messages from both buffers
> > and from all CPUs here.
> [..]
> > The perfect solution would be to remember the number of lost messages
> > in struct printk_safe_seq_buf. Then we might bump the value directly
> > in printk_safe_log_store() instead of returning the ugly -ENOSPC.
> 
> ok, I can take a look. this won't grow the per-CPU buffers bigger,
> but will shrink the actual message buffer size by sizeof(atomic),
> not that dramatic.

IMHO, the size is a negligible difference. If we are often getting
on the edge of the buffers, we have problems anyway.


> * unrelated, can be done later (if ever) *
> 
> speaking of tha actual message buffer size, we, may be, can move
> `struct irq_work' out of printk_safe_seq_buf. there is already
> a printk-related per-CPU irq_work in place - wake_up_klogd_work.
> so we may be can use it, instead of defining a bunch of new irq_works.
> this will increase the printk-safe/nmi per-CPU message buffer size
> by sizeof(irq_work).

Interesting idea! I think that there is a space for more optimization.
For example, we will not need to schedule the irq work if we are
flushing  the per-CPU buffers from irq work and we know that
we will flush consoles or wake up the kthread right after that.
Also I though about using a global "printk_pending" variable
and queue the irqwork only when the given event was not already set.

I would leave all this optimization for a later patchset.


> > Also we could use an universal message (no "NMI" or "printk-safe")
> > because it could be printed right after flushing the messages
> > that fit the buffer.
> 
> this "context" part probably can be dropped. both printk-safe and
> printk-nmi per-CPU buffer sizes are controlled by a single .config
> option anyway; user can't increase the printk-safe buffer size
> without increasing the printk-nmi buffer size (in case if printk-safe
> buffer is too small).

I agree.

Best Regards,
Petr

Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

On (12/12/16 16:58), Petr Mladek wrote:
> On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
[..]
> But not really because we report lost messages from both buffers
> and from all CPUs here.
[..]
> The perfect solution would be to remember the number of lost messages
> in struct printk_safe_seq_buf. Then we might bump the value directly
> in printk_safe_log_store() instead of returning the ugly -ENOSPC.

ok, I can take a look. this won't grow the per-CPU buffers bigger,
but will shrink the actual message buffer size by sizeof(atomic),
not that dramatic.

* unrelated, can be done later (if ever) *

speaking of tha actual message buffer size, we, may be, can move
`struct irq_work' out of printk_safe_seq_buf. there is already
a printk-related per-CPU irq_work in place - wake_up_klogd_work.
so we may be can use it, instead of defining a bunch of new irq_works.
this will increase the printk-safe/nmi per-CPU message buffer size
by sizeof(irq_work).

> Also we could use an universal message (no "NMI" or "printk-safe")
> because it could be printed right after flushing the messages
> that fit the buffer.

this "context" part probably can be dropped. both printk-safe and
printk-nmi per-CPU buffer sizes are controlled by a single .config
option anyway; user can't increase the printk-safe buffer size
without increasing the printk-nmi buffer size (in case if printk-safe
buffer is too small).

> This solution is good enough and still better than the previous one, so
> 
> Reviewed-by: Petr Mladek 

thanks.

-ss

Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

On (12/12/16 16:58), Petr Mladek wrote:
> On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
[..]
> But not really because we report lost messages from both buffers
> and from all CPUs here.
[..]
> The perfect solution would be to remember the number of lost messages
> in struct printk_safe_seq_buf. Then we might bump the value directly
> in printk_safe_log_store() instead of returning the ugly -ENOSPC.

ok, I can take a look. this won't grow the per-CPU buffers bigger,
but will shrink the actual message buffer size by sizeof(atomic),
not that dramatic.

* unrelated, can be done later (if ever) *

speaking of tha actual message buffer size, we, may be, can move
`struct irq_work' out of printk_safe_seq_buf. there is already
a printk-related per-CPU irq_work in place - wake_up_klogd_work.
so we may be can use it, instead of defining a bunch of new irq_works.
this will increase the printk-safe/nmi per-CPU message buffer size
by sizeof(irq_work).

> Also we could use an universal message (no "NMI" or "printk-safe")
> because it could be printed right after flushing the messages
> that fit the buffer.

this "context" part probably can be dropped. both printk-safe and
printk-nmi per-CPU buffer sizes are controlled by a single .config
option anyway; user can't increase the printk-safe buffer size
without increasing the printk-nmi buffer size (in case if printk-safe
buffer is too small).

> This solution is good enough and still better than the previous one, so
> 
> Reviewed-by: Petr Mladek 

thanks.

-ss

Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Petr Mladek]

On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
> Account lost messages in pritk-safe and printk-safe-nmi
> contexts and report those numbers during printk_safe_flush().
> 
> Signed-off-by: Sergey Senozhatsky 
> ---
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -211,6 +242,9 @@ static void __printk_safe_flush(struct irq_work *work)
>   if (atomic_cmpxchg(>len, len, 0) != len)
>   goto more;
>  
> + report_nmi_message_lost();
> + report_safe_message_lost();

The great thing about this solution is that we print this message
in the right order (after the messages that fit into the buffer).

But not really because we report lost messages from both buffers
and from all CPUs here.

The perfect solution would be to remember the number of lost messages
in struct printk_safe_seq_buf. Then we might bump the value directly
in printk_safe_log_store() instead of returning the ugly -ENOSPC.
Also we could use an universal message (no "NMI" or "printk-safe")
because it could be printed right after flushing the messages
that fit the buffer.

This solution is good enough and still better than the previous one, so

Reviewed-by: Petr Mladek 


But if you would want to change it to the "perfect" one, it would be
appreciated ;-) It will be even more straightforward and less code.
In this, case I would do the change in an earlier patch to make
it more straightforward. But we could also do this later
(in another patchset).

Best Regards,
Petr

Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Petr Mladek]

On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
> Account lost messages in pritk-safe and printk-safe-nmi
> contexts and report those numbers during printk_safe_flush().
> 
> Signed-off-by: Sergey Senozhatsky 
> ---
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -211,6 +242,9 @@ static void __printk_safe_flush(struct irq_work *work)
>   if (atomic_cmpxchg(>len, len, 0) != len)
>   goto more;
>  
> + report_nmi_message_lost();
> + report_safe_message_lost();

The great thing about this solution is that we print this message
in the right order (after the messages that fit into the buffer).

But not really because we report lost messages from both buffers
and from all CPUs here.

The perfect solution would be to remember the number of lost messages
in struct printk_safe_seq_buf. Then we might bump the value directly
in printk_safe_log_store() instead of returning the ugly -ENOSPC.
Also we could use an universal message (no "NMI" or "printk-safe")
because it could be printed right after flushing the messages
that fit the buffer.

This solution is good enough and still better than the previous one, so

Reviewed-by: Petr Mladek 


But if you would want to change it to the "perfect" one, it would be
appreciated ;-) It will be even more straightforward and less code.
In this, case I would do the change in an earlier patch to make
it more straightforward. But we could also do this later
(in another patchset).

Best Regards,
Petr

[RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

Account lost messages in pritk-safe and printk-safe-nmi
contexts and report those numbers during printk_safe_flush().

Signed-off-by: Sergey Senozhatsky 
---
 kernel/printk/internal.h| 17 -
 kernel/printk/printk.c  | 10 --
 kernel/printk/printk_safe.c | 45 +++--
 3 files changed, 43 insertions(+), 29 deletions(-)

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 97cee4f..d245602 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -16,23 +16,6 @@
  */
 #include 
 
-#ifdef CONFIG_PRINTK_NMI
-
-extern atomic_t nmi_message_lost;
-static inline int get_nmi_message_lost(void)
-{
-   return atomic_xchg(_message_lost, 0);
-}
-
-#else /* CONFIG_PRINTK_NMI */
-
-static inline int get_nmi_message_lost(void)
-{
-   return 0;
-}
-
-#endif /* CONFIG_PRINTK_NMI */
-
 #ifdef CONFIG_PRINTK
 
 #define PRINTK_SAFE_CONTEXT_MASK   0x7fff
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 77446ba..6f7b217 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1776,7 +1776,6 @@ asmlinkage int vprintk_emit(int facility, int level,
unsigned long flags;
int this_cpu;
int printed_len = 0;
-   int nmi_message_lost;
bool in_sched = false;
/* cpu currently holding logbuf_lock in this function */
static unsigned int logbuf_cpu = UINT_MAX;
@@ -1827,15 +1826,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 strlen(recursion_msg));
}
 
-   nmi_message_lost = get_nmi_message_lost();
-   if (unlikely(nmi_message_lost)) {
-   text_len = scnprintf(textbuf, sizeof(textbuf),
-"BAD LUCK: lost %d message(s) from NMI 
context!",
-nmi_message_lost);
-   printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
-NULL, 0, textbuf, text_len);
-   }
-
/*
 * The printf needs to come first; we need the syslog
 * prefix which might be passed-in as a parameter.
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index 3ded9e1..0689b94 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -52,10 +52,11 @@ struct printk_safe_seq_buf {
 
 static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq);
 static DEFINE_PER_CPU(int, printk_context);
+static atomic_t safe_message_lost;
 
 #ifdef CONFIG_PRINTK_NMI
 static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
-atomic_t nmi_message_lost;
+static atomic_t nmi_message_lost;
 #endif
 
 static int printk_safe_log_store(struct printk_safe_seq_buf *s,
@@ -155,6 +156,36 @@ static int printk_safe_flush_buffer(const char *start, 
size_t len)
return len;
 }
 
+static void report_message_lost(atomic_t *num_lost, const char *context)
+{
+   int lost = atomic_xchg(num_lost, 0);
+
+   if (lost)
+   printk_deferred("Lost %d message(s) from %s context!\n",
+   lost,
+   context);
+}
+
+#ifdef CONFIG_PRINTK_NMI
+
+static void report_nmi_message_lost(void)
+{
+   report_message_lost(_message_lost, "NMI");
+}
+
+#else
+
+static void report_nmi_message_lost(void)
+{
+}
+
+#endif /* CONFIG_PRINTK_NMI */
+
+static void report_safe_message_lost(void)
+{
+   report_message_lost(_message_lost, "printk-safe");
+}
+
 /*
  * Flush data from the associated per-CPU buffer. The function
  * can be called either via IRQ work or independently.
@@ -211,6 +242,9 @@ static void __printk_safe_flush(struct irq_work *work)
if (atomic_cmpxchg(>len, len, 0) != len)
goto more;
 
+   report_nmi_message_lost();
+   report_safe_message_lost();
+
 out:
raw_spin_unlock_irqrestore(_lock, flags);
 }
@@ -309,8 +343,15 @@ static int vprintk_safe_nmi(const char *fmt, va_list args)
 static int vprintk_safe(const char *fmt, va_list args)
 {
struct printk_safe_seq_buf *s = this_cpu_ptr(_print_seq);
+   int add;
 
-   return printk_safe_log_store(s, fmt, args);
+   add = printk_safe_log_store(s, fmt, args);
+   if (add == -ENOSPC) {
+   atomic_inc(_message_lost);
+   add = 0;
+   }
+
+   return add;
 }
 
 /* Can be preempted by NMI. */
-- 
2.10.2

[RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

Account lost messages in pritk-safe and printk-safe-nmi
contexts and report those numbers during printk_safe_flush().

Signed-off-by: Sergey Senozhatsky 
---
 kernel/printk/internal.h| 17 -
 kernel/printk/printk.c  | 10 --
 kernel/printk/printk_safe.c | 45 +++--
 3 files changed, 43 insertions(+), 29 deletions(-)

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 97cee4f..d245602 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -16,23 +16,6 @@
  */
 #include 
 
-#ifdef CONFIG_PRINTK_NMI
-
-extern atomic_t nmi_message_lost;
-static inline int get_nmi_message_lost(void)
-{
-   return atomic_xchg(_message_lost, 0);
-}
-
-#else /* CONFIG_PRINTK_NMI */
-
-static inline int get_nmi_message_lost(void)
-{
-   return 0;
-}
-
-#endif /* CONFIG_PRINTK_NMI */
-
 #ifdef CONFIG_PRINTK
 
 #define PRINTK_SAFE_CONTEXT_MASK   0x7fff
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 77446ba..6f7b217 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1776,7 +1776,6 @@ asmlinkage int vprintk_emit(int facility, int level,
unsigned long flags;
int this_cpu;
int printed_len = 0;
-   int nmi_message_lost;
bool in_sched = false;
/* cpu currently holding logbuf_lock in this function */
static unsigned int logbuf_cpu = UINT_MAX;
@@ -1827,15 +1826,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 strlen(recursion_msg));
}
 
-   nmi_message_lost = get_nmi_message_lost();
-   if (unlikely(nmi_message_lost)) {
-   text_len = scnprintf(textbuf, sizeof(textbuf),
-"BAD LUCK: lost %d message(s) from NMI 
context!",
-nmi_message_lost);
-   printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
-NULL, 0, textbuf, text_len);
-   }
-
/*
 * The printf needs to come first; we need the syslog
 * prefix which might be passed-in as a parameter.
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index 3ded9e1..0689b94 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -52,10 +52,11 @@ struct printk_safe_seq_buf {
 
 static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq);
 static DEFINE_PER_CPU(int, printk_context);
+static atomic_t safe_message_lost;
 
 #ifdef CONFIG_PRINTK_NMI
 static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
-atomic_t nmi_message_lost;
+static atomic_t nmi_message_lost;
 #endif
 
 static int printk_safe_log_store(struct printk_safe_seq_buf *s,
@@ -155,6 +156,36 @@ static int printk_safe_flush_buffer(const char *start, 
size_t len)
return len;
 }
 
+static void report_message_lost(atomic_t *num_lost, const char *context)
+{
+   int lost = atomic_xchg(num_lost, 0);
+
+   if (lost)
+   printk_deferred("Lost %d message(s) from %s context!\n",
+   lost,
+   context);
+}
+
+#ifdef CONFIG_PRINTK_NMI
+
+static void report_nmi_message_lost(void)
+{
+   report_message_lost(_message_lost, "NMI");
+}
+
+#else
+
+static void report_nmi_message_lost(void)
+{
+}
+
+#endif /* CONFIG_PRINTK_NMI */
+
+static void report_safe_message_lost(void)
+{
+   report_message_lost(_message_lost, "printk-safe");
+}
+
 /*
  * Flush data from the associated per-CPU buffer. The function
  * can be called either via IRQ work or independently.
@@ -211,6 +242,9 @@ static void __printk_safe_flush(struct irq_work *work)
if (atomic_cmpxchg(>len, len, 0) != len)
goto more;
 
+   report_nmi_message_lost();
+   report_safe_message_lost();
+
 out:
raw_spin_unlock_irqrestore(_lock, flags);
 }
@@ -309,8 +343,15 @@ static int vprintk_safe_nmi(const char *fmt, va_list args)
 static int vprintk_safe(const char *fmt, va_list args)
 {
struct printk_safe_seq_buf *s = this_cpu_ptr(_print_seq);
+   int add;
 
-   return printk_safe_log_store(s, fmt, args);
+   add = printk_safe_log_store(s, fmt, args);
+   if (add == -ENOSPC) {
+   atomic_inc(_message_lost);
+   add = 0;
+   }
+
+   return add;
 }
 
 /* Can be preempted by NMI. */
-- 
2.10.2