[PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Nicolas Boichat]

trace_printk is only meant as a debugging tool, and should never be
compiled into production code without 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.

Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
---
 include/linux/kernel.h | 17 ++++++++++++++++-
 kernel/trace/Kconfig   |  9 +++++++++
 2 files changed, 25 insertions(+), 1 deletion(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 196607aaf653082..b6addc6ba669e85 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -721,10 +721,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...)					\
@@ -773,6 +778,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;			\
@@ -794,6 +806,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..89ffddebe1864aa 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:
-- 
2.27.0.111.gc72c7da667-goog

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Jason Gunthorpe]

On Wed, Jun 24, 2020 at 04:45:24PM +0800, Nicolas Boichat wrote:
> trace_printk is only meant as a debugging tool, and should never be
> compiled into production code without 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.
> 
> Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
>  include/linux/kernel.h | 17 ++++++++++++++++-
>  kernel/trace/Kconfig   |  9 +++++++++
>  2 files changed, 25 insertions(+), 1 deletion(-)
> 
> diff --git a/include/linux/kernel.h b/include/linux/kernel.h
> index 196607aaf653082..b6addc6ba669e85 100644
> +++ b/include/linux/kernel.h
> @@ -721,10 +721,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."); \
> +							\

Why __static_assert not normal static_assert?

Jason

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Wed, 24 Jun 2020 16:45:24 +0800
Nicolas Boichat <drinkcat@chromium.org> wrote:

> trace_printk is only meant as a debugging tool, and should never be
> compiled into production code without 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.
> 
> Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>

Interesting. Note, this will prevent modules with trace_printk from
being loaded as well.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Wed, Jun 24, 2020 at 9:07 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 24 Jun 2020 16:45:24 +0800
> Nicolas Boichat <drinkcat@chromium.org> wrote:
>
> > trace_printk is only meant as a debugging tool, and should never be
> > compiled into production code without 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.
> >
> > Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
>
> Interesting. Note, this will prevent modules with trace_printk from
> being loaded as well.

Nack.
The message is bogus. It's used in production kernels.
bpf_trace_printk() calls it.

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[kernel test robot]

[-- Attachment #1: Type: text/plain, Size: 15800 bytes --]

Hi Nicolas,

Thank you for the patch! Yet something to improve:

[auto build test ERROR on linux/master]
[also build test ERROR on tip/perf/core kees/for-next/pstore linus/master v5.8-rc2 next-20200624]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use  as documented in
https://git-scm.com/docs/git-format-patch]

url:    https://github.com/0day-ci/linux/commits/Nicolas-Boichat/kernel-trace-Add-TRACING_ALLOW_PRINTK-config-option/20200624-164815
base:   https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git 5e857ce6eae7ca21b2055cca4885545e29228fe2
config: microblaze-randconfig-r026-20200624 (attached as .config)
compiler: microblaze-linux-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # save the attached .config to linux build tree
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross ARCH=microblaze 

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <lkp@intel.com>

All error/warnings (new ones prefixed by >>):

   In file included from include/linux/bits.h:23,
                    from include/linux/bitops.h:5,
                    from include/linux/kernel.h:12,
                    from include/asm-generic/bug.h:19,
                    from ./arch/microblaze/include/generated/asm/bug.h:1,
                    from include/linux/bug.h:5,
                    from include/linux/mmdebug.h:5,
                    from include/linux/mm.h:9,
                    from include/linux/ring_buffer.h:5,
                    from kernel/trace/ring_buffer_benchmark.c:7:
   kernel/trace/ring_buffer_benchmark.c: In function 'ring_buffer_producer':
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
>> kernel/trace/ring_buffer_benchmark.c:245:2: note: in expansion of macro 'trace_printk'
     245 |  trace_printk("Starting ring buffer hammer\n");
         |  ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:284:2: note: in expansion of macro 'trace_printk'
     284 |  trace_printk("End ring buffer hammer\n");
         |  ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:303:3: note: in expansion of macro 'trace_printk'
     303 |   trace_printk("ERROR!\n");
         |   ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:307:4: note: in expansion of macro 'trace_printk'
     307 |    trace_printk("Running Consumer at nice: %d\n",
         |    ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:310:4: note: in expansion of macro 'trace_printk'
     310 |    trace_printk("Running Consumer at SCHED_FIFO %d\n",
         |    ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:314:3: note: in expansion of macro 'trace_printk'
     314 |   trace_printk("Running Producer at nice: %d\n",
         |   ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:317:3: note: in expansion of macro 'trace_printk'
     317 |   trace_printk("Running Producer at SCHED_FIFO %d\n",
         |   ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:323:3: note: in expansion of macro 'trace_printk'
     323 |   trace_printk("WARNING!!! This test is running at lowest priority.\n");
         |   ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
>> include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:325:2: note: in expansion of macro 'trace_printk'
     325 |  trace_printk("Time:     %lld (usecs)\n", time);
         |  ^~~~~~~~~~~~
>> include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:326:2: note: in expansion of macro 'trace_printk'
     326 |  trace_printk("Overruns: %lld\n", overruns);
         |  ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:328:3: note: in expansion of macro 'trace_printk'
     328 |   trace_printk("Read:     (reader disabled)\n");
         |   ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:330:3: note: in expansion of macro 'trace_printk'
     330 |   trace_printk("Read:     %ld  (by %s)\n", read,
         |   ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:332:2: note: in expansion of macro 'trace_printk'
     332 |  trace_printk("Entries:  %lld\n", entries);
         |  ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:333:2: note: in expansion of macro 'trace_printk'
     333 |  trace_printk("Total:    %lld\n", entries + overruns + read);
         |  ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:334:2: note: in expansion of macro 'trace_printk'
     334 |  trace_printk("Missed:   %ld\n", missed);
         |  ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:335:2: note: in expansion of macro 'trace_printk'
     335 |  trace_printk("Hit:      %ld\n", hit);
         |  ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:342:3: note: in expansion of macro 'trace_printk'
     342 |   trace_printk("TIME IS ZERO??\n");
         |   ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:344:2: note: in expansion of macro 'trace_printk'
     344 |  trace_printk("Entries per millisec: %ld\n", hit);
         |  ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:349:3: note: in expansion of macro 'trace_printk'
     349 |   trace_printk("%ld ns per entry\n", avg);
         |   ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
   kernel/trace/ring_buffer_benchmark.c:356:3: note: in expansion of macro 'trace_printk'
     356 |   trace_printk("Total iterations per millisec: %ld\n",
         |   ^~~~~~~~~~~~
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)

vim +78 include/linux/build_bug.h

bc6245e5efd70c Ian Abbott       2017-07-10  60  
6bab69c65013be Rasmus Villemoes 2019-03-07  61  /**
6bab69c65013be Rasmus Villemoes 2019-03-07  62   * static_assert - check integer constant expression at build time
6bab69c65013be Rasmus Villemoes 2019-03-07  63   *
6bab69c65013be Rasmus Villemoes 2019-03-07  64   * static_assert() is a wrapper for the C11 _Static_assert, with a
6bab69c65013be Rasmus Villemoes 2019-03-07  65   * little macro magic to make the message optional (defaulting to the
6bab69c65013be Rasmus Villemoes 2019-03-07  66   * stringification of the tested expression).
6bab69c65013be Rasmus Villemoes 2019-03-07  67   *
6bab69c65013be Rasmus Villemoes 2019-03-07  68   * Contrary to BUILD_BUG_ON(), static_assert() can be used at global
6bab69c65013be Rasmus Villemoes 2019-03-07  69   * scope, but requires the expression to be an integer constant
6bab69c65013be Rasmus Villemoes 2019-03-07  70   * expression (i.e., it is not enough that __builtin_constant_p() is
6bab69c65013be Rasmus Villemoes 2019-03-07  71   * true for expr).
6bab69c65013be Rasmus Villemoes 2019-03-07  72   *
6bab69c65013be Rasmus Villemoes 2019-03-07  73   * Also note that BUILD_BUG_ON() fails the build if the condition is
6bab69c65013be Rasmus Villemoes 2019-03-07  74   * true, while static_assert() fails the build if the expression is
6bab69c65013be Rasmus Villemoes 2019-03-07  75   * false.
6bab69c65013be Rasmus Villemoes 2019-03-07  76   */
6bab69c65013be Rasmus Villemoes 2019-03-07  77  #define static_assert(expr, ...) __static_assert(expr, ##__VA_ARGS__, #expr)
6bab69c65013be Rasmus Villemoes 2019-03-07 @78  #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
6bab69c65013be Rasmus Villemoes 2019-03-07  79  

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all@lists.01.org

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 33429 bytes --]

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[kernel test robot]

[-- Attachment #1: Type: text/plain, Size: 7000 bytes --]

Hi Nicolas,

Thank you for the patch! Perhaps something to improve:

[auto build test WARNING on linux/master]
[also build test WARNING on tip/perf/core kees/for-next/pstore linus/master v5.8-rc2 next-20200624]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use  as documented in
https://git-scm.com/docs/git-format-patch]

url:    https://github.com/0day-ci/linux/commits/Nicolas-Boichat/kernel-trace-Add-TRACING_ALLOW_PRINTK-config-option/20200624-164815
base:   https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git 5e857ce6eae7ca21b2055cca4885545e29228fe2
config: sparc64-randconfig-r022-20200624 (attached as .config)
compiler: sparc64-linux-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # save the attached .config to linux build tree
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross ARCH=sparc64 

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <lkp@intel.com>

All warnings (new ones prefixed by >>):

   In file included from include/linux/bits.h:23,
                    from include/linux/bitops.h:5,
                    from include/linux/kernel.h:12,
                    from include/asm-generic/bug.h:19,
                    from arch/sparc/include/asm/bug.h:25,
                    from include/linux/bug.h:5,
                    from include/linux/thread_info.h:12,
                    from arch/sparc/include/asm/current.h:15,
                    from include/linux/sched.h:12,
                    from include/linux/ratelimit.h:6,
                    from include/linux/dev_printk.h:16,
                    from include/linux/device.h:15,
                    from include/linux/dma-mapping.h:7,
                    from drivers/usb/cdns3/gadget.c:59:
   drivers/usb/cdns3/gadget.c: In function 'cdns3_start_all_request':
   include/linux/build_bug.h:78:41: error: static assertion failed: "trace_printk called, please enable CONFIG_TRACING_ALLOW_PRINTK."
      78 | #define __static_assert(expr, msg, ...) _Static_assert(expr, msg)
         |                                         ^~~~~~~~~~~~~~
   include/linux/kernel.h:725:2: note: in expansion of macro '__static_assert'
     725 |  __static_assert(    \
         |  ^~~~~~~~~~~~~~~
>> drivers/usb/cdns3/gadget.c:424:4: note: in expansion of macro 'trace_printk'
     424 |    trace_printk("Blocking external request\n");
         |    ^~~~~~~~~~~~

vim +/trace_printk +424 drivers/usb/cdns3/gadget.c

7733f6c32e36ff Pawel Laszczak 2019-08-26  395  
7733f6c32e36ff Pawel Laszczak 2019-08-26  396  /**
7733f6c32e36ff Pawel Laszczak 2019-08-26  397   * cdns3_start_all_request - add to ring all request not started
7733f6c32e36ff Pawel Laszczak 2019-08-26  398   * @priv_dev: Extended gadget object
7733f6c32e36ff Pawel Laszczak 2019-08-26  399   * @priv_ep: The endpoint for whom request will be started.
7733f6c32e36ff Pawel Laszczak 2019-08-26  400   *
7733f6c32e36ff Pawel Laszczak 2019-08-26  401   * Returns return ENOMEM if transfer ring i not enough TRBs to start
7733f6c32e36ff Pawel Laszczak 2019-08-26  402   *         all requests.
7733f6c32e36ff Pawel Laszczak 2019-08-26  403   */
7733f6c32e36ff Pawel Laszczak 2019-08-26  404  static int cdns3_start_all_request(struct cdns3_device *priv_dev,
7733f6c32e36ff Pawel Laszczak 2019-08-26  405  				   struct cdns3_endpoint *priv_ep)
7733f6c32e36ff Pawel Laszczak 2019-08-26  406  {
7733f6c32e36ff Pawel Laszczak 2019-08-26  407  	struct usb_request *request;
7733f6c32e36ff Pawel Laszczak 2019-08-26  408  	int ret = 0;
54c4c69f0baa43 Jayshri Pawar  2019-12-13  409  	u8 pending_empty = list_empty(&priv_ep->pending_req_list);
54c4c69f0baa43 Jayshri Pawar  2019-12-13  410  
54c4c69f0baa43 Jayshri Pawar  2019-12-13  411  	/*
54c4c69f0baa43 Jayshri Pawar  2019-12-13  412  	 * If the last pending transfer is INTERNAL
54c4c69f0baa43 Jayshri Pawar  2019-12-13  413  	 * OR streams are enabled for this endpoint
54c4c69f0baa43 Jayshri Pawar  2019-12-13  414  	 * do NOT start new transfer till the last one is pending
54c4c69f0baa43 Jayshri Pawar  2019-12-13  415  	 */
54c4c69f0baa43 Jayshri Pawar  2019-12-13  416  	if (!pending_empty) {
54c4c69f0baa43 Jayshri Pawar  2019-12-13  417  		struct cdns3_request *priv_req;
54c4c69f0baa43 Jayshri Pawar  2019-12-13  418  
54c4c69f0baa43 Jayshri Pawar  2019-12-13  419  		request = cdns3_next_request(&priv_ep->pending_req_list);
54c4c69f0baa43 Jayshri Pawar  2019-12-13  420  		priv_req = to_cdns3_request(request);
54c4c69f0baa43 Jayshri Pawar  2019-12-13  421  		if ((priv_req->flags & REQUEST_INTERNAL) ||
54c4c69f0baa43 Jayshri Pawar  2019-12-13  422  		    (priv_ep->flags & EP_TDLCHK_EN) ||
54c4c69f0baa43 Jayshri Pawar  2019-12-13  423  			priv_ep->use_streams) {
54c4c69f0baa43 Jayshri Pawar  2019-12-13 @424  			trace_printk("Blocking external request\n");
54c4c69f0baa43 Jayshri Pawar  2019-12-13  425  			return ret;
54c4c69f0baa43 Jayshri Pawar  2019-12-13  426  		}
54c4c69f0baa43 Jayshri Pawar  2019-12-13  427  	}
7733f6c32e36ff Pawel Laszczak 2019-08-26  428  
7733f6c32e36ff Pawel Laszczak 2019-08-26  429  	while (!list_empty(&priv_ep->deferred_req_list)) {
7733f6c32e36ff Pawel Laszczak 2019-08-26  430  		request = cdns3_next_request(&priv_ep->deferred_req_list);
7733f6c32e36ff Pawel Laszczak 2019-08-26  431  
54c4c69f0baa43 Jayshri Pawar  2019-12-13  432  		if (!priv_ep->use_streams) {
7733f6c32e36ff Pawel Laszczak 2019-08-26  433  			ret = cdns3_ep_run_transfer(priv_ep, request);
54c4c69f0baa43 Jayshri Pawar  2019-12-13  434  		} else {
54c4c69f0baa43 Jayshri Pawar  2019-12-13  435  			priv_ep->stream_sg_idx = 0;
54c4c69f0baa43 Jayshri Pawar  2019-12-13  436  			ret = cdns3_ep_run_stream_transfer(priv_ep, request);
54c4c69f0baa43 Jayshri Pawar  2019-12-13  437  		}
7733f6c32e36ff Pawel Laszczak 2019-08-26  438  		if (ret)
7733f6c32e36ff Pawel Laszczak 2019-08-26  439  			return ret;
7733f6c32e36ff Pawel Laszczak 2019-08-26  440  
7733f6c32e36ff Pawel Laszczak 2019-08-26  441  		list_del(&request->list);
7733f6c32e36ff Pawel Laszczak 2019-08-26  442  		list_add_tail(&request->list,
7733f6c32e36ff Pawel Laszczak 2019-08-26  443  			      &priv_ep->pending_req_list);
54c4c69f0baa43 Jayshri Pawar  2019-12-13  444  		if (request->stream_id != 0 || (priv_ep->flags & EP_TDLCHK_EN))
54c4c69f0baa43 Jayshri Pawar  2019-12-13  445  			break;
7733f6c32e36ff Pawel Laszczak 2019-08-26  446  	}
7733f6c32e36ff Pawel Laszczak 2019-08-26  447  
7733f6c32e36ff Pawel Laszczak 2019-08-26  448  	priv_ep->flags &= ~EP_RING_FULL;
7733f6c32e36ff Pawel Laszczak 2019-08-26  449  	return ret;
7733f6c32e36ff Pawel Laszczak 2019-08-26  450  }
7733f6c32e36ff Pawel Laszczak 2019-08-26  451  

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all@lists.01.org

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 31981 bytes --]

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Nicolas Boichat]

On Wed, Jun 24, 2020 at 9:57 PM Jason Gunthorpe <jgg@ziepe.ca> wrote:
>
> On Wed, Jun 24, 2020 at 04:45:24PM +0800, Nicolas Boichat wrote:
> > trace_printk is only meant as a debugging tool, and should never be
> > compiled into production code without 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.
> >
> > Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
> >  include/linux/kernel.h | 17 ++++++++++++++++-
> >  kernel/trace/Kconfig   |  9 +++++++++
> >  2 files changed, 25 insertions(+), 1 deletion(-)
> >
> > diff --git a/include/linux/kernel.h b/include/linux/kernel.h
> > index 196607aaf653082..b6addc6ba669e85 100644
> > +++ b/include/linux/kernel.h
> > @@ -721,10 +721,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."); \
> > +                                                     \
>
> Why __static_assert not normal static_assert?

Oh, I misread the macro code (and didn't read the comment above in
include/linux/build_bug.h). static_assert would be just fine.

>
> Jason

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Nicolas Boichat]

On Thu, Jun 25, 2020 at 12:04 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 24 Jun 2020 16:45:24 +0800
> Nicolas Boichat <drinkcat@chromium.org> wrote:
>
> > trace_printk is only meant as a debugging tool, and should never be
> > compiled into production code without 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.
> >
> > Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
>
> Interesting. Note, this will prevent modules with trace_printk from
> being loaded as well.

Err, all of these changes are in macros (nothing gets built in the
kernel), so this will prevent modules with trace_printk from being
_built_.

Now, if you set the option to =y when building the module (separately,
even though the rest of the kernel has =n) then I don't see why the
module could not be loaded.

>
> -- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Nicolas Boichat]

On Thu, Jun 25, 2020 at 1:25 AM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Wed, Jun 24, 2020 at 9:07 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Wed, 24 Jun 2020 16:45:24 +0800
> > Nicolas Boichat <drinkcat@chromium.org> wrote:
> >
> > > trace_printk is only meant as a debugging tool, and should never be
> > > compiled into production code without 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.
> > >
> > > Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
> >
> > Interesting. Note, this will prevent modules with trace_printk from
> > being loaded as well.
>
> Nack.
> The message is bogus. It's used in production kernels.
> bpf_trace_printk() calls it.

Interesting. BTW, the same information (trace_printk is for debugging
only) is repeated all over the place, including where bpf_trace_printk
is documented:
https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157

Steven added that warning (2184db46e425c ("tracing: Print nasty banner
when trace_printk() is in use")), so maybe he can confirm if it's
still relevant.

Also, note that emitting the build error is behind a Kconfig option,
you don't have to select it if you don't want to (the default is =y
which allows trace_printk).

If the overhead is real, we (Chrome OS) would like to make sure
trace_printk does not slip into production kernels (we do want to
provide basic tracing support so we can't just remove CONFIG_TRACING
as a whole which would make trace_printk no-ops). I could also imagine
potential security issues if people print raw pointers/sensitive data
in trace_printk, assuming that the code is for debugging only.

Also, the fact that the kernel test robot already found a stray
trace_printk in drivers/usb/cdns3/gadget.c makes me think that this
change is working as intended ,-) (we're going to need to add a few
Kconfig deps though for other debugging options that intentionally use
trace_printk).

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Thu, Jun 25, 2020 at 10:00:09AM +0800, Nicolas Boichat wrote:
> On Thu, Jun 25, 2020 at 1:25 AM Alexei Starovoitov
> <alexei.starovoitov@gmail.com> wrote:
> >
> > On Wed, Jun 24, 2020 at 9:07 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> > >
> > > On Wed, 24 Jun 2020 16:45:24 +0800
> > > Nicolas Boichat <drinkcat@chromium.org> wrote:
> > >
> > > > trace_printk is only meant as a debugging tool, and should never be
> > > > compiled into production code without 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.
> > > >
> > > > Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
> > >
> > > Interesting. Note, this will prevent modules with trace_printk from
> > > being loaded as well.
> >
> > Nack.
> > The message is bogus. It's used in production kernels.
> > bpf_trace_printk() calls it.
> 
> Interesting. BTW, the same information (trace_printk is for debugging
> only) is repeated all over the place, including where bpf_trace_printk
> is documented:
> https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
> https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
> https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157
> 
> Steven added that warning (2184db46e425c ("tracing: Print nasty banner
> when trace_printk() is in use")), so maybe he can confirm if it's
> still relevant.

The banner is nasty and it's actively causing harm.
Every few month I have to explain to users that it's absolulte ok to
ignore that banner. Nothing bad is happening with the kernel.
The kernel is still perfectly safe for production use.
It's not a debug kernel.

What bpf_trace_printk() doc is saying that it's not recommended to use
this helper for production bpf programs. There are better alternatives.
It is absolutely fine to use bpf_trace_printk() to debug production and
experimental bpf programs on production servers, android phones and
everywhere else.

> Also, note that emitting the build error is behind a Kconfig option,
> you don't have to select it if you don't want to (the default is =y
> which allows trace_printk).
> 
> If the overhead is real, we (Chrome OS) would like to make sure
> trace_printk does not slip into production kernels (we do want to
> provide basic tracing support so we can't just remove CONFIG_TRACING
> as a whole which would make trace_printk no-ops). I could also imagine
> potential security issues if people print raw pointers/sensitive data
> in trace_printk, assuming that the code is for debugging only.
> 
> Also, the fact that the kernel test robot already found a stray
> trace_printk in drivers/usb/cdns3/gadget.c makes me think that this
> change is working as intended ,-) (we're going to need to add a few
> Kconfig deps though for other debugging options that intentionally use
> trace_printk).

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Wed, 24 Jun 2020 20:59:13 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> > >
> > > Nack.

I nack your nack ;-)

> > > The message is bogus. It's used in production kernels.
> > > bpf_trace_printk() calls it.  
> > 
> > Interesting. BTW, the same information (trace_printk is for debugging
> > only) is repeated all over the place, including where bpf_trace_printk
> > is documented:
> > https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
> > https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
> > https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157
> > 
> > Steven added that warning (2184db46e425c ("tracing: Print nasty banner
> > when trace_printk() is in use")), so maybe he can confirm if it's
> > still relevant.  
> 
> The banner is nasty and it's actively causing harm.

And it's doing exactly what it was intended on doing!

> Every few month I have to explain to users that it's absolulte ok to
> ignore that banner. Nothing bad is happening with the kernel.
> The kernel is still perfectly safe for production use.
> It's not a debug kernel.
> 
> What bpf_trace_printk() doc is saying that it's not recommended to use
> this helper for production bpf programs. There are better alternatives.
> It is absolutely fine to use bpf_trace_printk() to debug production and
> experimental bpf programs on production servers, android phones and
> everywhere else.

Now I do have an answer for you that I believe is a great compromise.

There's something you can call (and even call it from a module). It's
called "trace_array_vprintk()". But has one caveat, and that is, you
can not write to the main top level trace buffer with it (I have
patches for the next merge window to enforce that). And that's what
I've been trying to avoid trace_printk() from doing, as that's what it
does by default. It writes to /sys/kernel/tracing/trace.

Now what you can do, is have bpf create
a /sys/kernel/tracing/instances/bpf_trace/ instance, and use
trace_array_printk(), to print into that, and you will never have to
see that warning again! It shows up in your own
tracefs/instances/bpf_trace/trace file!

If you need more details, let me know, and I can give you all you need
to know to create you very own trace instance (that can enable events,
kprobe events, uprobe events, function tracing, and soon function graph
tracing). And the bonus, you get trace_array_vprintk() and no more
complaining. :-) :-) :-)

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Fri, Jun 26, 2020 at 06:14:55PM -0400, Steven Rostedt wrote:
> On Wed, 24 Jun 2020 20:59:13 -0700
> Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:
> 
> > > >
> > > > Nack.
> 
> I nack your nack ;-)

ok. let's take it up to Linus to decide.

> 
> > > > The message is bogus. It's used in production kernels.
> > > > bpf_trace_printk() calls it.  
> > > 
> > > Interesting. BTW, the same information (trace_printk is for debugging
> > > only) is repeated all over the place, including where bpf_trace_printk
> > > is documented:
> > > https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
> > > https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
> > > https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157
> > > 
> > > Steven added that warning (2184db46e425c ("tracing: Print nasty banner
> > > when trace_printk() is in use")), so maybe he can confirm if it's
> > > still relevant.  
> > 
> > The banner is nasty and it's actively causing harm.
> 
> And it's doing exactly what it was intended on doing!

I disagree. The message is _lying_ about the state of the kernel.
It's not a debug kernel and it's absolutely fine for production.

> > Every few month I have to explain to users that it's absolulte ok to
> > ignore that banner. Nothing bad is happening with the kernel.
> > The kernel is still perfectly safe for production use.
> > It's not a debug kernel.
> > 
> > What bpf_trace_printk() doc is saying that it's not recommended to use
> > this helper for production bpf programs. There are better alternatives.
> > It is absolutely fine to use bpf_trace_printk() to debug production and
> > experimental bpf programs on production servers, android phones and
> > everywhere else.
> 
> Now I do have an answer for you that I believe is a great compromise.
> 
> There's something you can call (and even call it from a module). It's
> called "trace_array_vprintk()". But has one caveat, and that is, you
> can not write to the main top level trace buffer with it (I have
> patches for the next merge window to enforce that). And that's what
> I've been trying to avoid trace_printk() from doing, as that's what it
> does by default. It writes to /sys/kernel/tracing/trace.
> 
> Now what you can do, is have bpf create
> a /sys/kernel/tracing/instances/bpf_trace/ instance, and use
> trace_array_printk(), to print into that, and you will never have to
> see that warning again! It shows up in your own
> tracefs/instances/bpf_trace/trace file!
> 
> If you need more details, let me know, and I can give you all you need
> to know to create you very own trace instance (that can enable events,
> kprobe events, uprobe events, function tracing, and soon function graph
> tracing). And the bonus, you get trace_array_vprintk() and no more
> complaining. :-) :-) :-)

We added a bunch of code to libbcc in the past to support instances,
but eventually removed it all due to memory overhead per instance.
If I recall it was ~8Mbyte per instance. That was couple years ago.

By now everyone has learned to use bpf_trace_printk() and expects
to see the output in /sys/kernel/debug/tracing/trace.
It's documented in uapi/bpf.h and various docs.

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Sun, 28 Jun 2020 10:27:00 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> On Fri, Jun 26, 2020 at 06:14:55PM -0400, Steven Rostedt wrote:
> > On Wed, 24 Jun 2020 20:59:13 -0700
> > Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:
> >   
> > > > >
> > > > > Nack.  
> > 
> > I nack your nack ;-)  
> 
> ok. let's take it up to Linus to decide.

I'm fine with that.

> 
> >   
> > > > > The message is bogus. It's used in production kernels.
> > > > > bpf_trace_printk() calls it.    
> > > > 
> > > > Interesting. BTW, the same information (trace_printk is for debugging
> > > > only) is repeated all over the place, including where bpf_trace_printk
> > > > is documented:
> > > > https://elixir.bootlin.com/linux/latest/source/include/linux/kernel.h#L757
> > > > https://elixir.bootlin.com/linux/latest/source/include/uapi/linux/bpf.h#L706
> > > > https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace.c#L3157
> > > > 
> > > > Steven added that warning (2184db46e425c ("tracing: Print nasty banner
> > > > when trace_printk() is in use")), so maybe he can confirm if it's
> > > > still relevant.    
> > > 
> > > The banner is nasty and it's actively causing harm.  
> > 
> > And it's doing exactly what it was intended on doing!  
> 
> I disagree. The message is _lying_ about the state of the kernel.
> It's not a debug kernel and it's absolutely fine for production.

No it is not!

It causes the trace buffer to be filled with crap that can not be
easily disabled. That's the reason I only allowed trace_printk() for
debug kernels. And the only way to prevent people from sticking it in
their code and making an API out of it was for this banner.

I refuse to remove that banner. It's my API!

> > 
> > Now I do have an answer for you that I believe is a great compromise.
> > 
> > There's something you can call (and even call it from a module). It's
> > called "trace_array_vprintk()". But has one caveat, and that is, you
> > can not write to the main top level trace buffer with it (I have
> > patches for the next merge window to enforce that). And that's what
> > I've been trying to avoid trace_printk() from doing, as that's what it
> > does by default. It writes to /sys/kernel/tracing/trace.
> > 
> > Now what you can do, is have bpf create
> > a /sys/kernel/tracing/instances/bpf_trace/ instance, and use
> > trace_array_printk(), to print into that, and you will never have to
> > see that warning again! It shows up in your own
> > tracefs/instances/bpf_trace/trace file!
> > 
> > If you need more details, let me know, and I can give you all you need
> > to know to create you very own trace instance (that can enable events,
> > kprobe events, uprobe events, function tracing, and soon function graph
> > tracing). And the bonus, you get trace_array_vprintk() and no more
> > complaining. :-) :-) :-)  
> 
> We added a bunch of code to libbcc in the past to support instances,
> but eventually removed it all due to memory overhead per instance.
> If I recall it was ~8Mbyte per instance. That was couple years ago.

I'd like to see where that 8 MB per instance came from. You can control
the size of the instance buffers. If size is still an issue, I'll be
happy to work with you to fix it.


> 
> By now everyone has learned to use bpf_trace_printk() and expects
> to see the output in /sys/kernel/debug/tracing/trace.
> It's documented in uapi/bpf.h and various docs.

Re-teach them, or are you finally admitting that the tracing system is
a permanent API?  This is the reason people are refusing to add trace
points into their subsystems. Because user space may make it required.

I see no reason why you can't create a dedicated BPF tracing instance
(you only need one) to add all your trace_array_printk()s to.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Sun, 28 Jun 2020 14:46:16 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> > We added a bunch of code to libbcc in the past to support instances,
> > but eventually removed it all due to memory overhead per instance.
> > If I recall it was ~8Mbyte per instance. That was couple years ago.  
> 
> I'd like to see where that 8 MB per instance came from. You can control
> the size of the instance buffers. If size is still an issue, I'll be
> happy to work with you to fix it.

Looks to be the duplication of the event directory tree. There's a lot
of duplicate data there. Instead of just punting and saying "instances
are too large" perhaps you could get someone to look at a way to
consolidate that data? I'm sure there's a lot of ways to help here.

Or you can just create a new event called bpf_printk() that passes in
and records a string and enable that automatically when a bpf module
has it. That could work as well.

In either case, your use of trace_printk() is an abuse of its purpose.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Sun, Jun 28, 2020 at 02:46:16PM -0400, Steven Rostedt wrote:
> > 
> > By now everyone has learned to use bpf_trace_printk() and expects
> > to see the output in /sys/kernel/debug/tracing/trace.
> > It's documented in uapi/bpf.h and various docs.
> 
> Re-teach them, or are you finally admitting that the tracing system is
> a permanent API?  This is the reason people are refusing to add trace
> points into their subsystems. Because user space may make it required.
> 
> I see no reason why you can't create a dedicated BPF tracing instance
> (you only need one) to add all your trace_array_printk()s to.

All bpf helpers are stable api. We cannot remove bpf_trace_printk() and
cannot change the fact that it has to print into /sys/kernel/debug/tracing/trace.
If we do so a lot of users will complain. Loudly.
If you really want to see the flames, go ahead and rename 'trace_pipe'
into something else.
This has nothing to do with tracing in general and tracepoints.
Those come and go.
If you really want to nuke trace_printk from the kernel we need time
to work on replacement and give users at least few releases of helper
deprecation time. We've never done in the past though.
There could be flames even if we deprecate it gradually.
Looking how unyielding you're about this banner I guess we have to start
working on replacement sooner than later. Oh well.

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

 On Sun, 28 Jun 2020 12:21:07 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> > Re-teach them, or are you finally admitting that the tracing system is
> > a permanent API?  This is the reason people are refusing to add trace
> > points into their subsystems. Because user space may make it required.
> > 
> > I see no reason why you can't create a dedicated BPF tracing instance
> > (you only need one) to add all your trace_array_printk()s to.  
> 
> All bpf helpers are stable api. We cannot remove bpf_trace_printk() and
> cannot change the fact that it has to print into /sys/kernel/debug/tracing/trace.

Then do a bpf trace event and enable it when a bpf_trace_printk() is
loaded. It will work the same for your users.

> If we do so a lot of users will complain. Loudly.
> If you really want to see the flames, go ahead and rename 'trace_pipe'
> into something else.

The layout of the tracefs system *is* a stable API. No argument there.

> This has nothing to do with tracing in general and tracepoints.
> Those come and go.

And in this case, trace_printk() is no different than any other trace
event. Obviously, your use case doesn't let it go. If some tool starts
relying on another trace event (say someone adds another bpf handler that
enables a trace event, and is documented) then under your scenario,
it's a stable API.

Hence, your "tracepoints come and go" is not universal, and there's no
telling which ones will end up being a stable API.


> If you really want to nuke trace_printk from the kernel we need time
> to work on replacement and give users at least few releases of helper
> deprecation time.

I never said I would nuke it. This patch in question makes it so those
that don't want that banner to ever show up can do so. A trace-printk()
is something to add via compiling. And since I and others use it
heavily for debugging, I would have this option not be a default, but
something that others can enable.

> We've never done in the past though.
> There could be flames even if we deprecate it gradually.
> Looking how unyielding you're about this banner I guess we have to start
> working on replacement sooner than later. Oh well.

Hmm, so you are happier to bully and burn bridges with me to deprecate
the trace_printk() interface, than to work with me and add an update to
look into an instance for the print instead of the top level? That's
not very collaborative.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Sun, Jun 28, 2020 at 03:43:31PM -0400, Steven Rostedt wrote:
>  On Sun, 28 Jun 2020 12:21:07 -0700
> Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:
> 
> > > Re-teach them, or are you finally admitting that the tracing system is
> > > a permanent API?  This is the reason people are refusing to add trace
> > > points into their subsystems. Because user space may make it required.
> > > 
> > > I see no reason why you can't create a dedicated BPF tracing instance
> > > (you only need one) to add all your trace_array_printk()s to.  
> > 
> > All bpf helpers are stable api. We cannot remove bpf_trace_printk() and
> > cannot change the fact that it has to print into /sys/kernel/debug/tracing/trace.
> 
> Then do a bpf trace event and enable it when a bpf_trace_printk() is
> loaded. It will work the same for your users.

I'm not sure I follow. How that would preserve the expectation
to see the output in /sys/kernel/debug/tracing/trace ?

> > If we do so a lot of users will complain. Loudly.
> > If you really want to see the flames, go ahead and rename 'trace_pipe'
> > into something else.
> 
> The layout of the tracefs system *is* a stable API. No argument there.
> 
> > This has nothing to do with tracing in general and tracepoints.
> > Those come and go.
> 
> And in this case, trace_printk() is no different than any other trace
> event. Obviously, your use case doesn't let it go. If some tool starts
> relying on another trace event (say someone adds another bpf handler that
> enables a trace event, and is documented) then under your scenario,
> it's a stable API.

not quite. Documneting kprobe+bpf as an example and writing a blog and a book
about it doesn't make it stable.

> 
> Hence, your "tracepoints come and go" is not universal, and there's no
> telling which ones will end up being a stable API.
> 
> 
> > If you really want to nuke trace_printk from the kernel we need time
> > to work on replacement and give users at least few releases of helper
> > deprecation time.
> 
> I never said I would nuke it. This patch in question makes it so those
> that don't want that banner to ever show up can do so. A trace-printk()
> is something to add via compiling. And since I and others use it
> heavily for debugging, I would have this option not be a default, but
> something that others can enable.
> 
> > We've never done in the past though.
> > There could be flames even if we deprecate it gradually.
> > Looking how unyielding you're about this banner I guess we have to start
> > working on replacement sooner than later. Oh well.
> 
> Hmm, so you are happier to bully and burn bridges with me to deprecate
> the trace_printk() interface, than to work with me and add an update to
> look into an instance for the print instead of the top level? That's
> not very collaborative.

I'm seeing it differently.
I'm saying bpf users are complaining about misleading dmesg warning.
You're saying 'screw your users I want to keep that warning'.
Though the warning is lying with a straight face. The only thing happened
is few pages were allocated that will never be freed. The kernel didn't
suddenly become non-production. It didn't become slower. No debug features
were turned on.

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Sun, 28 Jun 2020 15:02:09 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> > 
> > Then do a bpf trace event and enable it when a bpf_trace_printk() is
> > loaded. It will work the same for your users.  
> 
> I'm not sure I follow. How that would preserve the expectation
> to see the output in /sys/kernel/debug/tracing/trace ?

You create a bpf event just like you create any other event. When a bpf
program that uses a bpf_trace_printk() is loaded, you can enable that
event from within the kernel. Yes, there's internal interfaces to
enabled and disable events just like echoing 1 into
tracefs/events/system/event/enable. See trace_set_clr_event().

Then the data of that event will appear in
the /sys/kernel/tracing/trace file just like the trace_printk does.

The difference is, if something in the kernel decides to use that
event, I can easily disable it from user space, where trace_printk() I
can't.


> > 
> > Hmm, so you are happier to bully and burn bridges with me to deprecate
> > the trace_printk() interface, than to work with me and add an update to
> > look into an instance for the print instead of the top level? That's
> > not very collaborative.  
> 
> I'm seeing it differently.
> I'm saying bpf users are complaining about misleading dmesg warning.
> You're saying 'screw your users I want to keep that warning'.
> Though the warning is lying with a straight face. The only thing happened
> is few pages were allocated that will never be freed. The kernel didn't
> suddenly become non-production. It didn't become slower. No debug features
> were turned on.

Come now Alexei. That banner was there from day one trace_printk() was
added into the kernel. YOU used this knowing damn well that banner
existed. If the bpf users should be upset with someone, it is you for
not asking me for how to do this properly from the beginning.

This is not a regression. trace_printk() always has shown this, and
when I added trace_printk() I stated this is only for debugging a
kernel, and not to be kept in mainline. That banner helped enforce
that. If I didn't do that, there would be trace_printk()s all over the
place, and there's no way to disable one without disabling all the
others. This would have made trace_printk() become useless for
debugging a kernel, as then you will have to deal with everyone's
trace_printks() adding noise to what you want to debug.

-- Steve

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Sun, 28 Jun 2020 18:28:42 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> You create a bpf event just like you create any other event. When a bpf
> program that uses a bpf_trace_printk() is loaded, you can enable that
> event from within the kernel. Yes, there's internal interfaces to
> enabled and disable events just like echoing 1 into
> tracefs/events/system/event/enable. See trace_set_clr_event().

I just started playing with what the code would look like and have
this. It can be optimized with per-cpu sets of buffers to remove the
spin lock. I also didn't put in the enabling of the event, but I'm sure
you can figure that out.

Warning, not even compiled tested.

-- Steve

diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 6575bb0a0434..aeba5ee7325a 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE
 GCOV_PROFILE := y
 endif
 
+CFLAGS_bpf_trace.o := -I$(src)
+
 CFLAGS_trace_benchmark.o := -I$(src)
 CFLAGS_trace_events_filter.o := -I$(src)
 
diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
index dc05626979b8..01bedf335b2e 100644
--- a/kernel/trace/bpf_trace.c
+++ b/kernel/trace/bpf_trace.c
@@ -19,6 +19,9 @@
 #include "trace_probe.h"
 #include "trace.h"
 
+#define CREATE_TRACE_EVENTS
+#include "bpf_trace.h"
+
 #define bpf_event_rcu_dereference(p)					\
 	rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex))
 
@@ -473,13 +476,29 @@ BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1,
 		fmt_cnt++;
 	}
 
+static DEFINE_SPINLOCK(trace_printk_lock);
+#define BPF_TRACE_PRINTK_SIZE	1024
+
+static inline void do_trace_printk(const char *fmt, ...)
+{
+	static char buf[BPF_TRACE_PRINT_SIZE];
+	unsigned long flags;
+
+	spin_lock_irqsave(&trace_printk_lock, flags);
+	va_start(ap, fmt);
+	vsnprintf(buf, BPF_TRACE_PRINT_SIZE, fmt, ap);
+	va_end(ap);
+
+	trace_bpf_trace_printk(buf);
+	spin_unlock_irqrestore(&trace_printk_lock, flags);
+}
+
 /* Horrid workaround for getting va_list handling working with different
  * argument type combinations generically for 32 and 64 bit archs.
  */
 #define __BPF_TP_EMIT()	__BPF_ARG3_TP()
 #define __BPF_TP(...)							\
-	__trace_printk(0 /* Fake ip */,					\
-		       fmt, ##__VA_ARGS__)
+	do_trace_printk(fmt, ##__VA_ARGS__)
 
 #define __BPF_ARG1_TP(...)						\
 	((mod[0] == 2 || (mod[0] == 1 && __BITS_PER_LONG == 64))	\
diff --git a/kernel/trace/bpf_trace.h b/kernel/trace/bpf_trace.h
new file mode 100644
index 000000000000..09088bb92fe1
--- /dev/null
+++ b/kernel/trace/bpf_trace.h
@@ -0,0 +1,27 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM bpf_trace
+
+#if !defined(_TRACE_BPF_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_BPF_TRACE_H
+
+TRACE_EVENT(bpf_trace_printk,
+
+	TP_PROTO(bpf_string),
+
+	TP_ARGS(secs, err),
+
+	TP_STRUCT__entry(
+		__string(bpf_string, bpf_string)
+	),
+
+	TP_fast_assign(
+		__assign_string(bpf_string, bpf_string);
+	),
+
+	TP_printk("%s", __get_str(bpf_string))
+);
+
+#endif /* _TRACE_BPF_TRACE_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Alexei Starovoitov]

On Sun, Jun 28, 2020 at 07:43:34PM -0400, Steven Rostedt wrote:
> On Sun, 28 Jun 2020 18:28:42 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > You create a bpf event just like you create any other event. When a bpf
> > program that uses a bpf_trace_printk() is loaded, you can enable that
> > event from within the kernel. Yes, there's internal interfaces to
> > enabled and disable events just like echoing 1 into
> > tracefs/events/system/event/enable. See trace_set_clr_event().
> 
> I just started playing with what the code would look like and have
> this. It can be optimized with per-cpu sets of buffers to remove the
> spin lock. I also didn't put in the enabling of the event, but I'm sure
> you can figure that out.
> 
> Warning, not even compiled tested.

Thanks! I see what you mean now.

> 
> -- Steve
> 
> diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
> index 6575bb0a0434..aeba5ee7325a 100644
> --- a/kernel/trace/Makefile
> +++ b/kernel/trace/Makefile
> @@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE
>  GCOV_PROFILE := y
>  endif
>  
> +CFLAGS_bpf_trace.o := -I$(src)

not following. why this is needed?

> +
>  CFLAGS_trace_benchmark.o := -I$(src)
>  CFLAGS_trace_events_filter.o := -I$(src)
>  
> diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> index dc05626979b8..01bedf335b2e 100644
> --- a/kernel/trace/bpf_trace.c
> +++ b/kernel/trace/bpf_trace.c
> @@ -19,6 +19,9 @@
>  #include "trace_probe.h"
>  #include "trace.h"
>  
> +#define CREATE_TRACE_EVENTS

CREATE_TRACE_POINTS ?

> +#include "bpf_trace.h"
> +
>  #define bpf_event_rcu_dereference(p)					\
>  	rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex))
>  
> @@ -473,13 +476,29 @@ BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1,
>  		fmt_cnt++;
>  	}
>  
> +static DEFINE_SPINLOCK(trace_printk_lock);
> +#define BPF_TRACE_PRINTK_SIZE	1024
> +
> +static inline void do_trace_printk(const char *fmt, ...)
> +{
> +	static char buf[BPF_TRACE_PRINT_SIZE];
> +	unsigned long flags;
> +
> +	spin_lock_irqsave(&trace_printk_lock, flags);
> +	va_start(ap, fmt);
> +	vsnprintf(buf, BPF_TRACE_PRINT_SIZE, fmt, ap);
> +	va_end(ap);
> +
> +	trace_bpf_trace_printk(buf);
> +	spin_unlock_irqrestore(&trace_printk_lock, flags);

interesting. I don't think anyone would care about spin_lock overhead.
It's better because 'trace_bpf_trace_printk' would be a separate event
that can be individually enabled/disabled?
I guess it can work.
Thanks!

Re: [PATCH] kernel/trace: Add TRACING_ALLOW_PRINTK config option

[Steven Rostedt]

On Mon, 29 Jun 2020 22:16:59 -0700
Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> > 
> > Warning, not even compiled tested.  
> 
> Thanks! I see what you mean now.

Great! :-)

> 
> > 
> > -- Steve
> > 
> > diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
> > index 6575bb0a0434..aeba5ee7325a 100644
> > --- a/kernel/trace/Makefile
> > +++ b/kernel/trace/Makefile
> > @@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE
> >  GCOV_PROFILE := y
> >  endif
> >  
> > +CFLAGS_bpf_trace.o := -I$(src)  
> 
> not following. why this is needed?

It's required in order to have the TRACE_EVENT macro magic work. More
info about it here:

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/samples/trace_events/Makefile


> 
> > +
> >  CFLAGS_trace_benchmark.o := -I$(src)
> >  CFLAGS_trace_events_filter.o := -I$(src)
> >  
> > diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> > index dc05626979b8..01bedf335b2e 100644
> > --- a/kernel/trace/bpf_trace.c
> > +++ b/kernel/trace/bpf_trace.c
> > @@ -19,6 +19,9 @@
> >  #include "trace_probe.h"
> >  #include "trace.h"
> >  
> > +#define CREATE_TRACE_EVENTS  
> 
> CREATE_TRACE_POINTS ?


Doh, yeah. I did say it wasn't even compiled tested ;-)

> 
> > +#include "bpf_trace.h"
> > +
> >  #define bpf_event_rcu_dereference(p)					\
> >  	rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex))
> >  
> > @@ -473,13 +476,29 @@ BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1,
> >  		fmt_cnt++;
> >  	}
> >  
> > +static DEFINE_SPINLOCK(trace_printk_lock);
> > +#define BPF_TRACE_PRINTK_SIZE	1024
> > +
> > +static inline void do_trace_printk(const char *fmt, ...)
> > +{
> > +	static char buf[BPF_TRACE_PRINT_SIZE];
> > +	unsigned long flags;
> > +
> > +	spin_lock_irqsave(&trace_printk_lock, flags);
> > +	va_start(ap, fmt);
> > +	vsnprintf(buf, BPF_TRACE_PRINT_SIZE, fmt, ap);
> > +	va_end(ap);
> > +
> > +	trace_bpf_trace_printk(buf);
> > +	spin_unlock_irqrestore(&trace_printk_lock, flags);  
> 
> interesting. I don't think anyone would care about spin_lock overhead.
> It's better because 'trace_bpf_trace_printk' would be a separate event
> that can be individually enabled/disabled?
> I guess it can work.
> Thanks!

I hope this does everything you need for bpf_trace_printk. If there's
something  that's not working for you, PLEASE reach out to me and ask
what you need.

Cheers!

-- Steve