2020-08-20 09:19:14

by Nicolas Boichat

[permalink] [raw]
Subject: [PATCH v4 1/3, RESEND] media: camss: vfe: Use trace_printk for debugging only

trace_printk should not be used in production code. Since
tracing interrupts is presumably latency sensitive, pr_dbg is
not appropriate, so guard the call with a preprocessor symbol
that can be defined for debugging purpose.

Signed-off-by: Nicolas Boichat <[email protected]>
---

(resending this patch as part of the whole series, since we need a new
patch 3/3 now).

drivers/media/platform/qcom/camss/camss-vfe-4-1.c | 2 ++
drivers/media/platform/qcom/camss/camss-vfe-4-7.c | 2 ++
2 files changed, 4 insertions(+)

diff --git a/drivers/media/platform/qcom/camss/camss-vfe-4-1.c b/drivers/media/platform/qcom/camss/camss-vfe-4-1.c
index 174a36be6f5d866..0c57171fae4f9e9 100644
--- a/drivers/media/platform/qcom/camss/camss-vfe-4-1.c
+++ b/drivers/media/platform/qcom/camss/camss-vfe-4-1.c
@@ -936,8 +936,10 @@ static irqreturn_t vfe_isr(int irq, void *dev)

vfe->ops->isr_read(vfe, &value0, &value1);

+#ifdef CAMSS_VFE_TRACE_IRQ
trace_printk("VFE: status0 = 0x%08x, status1 = 0x%08x\n",
value0, value1);
+#endif

if (value0 & VFE_0_IRQ_STATUS_0_RESET_ACK)
vfe->isr_ops.reset_ack(vfe);
diff --git a/drivers/media/platform/qcom/camss/camss-vfe-4-7.c b/drivers/media/platform/qcom/camss/camss-vfe-4-7.c
index 0dca8bf9281e774..307675925e5c779 100644
--- a/drivers/media/platform/qcom/camss/camss-vfe-4-7.c
+++ b/drivers/media/platform/qcom/camss/camss-vfe-4-7.c
@@ -1058,8 +1058,10 @@ static irqreturn_t vfe_isr(int irq, void *dev)

vfe->ops->isr_read(vfe, &value0, &value1);

+#ifdef CAMSS_VFE_TRACE_IRQ
trace_printk("VFE: status0 = 0x%08x, status1 = 0x%08x\n",
value0, value1);
+#endif

if (value0 & VFE_0_IRQ_STATUS_0_RESET_ACK)
vfe->isr_ops.reset_ack(vfe);
--
2.28.0.220.ged08abb693-goog


2020-08-20 09:19:25

by Nicolas Boichat

[permalink] [raw]
Subject: [PATCH v4 2/3] kernel/trace: Add TRACING_ALLOW_PRINTK config option

trace_printk is meant as a debugging tool, and should not be
compiled into production code without specific debug Kconfig
options enabled, or source code changes, as indicated by the
warning that shows up on boot if any trace_printk is called:
** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE **
** **
** trace_printk() being used. Allocating extra memory. **
** **
** This means that this is a DEBUG kernel and it is **
** unsafe for production use. **

If this option is set to n, the kernel will generate a
build-time error if trace_printk is used.

Note that the code to handle trace_printk is still present,
so this does not prevent people from compiling out-of-tree
kernel modules with the option set to =y, or BPF programs.

Signed-off-by: Nicolas Boichat <[email protected]>

---

Changes since v2/v3:
- Rebase only, v3 didn't exist as I just split out the other
necessary patches.
- Added patch 3/3 to fix atomisp_compat_css20.c

Changes since v1:
- Use static_assert instead of __static_assert (Jason Gunthorpe)
- Fix issues that can be detected by this patch (running some
randconfig in a loop, kernel test robot, or manual inspection),
by:
- Making some debug config options that use trace_printk depend
on the new config option.
- Adding 3 patches before this one.

There is a question from Alexei whether the warning is warranted,
and it's possibly too strongly worded, but the fact is, we do
not want trace_printk to be sprinkled in kernel code by default,
unless a very specific Kconfig command is enabled (or preprocessor
macro).

There's at least 3 reasons that I can come up with:
1. trace_printk introduces some overhead.
2. If the kernel keeps adding always-enabled trace_printk, it will
be much harder for developers to make use of trace_printk for
debugging.
3. People may assume that trace_printk is for debugging only, and
may accidentally output sensitive data (theoritical at this
stage).

drivers/gpu/drm/i915/Kconfig.debug | 4 ++--
fs/f2fs/Kconfig | 1 +
include/linux/kernel.h | 17 ++++++++++++++++-
kernel/trace/Kconfig | 10 ++++++++++
samples/Kconfig | 2 ++
5 files changed, 31 insertions(+), 3 deletions(-)

diff --git a/drivers/gpu/drm/i915/Kconfig.debug b/drivers/gpu/drm/i915/Kconfig.debug
index 1cb28c20807c59d..fa30f9bdc82311f 100644
--- a/drivers/gpu/drm/i915/Kconfig.debug
+++ b/drivers/gpu/drm/i915/Kconfig.debug
@@ -84,7 +84,7 @@ config DRM_I915_ERRLOG_GEM
config DRM_I915_TRACE_GEM
bool "Insert extra ftrace output from the GEM internals"
depends on DRM_I915_DEBUG_GEM
- select TRACING
+ depends on TRACING_ALLOW_PRINTK
default n
help
Enable additional and verbose debugging output that will spam
@@ -98,7 +98,7 @@ config DRM_I915_TRACE_GEM
config DRM_I915_TRACE_GTT
bool "Insert extra ftrace output from the GTT internals"
depends on DRM_I915_DEBUG_GEM
- select TRACING
+ depends on TRACING_ALLOW_PRINTK
default n
help
Enable additional and verbose debugging output that will spam
diff --git a/fs/f2fs/Kconfig b/fs/f2fs/Kconfig
index d13c5c6a978769b..d161d96cc1b7418 100644
--- a/fs/f2fs/Kconfig
+++ b/fs/f2fs/Kconfig
@@ -80,6 +80,7 @@ config F2FS_IO_TRACE
bool "F2FS IO tracer"
depends on F2FS_FS
depends on FUNCTION_TRACER
+ depends on TRACING_ALLOW_PRINTK
help
F2FS IO trace is based on a function trace, which gathers process
information and block IO patterns in the filesystem level.
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 500def620d8f493..7cf24fa16a479ed 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -720,10 +720,15 @@ do { \
#define trace_printk(fmt, ...) \
do { \
char _______STR[] = __stringify((__VA_ARGS__)); \
+ \
+ static_assert( \
+ IS_ENABLED(CONFIG_TRACING_ALLOW_PRINTK),\
+ "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."); \
+ \
if (sizeof(_______STR) > 3) \
do_trace_printk(fmt, ##__VA_ARGS__); \
else \
- trace_puts(fmt); \
+ do_trace_puts(fmt); \
} while (0)

#define do_trace_printk(fmt, args...) \
@@ -772,6 +777,13 @@ int __trace_printk(unsigned long ip, const char *fmt, ...);
*/

#define trace_puts(str) ({ \
+ static_assert( \
+ IS_ENABLED(CONFIG_TRACING_ALLOW_PRINTK), \
+ "trace_puts called, please enable CONFIG_TRACING_ALLOW_PRINTK."); \
+ do_trace_puts(str); \
+})
+
+#define do_trace_puts(str) ({ \
static const char *trace_printk_fmt __used \
__attribute__((section("__trace_printk_fmt"))) = \
__builtin_constant_p(str) ? str : NULL; \
@@ -793,6 +805,9 @@ extern void trace_dump_stack(int skip);
*/
#define ftrace_vprintk(fmt, vargs) \
do { \
+ static_assert( \
+ IS_ENABLED(CONFIG_TRACING_ALLOW_PRINTK), \
+ "ftrace_vprintk called, please enable CONFIG_TRACING_ALLOW_PRINTK."); \
if (__builtin_constant_p(fmt)) { \
static const char *trace_printk_fmt __used \
__attribute__((section("__trace_printk_fmt"))) = \
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index a4020c0b4508c99..971b6035b197823 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -111,6 +111,15 @@ config GENERIC_TRACER
bool
select TRACING

+config TRACING_ALLOW_PRINTK
+ bool "Allow trace_printk"
+ default y if DEBUG_KERNEL
+ depends on TRACING
+ help
+ trace_printk is only meant as a debugging tool. If this option is
+ set to n, the kernel will generate a build-time error if trace_printk
+ is used.
+
#
# Minimum requirements an architecture has to meet for us to
# be able to offer generic tracing facilities:
@@ -686,6 +695,7 @@ config TRACEPOINT_BENCHMARK
config RING_BUFFER_BENCHMARK
tristate "Ring buffer benchmark stress tester"
depends on RING_BUFFER
+ depends on TRACING_ALLOW_PRINTK
help
This option creates a test to stress the ring buffer and benchmark it.
It creates its own ring buffer such that it will not interfere with
diff --git a/samples/Kconfig b/samples/Kconfig
index 0ed6e4d71d87b16..6b1ade57f00dd5d 100644
--- a/samples/Kconfig
+++ b/samples/Kconfig
@@ -19,6 +19,7 @@ config SAMPLE_TRACE_EVENTS
config SAMPLE_TRACE_PRINTK
tristate "Build trace_printk module - tests various trace_printk formats"
depends on EVENT_TRACING && m
+ depends on TRACING_ALLOW_PRINTK
help
This builds a module that calls trace_printk() and can be used to
test various trace_printk() calls from a module.
@@ -26,6 +27,7 @@ config SAMPLE_TRACE_PRINTK
config SAMPLE_FTRACE_DIRECT
tristate "Build register_ftrace_direct() example"
depends on DYNAMIC_FTRACE_WITH_DIRECT_CALLS && m
+ depends on TRACING_ALLOW_PRINTK
depends on X86_64 # has x86_64 inlined asm
help
This builds an ftrace direct function example
--
2.28.0.220.ged08abb693-goog

2020-08-20 14:24:49

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v4 1/3, RESEND] media: camss: vfe: Use trace_printk for debugging only

On Thu, 20 Aug 2020 17:14:10 +0800
Nicolas Boichat <[email protected]> wrote:

> trace_printk should not be used in production code. Since
> tracing interrupts is presumably latency sensitive, pr_dbg is
> not appropriate, so guard the call with a preprocessor symbol
> that can be defined for debugging purpose.
>
> Signed-off-by: Nicolas Boichat <[email protected]>
> ---
>
> (resending this patch as part of the whole series, since we need a new
> patch 3/3 now).
>
> drivers/media/platform/qcom/camss/camss-vfe-4-1.c | 2 ++
> drivers/media/platform/qcom/camss/camss-vfe-4-7.c | 2 ++
> 2 files changed, 4 insertions(+)
>
> diff --git a/drivers/media/platform/qcom/camss/camss-vfe-4-1.c b/drivers/media/platform/qcom/camss/camss-vfe-4-1.c
> index 174a36be6f5d866..0c57171fae4f9e9 100644
> --- a/drivers/media/platform/qcom/camss/camss-vfe-4-1.c
> +++ b/drivers/media/platform/qcom/camss/camss-vfe-4-1.c
> @@ -936,8 +936,10 @@ static irqreturn_t vfe_isr(int irq, void *dev)
>
> vfe->ops->isr_read(vfe, &value0, &value1);
>
> +#ifdef CAMSS_VFE_TRACE_IRQ
> trace_printk("VFE: status0 = 0x%08x, status1 = 0x%08x\n",
> value0, value1);

Why are these not trace events?

The reason I have that ugly banner is to keep people from doing EXACTLY THIS!

trace_printk() is really easy to add, but it also is not configurable.
When a trace_printk() is in the code, it is always enabled (well, you
can turn trace_printk off, but that's an all or nothing. That is, by
turning trace_printk off, you turn off *all* trace_printks).

Instead, people should add trace events. This here is a perfect place
to have a trace event. You don't need to add #ifdef around trace events
because when not enabled, they are simply a nop. When enabled, the nop
is turned into a jump to the tracing code. It should not affect
performance. And as a trace event, you get a bunch of features with it
(filtering, histograms, etc).

-- Steve


> +#endif
>
> if (value0 & VFE_0_IRQ_STATUS_0_RESET_ACK)
> vfe->isr_ops.reset_ack(vfe);
> diff --git a/drivers/media/platform/qcom/camss/camss-vfe-4-7.c b/drivers/media/platform/qcom/camss/camss-vfe-4-7.c
> index 0dca8bf9281e774..307675925e5c779 100644
> --- a/drivers/media/platform/qcom/camss/camss-vfe-4-7.c
> +++ b/drivers/media/platform/qcom/camss/camss-vfe-4-7.c
> @@ -1058,8 +1058,10 @@ static irqreturn_t vfe_isr(int irq, void *dev)
>
> vfe->ops->isr_read(vfe, &value0, &value1);
>
> +#ifdef CAMSS_VFE_TRACE_IRQ
> trace_printk("VFE: status0 = 0x%08x, status1 = 0x%08x\n",
> value0, value1);
> +#endif
>
> if (value0 & VFE_0_IRQ_STATUS_0_RESET_ACK)
> vfe->isr_ops.reset_ack(vfe);