Commit ac5a72ea authored by Alan Maguire's avatar Alan Maguire Committed by Alexei Starovoitov

bpf: Use dedicated bpf_trace_printk event instead of trace_printk()

The bpf helper bpf_trace_printk() uses trace_printk() under the hood.
This leads to an alarming warning message originating from trace
buffer allocation which occurs the first time a program using
bpf_trace_printk() is loaded.

We can instead create a trace event for bpf_trace_printk() and enable
it in-kernel when/if we encounter a program using the
bpf_trace_printk() helper.  With this approach, trace_printk()
is not used directly and no warning message appears.

This work was started by Steven (see Link) and finished by Alan; added
Steven's Signed-off-by with his permission.
Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: default avatarAlan Maguire <alan.maguire@oracle.com>
Signed-off-by: default avatarAlexei Starovoitov <ast@kernel.org>
Acked-by: default avatarAndrii Nakryiko <andriin@fb.com>
Link: https://lore.kernel.org/r/20200628194334.6238b933@oasis.local.home
Link: https://lore.kernel.org/bpf/1594641154-18897-2-git-send-email-alan.maguire@oracle.com
parent 93776cb9
...@@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE ...@@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE
GCOV_PROFILE := y GCOV_PROFILE := y
endif endif
CFLAGS_bpf_trace.o := -I$(src)
CFLAGS_trace_benchmark.o := -I$(src) CFLAGS_trace_benchmark.o := -I$(src)
CFLAGS_trace_events_filter.o := -I$(src) CFLAGS_trace_events_filter.o := -I$(src)
......
...@@ -11,6 +11,7 @@ ...@@ -11,6 +11,7 @@
#include <linux/uaccess.h> #include <linux/uaccess.h>
#include <linux/ctype.h> #include <linux/ctype.h>
#include <linux/kprobes.h> #include <linux/kprobes.h>
#include <linux/spinlock.h>
#include <linux/syscalls.h> #include <linux/syscalls.h>
#include <linux/error-injection.h> #include <linux/error-injection.h>
#include <linux/btf_ids.h> #include <linux/btf_ids.h>
...@@ -20,6 +21,9 @@ ...@@ -20,6 +21,9 @@
#include "trace_probe.h" #include "trace_probe.h"
#include "trace.h" #include "trace.h"
#define CREATE_TRACE_POINTS
#include "bpf_trace.h"
#define bpf_event_rcu_dereference(p) \ #define bpf_event_rcu_dereference(p) \
rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex)) rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex))
...@@ -375,6 +379,30 @@ static void bpf_trace_copy_string(char *buf, void *unsafe_ptr, char fmt_ptype, ...@@ -375,6 +379,30 @@ static void bpf_trace_copy_string(char *buf, void *unsafe_ptr, char fmt_ptype,
} }
} }
static DEFINE_RAW_SPINLOCK(trace_printk_lock);
#define BPF_TRACE_PRINTK_SIZE 1024
static inline __printf(1, 0) int bpf_do_trace_printk(const char *fmt, ...)
{
static char buf[BPF_TRACE_PRINTK_SIZE];
unsigned long flags;
va_list ap;
int ret;
raw_spin_lock_irqsave(&trace_printk_lock, flags);
va_start(ap, fmt);
ret = vsnprintf(buf, sizeof(buf), fmt, ap);
va_end(ap);
/* vsnprintf() will not append null for zero-length strings */
if (ret == 0)
buf[0] = '\0';
trace_bpf_trace_printk(buf);
raw_spin_unlock_irqrestore(&trace_printk_lock, flags);
return ret;
}
/* /*
* Only limited trace_printk() conversion specifiers allowed: * Only limited trace_printk() conversion specifiers allowed:
* %d %i %u %x %ld %li %lu %lx %lld %lli %llu %llx %p %pB %pks %pus %s * %d %i %u %x %ld %li %lu %lx %lld %lli %llu %llx %p %pB %pks %pus %s
...@@ -484,8 +512,7 @@ BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1, ...@@ -484,8 +512,7 @@ BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1,
*/ */
#define __BPF_TP_EMIT() __BPF_ARG3_TP() #define __BPF_TP_EMIT() __BPF_ARG3_TP()
#define __BPF_TP(...) \ #define __BPF_TP(...) \
__trace_printk(0 /* Fake ip */, \ bpf_do_trace_printk(fmt, ##__VA_ARGS__)
fmt, ##__VA_ARGS__)
#define __BPF_ARG1_TP(...) \ #define __BPF_ARG1_TP(...) \
((mod[0] == 2 || (mod[0] == 1 && __BITS_PER_LONG == 64)) \ ((mod[0] == 2 || (mod[0] == 1 && __BITS_PER_LONG == 64)) \
...@@ -522,10 +549,15 @@ static const struct bpf_func_proto bpf_trace_printk_proto = { ...@@ -522,10 +549,15 @@ static const struct bpf_func_proto bpf_trace_printk_proto = {
const struct bpf_func_proto *bpf_get_trace_printk_proto(void) const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
{ {
/* /*
* this program might be calling bpf_trace_printk, * This program might be calling bpf_trace_printk,
* so allocate per-cpu printk buffers * so enable the associated bpf_trace/bpf_trace_printk event.
* Repeat this each time as it is possible a user has
* disabled bpf_trace_printk events. By loading a program
* calling bpf_trace_printk() however the user has expressed
* the intent to see such events.
*/ */
trace_printk_init_buffers(); if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
pr_warn_ratelimited("could not enable bpf_trace_printk events");
return &bpf_trace_printk_proto; return &bpf_trace_printk_proto;
} }
......
/* SPDX-License-Identifier: GPL-2.0 */
#undef TRACE_SYSTEM
#define TRACE_SYSTEM bpf_trace
#if !defined(_TRACE_BPF_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
#define _TRACE_BPF_TRACE_H
#include <linux/tracepoint.h>
TRACE_EVENT(bpf_trace_printk,
TP_PROTO(const char *bpf_string),
TP_ARGS(bpf_string),
TP_STRUCT__entry(
__string(bpf_string, bpf_string)
),
TP_fast_assign(
__assign_str(bpf_string, bpf_string);
),
TP_printk("%s", __get_str(bpf_string))
);
#endif /* _TRACE_BPF_TRACE_H */
#undef TRACE_INCLUDE_PATH
#define TRACE_INCLUDE_PATH .
#define TRACE_INCLUDE_FILE bpf_trace
#include <trace/define_trace.h>
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment