[PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[Andy Lutomirski]

Currently, the trace_printk code chooses which static buffer to use based
on what type of atomic context (NMI, IRQ, etc) it's in.  Simplify the
code and make it more robust: simply count the nesting depth and choose
a buffer based on the current nesting depth.

The new code will only drop an event if we nest more than 4 deep,
and the old code was guaranteed to malfunction if that happened.

Signed-off-by: Andy Lutomirski <luto@kernel.org>
---
 kernel/trace/trace.c | 83 +++++++++++++++-------------------------------------
 1 file changed, 24 insertions(+), 59 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index a2f0b9f33e9b..4508f3bf4a97 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1986,83 +1986,41 @@ static void __trace_userstack(struct trace_array *tr, unsigned long flags)
 
 /* created for use with alloc_percpu */
 struct trace_buffer_struct {
-	char buffer[TRACE_BUF_SIZE];
+	int nesting;
+	char buffer[4][TRACE_BUF_SIZE];
 };
 
 static struct trace_buffer_struct *trace_percpu_buffer;
-static struct trace_buffer_struct *trace_percpu_sirq_buffer;
-static struct trace_buffer_struct *trace_percpu_irq_buffer;
-static struct trace_buffer_struct *trace_percpu_nmi_buffer;
 
 /*
- * The buffer used is dependent on the context. There is a per cpu
- * buffer for normal context, softirq contex, hard irq context and
- * for NMI context. Thise allows for lockless recording.
- *
- * Note, if the buffers failed to be allocated, then this returns NULL
+ * Thise allows for lockless recording.  If we're nested too deeply, then
+ * this returns NULL.
  */
 static char *get_trace_buf(void)
 {
-	struct trace_buffer_struct *percpu_buffer;
-
-	/*
-	 * If we have allocated per cpu buffers, then we do not
-	 * need to do any locking.
-	 */
-	if (in_nmi())
-		percpu_buffer = trace_percpu_nmi_buffer;
-	else if (in_irq())
-		percpu_buffer = trace_percpu_irq_buffer;
-	else if (in_softirq())
-		percpu_buffer = trace_percpu_sirq_buffer;
-	else
-		percpu_buffer = trace_percpu_buffer;
+	struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);
 
-	if (!percpu_buffer)
+	if (!buffer || buffer->nesting >= 4)
 		return NULL;
 
-	return this_cpu_ptr(&percpu_buffer->buffer[0]);
+	return &buffer->buffer[buffer->nesting++][0];
+}
+
+static void put_trace_buf(void)
+{
+	this_cpu_dec(trace_percpu_buffer->nesting);
 }
 
 static int alloc_percpu_trace_buffer(void)
 {
 	struct trace_buffer_struct *buffers;
-	struct trace_buffer_struct *sirq_buffers;
-	struct trace_buffer_struct *irq_buffers;
-	struct trace_buffer_struct *nmi_buffers;
 
 	buffers = alloc_percpu(struct trace_buffer_struct);
-	if (!buffers)
-		goto err_warn;
-
-	sirq_buffers = alloc_percpu(struct trace_buffer_struct);
-	if (!sirq_buffers)
-		goto err_sirq;
-
-	irq_buffers = alloc_percpu(struct trace_buffer_struct);
-	if (!irq_buffers)
-		goto err_irq;
-
-	nmi_buffers = alloc_percpu(struct trace_buffer_struct);
-	if (!nmi_buffers)
-		goto err_nmi;
+	if (WARN(!buffers, "Could not allocate percpu trace_printk buffer"))
+		return -ENOMEM;
 
 	trace_percpu_buffer = buffers;
-	trace_percpu_sirq_buffer = sirq_buffers;
-	trace_percpu_irq_buffer = irq_buffers;
-	trace_percpu_nmi_buffer = nmi_buffers;
-
 	return 0;
-
- err_nmi:
-	free_percpu(irq_buffers);
- err_irq:
-	free_percpu(sirq_buffers);
- err_sirq:
-	free_percpu(buffers);
- err_warn:
-	WARN(1, "Could not allocate percpu trace_printk buffer");
-	return -ENOMEM;
 }
 
 static int buffers_allocated;
@@ -2153,7 +2111,7 @@ int trace_vbprintk(unsigned long ip, const char *fmt, va_list args)
 	tbuffer = get_trace_buf();
 	if (!tbuffer) {
 		len = 0;
-		goto out;
+		goto out_nobuffer;
 	}
 
 	len = vbin_printf((u32 *)tbuffer, TRACE_BUF_SIZE/sizeof(int), fmt, args);
@@ -2179,6 +2137,9 @@ int trace_vbprintk(unsigned long ip, const char *fmt, va_list args)
 	}
 
 out:
+	put_trace_buf();
+
+out_nobuffer:
 	preempt_enable_notrace();
 	unpause_graph_tracing();
 
@@ -2210,7 +2171,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 	tbuffer = get_trace_buf();
 	if (!tbuffer) {
 		len = 0;
-		goto out;
+		goto out_nobuffer;
 	}
 
 	len = vscnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
@@ -2229,7 +2190,11 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 		__buffer_unlock_commit(buffer, event);
 		ftrace_trace_stack(&global_trace, buffer, flags, 6, pc, NULL);
 	}
- out:
+
+out_nobuffer:
+	put_trace_buf();
+
+out:
 	preempt_enable_notrace();
 	unpause_graph_tracing();
 
-- 
2.5.5

Re: [PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[Steven Rostedt]

On Tue, 24 May 2016 15:52:28 -0700
Andy Lutomirski <luto@kernel.org> wrote:

> Currently, the trace_printk code chooses which static buffer to use based
> on what type of atomic context (NMI, IRQ, etc) it's in.  Simplify the
> code and make it more robust: simply count the nesting depth and choose
> a buffer based on the current nesting depth.
> 
> The new code will only drop an event if we nest more than 4 deep,
> and the old code was guaranteed to malfunction if that happened.
> 
> Signed-off-by: Andy Lutomirski <luto@kernel.org>

A quick scan of this patch looks good. But as the merge window is
currently open, and I'll be traveling next week, I may not get to it
for a couple of weeks.

Can you ping me again sometime after June 7th?

I may just pull this in my next queue and hopefully I remember to
review it ;-)

-- Steve

Re: [PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[Peter Zijlstra]

On Tue, May 24, 2016 at 03:52:28PM -0700, Andy Lutomirski wrote:
> Currently, the trace_printk code chooses which static buffer to use based
> on what type of atomic context (NMI, IRQ, etc) it's in.  Simplify the
> code and make it more robust: simply count the nesting depth and choose
> a buffer based on the current nesting depth.
> 
> The new code will only drop an event if we nest more than 4 deep,
> and the old code was guaranteed to malfunction if that happened.
> 
> Signed-off-by: Andy Lutomirski <luto@kernel.org>
> ---
>  kernel/trace/trace.c | 83 +++++++++++++++-------------------------------------
>  1 file changed, 24 insertions(+), 59 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index a2f0b9f33e9b..4508f3bf4a97 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -1986,83 +1986,41 @@ static void __trace_userstack(struct trace_array *tr, unsigned long flags)
>  
>  /* created for use with alloc_percpu */
>  struct trace_buffer_struct {
> -	char buffer[TRACE_BUF_SIZE];
> +	int nesting;
> +	char buffer[4][TRACE_BUF_SIZE];
>  };
>  
>  static struct trace_buffer_struct *trace_percpu_buffer;
>  /*
> + * Thise allows for lockless recording.  If we're nested too deeply, then
> + * this returns NULL.
>   */
>  static char *get_trace_buf(void)
>  {
> +	struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);
>  
> +	if (!buffer || buffer->nesting >= 4)
>  		return NULL;

This is buggy fwiw; you need to unconditionally increment
buffer->nesting to match the unconditional decrement.

Otherwise 5 'increments' and 5 decrements will land you at -1.

>  
> +	return &buffer->buffer[buffer->nesting++][0];
> +}
> +
> +static void put_trace_buf(void)
> +{
> +	this_cpu_dec(trace_percpu_buffer->nesting);
>  }

So I don't know about tracing; but for perf this construct would not
work 'properly'.

The per context counter -- which is lost in this scheme -- guards
against in-context recursion.

Only if we nest from another context do we allow generation of a new
event.

Re: [PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[Namhyung Kim]

Hi Andy,

On Wed, May 25, 2016 at 7:52 AM, Andy Lutomirski <luto@kernel.org> wrote:
> Currently, the trace_printk code chooses which static buffer to use based
> on what type of atomic context (NMI, IRQ, etc) it's in.  Simplify the
> code and make it more robust: simply count the nesting depth and choose
> a buffer based on the current nesting depth.
>
> The new code will only drop an event if we nest more than 4 deep,
> and the old code was guaranteed to malfunction if that happened.
>
> Signed-off-by: Andy Lutomirski <luto@kernel.org>
> ---
>  kernel/trace/trace.c | 83 +++++++++++++++-------------------------------------
>  1 file changed, 24 insertions(+), 59 deletions(-)
>
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index a2f0b9f33e9b..4508f3bf4a97 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -1986,83 +1986,41 @@ static void __trace_userstack(struct trace_array *tr, unsigned long flags)
>
>  /* created for use with alloc_percpu */
>  struct trace_buffer_struct {
> -       char buffer[TRACE_BUF_SIZE];
> +       int nesting;
> +       char buffer[4][TRACE_BUF_SIZE];
>  };
>
>  static struct trace_buffer_struct *trace_percpu_buffer;
> -static struct trace_buffer_struct *trace_percpu_sirq_buffer;
> -static struct trace_buffer_struct *trace_percpu_irq_buffer;
> -static struct trace_buffer_struct *trace_percpu_nmi_buffer;
>
>  /*
> - * The buffer used is dependent on the context. There is a per cpu
> - * buffer for normal context, softirq contex, hard irq context and
> - * for NMI context. Thise allows for lockless recording.
> - *
> - * Note, if the buffers failed to be allocated, then this returns NULL
> + * Thise allows for lockless recording.  If we're nested too deeply, then
> + * this returns NULL.
>   */
>  static char *get_trace_buf(void)
>  {
> -       struct trace_buffer_struct *percpu_buffer;
> -
> -       /*
> -        * If we have allocated per cpu buffers, then we do not
> -        * need to do any locking.
> -        */
> -       if (in_nmi())
> -               percpu_buffer = trace_percpu_nmi_buffer;
> -       else if (in_irq())
> -               percpu_buffer = trace_percpu_irq_buffer;
> -       else if (in_softirq())
> -               percpu_buffer = trace_percpu_sirq_buffer;
> -       else
> -               percpu_buffer = trace_percpu_buffer;
> +       struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);
>
> -       if (!percpu_buffer)
> +       if (!buffer || buffer->nesting >= 4)
>                 return NULL;
>
> -       return this_cpu_ptr(&percpu_buffer->buffer[0]);
> +       return &buffer->buffer[buffer->nesting++][0];
> +}
> +
> +static void put_trace_buf(void)
> +{
> +       this_cpu_dec(trace_percpu_buffer->nesting);
>  }
>
>  static int alloc_percpu_trace_buffer(void)
>  {
>         struct trace_buffer_struct *buffers;
> -       struct trace_buffer_struct *sirq_buffers;
> -       struct trace_buffer_struct *irq_buffers;
> -       struct trace_buffer_struct *nmi_buffers;
>
>         buffers = alloc_percpu(struct trace_buffer_struct);
> -       if (!buffers)
> -               goto err_warn;
> -
> -       sirq_buffers = alloc_percpu(struct trace_buffer_struct);
> -       if (!sirq_buffers)
> -               goto err_sirq;
> -
> -       irq_buffers = alloc_percpu(struct trace_buffer_struct);
> -       if (!irq_buffers)
> -               goto err_irq;
> -
> -       nmi_buffers = alloc_percpu(struct trace_buffer_struct);
> -       if (!nmi_buffers)
> -               goto err_nmi;
> +       if (WARN(!buffers, "Could not allocate percpu trace_printk buffer"))
> +               return -ENOMEM;
>
>         trace_percpu_buffer = buffers;
> -       trace_percpu_sirq_buffer = sirq_buffers;
> -       trace_percpu_irq_buffer = irq_buffers;
> -       trace_percpu_nmi_buffer = nmi_buffers;
> -
>         return 0;
> -
> - err_nmi:
> -       free_percpu(irq_buffers);
> - err_irq:
> -       free_percpu(sirq_buffers);
> - err_sirq:
> -       free_percpu(buffers);
> - err_warn:
> -       WARN(1, "Could not allocate percpu trace_printk buffer");
> -       return -ENOMEM;
>  }
>
>  static int buffers_allocated;
> @@ -2153,7 +2111,7 @@ int trace_vbprintk(unsigned long ip, const char *fmt, va_list args)
>         tbuffer = get_trace_buf();
>         if (!tbuffer) {
>                 len = 0;
> -               goto out;
> +               goto out_nobuffer;
>         }
>
>         len = vbin_printf((u32 *)tbuffer, TRACE_BUF_SIZE/sizeof(int), fmt, args);
> @@ -2179,6 +2137,9 @@ int trace_vbprintk(unsigned long ip, const char *fmt, va_list args)
>         }
>
>  out:
> +       put_trace_buf();
> +
> +out_nobuffer:
>         preempt_enable_notrace();
>         unpause_graph_tracing();
>
> @@ -2210,7 +2171,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
>         tbuffer = get_trace_buf();
>         if (!tbuffer) {
>                 len = 0;
> -               goto out;
> +               goto out_nobuffer;
>         }
>
>         len = vscnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
> @@ -2229,7 +2190,11 @@ __trace_array_vprintk(struct ring_buffer *buffer,
>                 __buffer_unlock_commit(buffer, event);
>                 ftrace_trace_stack(&global_trace, buffer, flags, 6, pc, NULL);
>         }
> - out:
> +
> +out_nobuffer:
> +       put_trace_buf();
> +
> +out:

Shouldn't the labels be reversed like below?

out:
        put_trace_buf();

out_nobuffer:

>         preempt_enable_notrace();
>         unpause_graph_tracing();


Thanks,
Namhyung

Re: [PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[Steven Rostedt]

On Wed, 25 May 2016 15:16:40 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> >  static char *get_trace_buf(void)
> >  {
> > +	struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);
> >  
> > +	if (!buffer || buffer->nesting >= 4)
> >  		return NULL;  
> 
> This is buggy fwiw; you need to unconditionally increment
> buffer->nesting to match the unconditional decrement.
> 
> Otherwise 5 'increments' and 5 decrements will land you at -1.

As I said, I did a quick look and haven't reviewed it.

Peter, thanks for looking at it.

> 
> >  
> > +	return &buffer->buffer[buffer->nesting++][0];
> > +}
> > +
> > +static void put_trace_buf(void)
> > +{
> > +	this_cpu_dec(trace_percpu_buffer->nesting);
> >  }  
> 
> So I don't know about tracing; but for perf this construct would not
> work 'properly'.
> 
> The per context counter -- which is lost in this scheme -- guards
> against in-context recursion.
> 
> Only if we nest from another context do we allow generation of a new
> event.

The ring buffer itself has a context check, where if you try to record
another event nested in the same context, it will simply return NULL.

But this buffer is only used for trace_printk() to manipulate a printf
format. It writes into here first, and then copies it into the tracing
ring buffer. If it happens at a nested event within the same context,
then trace_buffer_lock_reserve() will return NULL and the event wont be
recorded.

-- Steve

Re: [PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[Peter Zijlstra]

On Wed, May 25, 2016 at 03:16:40PM +0200, Peter Zijlstra wrote:
> On Tue, May 24, 2016 at 03:52:28PM -0700, Andy Lutomirski wrote:
> > +	struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);
> >  
> > +	if (!buffer || buffer->nesting >= 4)
> >  		return NULL;
> 
> This is buggy fwiw; you need to unconditionally increment
> buffer->nesting to match the unconditional decrement.
> 
> Otherwise 5 'increments' and 5 decrements will land you at -1.

Urgh, never mind me; if you don't dec when returning NULL  this should
work out fine.

My head really aint working right today.

Re: [PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[Andy Lutomirski]

On May 25, 2016 6:16 AM, "Peter Zijlstra" <peterz@infradead.org> wrote:
>
> On Tue, May 24, 2016 at 03:52:28PM -0700, Andy Lutomirski wrote:
> > Currently, the trace_printk code chooses which static buffer to use based
> > on what type of atomic context (NMI, IRQ, etc) it's in.  Simplify the
> > code and make it more robust: simply count the nesting depth and choose
> > a buffer based on the current nesting depth.
> >
> > The new code will only drop an event if we nest more than 4 deep,
> > and the old code was guaranteed to malfunction if that happened.
> >
> > Signed-off-by: Andy Lutomirski <luto@kernel.org>
> > ---
> >  kernel/trace/trace.c | 83 +++++++++++++++-------------------------------------
> >  1 file changed, 24 insertions(+), 59 deletions(-)
> >
> > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > index a2f0b9f33e9b..4508f3bf4a97 100644
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
> > @@ -1986,83 +1986,41 @@ static void __trace_userstack(struct trace_array *tr, unsigned long flags)
> >
> >  /* created for use with alloc_percpu */
> >  struct trace_buffer_struct {
> > -     char buffer[TRACE_BUF_SIZE];
> > +     int nesting;
> > +     char buffer[4][TRACE_BUF_SIZE];
> >  };
> >
> >  static struct trace_buffer_struct *trace_percpu_buffer;
> >  /*
> > + * Thise allows for lockless recording.  If we're nested too deeply, then
> > + * this returns NULL.
> >   */
> >  static char *get_trace_buf(void)
> >  {
> > +     struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);
> >
> > +     if (!buffer || buffer->nesting >= 4)
> >               return NULL;
>
> This is buggy fwiw; you need to unconditionally increment
> buffer->nesting to match the unconditional decrement.
>
> Otherwise 5 'increments' and 5 decrements will land you at -1.

I did indeed mess up the error handling.  I'll fix it.

>
> >
> > +     return &buffer->buffer[buffer->nesting++][0];
> > +}
> > +
> > +static void put_trace_buf(void)
> > +{
> > +     this_cpu_dec(trace_percpu_buffer->nesting);
> >  }
>
> So I don't know about tracing; but for perf this construct would not
> work 'properly'.
>
> The per context counter -- which is lost in this scheme -- guards
> against in-context recursion.
>
> Only if we nest from another context do we allow generation of a new
> event.

What's the purpose of this feature?

I'm guessing that the idea is to prevent events that are triggered
synchronously during processing of another event.  So, for example, if
you get a page fault or trigger a data breakpoint while generating a
callchain, it's not terribly helpful to emit events due to that fault
or breakpoint.  In this respect, my patch is an improvement:
watchpoints are synchronous events.

If that's the goal, then the current heuristic may be fairly good after all.

--Andy

Re: [PATCH] tracing: Choose static tp_printk buffer by explicit nesting count

[Andy Lutomirski]

On Wed, May 25, 2016 at 6:20 AM, Namhyung Kim <namhyung@gmail.com> wrote:
> Hi Andy,

>> - out:
>> +
>> +out_nobuffer:
>> +       put_trace_buf();
>> +
>> +out:
>
> Shouldn't the labels be reversed like below?
>
> out:
>         put_trace_buf();
>
> out_nobuffer:

Yes.  I'll send a new version.

--Andy