[PATCH bpf-next 0/5] bpf: implement variadic printk helper

[PATCH bpf-next 0/5] bpf: implement variadic printk helper

[Dave Marchevsky]

This series introduces a new helper, bpf_trace_vprintk, which functions
like bpf_trace_printk but supports > 3 arguments via a pseudo-vararg u64
array. A libbpf convienience macro, bpf_vprintk, is added to support
true vararg calling style.

Helper functions and macros added during the implementation of
bpf_seq_printf and bpf_snprintf do most of the heavy lifting for
bpf_trace_vprintk. There's no novel format string wrangling here.

Usecase here is straightforward: Giving BPF program writers a more
powerful printk will ease development of BPF programs, particularly
during debugging and testing, where printk tends to be used.

Hypothetically libbpf's bpf_printk convenience macro could be modified
to use bpf_trace_vprintk under the hood. This patchset does not attempt
to do this, though, nor am I confident that it's desired.

This feature was proposed by Andrii in libbpf mirror's issue tracker
[1].

[1] https://github.com/libbpf/libbpf/issues/315

Dave Marchevsky (5):
  bpf: merge printk and seq_printf VARARG max macros
  bpf: add bpf_trace_vprintk helper
  libbpf: Add bpf_vprintk convenience macro
  bpftool: only probe trace_vprintk feature in 'full' mode
  selftests/bpf: add trace_vprintk test prog

 include/linux/bpf.h                           |  3 +
 include/uapi/linux/bpf.h                      | 23 ++++++
 kernel/bpf/core.c                             |  5 ++
 kernel/bpf/helpers.c                          |  6 +-
 kernel/trace/bpf_trace.c                      | 54 ++++++++++++-
 tools/bpf/bpftool/feature.c                   |  1 +
 tools/include/uapi/linux/bpf.h                | 23 ++++++
 tools/lib/bpf/bpf_helpers.h                   | 18 +++++
 tools/testing/selftests/bpf/Makefile          |  3 +-
 .../selftests/bpf/prog_tests/trace_vprintk.c  | 75 +++++++++++++++++++
 .../selftests/bpf/progs/trace_vprintk.c       | 25 +++++++
 tools/testing/selftests/bpf/test_bpftool.py   | 22 +++---
 12 files changed, 238 insertions(+), 20 deletions(-)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
 create mode 100644 tools/testing/selftests/bpf/progs/trace_vprintk.c

-- 
2.30.2

[PATCH bpf-next 1/5] bpf: merge printk and seq_printf VARARG max macros

[Dave Marchevsky]

MAX_SNPRINTF_VARARGS and MAX_SEQ_PRINTF_VARARGS are used by bpf helpers
bpf_snprintf and bpf_seq_printf to limit their varargs. Both call into
bpf_bprintf_prepare for print formatting logic and have convenience
macros in libbpf (BPF_SNPRINTF, BPF_SEQ_PRINTF) which use the same
helper macros to convert varargs to a byte array.

Changing shared functionality to support more varargs for either bpf
helper would affect the other as well, so let's combine the _VARARGS
macros to make this more obvious.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 include/linux/bpf.h      | 2 ++
 kernel/bpf/helpers.c     | 4 +---
 kernel/trace/bpf_trace.c | 4 +---
 3 files changed, 4 insertions(+), 6 deletions(-)

diff --git a/include/linux/bpf.h b/include/linux/bpf.h
index f4c16f19f83e..be8d57e6e78a 100644
--- a/include/linux/bpf.h
+++ b/include/linux/bpf.h
@@ -2216,6 +2216,8 @@ int bpf_arch_text_poke(void *ip, enum bpf_text_poke_type t,
 struct btf_id_set;
 bool btf_id_set_contains(const struct btf_id_set *set, u32 id);
 
+#define MAX_BPRINTF_VARARGS		12
+
 int bpf_bprintf_prepare(char *fmt, u32 fmt_size, const u64 *raw_args,
 			u32 **bin_buf, u32 num_args);
 void bpf_bprintf_cleanup(void);
diff --git a/kernel/bpf/helpers.c b/kernel/bpf/helpers.c
index 4e8540716187..5ce19b376ef7 100644
--- a/kernel/bpf/helpers.c
+++ b/kernel/bpf/helpers.c
@@ -969,15 +969,13 @@ int bpf_bprintf_prepare(char *fmt, u32 fmt_size, const u64 *raw_args,
 	return err;
 }
 
-#define MAX_SNPRINTF_VARARGS		12
-
 BPF_CALL_5(bpf_snprintf, char *, str, u32, str_size, char *, fmt,
 	   const void *, data, u32, data_len)
 {
 	int err, num_args;
 	u32 *bin_args;
 
-	if (data_len % 8 || data_len > MAX_SNPRINTF_VARARGS * 8 ||
+	if (data_len % 8 || data_len > MAX_BPRINTF_VARARGS * 8 ||
 	    (data_len && !data))
 		return -EINVAL;
 	num_args = data_len / 8;
diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
index cbc73c08c4a4..2cf4bfa1ab7b 100644
--- a/kernel/trace/bpf_trace.c
+++ b/kernel/trace/bpf_trace.c
@@ -414,15 +414,13 @@ const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
 	return &bpf_trace_printk_proto;
 }
 
-#define MAX_SEQ_PRINTF_VARARGS		12
-
 BPF_CALL_5(bpf_seq_printf, struct seq_file *, m, char *, fmt, u32, fmt_size,
 	   const void *, data, u32, data_len)
 {
 	int err, num_args;
 	u32 *bin_args;
 
-	if (data_len & 7 || data_len > MAX_SEQ_PRINTF_VARARGS * 8 ||
+	if (data_len & 7 || data_len > MAX_BPRINTF_VARARGS * 8 ||
 	    (data_len && !data))
 		return -EINVAL;
 	num_args = data_len / 8;
-- 
2.30.2

Re: [PATCH bpf-next 1/5] bpf: merge printk and seq_printf VARARG max macros

[Andrii Nakryiko]

On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
>
> MAX_SNPRINTF_VARARGS and MAX_SEQ_PRINTF_VARARGS are used by bpf helpers
> bpf_snprintf and bpf_seq_printf to limit their varargs. Both call into
> bpf_bprintf_prepare for print formatting logic and have convenience
> macros in libbpf (BPF_SNPRINTF, BPF_SEQ_PRINTF) which use the same
> helper macros to convert varargs to a byte array.
>
> Changing shared functionality to support more varargs for either bpf
> helper would affect the other as well, so let's combine the _VARARGS
> macros to make this more obvious.
>
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---

Acked-by: Andrii Nakryiko <andrii@kernel.org>

>  include/linux/bpf.h      | 2 ++
>  kernel/bpf/helpers.c     | 4 +---
>  kernel/trace/bpf_trace.c | 4 +---
>  3 files changed, 4 insertions(+), 6 deletions(-)
>
> diff --git a/include/linux/bpf.h b/include/linux/bpf.h
> index f4c16f19f83e..be8d57e6e78a 100644
> --- a/include/linux/bpf.h
> +++ b/include/linux/bpf.h
> @@ -2216,6 +2216,8 @@ int bpf_arch_text_poke(void *ip, enum bpf_text_poke_type t,
>  struct btf_id_set;
>  bool btf_id_set_contains(const struct btf_id_set *set, u32 id);
>
> +#define MAX_BPRINTF_VARARGS            12
> +
>  int bpf_bprintf_prepare(char *fmt, u32 fmt_size, const u64 *raw_args,
>                         u32 **bin_buf, u32 num_args);
>  void bpf_bprintf_cleanup(void);
> diff --git a/kernel/bpf/helpers.c b/kernel/bpf/helpers.c
> index 4e8540716187..5ce19b376ef7 100644
> --- a/kernel/bpf/helpers.c
> +++ b/kernel/bpf/helpers.c
> @@ -969,15 +969,13 @@ int bpf_bprintf_prepare(char *fmt, u32 fmt_size, const u64 *raw_args,
>         return err;
>  }
>
> -#define MAX_SNPRINTF_VARARGS           12
> -
>  BPF_CALL_5(bpf_snprintf, char *, str, u32, str_size, char *, fmt,
>            const void *, data, u32, data_len)
>  {
>         int err, num_args;
>         u32 *bin_args;
>
> -       if (data_len % 8 || data_len > MAX_SNPRINTF_VARARGS * 8 ||
> +       if (data_len % 8 || data_len > MAX_BPRINTF_VARARGS * 8 ||
>             (data_len && !data))
>                 return -EINVAL;
>         num_args = data_len / 8;
> diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> index cbc73c08c4a4..2cf4bfa1ab7b 100644
> --- a/kernel/trace/bpf_trace.c
> +++ b/kernel/trace/bpf_trace.c
> @@ -414,15 +414,13 @@ const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
>         return &bpf_trace_printk_proto;
>  }
>
> -#define MAX_SEQ_PRINTF_VARARGS         12
> -
>  BPF_CALL_5(bpf_seq_printf, struct seq_file *, m, char *, fmt, u32, fmt_size,
>            const void *, data, u32, data_len)
>  {
>         int err, num_args;
>         u32 *bin_args;
>
> -       if (data_len & 7 || data_len > MAX_SEQ_PRINTF_VARARGS * 8 ||
> +       if (data_len & 7 || data_len > MAX_BPRINTF_VARARGS * 8 ||
>             (data_len && !data))
>                 return -EINVAL;
>         num_args = data_len / 8;
> --
> 2.30.2
>

[PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Dave Marchevsky]

This helper is meant to be "bpf_trace_printk, but with proper vararg
support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
array. Write to dmesg using the same mechanism as bpf_trace_printk.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 include/linux/bpf.h            |  1 +
 include/uapi/linux/bpf.h       | 23 +++++++++++++++
 kernel/bpf/core.c              |  5 ++++
 kernel/bpf/helpers.c           |  2 ++
 kernel/trace/bpf_trace.c       | 52 +++++++++++++++++++++++++++++++++-
 tools/include/uapi/linux/bpf.h | 23 +++++++++++++++
 6 files changed, 105 insertions(+), 1 deletion(-)

diff --git a/include/linux/bpf.h b/include/linux/bpf.h
index be8d57e6e78a..b6c45a6cbbba 100644
--- a/include/linux/bpf.h
+++ b/include/linux/bpf.h
@@ -1088,6 +1088,7 @@ bool bpf_prog_array_compatible(struct bpf_array *array, const struct bpf_prog *f
 int bpf_prog_calc_tag(struct bpf_prog *fp);
 
 const struct bpf_func_proto *bpf_get_trace_printk_proto(void);
+const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void);
 
 typedef unsigned long (*bpf_ctx_copy_t)(void *dst, const void *src,
 					unsigned long off, unsigned long len);
diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
index c4f7892edb2b..899a2649d986 100644
--- a/include/uapi/linux/bpf.h
+++ b/include/uapi/linux/bpf.h
@@ -4871,6 +4871,28 @@ union bpf_attr {
  * 	Return
  *		Value specified by user at BPF link creation/attachment time
  *		or 0, if it was not specified.
+ *
+ * u64 bpf_trace_vprintk(const char *fmt, u32 fmt_size, const void *data, u32 data_len)
+ *	Description
+ *		Behaves like **bpf_trace_printk**\ () helper, but takes an array of u64
+ *		to format. Supports up to 12 arguments to print in this way.
+ *		The *fmt* and *fmt_size* are for the format string itself. The *data* and
+ *		*data_len* are format string arguments.
+ *
+ *		Each format specifier in **fmt** corresponds to one u64 element
+ *		in the **data** array. For strings and pointers where pointees
+ *		are accessed, only the pointer values are stored in the *data*
+ *		array. The *data_len* is the size of *data* in bytes.
+ *		Formats **%s**, **%p{i,I}{4,6}** requires to read kernel memory.
+ *		Reading kernel memory may fail due to either invalid address or
+ *		valid address but requiring a major memory fault. If reading kernel memory
+ *		fails, the string for **%s** will be an empty string, and the ip
+ *		address for **%p{i,I}{4,6}** will be 0. Not returning error to
+ *		bpf program is consistent with what **bpf_trace_printk**\ () does for now.
+ *
+ *	Return
+ *		The number of bytes written to the buffer, or a negative error
+ *		in case of failure.
  */
 #define __BPF_FUNC_MAPPER(FN)		\
 	FN(unspec),			\
@@ -5048,6 +5070,7 @@ union bpf_attr {
 	FN(timer_cancel),		\
 	FN(get_func_ip),		\
 	FN(get_attach_cookie),		\
+	FN(trace_vprintk),		\
 	/* */
 
 /* integer value in 'imm' field of BPF_CALL instruction selects which helper
diff --git a/kernel/bpf/core.c b/kernel/bpf/core.c
index 91f24c7b38a1..a137c550046c 100644
--- a/kernel/bpf/core.c
+++ b/kernel/bpf/core.c
@@ -2357,6 +2357,11 @@ const struct bpf_func_proto * __weak bpf_get_trace_printk_proto(void)
 	return NULL;
 }
 
+const struct bpf_func_proto * __weak bpf_get_trace_vprintk_proto(void)
+{
+	return NULL;
+}
+
 u64 __weak
 bpf_event_output(struct bpf_map *map, u64 flags, void *meta, u64 meta_size,
 		 void *ctx, u64 ctx_size, bpf_ctx_copy_t ctx_copy)
diff --git a/kernel/bpf/helpers.c b/kernel/bpf/helpers.c
index 5ce19b376ef7..863e5ee68558 100644
--- a/kernel/bpf/helpers.c
+++ b/kernel/bpf/helpers.c
@@ -1419,6 +1419,8 @@ bpf_base_func_proto(enum bpf_func_id func_id)
 		return &bpf_snprintf_btf_proto;
 	case BPF_FUNC_snprintf:
 		return &bpf_snprintf_proto;
+	case BPF_FUNC_trace_vprintk:
+		return bpf_get_trace_vprintk_proto();
 	default:
 		return NULL;
 	}
diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
index 2cf4bfa1ab7b..8b3f1ec9e082 100644
--- a/kernel/trace/bpf_trace.c
+++ b/kernel/trace/bpf_trace.c
@@ -398,7 +398,7 @@ static const struct bpf_func_proto bpf_trace_printk_proto = {
 	.arg2_type	= ARG_CONST_SIZE,
 };
 
-const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
+static __always_inline void __set_printk_clr_event(void)
 {
 	/*
 	 * This program might be calling bpf_trace_printk,
@@ -410,10 +410,58 @@ const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
 	 */
 	if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
 		pr_warn_ratelimited("could not enable bpf_trace_printk events");
+}
 
+const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
+{
+	__set_printk_clr_event();
 	return &bpf_trace_printk_proto;
 }
 
+BPF_CALL_4(bpf_trace_vprintk, char *, fmt, u32, fmt_size, const void *, data,
+	   u32, data_len)
+{
+	static char buf[BPF_TRACE_PRINTK_SIZE];
+	unsigned long flags;
+	int ret, num_args;
+	u32 *bin_args;
+
+	if (data_len & 7 || data_len > MAX_BPRINTF_VARARGS * 8 ||
+	    (data_len && !data))
+		return -EINVAL;
+	num_args = data_len / 8;
+
+	ret = bpf_bprintf_prepare(fmt, fmt_size, data, &bin_args, num_args);
+	if (ret < 0)
+		return ret;
+
+	raw_spin_lock_irqsave(&trace_printk_lock, flags);
+	ret = bstr_printf(buf, sizeof(buf), fmt, bin_args);
+
+	trace_bpf_trace_printk(buf);
+	raw_spin_unlock_irqrestore(&trace_printk_lock, flags);
+
+	bpf_bprintf_cleanup();
+
+	return ret;
+}
+
+static const struct bpf_func_proto bpf_trace_vprintk_proto = {
+	.func		= bpf_trace_vprintk,
+	.gpl_only	= true,
+	.ret_type	= RET_INTEGER,
+	.arg1_type	= ARG_PTR_TO_MEM,
+	.arg2_type	= ARG_CONST_SIZE,
+	.arg3_type	= ARG_PTR_TO_MEM_OR_NULL,
+	.arg4_type	= ARG_CONST_SIZE_OR_ZERO,
+};
+
+const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void)
+{
+	__set_printk_clr_event();
+	return &bpf_trace_vprintk_proto;
+}
+
 BPF_CALL_5(bpf_seq_printf, struct seq_file *, m, char *, fmt, u32, fmt_size,
 	   const void *, data, u32, data_len)
 {
@@ -1113,6 +1161,8 @@ bpf_tracing_func_proto(enum bpf_func_id func_id, const struct bpf_prog *prog)
 		return &bpf_snprintf_proto;
 	case BPF_FUNC_get_func_ip:
 		return &bpf_get_func_ip_proto_tracing;
+	case BPF_FUNC_trace_vprintk:
+		return bpf_get_trace_vprintk_proto();
 	default:
 		return bpf_base_func_proto(func_id);
 	}
diff --git a/tools/include/uapi/linux/bpf.h b/tools/include/uapi/linux/bpf.h
index c4f7892edb2b..899a2649d986 100644
--- a/tools/include/uapi/linux/bpf.h
+++ b/tools/include/uapi/linux/bpf.h
@@ -4871,6 +4871,28 @@ union bpf_attr {
  * 	Return
  *		Value specified by user at BPF link creation/attachment time
  *		or 0, if it was not specified.
+ *
+ * u64 bpf_trace_vprintk(const char *fmt, u32 fmt_size, const void *data, u32 data_len)
+ *	Description
+ *		Behaves like **bpf_trace_printk**\ () helper, but takes an array of u64
+ *		to format. Supports up to 12 arguments to print in this way.
+ *		The *fmt* and *fmt_size* are for the format string itself. The *data* and
+ *		*data_len* are format string arguments.
+ *
+ *		Each format specifier in **fmt** corresponds to one u64 element
+ *		in the **data** array. For strings and pointers where pointees
+ *		are accessed, only the pointer values are stored in the *data*
+ *		array. The *data_len* is the size of *data* in bytes.
+ *		Formats **%s**, **%p{i,I}{4,6}** requires to read kernel memory.
+ *		Reading kernel memory may fail due to either invalid address or
+ *		valid address but requiring a major memory fault. If reading kernel memory
+ *		fails, the string for **%s** will be an empty string, and the ip
+ *		address for **%p{i,I}{4,6}** will be 0. Not returning error to
+ *		bpf program is consistent with what **bpf_trace_printk**\ () does for now.
+ *
+ *	Return
+ *		The number of bytes written to the buffer, or a negative error
+ *		in case of failure.
  */
 #define __BPF_FUNC_MAPPER(FN)		\
 	FN(unspec),			\
@@ -5048,6 +5070,7 @@ union bpf_attr {
 	FN(timer_cancel),		\
 	FN(get_func_ip),		\
 	FN(get_attach_cookie),		\
+	FN(trace_vprintk),		\
 	/* */
 
 /* integer value in 'imm' field of BPF_CALL instruction selects which helper
-- 
2.30.2

Re: [PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Andrii Nakryiko]

On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
>
> This helper is meant to be "bpf_trace_printk, but with proper vararg

We have bpf_snprintf() and bpf_seq_printf() names for other BPF
helpers using the same approach. How about we call this one simply
`bpf_printf`? It will be in line with other naming, it is logical BPF
equivalent of user-space printf (which outputs to stderr, which in BPF
land is /sys/kernel/debug/tracing/trace_pipe). And it will be logical
to have a nice and short BPF_PRINTF() convenience macro provided by
libbpf.

> support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> array. Write to dmesg using the same mechanism as bpf_trace_printk.

Are you sure about the dmesg part?... bpf_trace_printk is outputting
into /sys/kernel/debug/tracing/trace_pipe.

>
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---
>  include/linux/bpf.h            |  1 +
>  include/uapi/linux/bpf.h       | 23 +++++++++++++++
>  kernel/bpf/core.c              |  5 ++++
>  kernel/bpf/helpers.c           |  2 ++
>  kernel/trace/bpf_trace.c       | 52 +++++++++++++++++++++++++++++++++-
>  tools/include/uapi/linux/bpf.h | 23 +++++++++++++++
>  6 files changed, 105 insertions(+), 1 deletion(-)
>
> diff --git a/include/linux/bpf.h b/include/linux/bpf.h
> index be8d57e6e78a..b6c45a6cbbba 100644
> --- a/include/linux/bpf.h
> +++ b/include/linux/bpf.h
> @@ -1088,6 +1088,7 @@ bool bpf_prog_array_compatible(struct bpf_array *array, const struct bpf_prog *f
>  int bpf_prog_calc_tag(struct bpf_prog *fp);
>
>  const struct bpf_func_proto *bpf_get_trace_printk_proto(void);
> +const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void);
>
>  typedef unsigned long (*bpf_ctx_copy_t)(void *dst, const void *src,
>                                         unsigned long off, unsigned long len);
> diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
> index c4f7892edb2b..899a2649d986 100644
> --- a/include/uapi/linux/bpf.h
> +++ b/include/uapi/linux/bpf.h
> @@ -4871,6 +4871,28 @@ union bpf_attr {
>   *     Return
>   *             Value specified by user at BPF link creation/attachment time
>   *             or 0, if it was not specified.
> + *
> + * u64 bpf_trace_vprintk(const char *fmt, u32 fmt_size, const void *data, u32 data_len)
> + *     Description
> + *             Behaves like **bpf_trace_printk**\ () helper, but takes an array of u64
> + *             to format. Supports up to 12 arguments to print in this way.

we didn't specify 12 in the description of bpf_snprintf() or
bpf_seq_printf(), so why start doing that here? For data/args format,
let's just refer to bpf_snprintf() or bpf_seq_printf(), whichever does
a better job explaining this :)


> + *             The *fmt* and *fmt_size* are for the format string itself. The *data* and
> + *             *data_len* are format string arguments.
> + *
> + *             Each format specifier in **fmt** corresponds to one u64 element
> + *             in the **data** array. For strings and pointers where pointees
> + *             are accessed, only the pointer values are stored in the *data*
> + *             array. The *data_len* is the size of *data* in bytes.
> + *             Formats **%s**, **%p{i,I}{4,6}** requires to read kernel memory.
> + *             Reading kernel memory may fail due to either invalid address or
> + *             valid address but requiring a major memory fault. If reading kernel memory
> + *             fails, the string for **%s** will be an empty string, and the ip
> + *             address for **%p{i,I}{4,6}** will be 0. Not returning error to
> + *             bpf program is consistent with what **bpf_trace_printk**\ () does for now.

This is just a copy/paste from other helpers. Let's avoid duplication
and just point people to a description in other helpers.

> + *
> + *     Return
> + *             The number of bytes written to the buffer, or a negative error
> + *             in case of failure.
>   */
>  #define __BPF_FUNC_MAPPER(FN)          \
>         FN(unspec),                     \
> @@ -5048,6 +5070,7 @@ union bpf_attr {
>         FN(timer_cancel),               \
>         FN(get_func_ip),                \
>         FN(get_attach_cookie),          \
> +       FN(trace_vprintk),              \
>         /* */
>
>  /* integer value in 'imm' field of BPF_CALL instruction selects which helper
> diff --git a/kernel/bpf/core.c b/kernel/bpf/core.c
> index 91f24c7b38a1..a137c550046c 100644
> --- a/kernel/bpf/core.c
> +++ b/kernel/bpf/core.c
> @@ -2357,6 +2357,11 @@ const struct bpf_func_proto * __weak bpf_get_trace_printk_proto(void)
>         return NULL;
>  }
>
> +const struct bpf_func_proto * __weak bpf_get_trace_vprintk_proto(void)
> +{
> +       return NULL;
> +}
> +
>  u64 __weak
>  bpf_event_output(struct bpf_map *map, u64 flags, void *meta, u64 meta_size,
>                  void *ctx, u64 ctx_size, bpf_ctx_copy_t ctx_copy)
> diff --git a/kernel/bpf/helpers.c b/kernel/bpf/helpers.c
> index 5ce19b376ef7..863e5ee68558 100644
> --- a/kernel/bpf/helpers.c
> +++ b/kernel/bpf/helpers.c
> @@ -1419,6 +1419,8 @@ bpf_base_func_proto(enum bpf_func_id func_id)
>                 return &bpf_snprintf_btf_proto;
>         case BPF_FUNC_snprintf:
>                 return &bpf_snprintf_proto;
> +       case BPF_FUNC_trace_vprintk:
> +               return bpf_get_trace_vprintk_proto();
>         default:
>                 return NULL;
>         }
> diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> index 2cf4bfa1ab7b..8b3f1ec9e082 100644
> --- a/kernel/trace/bpf_trace.c
> +++ b/kernel/trace/bpf_trace.c
> @@ -398,7 +398,7 @@ static const struct bpf_func_proto bpf_trace_printk_proto = {
>         .arg2_type      = ARG_CONST_SIZE,
>  };
>
> -const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
> +static __always_inline void __set_printk_clr_event(void)

Please drop __always_inline, we only use __always_inline for
absolutely performance critical routines. Let the compiler decide.

>  {
>         /*
>          * This program might be calling bpf_trace_printk,
> @@ -410,10 +410,58 @@ const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
>          */
>         if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
>                 pr_warn_ratelimited("could not enable bpf_trace_printk events");
> +}
>
> +const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
> +{
> +       __set_printk_clr_event();
>         return &bpf_trace_printk_proto;
>  }
>
> +BPF_CALL_4(bpf_trace_vprintk, char *, fmt, u32, fmt_size, const void *, data,
> +          u32, data_len)
> +{
> +       static char buf[BPF_TRACE_PRINTK_SIZE];
> +       unsigned long flags;
> +       int ret, num_args;
> +       u32 *bin_args;
> +
> +       if (data_len & 7 || data_len > MAX_BPRINTF_VARARGS * 8 ||
> +           (data_len && !data))
> +               return -EINVAL;
> +       num_args = data_len / 8;
> +
> +       ret = bpf_bprintf_prepare(fmt, fmt_size, data, &bin_args, num_args);
> +       if (ret < 0)
> +               return ret;
> +
> +       raw_spin_lock_irqsave(&trace_printk_lock, flags);
> +       ret = bstr_printf(buf, sizeof(buf), fmt, bin_args);
> +
> +       trace_bpf_trace_printk(buf);
> +       raw_spin_unlock_irqrestore(&trace_printk_lock, flags);
> +
> +       bpf_bprintf_cleanup();
> +
> +       return ret;
> +}
> +
> +static const struct bpf_func_proto bpf_trace_vprintk_proto = {
> +       .func           = bpf_trace_vprintk,
> +       .gpl_only       = true,
> +       .ret_type       = RET_INTEGER,
> +       .arg1_type      = ARG_PTR_TO_MEM,
> +       .arg2_type      = ARG_CONST_SIZE,
> +       .arg3_type      = ARG_PTR_TO_MEM_OR_NULL,
> +       .arg4_type      = ARG_CONST_SIZE_OR_ZERO,
> +};
> +
> +const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void)
> +{
> +       __set_printk_clr_event();
> +       return &bpf_trace_vprintk_proto;
> +}
> +
>  BPF_CALL_5(bpf_seq_printf, struct seq_file *, m, char *, fmt, u32, fmt_size,
>            const void *, data, u32, data_len)
>  {
> @@ -1113,6 +1161,8 @@ bpf_tracing_func_proto(enum bpf_func_id func_id, const struct bpf_prog *prog)
>                 return &bpf_snprintf_proto;
>         case BPF_FUNC_get_func_ip:
>                 return &bpf_get_func_ip_proto_tracing;
> +       case BPF_FUNC_trace_vprintk:
> +               return bpf_get_trace_vprintk_proto();
>         default:
>                 return bpf_base_func_proto(func_id);
>         }
> diff --git a/tools/include/uapi/linux/bpf.h b/tools/include/uapi/linux/bpf.h
> index c4f7892edb2b..899a2649d986 100644
> --- a/tools/include/uapi/linux/bpf.h
> +++ b/tools/include/uapi/linux/bpf.h
> @@ -4871,6 +4871,28 @@ union bpf_attr {
>   *     Return
>   *             Value specified by user at BPF link creation/attachment time
>   *             or 0, if it was not specified.
> + *
> + * u64 bpf_trace_vprintk(const char *fmt, u32 fmt_size, const void *data, u32 data_len)
> + *     Description
> + *             Behaves like **bpf_trace_printk**\ () helper, but takes an array of u64
> + *             to format. Supports up to 12 arguments to print in this way.
> + *             The *fmt* and *fmt_size* are for the format string itself. The *data* and
> + *             *data_len* are format string arguments.
> + *
> + *             Each format specifier in **fmt** corresponds to one u64 element
> + *             in the **data** array. For strings and pointers where pointees
> + *             are accessed, only the pointer values are stored in the *data*
> + *             array. The *data_len* is the size of *data* in bytes.
> + *             Formats **%s**, **%p{i,I}{4,6}** requires to read kernel memory.
> + *             Reading kernel memory may fail due to either invalid address or
> + *             valid address but requiring a major memory fault. If reading kernel memory
> + *             fails, the string for **%s** will be an empty string, and the ip
> + *             address for **%p{i,I}{4,6}** will be 0. Not returning error to
> + *             bpf program is consistent with what **bpf_trace_printk**\ () does for now.
> + *
> + *     Return
> + *             The number of bytes written to the buffer, or a negative error
> + *             in case of failure.
>   */
>  #define __BPF_FUNC_MAPPER(FN)          \
>         FN(unspec),                     \
> @@ -5048,6 +5070,7 @@ union bpf_attr {
>         FN(timer_cancel),               \
>         FN(get_func_ip),                \
>         FN(get_attach_cookie),          \
> +       FN(trace_vprintk),              \
>         /* */
>
>  /* integer value in 'imm' field of BPF_CALL instruction selects which helper
> --
> 2.30.2
>

Re: [PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Alexei Starovoitov]

On Mon, Aug 23, 2021 at 9:50 PM Andrii Nakryiko
<andrii.nakryiko@gmail.com> wrote:
>
> On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
> >
> > This helper is meant to be "bpf_trace_printk, but with proper vararg
>
> We have bpf_snprintf() and bpf_seq_printf() names for other BPF
> helpers using the same approach. How about we call this one simply
> `bpf_printf`? It will be in line with other naming, it is logical BPF
> equivalent of user-space printf (which outputs to stderr, which in BPF
> land is /sys/kernel/debug/tracing/trace_pipe). And it will be logical
> to have a nice and short BPF_PRINTF() convenience macro provided by
> libbpf.
>
> > support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> > array. Write to dmesg using the same mechanism as bpf_trace_printk.
>
> Are you sure about the dmesg part?... bpf_trace_printk is outputting
> into /sys/kernel/debug/tracing/trace_pipe.

Actually I like bpf_trace_vprintk() name, since it makes it obvious that
it's a flavor of bpf_trace_printk() and its quirks that users learned
to deal with.
I would reserve bpf_printf() for the future. We might have standalone
bpf programs in the future (without user space component) and a better
equivalent
of stdin/stdout. clang -target bpf hello_world.c -o a.out; ./a.out
should print to a terminal. Such future hello world in bpf would be
using bpf_printf()
or bpf_dprintf().

Re: [PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Andrii Nakryiko]

On Tue, Aug 24, 2021 at 10:57 AM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Mon, Aug 23, 2021 at 9:50 PM Andrii Nakryiko
> <andrii.nakryiko@gmail.com> wrote:
> >
> > On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
> > >
> > > This helper is meant to be "bpf_trace_printk, but with proper vararg
> >
> > We have bpf_snprintf() and bpf_seq_printf() names for other BPF
> > helpers using the same approach. How about we call this one simply
> > `bpf_printf`? It will be in line with other naming, it is logical BPF
> > equivalent of user-space printf (which outputs to stderr, which in BPF
> > land is /sys/kernel/debug/tracing/trace_pipe). And it will be logical
> > to have a nice and short BPF_PRINTF() convenience macro provided by
> > libbpf.
> >
> > > support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> > > array. Write to dmesg using the same mechanism as bpf_trace_printk.
> >
> > Are you sure about the dmesg part?... bpf_trace_printk is outputting
> > into /sys/kernel/debug/tracing/trace_pipe.
>
> Actually I like bpf_trace_vprintk() name, since it makes it obvious that

It's the inconsistency with bpf_snprintf() and bpf_seq_printf() that's
mildly annoying (it's f at the end, and no v- prefix). Maybe
bpf_trace_printf() then? Or is it too close to bpf_trace_printk()? But
either way you would be using BPF_PRINTF() macro for this. And we can
make that macro use bpf_trace_printk() transparently for <3 args, so
that new macro works on old kernels.

> it's a flavor of bpf_trace_printk() and its quirks that users learned
> to deal with.
> I would reserve bpf_printf() for the future. We might have standalone
> bpf programs in the future (without user space component) and a better
> equivalent
> of stdin/stdout. clang -target bpf hello_world.c -o a.out; ./a.out
> should print to a terminal. Such future hello world in bpf would be
> using bpf_printf()
> or bpf_dprintf().

Re: [PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Alexei Starovoitov]

On Tue, Aug 24, 2021 at 11:02 AM Andrii Nakryiko
<andrii.nakryiko@gmail.com> wrote:
>
> On Tue, Aug 24, 2021 at 10:57 AM Alexei Starovoitov
> <alexei.starovoitov@gmail.com> wrote:
> >
> > On Mon, Aug 23, 2021 at 9:50 PM Andrii Nakryiko
> > <andrii.nakryiko@gmail.com> wrote:
> > >
> > > On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
> > > >
> > > > This helper is meant to be "bpf_trace_printk, but with proper vararg
> > >
> > > We have bpf_snprintf() and bpf_seq_printf() names for other BPF
> > > helpers using the same approach. How about we call this one simply
> > > `bpf_printf`? It will be in line with other naming, it is logical BPF
> > > equivalent of user-space printf (which outputs to stderr, which in BPF
> > > land is /sys/kernel/debug/tracing/trace_pipe). And it will be logical
> > > to have a nice and short BPF_PRINTF() convenience macro provided by
> > > libbpf.
> > >
> > > > support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> > > > array. Write to dmesg using the same mechanism as bpf_trace_printk.
> > >
> > > Are you sure about the dmesg part?... bpf_trace_printk is outputting
> > > into /sys/kernel/debug/tracing/trace_pipe.
> >
> > Actually I like bpf_trace_vprintk() name, since it makes it obvious that
>
> It's the inconsistency with bpf_snprintf() and bpf_seq_printf() that's
> mildly annoying (it's f at the end, and no v- prefix). Maybe
> bpf_trace_printf() then? Or is it too close to bpf_trace_printk()?

bpf_trace_printf could be ok, but see below.

> But
> either way you would be using BPF_PRINTF() macro for this. And we can
> make that macro use bpf_trace_printk() transparently for <3 args, so
> that new macro works on old kernels.

Cannot we change the existing bpf_printk() macro to work on old and new kernels?
So bpf_printk() would use bpf_trace_printf() on new and
bpf_trace_printk() on old?
I think bpf_trace_vprintk() looks cleaner in this context if we reuse
bpf_printk() macro.

Re: [PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Andrii Nakryiko]

On Tue, Aug 24, 2021 at 11:17 AM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Tue, Aug 24, 2021 at 11:02 AM Andrii Nakryiko
> <andrii.nakryiko@gmail.com> wrote:
> >
> > On Tue, Aug 24, 2021 at 10:57 AM Alexei Starovoitov
> > <alexei.starovoitov@gmail.com> wrote:
> > >
> > > On Mon, Aug 23, 2021 at 9:50 PM Andrii Nakryiko
> > > <andrii.nakryiko@gmail.com> wrote:
> > > >
> > > > On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
> > > > >
> > > > > This helper is meant to be "bpf_trace_printk, but with proper vararg
> > > >
> > > > We have bpf_snprintf() and bpf_seq_printf() names for other BPF
> > > > helpers using the same approach. How about we call this one simply
> > > > `bpf_printf`? It will be in line with other naming, it is logical BPF
> > > > equivalent of user-space printf (which outputs to stderr, which in BPF
> > > > land is /sys/kernel/debug/tracing/trace_pipe). And it will be logical
> > > > to have a nice and short BPF_PRINTF() convenience macro provided by
> > > > libbpf.
> > > >
> > > > > support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> > > > > array. Write to dmesg using the same mechanism as bpf_trace_printk.
> > > >
> > > > Are you sure about the dmesg part?... bpf_trace_printk is outputting
> > > > into /sys/kernel/debug/tracing/trace_pipe.
> > >
> > > Actually I like bpf_trace_vprintk() name, since it makes it obvious that
> >
> > It's the inconsistency with bpf_snprintf() and bpf_seq_printf() that's
> > mildly annoying (it's f at the end, and no v- prefix). Maybe
> > bpf_trace_printf() then? Or is it too close to bpf_trace_printk()?
>
> bpf_trace_printf could be ok, but see below.
>
> > But
> > either way you would be using BPF_PRINTF() macro for this. And we can
> > make that macro use bpf_trace_printk() transparently for <3 args, so
> > that new macro works on old kernels.
>
> Cannot we change the existing bpf_printk() macro to work on old and new kernels?

Only if we break backwards compatibility. And I only know how to
detect the presence of new helper with CO-RE, which automatically
makes any BPF program using this macro CO-RE-dependent, which might
not be what users want (vmlinux BTF is still not universally
available). If I could do something like that without breaking change
and without CO-RE, I'd update bpf_printk() to use `const char *fmt`
for format string a long time ago. But adding CO-RE dependency for
bpf_printk() seems like a no-go.

> So bpf_printk() would use bpf_trace_printf() on new and
> bpf_trace_printk() on old?
> I think bpf_trace_vprintk() looks cleaner in this context if we reuse
> bpf_printk() macro.

Re: [PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Alexei Starovoitov]

On Tue, Aug 24, 2021 at 11:24 AM Andrii Nakryiko
<andrii.nakryiko@gmail.com> wrote:
>
> On Tue, Aug 24, 2021 at 11:17 AM Alexei Starovoitov
> <alexei.starovoitov@gmail.com> wrote:
> >
> > On Tue, Aug 24, 2021 at 11:02 AM Andrii Nakryiko
> > <andrii.nakryiko@gmail.com> wrote:
> > >
> > > On Tue, Aug 24, 2021 at 10:57 AM Alexei Starovoitov
> > > <alexei.starovoitov@gmail.com> wrote:
> > > >
> > > > On Mon, Aug 23, 2021 at 9:50 PM Andrii Nakryiko
> > > > <andrii.nakryiko@gmail.com> wrote:
> > > > >
> > > > > On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
> > > > > >
> > > > > > This helper is meant to be "bpf_trace_printk, but with proper vararg
> > > > >
> > > > > We have bpf_snprintf() and bpf_seq_printf() names for other BPF
> > > > > helpers using the same approach. How about we call this one simply
> > > > > `bpf_printf`? It will be in line with other naming, it is logical BPF
> > > > > equivalent of user-space printf (which outputs to stderr, which in BPF
> > > > > land is /sys/kernel/debug/tracing/trace_pipe). And it will be logical
> > > > > to have a nice and short BPF_PRINTF() convenience macro provided by
> > > > > libbpf.
> > > > >
> > > > > > support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> > > > > > array. Write to dmesg using the same mechanism as bpf_trace_printk.
> > > > >
> > > > > Are you sure about the dmesg part?... bpf_trace_printk is outputting
> > > > > into /sys/kernel/debug/tracing/trace_pipe.
> > > >
> > > > Actually I like bpf_trace_vprintk() name, since it makes it obvious that
> > >
> > > It's the inconsistency with bpf_snprintf() and bpf_seq_printf() that's
> > > mildly annoying (it's f at the end, and no v- prefix). Maybe
> > > bpf_trace_printf() then? Or is it too close to bpf_trace_printk()?
> >
> > bpf_trace_printf could be ok, but see below.
> >
> > > But
> > > either way you would be using BPF_PRINTF() macro for this. And we can
> > > make that macro use bpf_trace_printk() transparently for <3 args, so
> > > that new macro works on old kernels.
> >
> > Cannot we change the existing bpf_printk() macro to work on old and new kernels?
>
> Only if we break backwards compatibility. And I only know how to
> detect the presence of new helper with CO-RE, which automatically
> makes any BPF program using this macro CO-RE-dependent, which might
> not be what users want (vmlinux BTF is still not universally
> available). If I could do something like that without breaking change
> and without CO-RE, I'd update bpf_printk() to use `const char *fmt`
> for format string a long time ago. But adding CO-RE dependency for
> bpf_printk() seems like a no-go.

I see. Naming is the hardest.
I think Dave's current choice of lower case bpf_vprintk() macro and
bpf_trace_vprintk()
helper fits the existing bpf_printk/bpf_trace_printk the best.
Yes, it's inconsistent with BPF_SEQ_PRINTF/BPF_SNPRINTF,
but consistent with trace_printk. Whichever way we go it will be inconsistent.
Stylistically I like the lower case macro, since it doesn't scream at me.

Re: [PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Andrii Nakryiko]

On Tue, Aug 24, 2021 at 2:00 PM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Tue, Aug 24, 2021 at 11:24 AM Andrii Nakryiko
> <andrii.nakryiko@gmail.com> wrote:
> >
> > On Tue, Aug 24, 2021 at 11:17 AM Alexei Starovoitov
> > <alexei.starovoitov@gmail.com> wrote:
> > >
> > > On Tue, Aug 24, 2021 at 11:02 AM Andrii Nakryiko
> > > <andrii.nakryiko@gmail.com> wrote:
> > > >
> > > > On Tue, Aug 24, 2021 at 10:57 AM Alexei Starovoitov
> > > > <alexei.starovoitov@gmail.com> wrote:
> > > > >
> > > > > On Mon, Aug 23, 2021 at 9:50 PM Andrii Nakryiko
> > > > > <andrii.nakryiko@gmail.com> wrote:
> > > > > >
> > > > > > On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
> > > > > > >
> > > > > > > This helper is meant to be "bpf_trace_printk, but with proper vararg
> > > > > >
> > > > > > We have bpf_snprintf() and bpf_seq_printf() names for other BPF
> > > > > > helpers using the same approach. How about we call this one simply
> > > > > > `bpf_printf`? It will be in line with other naming, it is logical BPF
> > > > > > equivalent of user-space printf (which outputs to stderr, which in BPF
> > > > > > land is /sys/kernel/debug/tracing/trace_pipe). And it will be logical
> > > > > > to have a nice and short BPF_PRINTF() convenience macro provided by
> > > > > > libbpf.
> > > > > >
> > > > > > > support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> > > > > > > array. Write to dmesg using the same mechanism as bpf_trace_printk.
> > > > > >
> > > > > > Are you sure about the dmesg part?... bpf_trace_printk is outputting
> > > > > > into /sys/kernel/debug/tracing/trace_pipe.
> > > > >
> > > > > Actually I like bpf_trace_vprintk() name, since it makes it obvious that
> > > >
> > > > It's the inconsistency with bpf_snprintf() and bpf_seq_printf() that's
> > > > mildly annoying (it's f at the end, and no v- prefix). Maybe
> > > > bpf_trace_printf() then? Or is it too close to bpf_trace_printk()?
> > >
> > > bpf_trace_printf could be ok, but see below.
> > >
> > > > But
> > > > either way you would be using BPF_PRINTF() macro for this. And we can
> > > > make that macro use bpf_trace_printk() transparently for <3 args, so
> > > > that new macro works on old kernels.
> > >
> > > Cannot we change the existing bpf_printk() macro to work on old and new kernels?
> >
> > Only if we break backwards compatibility. And I only know how to
> > detect the presence of new helper with CO-RE, which automatically
> > makes any BPF program using this macro CO-RE-dependent, which might
> > not be what users want (vmlinux BTF is still not universally
> > available). If I could do something like that without breaking change
> > and without CO-RE, I'd update bpf_printk() to use `const char *fmt`
> > for format string a long time ago. But adding CO-RE dependency for
> > bpf_printk() seems like a no-go.
>
> I see. Naming is the hardest.
> I think Dave's current choice of lower case bpf_vprintk() macro and
> bpf_trace_vprintk()
> helper fits the existing bpf_printk/bpf_trace_printk the best.
> Yes, it's inconsistent with BPF_SEQ_PRINTF/BPF_SNPRINTF,
> but consistent with trace_printk. Whichever way we go it will be inconsistent.
> Stylistically I like the lower case macro, since it doesn't scream at me.

Ok, it's fine. Even more so because we don't need a new macro, we can
just extend the existing bpf_printk() macro to automatically pick
bpf_trace_printk() if more than 3 arguments is provided.

Dave, you'll have to solve a bit of a puzzle macro-wise, but it's
possible to use either bpf_trace_printk() or bpf_trace_vprintk()
transparently for the user.

The only downside is that for <3 args, for backwards compatibility,
we'd have to stick to

char ___fmt[] = fmt;

vs more efficient

static const char ___fmt[] = fmt;

But I'm thinking it might be time to finally make this improvement. We
can also allow users to fallback to less efficient ways for really old
kernels with some extra flag, like so

#ifdef BPF_NO_GLOBAL_DATA
char ___fmt[] = fmt;
#else
static const char ___fmt[] = fmt;
#end

Thoughts?

Re: [PATCH bpf-next 2/5] bpf: add bpf_trace_vprintk helper

[Alexei Starovoitov]

On Tue, Aug 24, 2021 at 2:24 PM Andrii Nakryiko
<andrii.nakryiko@gmail.com> wrote:
>
> On Tue, Aug 24, 2021 at 2:00 PM Alexei Starovoitov
> <alexei.starovoitov@gmail.com> wrote:
> >
> > On Tue, Aug 24, 2021 at 11:24 AM Andrii Nakryiko
> > <andrii.nakryiko@gmail.com> wrote:
> > >
> > > On Tue, Aug 24, 2021 at 11:17 AM Alexei Starovoitov
> > > <alexei.starovoitov@gmail.com> wrote:
> > > >
> > > > On Tue, Aug 24, 2021 at 11:02 AM Andrii Nakryiko
> > > > <andrii.nakryiko@gmail.com> wrote:
> > > > >
> > > > > On Tue, Aug 24, 2021 at 10:57 AM Alexei Starovoitov
> > > > > <alexei.starovoitov@gmail.com> wrote:
> > > > > >
> > > > > > On Mon, Aug 23, 2021 at 9:50 PM Andrii Nakryiko
> > > > > > <andrii.nakryiko@gmail.com> wrote:
> > > > > > >
> > > > > > > On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
> > > > > > > >
> > > > > > > > This helper is meant to be "bpf_trace_printk, but with proper vararg
> > > > > > >
> > > > > > > We have bpf_snprintf() and bpf_seq_printf() names for other BPF
> > > > > > > helpers using the same approach. How about we call this one simply
> > > > > > > `bpf_printf`? It will be in line with other naming, it is logical BPF
> > > > > > > equivalent of user-space printf (which outputs to stderr, which in BPF
> > > > > > > land is /sys/kernel/debug/tracing/trace_pipe). And it will be logical
> > > > > > > to have a nice and short BPF_PRINTF() convenience macro provided by
> > > > > > > libbpf.
> > > > > > >
> > > > > > > > support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> > > > > > > > array. Write to dmesg using the same mechanism as bpf_trace_printk.
> > > > > > >
> > > > > > > Are you sure about the dmesg part?... bpf_trace_printk is outputting
> > > > > > > into /sys/kernel/debug/tracing/trace_pipe.
> > > > > >
> > > > > > Actually I like bpf_trace_vprintk() name, since it makes it obvious that
> > > > >
> > > > > It's the inconsistency with bpf_snprintf() and bpf_seq_printf() that's
> > > > > mildly annoying (it's f at the end, and no v- prefix). Maybe
> > > > > bpf_trace_printf() then? Or is it too close to bpf_trace_printk()?
> > > >
> > > > bpf_trace_printf could be ok, but see below.
> > > >
> > > > > But
> > > > > either way you would be using BPF_PRINTF() macro for this. And we can
> > > > > make that macro use bpf_trace_printk() transparently for <3 args, so
> > > > > that new macro works on old kernels.
> > > >
> > > > Cannot we change the existing bpf_printk() macro to work on old and new kernels?
> > >
> > > Only if we break backwards compatibility. And I only know how to
> > > detect the presence of new helper with CO-RE, which automatically
> > > makes any BPF program using this macro CO-RE-dependent, which might
> > > not be what users want (vmlinux BTF is still not universally
> > > available). If I could do something like that without breaking change
> > > and without CO-RE, I'd update bpf_printk() to use `const char *fmt`
> > > for format string a long time ago. But adding CO-RE dependency for
> > > bpf_printk() seems like a no-go.
> >
> > I see. Naming is the hardest.
> > I think Dave's current choice of lower case bpf_vprintk() macro and
> > bpf_trace_vprintk()
> > helper fits the existing bpf_printk/bpf_trace_printk the best.
> > Yes, it's inconsistent with BPF_SEQ_PRINTF/BPF_SNPRINTF,
> > but consistent with trace_printk. Whichever way we go it will be inconsistent.
> > Stylistically I like the lower case macro, since it doesn't scream at me.
>
> Ok, it's fine. Even more so because we don't need a new macro, we can
> just extend the existing bpf_printk() macro to automatically pick
> bpf_trace_printk() if more than 3 arguments is provided.
>
> Dave, you'll have to solve a bit of a puzzle macro-wise, but it's
> possible to use either bpf_trace_printk() or bpf_trace_vprintk()
> transparently for the user.
>
> The only downside is that for <3 args, for backwards compatibility,
> we'd have to stick to
>
> char ___fmt[] = fmt;
>
> vs more efficient
>
> static const char ___fmt[] = fmt;
>
> But I'm thinking it might be time to finally make this improvement. We
> can also allow users to fallback to less efficient ways for really old
> kernels with some extra flag, like so
>
> #ifdef BPF_NO_GLOBAL_DATA
> char ___fmt[] = fmt;
> #else
> static const char ___fmt[] = fmt;
> #end
>
> Thoughts?

+1 from me for the latter assuming macro magic is possible.

[PATCH bpf-next 3/5] libbpf: Add bpf_vprintk convenience macro

[Dave Marchevsky]

bpf_vprintk functions similarly to BPF_SEQ_PRINTF and BPF_SNPRINTF
macros elsewhere in the file - it allows use of bpf_trace_vprintk
without manual conversion of varargs to u64 array.

Like the bpf_printk macro, bpf_vprintk is meant to be the main interface
to the bpf_trace_vprintk helper and thus is uncapitalized.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 tools/lib/bpf/bpf_helpers.h | 18 ++++++++++++++++++
 1 file changed, 18 insertions(+)

diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
index b9987c3efa3c..43c8115956c3 100644
--- a/tools/lib/bpf/bpf_helpers.h
+++ b/tools/lib/bpf/bpf_helpers.h
@@ -224,4 +224,22 @@ enum libbpf_tristate {
 		     ___param, sizeof(___param));		\
 })
 
+/*
+ * bpf_vprintk wraps the bpf_trace_printk helper with variadic arguments
+ * instead of an array of u64.
+ */
+#define bpf_vprintk(fmt, args...)				\
+({								\
+	static const char ___fmt[] = fmt;			\
+	unsigned long long ___param[___bpf_narg(args)];		\
+								\
+	_Pragma("GCC diagnostic push")				\
+	_Pragma("GCC diagnostic ignored \"-Wint-conversion\"")	\
+	___bpf_fill(___param, args);				\
+	_Pragma("GCC diagnostic pop")				\
+								\
+	bpf_trace_vprintk(___fmt, sizeof(___fmt),		\
+		     ___param, sizeof(___param));		\
+})
+
 #endif
-- 
2.30.2

Re: [PATCH bpf-next 3/5] libbpf: Add bpf_vprintk convenience macro

[Andrii Nakryiko]

On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
>
> bpf_vprintk functions similarly to BPF_SEQ_PRINTF and BPF_SNPRINTF
> macros elsewhere in the file - it allows use of bpf_trace_vprintk
> without manual conversion of varargs to u64 array.
>
> Like the bpf_printk macro, bpf_vprintk is meant to be the main interface
> to the bpf_trace_vprintk helper and thus is uncapitalized.
>
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---
>  tools/lib/bpf/bpf_helpers.h | 18 ++++++++++++++++++
>  1 file changed, 18 insertions(+)
>
> diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
> index b9987c3efa3c..43c8115956c3 100644
> --- a/tools/lib/bpf/bpf_helpers.h
> +++ b/tools/lib/bpf/bpf_helpers.h
> @@ -224,4 +224,22 @@ enum libbpf_tristate {
>                      ___param, sizeof(___param));               \
>  })
>
> +/*
> + * bpf_vprintk wraps the bpf_trace_printk helper with variadic arguments
> + * instead of an array of u64.
> + */
> +#define bpf_vprintk(fmt, args...)                              \

Given BPF_SNPRINTF and BPF_SEQ_PRINTF, should we call this one in
all-caps as well?

> +({                                                             \
> +       static const char ___fmt[] = fmt;                       \
> +       unsigned long long ___param[___bpf_narg(args)];         \

I wonder how hard would it be to still use bpf_trace_printk() if the
number of input arguments is less than 3? That way you could use
BPF_PRINTF() everywhere, even on old kernels (you just need to
remember to use < 3 arguments). WDYT? It might be more challenging
than it seems, given it's hard to do conditionals inside #defines :(

> +                                                               \
> +       _Pragma("GCC diagnostic push")                          \
> +       _Pragma("GCC diagnostic ignored \"-Wint-conversion\"")  \
> +       ___bpf_fill(___param, args);                            \
> +       _Pragma("GCC diagnostic pop")                           \
> +                                                               \
> +       bpf_trace_vprintk(___fmt, sizeof(___fmt),               \
> +                    ___param, sizeof(___param));               \
> +})
> +
>  #endif
> --
> 2.30.2
>

[PATCH bpf-next 4/5] bpftool: only probe trace_vprintk feature in 'full' mode

[Dave Marchevsky]

Since commit 368cb0e7cdb5e ("bpftool: Make probes which emit dmesg
warnings optional"), some helpers aren't probed by bpftool unless
`full` arg is added to `bpftool feature probe`.

bpf_trace_vprintk can emit dmesg warnings when probed, so include it.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 tools/bpf/bpftool/feature.c                 |  1 +
 tools/testing/selftests/bpf/test_bpftool.py | 22 +++++++++------------
 2 files changed, 10 insertions(+), 13 deletions(-)

diff --git a/tools/bpf/bpftool/feature.c b/tools/bpf/bpftool/feature.c
index 7f36385aa9e2..ade44577688e 100644
--- a/tools/bpf/bpftool/feature.c
+++ b/tools/bpf/bpftool/feature.c
@@ -624,6 +624,7 @@ probe_helpers_for_progtype(enum bpf_prog_type prog_type, bool supported_type,
 		 */
 		switch (id) {
 		case BPF_FUNC_trace_printk:
+		case BPF_FUNC_trace_vprintk:
 		case BPF_FUNC_probe_write_user:
 			if (!full_mode)
 				continue;
diff --git a/tools/testing/selftests/bpf/test_bpftool.py b/tools/testing/selftests/bpf/test_bpftool.py
index 4fed2dc25c0a..1c2408ee1f5d 100644
--- a/tools/testing/selftests/bpf/test_bpftool.py
+++ b/tools/testing/selftests/bpf/test_bpftool.py
@@ -57,6 +57,11 @@ def default_iface(f):
         return f(*args, iface, **kwargs)
     return wrapper
 
+DMESG_EMITTING_HELPERS = [
+        "bpf_probe_write_user",
+        "bpf_trace_printk",
+        "bpf_trace_vprintk",
+    ]
 
 class TestBpftool(unittest.TestCase):
     @classmethod
@@ -67,10 +72,7 @@ class TestBpftool(unittest.TestCase):
 
     @default_iface
     def test_feature_dev_json(self, iface):
-        unexpected_helpers = [
-            "bpf_probe_write_user",
-            "bpf_trace_printk",
-        ]
+        unexpected_helpers = DMESG_EMITTING_HELPERS
         expected_keys = [
             "syscall_config",
             "program_types",
@@ -94,10 +96,7 @@ class TestBpftool(unittest.TestCase):
             bpftool_json(["feature", "probe"]),
             bpftool_json(["feature"]),
         ]
-        unexpected_helpers = [
-            "bpf_probe_write_user",
-            "bpf_trace_printk",
-        ]
+        unexpected_helpers = DMESG_EMITTING_HELPERS
         expected_keys = [
             "syscall_config",
             "system_config",
@@ -121,10 +120,7 @@ class TestBpftool(unittest.TestCase):
             bpftool_json(["feature", "probe", "kernel", "full"]),
             bpftool_json(["feature", "probe", "full"]),
         ]
-        expected_helpers = [
-            "bpf_probe_write_user",
-            "bpf_trace_printk",
-        ]
+        expected_helpers = DMESG_EMITTING_HELPERS
 
         for tc in test_cases:
             # Check if expected helpers are included at least once in any
@@ -157,7 +153,7 @@ class TestBpftool(unittest.TestCase):
                 not_full_set.add(helper)
 
         self.assertCountEqual(full_set - not_full_set,
-                                {"bpf_probe_write_user", "bpf_trace_printk"})
+                              set(DMESG_EMITTING_HELPERS))
         self.assertCountEqual(not_full_set - full_set, set())
 
     def test_feature_macros(self):
-- 
2.30.2

[PATCH bpf-next 5/5] selftests/bpf: add trace_vprintk test prog

[Dave Marchevsky]

This commit adds a test prog for vprintk which confirms that:
  * bpf_trace_vprintk is writing to dmesg
  * bpf_vprintk convenience macro works as expected
  * >3 args are printed

Approach and code are borrowed from trace_printk test.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 tools/testing/selftests/bpf/Makefile          |  3 +-
 .../selftests/bpf/prog_tests/trace_vprintk.c  | 75 +++++++++++++++++++
 .../selftests/bpf/progs/trace_vprintk.c       | 25 +++++++
 3 files changed, 102 insertions(+), 1 deletion(-)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
 create mode 100644 tools/testing/selftests/bpf/progs/trace_vprintk.c

diff --git a/tools/testing/selftests/bpf/Makefile b/tools/testing/selftests/bpf/Makefile
index 2a58b7b5aea4..af5e7a1e9a7c 100644
--- a/tools/testing/selftests/bpf/Makefile
+++ b/tools/testing/selftests/bpf/Makefile
@@ -313,7 +313,8 @@ LINKED_SKELS := test_static_linked.skel.h linked_funcs.skel.h		\
 		linked_vars.skel.h linked_maps.skel.h
 
 LSKELS := kfunc_call_test.c fentry_test.c fexit_test.c fexit_sleep.c \
-	test_ksyms_module.c test_ringbuf.c atomics.c trace_printk.c
+	test_ksyms_module.c test_ringbuf.c atomics.c trace_printk.c \
+	trace_vprintk.c
 SKEL_BLACKLIST += $$(LSKELS)
 
 test_static_linked.skel.h-deps := test_static_linked1.o test_static_linked2.o
diff --git a/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c b/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
new file mode 100644
index 000000000000..fd70427d2918
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
@@ -0,0 +1,75 @@
+// SPDX-License-Identifier: GPL-2.0
+/* Copyright (c) 2021 Facebook */
+
+#include <test_progs.h>
+
+#include "trace_vprintk.lskel.h"
+
+#define TRACEBUF	"/sys/kernel/debug/tracing/trace_pipe"
+#define SEARCHMSG	"1,2,3,4,5,6,7,8,9,10"
+
+void test_trace_vprintk(void)
+{
+	int err, iter = 0, duration = 0, found = 0;
+	struct trace_vprintk__bss *bss;
+	struct trace_vprintk *skel;
+	char *buf = NULL;
+	FILE *fp = NULL;
+	size_t buflen;
+
+	skel = trace_vprintk__open();
+	if (CHECK(!skel, "skel_open", "failed to open skeleton\n"))
+		return;
+
+	err = trace_vprintk__load(skel);
+	if (CHECK(err, "skel_load", "failed to load skeleton: %d\n", err))
+		goto cleanup;
+
+	bss = skel->bss;
+
+	err = trace_vprintk__attach(skel);
+	if (CHECK(err, "skel_attach", "skeleton attach failed: %d\n", err))
+		goto cleanup;
+
+	fp = fopen(TRACEBUF, "r");
+	if (CHECK(fp == NULL, "could not open trace buffer",
+		  "error %d opening %s", errno, TRACEBUF))
+		goto cleanup;
+
+	/* We do not want to wait forever if this test fails... */
+	fcntl(fileno(fp), F_SETFL, O_NONBLOCK);
+
+	/* wait for tracepoint to trigger */
+	usleep(1);
+	trace_vprintk__detach(skel);
+
+	if (CHECK(bss->trace_vprintk_ran == 0,
+		  "bpf_trace_vprintk never ran",
+		  "ran == %d", bss->trace_vprintk_ran))
+		goto cleanup;
+
+	if (CHECK(bss->trace_vprintk_ret <= 0,
+		  "bpf_trace_vprintk returned <= 0 value",
+		  "got %d", bss->trace_vprintk_ret))
+		goto cleanup;
+
+	/* verify our search string is in the trace buffer */
+	while (getline(&buf, &buflen, fp) >= 0 || errno == EAGAIN) {
+		if (strstr(buf, SEARCHMSG) != NULL)
+			found++;
+		if (found == bss->trace_vprintk_ran)
+			break;
+		if (++iter > 1000)
+			break;
+	}
+
+	if (CHECK(!found, "message from bpf_trace_vprintk not found",
+		  "no instance of %s in %s", SEARCHMSG, TRACEBUF))
+		goto cleanup;
+
+cleanup:
+	trace_vprintk__destroy(skel);
+	free(buf);
+	if (fp)
+		fclose(fp);
+}
diff --git a/tools/testing/selftests/bpf/progs/trace_vprintk.c b/tools/testing/selftests/bpf/progs/trace_vprintk.c
new file mode 100644
index 000000000000..993439a19e1e
--- /dev/null
+++ b/tools/testing/selftests/bpf/progs/trace_vprintk.c
@@ -0,0 +1,25 @@
+// SPDX-License-Identifier: GPL-2.0
+/* Copyright (c) 2021 Facebook */
+
+#include "vmlinux.h"
+#include <bpf/bpf_helpers.h>
+#include <bpf/bpf_tracing.h>
+
+char _license[] SEC("license") = "GPL";
+
+int trace_vprintk_ret = 0;
+int trace_vprintk_ran = 0;
+
+SEC("fentry/__x64_sys_nanosleep")
+int sys_enter(void *ctx)
+{
+	static const char one[] = "1";
+	static const char three[] = "3";
+	static const char five[] = "5";
+	static const char seven[] = "7";
+	static const char nine[] = "9";
+
+	trace_vprintk_ret = bpf_vprintk("%s,%d,%s,%d,%s,%d,%s,%d,%s,%d %d\n",
+		one, 2, three, 4, five, 6, seven, 8, nine, 10, ++trace_vprintk_ran);
+	return 0;
+}
-- 
2.30.2

Re: [PATCH bpf-next 5/5] selftests/bpf: add trace_vprintk test prog

[Andrii Nakryiko]

On Fri, Aug 20, 2021 at 7:59 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
>
> This commit adds a test prog for vprintk which confirms that:
>   * bpf_trace_vprintk is writing to dmesg
>   * bpf_vprintk convenience macro works as expected
>   * >3 args are printed
>
> Approach and code are borrowed from trace_printk test.
>
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---
>  tools/testing/selftests/bpf/Makefile          |  3 +-
>  .../selftests/bpf/prog_tests/trace_vprintk.c  | 75 +++++++++++++++++++
>  .../selftests/bpf/progs/trace_vprintk.c       | 25 +++++++
>  3 files changed, 102 insertions(+), 1 deletion(-)
>  create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
>  create mode 100644 tools/testing/selftests/bpf/progs/trace_vprintk.c
>
> diff --git a/tools/testing/selftests/bpf/Makefile b/tools/testing/selftests/bpf/Makefile
> index 2a58b7b5aea4..af5e7a1e9a7c 100644
> --- a/tools/testing/selftests/bpf/Makefile
> +++ b/tools/testing/selftests/bpf/Makefile
> @@ -313,7 +313,8 @@ LINKED_SKELS := test_static_linked.skel.h linked_funcs.skel.h               \
>                 linked_vars.skel.h linked_maps.skel.h
>
>  LSKELS := kfunc_call_test.c fentry_test.c fexit_test.c fexit_sleep.c \
> -       test_ksyms_module.c test_ringbuf.c atomics.c trace_printk.c
> +       test_ksyms_module.c test_ringbuf.c atomics.c trace_printk.c \
> +       trace_vprintk.c
>  SKEL_BLACKLIST += $$(LSKELS)
>
>  test_static_linked.skel.h-deps := test_static_linked1.o test_static_linked2.o
> diff --git a/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c b/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
> new file mode 100644
> index 000000000000..fd70427d2918
> --- /dev/null
> +++ b/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
> @@ -0,0 +1,75 @@
> +// SPDX-License-Identifier: GPL-2.0
> +/* Copyright (c) 2021 Facebook */
> +
> +#include <test_progs.h>
> +
> +#include "trace_vprintk.lskel.h"
> +
> +#define TRACEBUF       "/sys/kernel/debug/tracing/trace_pipe"
> +#define SEARCHMSG      "1,2,3,4,5,6,7,8,9,10"
> +
> +void test_trace_vprintk(void)
> +{
> +       int err, iter = 0, duration = 0, found = 0;
> +       struct trace_vprintk__bss *bss;
> +       struct trace_vprintk *skel;
> +       char *buf = NULL;
> +       FILE *fp = NULL;
> +       size_t buflen;
> +
> +       skel = trace_vprintk__open();
> +       if (CHECK(!skel, "skel_open", "failed to open skeleton\n"))
> +               return;

Let's use ASSERT_xxx() in new tests, no new CHECK() uses.


> +
> +       err = trace_vprintk__load(skel);
> +       if (CHECK(err, "skel_load", "failed to load skeleton: %d\n", err))

you should be able to combine open and load into trace_vprintk__open_and_load()

> +               goto cleanup;
> +
> +       bss = skel->bss;
> +
> +       err = trace_vprintk__attach(skel);
> +       if (CHECK(err, "skel_attach", "skeleton attach failed: %d\n", err))
> +               goto cleanup;
> +

[...]