[RFC,V2,12/21] rv/reactor: Add the printk reactor

Commit Message

Daniel Bristot de Oliveira Feb. 14, 2022, 10:45 a.m. UTC

Sample reactor that printks the reaction message.

Note: do not use this reactor with rq_lock taken, it will lock the
system until printk can handle that.

Cc: Jonathan Corbet <[e-mail]>
Cc: Steven Rostedt <[e-mail]>
Cc: Ingo Molnar <[e-mail]>
Cc: Thomas Gleixner <[e-mail]>
Cc: Peter Zijlstra <[e-mail]>
Cc: Will Deacon <[e-mail]>
Cc: Catalin Marinas <[e-mail]>
Cc: Marco Elver <[e-mail]>
Cc: Dmitry Vyukov <[e-mail]>
Cc: "Paul E. McKenney" <[e-mail]>
Cc: Shuah Khan <[e-mail]>
Cc: Gabriele Paoloni <[e-mail]>
Cc: Juri Lelli <[e-mail]>
Cc: Clark Williams <[e-mail]>
Cc: [e-mail]
Cc: [e-mail]
Cc: [e-mail]
Signed-off-by: Daniel Bristot de Oliveira <[e-mail]>
---
 kernel/trace/rv/Kconfig          |  8 ++++++
 kernel/trace/rv/Makefile         |  3 ++-
 kernel/trace/rv/reactor_printk.c | 43 ++++++++++++++++++++++++++++++++
 3 files changed, 53 insertions(+), 1 deletion(-)
 create mode 100644 kernel/trace/rv/reactor_printk.c

Comments

Shuah Khan Feb. 14, 2022, 5:25 p.m. UTC | #1

On 2/14/22 3:45 AM, Daniel Bristot de Oliveira wrote:
> Sample reactor that printks the reaction message.
> 

Who is supposed to take action on this message and how do they
get notified?

> Note: do not use this reactor with rq_lock taken, it will lock the
> system until printk can handle that.

Please give more details on "lock the system" and how locking
would impact users and system operation

> 
> Cc: Jonathan Corbet <[e-mail]>
> Cc: Steven Rostedt <[e-mail]>
> Cc: Ingo Molnar <[e-mail]>
> Cc: Thomas Gleixner <[e-mail]>
> Cc: Peter Zijlstra <[e-mail]>
> Cc: Will Deacon <[e-mail]>
> Cc: Catalin Marinas <[e-mail]>
> Cc: Marco Elver <[e-mail]>
> Cc: Dmitry Vyukov <[e-mail]>
> Cc: "Paul E. McKenney" <[e-mail]>
> Cc: Shuah Khan <[e-mail]>
> Cc: Gabriele Paoloni <[e-mail]>
> Cc: Juri Lelli <[e-mail]>
> Cc: Clark Williams <[e-mail]>
> Cc: [e-mail]
> Cc: [e-mail]
> Cc: [e-mail]
> Signed-off-by: Daniel Bristot de Oliveira <[e-mail]>
> ---
>   kernel/trace/rv/Kconfig          |  8 ++++++
>   kernel/trace/rv/Makefile         |  3 ++-
>   kernel/trace/rv/reactor_printk.c | 43 ++++++++++++++++++++++++++++++++
>   3 files changed, 53 insertions(+), 1 deletion(-)
>   create mode 100644 kernel/trace/rv/reactor_printk.c
> 
> diff --git a/kernel/trace/rv/Kconfig b/kernel/trace/rv/Kconfig
> index f2d0bed05a55..490f1417def9 100644
> --- a/kernel/trace/rv/Kconfig
> +++ b/kernel/trace/rv/Kconfig
> @@ -37,4 +37,12 @@ config RV_REACTORS
>   	  tracing reactions, printing the monitor output via tracepoints,
>   	  but other reactions can be added (on-demand) via this interface.
>   
> +config RV_REACT_PRINTK
> +	tristate "Printk reactor"
> +	depends on RV_REACTORS
> +	default y if RV_REACTORS
> +	help
> +	  Enables the printk reactor. The printk reactor emmits a printk()
> +	  message if an exception is found.
> +
>   endif # RV
> diff --git a/kernel/trace/rv/Makefile b/kernel/trace/rv/Makefile
> index edad01bb2b5d..d86ceb103ef2 100644
> --- a/kernel/trace/rv/Makefile
> +++ b/kernel/trace/rv/Makefile
> @@ -1,6 +1,7 @@
>   # SPDX-License-Identifier: GPL-2.0
>   
>   obj-$(CONFIG_RV) += rv.o
> -obj-$(CONFIG_RV_REACTORS) += rv_reactors.o
>   obj-$(CONFIG_RV_MON_WIP) += monitor_wip/wip.o
>   obj-$(CONFIG_RV_MON_WWNR) += monitor_wwnr/wwnr.o
> +obj-$(CONFIG_RV_REACTORS) += rv_reactors.o
> +obj-$(CONFIG_RV_REACT_PRINTK) += reactor_printk.o
> diff --git a/kernel/trace/rv/reactor_printk.c b/kernel/trace/rv/reactor_printk.c
> new file mode 100644
> index 000000000000..9f9c9bb2d304
> --- /dev/null
> +++ b/kernel/trace/rv/reactor_printk.c
> @@ -0,0 +1,43 @@
> +/*
> + * Printk RV reactor:
> + *   Prints the exception msg to the kernel message log.
> + *
> + * Copyright (C) 2019-2022 Daniel Bristot de Oliveira <[e-mail]>
> + *
> + * SPDX-License-Identifier: GPL-2.0
> + */
> +#include <linux/ftrace.h>
> +#include <linux/tracepoint.h>
> +#include <linux/kernel.h>
> +#include <linux/module.h>
> +#include <linux/init.h>
> +#include <linux/rv.h>
> +
> +static void rv_printk_reaction(char *msg)
> +{
> +	printk(msg);
> +}
> +
> +struct rv_reactor rv_printk = {
> +	.name = "printk",
> +	.description = "prints the exception msg to the kernel message log",
> +	.react = rv_printk_reaction
> +};
> +
> +int register_react_printk(void)
> +{
> +	rv_register_reactor(&rv_printk);
> +	return 0;
> +}
> +
> +void unregister_react_printk(void)
> +{
> +	rv_unregister_reactor(&rv_printk);
> +}
> +
> +module_init(register_react_printk);
> +module_exit(unregister_react_printk);
> +
> +MODULE_LICENSE("GPL v2");
> +MODULE_AUTHOR("Daniel Bristot de Oliveira");
> +MODULE_DESCRIPTION("printk rv reactor: printk if an exception is hit");
>

Daniel Bristot de Oliveira Feb. 14, 2022, 6:06 p.m. UTC | #2

On 2/14/22 18:25, Shuah Khan wrote:
> On 2/14/22 3:45 AM, Daniel Bristot de Oliveira wrote:
>> Sample reactor that printks the reaction message.
>>
> 
> Who is supposed to take action on this message and how do they
> get notified?

The same people that use printk to debug systems (who never?), on conditions
where other debugging methods might not available.

> 
>> Note: do not use this reactor with rq_lock taken, it will lock the
>> system until printk can handle that.
> 
> Please give more details on "lock the system" and how locking
> would impact users and system operation

It is a deadlock on the rq_lock. Hopefully the new printk implementation handles
that better.

/me looks at John Ogness

-- Daniel

John Ogness Feb. 15, 2022, 10:03 a.m. UTC | #3

On 2022-02-14, Daniel Bristot de Oliveira <[e-mail]> wrote:
> On 2/14/22 18:25, Shuah Khan wrote:
>> On 2/14/22 3:45 AM, Daniel Bristot de Oliveira wrote:
>>> Note: do not use this reactor with rq_lock taken, it will lock the
>>> system until printk can handle that.
>> 
>> Please give more details on "lock the system" and how locking
>> would impact users and system operation
>
> It is a deadlock on the rq_lock. Hopefully the new printk
> implementation handles that better.

I suggest using printk_deferred() for this reactor for now. With
printk_deferred() the message and timestamp are immediately and
locklessly stored in the buffer, and the printing is performed in a
separate context. printk_deferred() is safe for all contexts.

John

Daniel Bristot de Oliveira Feb. 15, 2022, 12:43 p.m. UTC | #4

On 2/15/22 11:03, John Ogness wrote:
> On 2022-02-14, Daniel Bristot de Oliveira <[e-mail]> wrote:
>> On 2/14/22 18:25, Shuah Khan wrote:
>>> On 2/14/22 3:45 AM, Daniel Bristot de Oliveira wrote:
>>>> Note: do not use this reactor with rq_lock taken, it will lock the
>>>> system until printk can handle that.
>>>
>>> Please give more details on "lock the system" and how locking
>>> would impact users and system operation
>>
>> It is a deadlock on the rq_lock. Hopefully the new printk
>> implementation handles that better.
> 
> I suggest using printk_deferred() for this reactor for now. With
> printk_deferred() the message and timestamp are immediately and
> locklessly stored in the buffer, and the printing is performed in a
> separate context. printk_deferred() is safe for all contexts.

Question: Does it always postpone or only postpone when in a particular
contexts, like, with irqs disabled?

-- Daniel

> John

John Ogness Feb. 15, 2022, 1:33 p.m. UTC | #5

On 2022-02-15, Daniel Bristot de Oliveira <[e-mail]> wrote:
>> I suggest using printk_deferred() for this reactor for now. With
>> printk_deferred() the message and timestamp are immediately and
>> locklessly stored in the buffer, and the printing is performed in a
>> separate context. printk_deferred() is safe for all contexts.
>
> Question: Does it always postpone or only postpone when in a
> particular contexts, like, with irqs disabled?

printk_deferred() always postpones printing.

> Note: do not use this reactor with rq_lock taken, it will lock the
> system until printk can handle that.

Perhaps you could explain thi comment in your commit message?  printk()
should never lock the system.

John

Daniel Bristot de Oliveira Feb. 15, 2022, 5:21 p.m. UTC | #6

On 2/15/22 14:33, John Ogness wrote:
> On 2022-02-15, Daniel Bristot de Oliveira <[e-mail]> wrote:
>>> I suggest using printk_deferred() for this reactor for now. With
>>> printk_deferred() the message and timestamp are immediately and
>>> locklessly stored in the buffer, and the printing is performed in a
>>> separate context. printk_deferred() is safe for all contexts.
>> Question: Does it always postpone or only postpone when in a
>> particular contexts, like, with irqs disabled?
> printk_deferred() always postpones printing.

That is why printk() seems to be the better option, though I can use the
deferred option too.

Noting that, I am aware of printk_deferred(), and every once and while I am
Cc'ed on patches suggesting changing printk() to printk_deferred(), but they are
not, let's say, welcome [1]... that is why I am not using it.

>> Note: do not use this reactor with rq_lock taken, it will lock the
>> system until printk can handle that.
> Perhaps you could explain thi comment in your commit message?  printk()
> should never lock the system.

I saw deadlocks in the past, and while testing the WIP monitor some time ago, it
seems it depends on the console type. If such restriction does not exist
anymore, I can remove that comment, it would be even better!

[1]
https://lore.kernel.org/lkml/[e-mail]/

-- Daniel

John Ogness Feb. 15, 2022, 7:33 p.m. UTC | #7

On 2022-02-15, Daniel Bristot de Oliveira <[e-mail]> wrote:
> I am aware of printk_deferred(), and every once and while I am Cc'ed
> on patches suggesting changing printk() to printk_deferred(), but they
> are not, let's say, welcome [1]... that is why I am not using it.

Yes. printk_deferred() is a workaround until we can get printk
"PROVE_RAW_LOCK_NESTING clean". But currently there is real deadlock
potential in the kernel with printk. For the most common cases, we use
printk_deferred() to get around it. Once printk() is clean, we can
replace all printk_deferred() call sites with printk().

I haven't looked into the details of your runtime verification method,
but I assume it digs deep into some interfaces. In that case, the
deadlock potential of printk may be relatively high. (And indeed, you
have seen some.) IMHO, before warning users not to use this reactor if
locks XYZ are taken, it would be better just to use printk_deferred()
and it will always log without causing problems to the system you are
trying to verify.

> I saw deadlocks in the past, and while testing the WIP monitor some
> time ago, it seems it depends on the console type. If such restriction
> does not exist anymore, I can remove that comment, it would be even
> better!

If you say it depended on the console type, then it was probably the
framebuffer console that was at fault. The fbcon is a landmine for
deadlocks, which is why PREEMPT_RT avoids fbcon printing from
non-preemptible context. For mainline, the series is currently in
review.

Perhaps avoiding fbcon would be good enough for you to avoid deadlocks
with this reactor using printk().

John

> [1]  https://lore.kernel.org/lkml/[e-mail]/

Daniel Bristot de Oliveira Feb. 16, 2022, 8:58 a.m. UTC | #8

On 2/15/22 20:33, John Ogness wrote:
>> I saw deadlocks in the past, and while testing the WIP monitor some
>> time ago, it seems it depends on the console type. If such restriction
>> does not exist anymore, I can remove that comment, it would be even
>> better!
> If you say it depended on the console type, then it was probably the
> framebuffer console that was at fault. The fbcon is a landmine for
> deadlocks, which is why PREEMPT_RT avoids fbcon printing from
> non-preemptible context. For mainline, the series is currently in
> review.
> 
> Perhaps avoiding fbcon would be good enough for you to avoid deadlocks
> with this reactor using printk().

So, I will keep printk(), add a depends on *!* fbcon, and remove the comment.
What do you think?

-- Daniel

John Ogness Feb. 16, 2022, 10:51 a.m. UTC | #9

On 2022-02-16, Daniel Bristot de Oliveira <[e-mail]> wrote:
> So, I will keep printk(), add a depends on *!* fbcon, and remove the
> comment.  What do you think?

printk() and depends on !VT_CONSOLE. OK for me. Hopefully soon this
restriction can be removed.

John

Daniel Bristot de Oliveira Feb. 16, 2022, 1:19 p.m. UTC | #10

On 2/16/22 11:51, John Ogness wrote:
> On 2022-02-16, Daniel Bristot de Oliveira <[e-mail]> wrote:
>> So, I will keep printk(), add a depends on *!* fbcon, and remove the
>> comment.  What do you think?
> printk() and depends on !VT_CONSOLE. OK for me. Hopefully soon this
> restriction can be removed.

ack.

Thanks, John!
-- Daniel

> John

Patch

diff --git a/kernel/trace/rv/Kconfig b/kernel/trace/rv/Kconfig
index f2d0bed05a55..490f1417def9 100644
--- a/kernel/trace/rv/Kconfig
+++ b/kernel/trace/rv/Kconfig
@@ -37,4 +37,12 @@  config RV_REACTORS
 	  tracing reactions, printing the monitor output via tracepoints,
 	  but other reactions can be added (on-demand) via this interface.
 
+config RV_REACT_PRINTK
+	tristate "Printk reactor"
+	depends on RV_REACTORS
+	default y if RV_REACTORS
+	help
+	  Enables the printk reactor. The printk reactor emmits a printk()
+	  message if an exception is found.
+
 endif # RV
diff --git a/kernel/trace/rv/Makefile b/kernel/trace/rv/Makefile
index edad01bb2b5d..d86ceb103ef2 100644
--- a/kernel/trace/rv/Makefile
+++ b/kernel/trace/rv/Makefile
@@ -1,6 +1,7 @@ 
 # SPDX-License-Identifier: GPL-2.0
 
 obj-$(CONFIG_RV) += rv.o
-obj-$(CONFIG_RV_REACTORS) += rv_reactors.o
 obj-$(CONFIG_RV_MON_WIP) += monitor_wip/wip.o
 obj-$(CONFIG_RV_MON_WWNR) += monitor_wwnr/wwnr.o
+obj-$(CONFIG_RV_REACTORS) += rv_reactors.o
+obj-$(CONFIG_RV_REACT_PRINTK) += reactor_printk.o
diff --git a/kernel/trace/rv/reactor_printk.c b/kernel/trace/rv/reactor_printk.c
new file mode 100644
index 000000000000..9f9c9bb2d304
--- /dev/null
+++ b/kernel/trace/rv/reactor_printk.c
@@ -0,0 +1,43 @@ 
+/*
+ * Printk RV reactor:
+ *   Prints the exception msg to the kernel message log.
+ *
+ * Copyright (C) 2019-2022 Daniel Bristot de Oliveira <[e-mail]>
+ *
+ * SPDX-License-Identifier: GPL-2.0
+ */
+#include <linux/ftrace.h>
+#include <linux/tracepoint.h>
+#include <linux/kernel.h>
+#include <linux/module.h>
+#include <linux/init.h>
+#include <linux/rv.h>
+
+static void rv_printk_reaction(char *msg)
+{
+	printk(msg);
+}
+
+struct rv_reactor rv_printk = {
+	.name = "printk",
+	.description = "prints the exception msg to the kernel message log",
+	.react = rv_printk_reaction
+};
+
+int register_react_printk(void)
+{
+	rv_register_reactor(&rv_printk);
+	return 0;
+}
+
+void unregister_react_printk(void)
+{
+	rv_unregister_reactor(&rv_printk);
+}
+
+module_init(register_react_printk);
+module_exit(unregister_react_printk);
+
+MODULE_LICENSE("GPL v2");
+MODULE_AUTHOR("Daniel Bristot de Oliveira");
+MODULE_DESCRIPTION("printk rv reactor: printk if an exception is hit");