Re: [PATCHv2 bpf-next] bpf: Remove trace_printk_lock

[Yonghong Song <yhs@meta.com>]

On 12/14/22 2:04 AM, Jiri Olsa wrote:
> Both bpf_trace_printk and bpf_trace_vprintk helpers use static buffer
> guarded with trace_printk_lock spin lock.
> 
> The spin lock contention causes issues with bpf programs attached to
> contention_begin tracepoint [1] [2].
> 
> Andrii suggested we could get rid of the contention by using trylock,
> but we could actually get rid of the spinlock completely by using
> percpu buffers the same way as for bin_args in bpf_bprintf_prepare
> function.
> 
> Adding 4 per cpu buffers (1k each) which should be enough for all
> possible nesting contexts (normal, softirq, irq, nmi) or possible
> (yet unlikely) probe within the printk helpers.
> 
> In very unlikely case we'd run out of the nesting levels the printk
> will be omitted.
> 
> [1] https://lore.kernel.org/bpf/CACkBjsakT_yWxnSWr4r-0TpPvbKm9-OBmVUhJb7hV3hY8fdCkw@mail.gmail.com/
> [2] https://lore.kernel.org/bpf/CACkBjsaCsTovQHFfkqJKto6S4Z8d02ud1D7MPESrHa1cVNNTrw@mail.gmail.com/
> 
> Reported-by: Hao Sun <sunhao.th@gmail.com>
> Suggested-by: Andrii Nakryiko <andrii@kernel.org>
> Signed-off-by: Jiri Olsa <jolsa@kernel.org>
> ---
> v2 changes:
>    - changed subject [Yonghong]
>    - added WARN_ON_ONCE to get_printk_buf [Song]
> 
>   kernel/trace/bpf_trace.c | 61 +++++++++++++++++++++++++++++++---------
>   1 file changed, 47 insertions(+), 14 deletions(-)

Ack with a nit below.

Acked-by: Yonghong Song <yhs@fb.com>

> 
> diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> index 3bbd3f0c810c..a992b5a47fd6 100644
> --- a/kernel/trace/bpf_trace.c
> +++ b/kernel/trace/bpf_trace.c
> @@ -369,33 +369,62 @@ static const struct bpf_func_proto *bpf_get_probe_write_proto(void)
>   	return &bpf_probe_write_user_proto;
>   }
>   
> -static DEFINE_RAW_SPINLOCK(trace_printk_lock);
> -
>   #define MAX_TRACE_PRINTK_VARARGS	3
>   #define BPF_TRACE_PRINTK_SIZE		1024
> +#define BPF_TRACE_PRINTK_LEVELS		4
> +
> +struct trace_printk_buf {
> +	char data[BPF_TRACE_PRINTK_LEVELS][BPF_TRACE_PRINTK_SIZE];
> +	int level;
> +};
> +static DEFINE_PER_CPU(struct trace_printk_buf, printk_buf);
> +
> +static void put_printk_buf(struct trace_printk_buf __percpu *buf)
> +{
> +	if (WARN_ON_ONCE(this_cpu_read(buf->level) == 0))
> +		return;

The above WARN_ON_ONCE is not needed as it never happens based on
implementation. There are a few other similar cases in bpf_trace.c and 
none of them has WARN_ON_ONCE.

> +	this_cpu_dec(buf->level);
> +	preempt_enable();
> +}
> +
> +static bool get_printk_buf(struct trace_printk_buf __percpu *buf, char **data)
> +{
> +	int level;
> +
> +	preempt_disable();
> +	level = this_cpu_inc_return(buf->level);
> +	if (WARN_ON_ONCE(level > BPF_TRACE_PRINTK_LEVELS)) {
> +		put_printk_buf(buf);
> +		return false;
> +	}
> +	*data = (char *) this_cpu_ptr(&buf->data[level - 1]);
> +	return true;
> +}
>   
[...]