[PATCH 0/2] tracing - avoid soft lockup in trace_pipe

[PATCH 0/2] tracing - avoid soft lockup in trace_pipe

[Jiri Olsa]

hi,

running following commands:

  echo 1 > ./options/bin
  echo 0 > ./options/context-info 
  echo 1 > ./events/enable
  cat trace_pipe

is causing soft lockup inside tracing_read_pipe function.

The reason is, that bin/hex/raw output functions for events
are set to trace_nop_print function, which prints nothing
and returns TRACE_TYPE_HANDLED value.

So, choosing:
	- NON preemptive kernel
	- trace only events
	- enable bin/hex options
	  (raw option traces new line always, so it will get out eventually).
	- disable all other output (context-info option)

will cause the tracing_read_pipe to loop forever, because the only
loop escapes are:
	1) ring buffer is empty
	2) TRACE_TYPE_PARTIAL_LINE returned from trace output function
	3) trace_seq buffer limit is reached

ad 1)
with all events enabled, the other CPU(s) keep ring buffer full
(did not try on single CPU machine)

ad 2)
with all other output disabled, the only called trace function
is trace_nop_print, which returns TRACE_TYPE_HANDLED

ad 3)
the only traced information is LOST EVENT trace, but it's
without the check for the trace_seq limit crossing, so
we stay in the loop


The attached patch (1/2) fixies handling of lost event trace.
This change will also make the soft lockup practically disappear,
since I think there will allways be some lost events, which will
cause the trace_seq buffer overflow and escape the loop.


To improve the latency and make sure we won't stuck if there are no
lost events, I added to the loop (patch 2/2):
	- cond_resched call
	- check for signal to leave the loop


Attached patches:
1/2 - tracing - trace lost events properly
2/2 - tracing - putting cond_resched into tace_pipe loop

Thanks a lot to Oleg Nestorov for helping me to nail this down.

..hopefully I haven't missed anything ;)

wbr,
jirka
---
 kernel/trace/trace.c |   27 ++++++++++++++++++++++++---
 1 files changed, 24 insertions(+), 3 deletions(-)

[PATCH 1/2] tracing - trace lost events properly

[Jiri Olsa]

Add proper handling of lost event trace, allowing callers
to get correct trace buffer info.

 - returning TRACE_TYPE_PARTIAL_LINE, in case we dont fit into
   the trace_seq buffer
 - added WARN_ON to make sure we don't miss incorrect trace_seq
   handling

wbr,
jirka


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 kernel/trace/trace.c |   14 +++++++++++---
 1 files changed, 11 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 9541c27..20d84f8 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2013,9 +2013,10 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
 {
 	enum print_line_t ret;
 
-	if (iter->lost_events)
-		trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
-				 iter->cpu, iter->lost_events);
+	if (iter->lost_events &&
+	    !trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
+				 iter->cpu, iter->lost_events))
+		return TRACE_TYPE_PARTIAL_LINE;
 
 	if (iter->trace && iter->trace->print_line) {
 		ret = iter->trace->print_line(iter);
@@ -3229,6 +3230,13 @@ waitagain:
 
 		if (iter->seq.len >= cnt)
 			break;
+
+		/*
+		 * Setting the full flag means we reached the trace_seq buffer
+		 * size and we should leave by partial output condition above.
+		 * One of the trace_seq_* functions is not used properly.
+		 */
+		WARN_ON(iter->seq.full);
 	}
 	trace_access_unlock(iter->cpu_file);
 	trace_event_read_unlock();
-- 
1.7.1

[PATCH 2/2] tracing - putting cond_resched into tace_pipe loop

[Jiri Olsa]

Adding cond_resched call to the tracing_read_pipe while loop.
Plus check for signal to leave the loop.

This will protect us from soft lockup on NON preemptive kernels
and improve latency.

Thanks a lot to Oleg Nestorov for helping me to nail this down.

wbr,
jirka


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 kernel/trace/trace.c |   13 +++++++++++++
 1 files changed, 13 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 20d84f8..7d66476 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3237,10 +3237,23 @@ waitagain:
 		 * One of the trace_seq_* functions is not used properly.
 		 */
 		WARN_ON(iter->seq.full);
+
+		/*
+		 * There's a chance this loop might get quite tight,
+		 * causing latency in non preemptive kernel.
+		 */
+		cond_resched();
+		if (signal_pending(current)) {
+			sret = -EINTR;
+			break;
+		}
 	}
 	trace_access_unlock(iter->cpu_file);
 	trace_event_read_unlock();
 
+	if (sret == -EINTR)
+		goto out;
+
 	/* Now copy what we have to the user */
 	sret = trace_seq_to_user(&iter->seq, ubuf, cnt);
 	if (iter->seq.readpos >= iter->seq.len)
-- 
1.7.1

Re: [PATCH 2/2] tracing - putting cond_resched into tace_pipe loop

[Oleg Nesterov]

On 03/12, Jiri Olsa wrote:
>
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -3237,10 +3237,23 @@ waitagain:
>  		 * One of the trace_seq_* functions is not used properly.
>  		 */
>  		WARN_ON(iter->seq.full);
> +
> +		/*
> +		 * There's a chance this loop might get quite tight,
> +		 * causing latency in non preemptive kernel.
> +		 */
> +		cond_resched();
> +		if (signal_pending(current)) {
> +			sret = -EINTR;
> +			break;

First of all: I do not pretend I understand this code ;) Still, a
couple of nits.

-EINTR doesn't look exactly right, I'd suggest -ERESTARTSYS. The same
for tracing_wait_pipe() btw, I think it should be fixed.



I wonder if it makes sense to simply "break" if signal_pending(), it
is possible we already have something to report via trace_seq_to_user().
Then we could do

	-	if (sret == -EBUSY)
	-		goto waitagain;
	+	if (sret == -EBUSY) {
	+		if (!signal_pending())
	+			goto waitagain;
	+		sret = -ERESTARTSYS;
	+	}

Or we can change tracing_wait_pipe() to check signal_pending()
uncondditionally, I dunno.

Up to you, but note that otherwise the logic looks a bit strange.
Suppose that signal_pending() is already true when we call
tracing_wait_pipe(). In this case we are going to do the "unnecessary"
work and then return EINTR/ERESTART. This is correct, the next
invocation does trace_seq_to_user() before anything else, just
looks a bit strange.

Oleg.

Re: [PATCH 2/2] tracing - putting cond_resched into tace_pipe loop

[Steven Rostedt]

On Sun, 2011-03-13 at 15:58 +0100, Oleg Nesterov wrote:
> On 03/12, Jiri Olsa wrote:
> >
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
> > @@ -3237,10 +3237,23 @@ waitagain:
> >  		 * One of the trace_seq_* functions is not used properly.
> >  		 */
> >  		WARN_ON(iter->seq.full);
> > +
> > +		/*
> > +		 * There's a chance this loop might get quite tight,
> > +		 * causing latency in non preemptive kernel.
> > +		 */
> > +		cond_resched();
> > +		if (signal_pending(current)) {
> > +			sret = -EINTR;
> > +			break;
> 
> First of all: I do not pretend I understand this code ;) Still, a
> couple of nits.
> 
> -EINTR doesn't look exactly right, I'd suggest -ERESTARTSYS. The same
> for tracing_wait_pipe() btw, I think it should be fixed.

Yeah, the tracing_wait_pipe() could be changed. I probably copied that
from someplace else in the kernel ;)

> 
> 
> 
> I wonder if it makes sense to simply "break" if signal_pending(), it
> is possible we already have something to report via trace_seq_to_user().
> Then we could do
> 
> 	-	if (sret == -EBUSY)
> 	-		goto waitagain;
> 	+	if (sret == -EBUSY) {
> 	+		if (!signal_pending())
> 	+			goto waitagain;
> 	+		sret = -ERESTARTSYS;
> 	+	}
> 
> Or we can change tracing_wait_pipe() to check signal_pending()
> uncondditionally, I dunno.
> 
> Up to you, but note that otherwise the logic looks a bit strange.
> Suppose that signal_pending() is already true when we call
> tracing_wait_pipe(). In this case we are going to do the "unnecessary"
> work and then return EINTR/ERESTART. This is correct, the next
> invocation does trace_seq_to_user() before anything else, just
> looks a bit strange.

I'm not sure that this needs the signal_pending() or the break, or even
the cond_resched(). Perhaps the first patch fixes the bug. But that
while loop does not block, and it should just spin enough to fill a
page. If it is not filling the page then that's a bug.

Jiri,

Can you reproduce the bug with just he first patch? Actually, I can
reproduce it on vanilla, I'll apply your first patch and see if that
fixes things. If not, then we need to find out why and fix those.

-- Steve

Re: [PATCH 2/2] tracing - putting cond_resched into tace_pipe loop

[Jiri Olsa]

On Mon, Mar 14, 2011 at 10:07:31AM -0400, Steven Rostedt wrote:
> On Sun, 2011-03-13 at 15:58 +0100, Oleg Nesterov wrote:
> > On 03/12, Jiri Olsa wrote:
> > >
> > > --- a/kernel/trace/trace.c
> > > +++ b/kernel/trace/trace.c
> > > @@ -3237,10 +3237,23 @@ waitagain:
> > >  		 * One of the trace_seq_* functions is not used properly.
> > >  		 */
> > >  		WARN_ON(iter->seq.full);
> > > +
> > > +		/*
> > > +		 * There's a chance this loop might get quite tight,
> > > +		 * causing latency in non preemptive kernel.
> > > +		 */
> > > +		cond_resched();
> > > +		if (signal_pending(current)) {
> > > +			sret = -EINTR;
> > > +			break;
> > 
> > First of all: I do not pretend I understand this code ;) Still, a
> > couple of nits.
> > 
> > -EINTR doesn't look exactly right, I'd suggest -ERESTARTSYS. The same
> > for tracing_wait_pipe() btw, I think it should be fixed.
> 
> Yeah, the tracing_wait_pipe() could be changed. I probably copied that
> from someplace else in the kernel ;)
> 
> > 
> > 
> > 
> > I wonder if it makes sense to simply "break" if signal_pending(), it
> > is possible we already have something to report via trace_seq_to_user().
> > Then we could do
> > 
> > 	-	if (sret == -EBUSY)
> > 	-		goto waitagain;
> > 	+	if (sret == -EBUSY) {
> > 	+		if (!signal_pending())
> > 	+			goto waitagain;
> > 	+		sret = -ERESTARTSYS;
> > 	+	}
> > 
> > Or we can change tracing_wait_pipe() to check signal_pending()
> > uncondditionally, I dunno.
> > 
> > Up to you, but note that otherwise the logic looks a bit strange.
> > Suppose that signal_pending() is already true when we call
> > tracing_wait_pipe(). In this case we are going to do the "unnecessary"
> > work and then return EINTR/ERESTART. This is correct, the next
> > invocation does trace_seq_to_user() before anything else, just
> > looks a bit strange.
> 
> I'm not sure that this needs the signal_pending() or the break, or even
> the cond_resched(). Perhaps the first patch fixes the bug. But that
> while loop does not block, and it should just spin enough to fill a
> page. If it is not filling the page then that's a bug.

well, if there are no "event lost" messages and the flags are set
to the "bin or raw" and you trace events only, then the page
is not be filled.

But as there'll be allways lost events, the page will be populated
and it will get out of the loop.

> 
> Jiri,
> 
> Can you reproduce the bug with just he first patch? Actually, I can
> reproduce it on vanilla, I'll apply your first patch and see if that
> fixes things. If not, then we need to find out why and fix those.

The first patch fixies the 'lost evets' trace, so the loop is escaped
when the page is full.
(I was going to send some change for first patch WARN_ON -> WARN_ONCE)

I think in case there are no 'lost events' and we have the conditions
I describe, we need the cond_resched call.

I'll send new patch version shortly.

thanks,
jirka
> 
> -- Steve
> 
> 

Re: [PATCH 2/2] tracing - putting cond_resched into tace_pipe loop

[Steven Rostedt]

On Mon, 2011-03-14 at 15:18 +0100, Jiri Olsa wrote:


> > I'm not sure that this needs the signal_pending() or the break, or even
> > the cond_resched(). Perhaps the first patch fixes the bug. But that
> > while loop does not block, and it should just spin enough to fill a
> > page. If it is not filling the page then that's a bug.
> 
> well, if there are no "event lost" messages and the flags are set
> to the "bin or raw" and you trace events only, then the page
> is not be filled.
> 
> But as there'll be allways lost events, the page will be populated
> and it will get out of the loop.

There's two loops, I'm talking about the inner one, which will break out
when there are no events left to process.

The "waitagain" calls into tracing_wait_pipe which has the
signal_pending() attribute. It should also block, or return -EAGAIN if
the caller is not blocking.

> 
> > 
> > Jiri,
> > 
> > Can you reproduce the bug with just he first patch? Actually, I can
> > reproduce it on vanilla, I'll apply your first patch and see if that
> > fixes things. If not, then we need to find out why and fix those.
> 
> The first patch fixies the 'lost evets' trace, so the loop is escaped
> when the page is full.
> (I was going to send some change for first patch WARN_ON -> WARN_ONCE)

Yes, I was going to recommend doing that too.

> 
> I think in case there are no 'lost events' and we have the conditions
> I describe, we need the cond_resched call.

No we don't.

As for non preempt kernels, honestly, I don't care about latencies. If
you are worried about latencies, don't run a non preempt kernel. I do
care if it goes into an infinite loop, or never processes signals, which
would be a bug. But long running times in the kernel on a non preempt
kernel. Well, that's just part of the game.

-- Steve

> 
> I'll send new patch version shortly.
> 
> thanks,
> jirka
> > 
> > -- Steve
> > 
> > 

Re: [PATCH 2/2] tracing - putting cond_resched into tace_pipe loop

[Jiri Olsa]

On Mon, Mar 14, 2011 at 10:28:46AM -0400, Steven Rostedt wrote:
> On Mon, 2011-03-14 at 15:18 +0100, Jiri Olsa wrote:
> 
> 
> > > I'm not sure that this needs the signal_pending() or the break, or even
> > > the cond_resched(). Perhaps the first patch fixes the bug. But that
> > > while loop does not block, and it should just spin enough to fill a
> > > page. If it is not filling the page then that's a bug.
> > 
> > well, if there are no "event lost" messages and the flags are set
> > to the "bin or raw" and you trace events only, then the page
> > is not be filled.
> > 
> > But as there'll be allways lost events, the page will be populated
> > and it will get out of the loop.
> 
> There's two loops, I'm talking about the inner one, which will break out
> when there are no events left to process.
> 
> The "waitagain" calls into tracing_wait_pipe which has the
> signal_pending() attribute. It should also block, or return -EAGAIN if
> the caller is not blocking.
> 
> > 
> > > 
> > > Jiri,
> > > 
> > > Can you reproduce the bug with just he first patch? Actually, I can
> > > reproduce it on vanilla, I'll apply your first patch and see if that
> > > fixes things. If not, then we need to find out why and fix those.
> > 
> > The first patch fixies the 'lost evets' trace, so the loop is escaped
> > when the page is full.
> > (I was going to send some change for first patch WARN_ON -> WARN_ONCE)
> 
> Yes, I was going to recommend doing that too.
> 
> > 
> > I think in case there are no 'lost events' and we have the conditions
> > I describe, we need the cond_resched call.
> 
> No we don't.

ok, probably I'm missing something, but here's the path that dont produce
any data and will keeps us in the inner loop:
(assuming events only, disabled context info and no event lost)

while (trace_find_next_entry_inc(iter) != NULL)
..
	print_trace_line(iter);
		...
		if (trace_flags & TRACE_ITER_BIN)
	                return print_bin_fmt(iter);
			...
			print_bin_fmt
				return event ?event->funcs->binary(iter, 0, event) : TRACE_TYPE_HANDLED;

...


now, "event->funcs->binary" is trace_nop_print, which is defined as:

	enum print_line_t trace_nop_print(struct trace_iterator *iter, int
	flags,
					  struct trace_event *event)
	{
		return TRACE_TYPE_HANDLED;
	}


So we get back the the while loop with no data added and with
TRACE_TYPE_HANDLED return code, which will keep us in the loop.

Not sure this is bug or feature :)

jirka

> 
> As for non preempt kernels, honestly, I don't care about latencies. If
> you are worried about latencies, don't run a non preempt kernel. I do
> care if it goes into an infinite loop, or never processes signals, which
> would be a bug. But long running times in the kernel on a non preempt
> kernel. Well, that's just part of the game.
> 
> -- Steve
> 
> > 
> > I'll send new patch version shortly.
> > 
> > thanks,
> > jirka
> > > 
> > > -- Steve
> > > 
> > > 
> 
> 

Re: [PATCH 2/2] tracing - putting cond_resched into tace_pipe loop

[Steven Rostedt]

On Mon, 2011-03-14 at 16:07 +0100, Jiri Olsa wrote:
> So we get back the the while loop with no data added and with
> TRACE_TYPE_HANDLED return code, which will keep us in the loop.
> 
> Not sure this is bug or feature :)
> 
> 
Most bugs are features ;)

honestly, I'd love to rip out all the "bin", "hex" etc formats as they
are pretty much deprecated.

But as you pointed out that this can keep us in the inner loop, we need
to fix that. I prefer to fix it within the nop print function. Perhaps
we need to fill in something. "type: %d", iter->ent->type ?

-- Steve

[PATCHv2] tracing - avoid soft lockup in trace_pipe

[Jiri Olsa]

On Mon, Mar 14, 2011 at 11:20:57AM -0400, Steven Rostedt wrote:
> On Mon, 2011-03-14 at 16:07 +0100, Jiri Olsa wrote:
> > So we get back the the while loop with no data added and with
> > TRACE_TYPE_HANDLED return code, which will keep us in the loop.
> > 
> > Not sure this is bug or feature :)
> > 
> > 
> Most bugs are features ;)
> 
> honestly, I'd love to rip out all the "bin", "hex" etc formats as they
> are pretty much deprecated.
> 
> But as you pointed out that this can keep us in the inner loop, we need
> to fix that. I prefer to fix it within the nop print function. Perhaps
> we need to fill in something. "type: %d", iter->ent->type ?

sounds ok :) attaching v2 patch

thanks,
jirka


---
running following commands:

  # enable the binary option
  echo 1 > ./options/bin
  # disable context info option
  echo 0 > ./options/context-info 
  # tracing only events
  echo 1 > ./events/enable
  cat trace_pipe

is causing lockup (in NON preemptive kernels) inside
tracing_read_pipe function.

The reason are:
 - bin/hex/raw output functions for events are set to
   trace_nop_print function, which prints nothing and
   returns TRACE_TYPE_HANDLED value
 - LOST EVENT trace do not handle trace_seq overflow

These reasons force the while loop in tracing_read_pipe
function never to break.

The attached patch fixies handling of lost event trace, and
changes trace_nop_print to print minimal info, which is needed
for the correct tracing_read_pipe processing.

v2 changes:
 - omit the cond_resched changes by trace_nop_print changes
 - WARN changed to WARN_ONCE and added info to be able
   to find out the culprit

wbr,
jirka


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 kernel/trace/trace.c        |   15 ++++++++++++---
 kernel/trace/trace_output.c |    3 +++
 2 files changed, 15 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 9541c27..5af42f4 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2013,9 +2013,10 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
 {
 	enum print_line_t ret;
 
-	if (iter->lost_events)
-		trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
-				 iter->cpu, iter->lost_events);
+	if (iter->lost_events &&
+	    !trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
+				 iter->cpu, iter->lost_events))
+		return TRACE_TYPE_PARTIAL_LINE;
 
 	if (iter->trace && iter->trace->print_line) {
 		ret = iter->trace->print_line(iter);
@@ -3229,6 +3230,14 @@ waitagain:
 
 		if (iter->seq.len >= cnt)
 			break;
+
+		/*
+		 * Setting the full flag means we reached the trace_seq buffer
+		 * size and we should leave by partial output condition above.
+		 * One of the trace_seq_* functions is not used properly.
+		 */
+		WARN_ONCE(iter->seq.full, "full flag set for trace type %d",
+			  iter->ent->type);
 	}
 	trace_access_unlock(iter->cpu_file);
 	trace_event_read_unlock();
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 456be90..cf535cc 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -830,6 +830,9 @@ EXPORT_SYMBOL_GPL(unregister_ftrace_event);
 enum print_line_t trace_nop_print(struct trace_iterator *iter, int flags,
 				  struct trace_event *event)
 {
+	if (!trace_seq_printf(&iter->seq, "type: %d\n", iter->ent->type))
+		return TRACE_TYPE_PARTIAL_LINE;
+
 	return TRACE_TYPE_HANDLED;
 }
 
-- 
1.7.1

Re: [PATCHv2] tracing - avoid soft lockup in trace_pipe

[Jiri Olsa]

On Mon, Mar 14, 2011 at 07:06:21PM +0100, Jiri Olsa wrote:
> On Mon, Mar 14, 2011 at 11:20:57AM -0400, Steven Rostedt wrote:
> > On Mon, 2011-03-14 at 16:07 +0100, Jiri Olsa wrote:
> > > So we get back the the while loop with no data added and with
> > > TRACE_TYPE_HANDLED return code, which will keep us in the loop.
> > > 
> > > Not sure this is bug or feature :)
> > > 
> > > 
> > Most bugs are features ;)
> > 
> > honestly, I'd love to rip out all the "bin", "hex" etc formats as they
> > are pretty much deprecated.
> > 
> > But as you pointed out that this can keep us in the inner loop, we need
> > to fix that. I prefer to fix it within the nop print function. Perhaps
> > we need to fill in something. "type: %d", iter->ent->type ?
> 
> sounds ok :) attaching v2 patch
hi, any feedback?

thanks,
jirka

> 
> thanks,
> jirka
> 
> 
> ---
> running following commands:
> 
>   # enable the binary option
>   echo 1 > ./options/bin
>   # disable context info option
>   echo 0 > ./options/context-info 
>   # tracing only events
>   echo 1 > ./events/enable
>   cat trace_pipe
> 
> is causing lockup (in NON preemptive kernels) inside
> tracing_read_pipe function.
> 
> The reason are:
>  - bin/hex/raw output functions for events are set to
>    trace_nop_print function, which prints nothing and
>    returns TRACE_TYPE_HANDLED value
>  - LOST EVENT trace do not handle trace_seq overflow
> 
> These reasons force the while loop in tracing_read_pipe
> function never to break.
> 
> The attached patch fixies handling of lost event trace, and
> changes trace_nop_print to print minimal info, which is needed
> for the correct tracing_read_pipe processing.
> 
> v2 changes:
>  - omit the cond_resched changes by trace_nop_print changes
>  - WARN changed to WARN_ONCE and added info to be able
>    to find out the culprit
> 
> wbr,
> jirka
> 
> 
> Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> ---
>  kernel/trace/trace.c        |   15 ++++++++++++---
>  kernel/trace/trace_output.c |    3 +++
>  2 files changed, 15 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 9541c27..5af42f4 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -2013,9 +2013,10 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
>  {
>  	enum print_line_t ret;
>  
> -	if (iter->lost_events)
> -		trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
> -				 iter->cpu, iter->lost_events);
> +	if (iter->lost_events &&
> +	    !trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
> +				 iter->cpu, iter->lost_events))
> +		return TRACE_TYPE_PARTIAL_LINE;
>  
>  	if (iter->trace && iter->trace->print_line) {
>  		ret = iter->trace->print_line(iter);
> @@ -3229,6 +3230,14 @@ waitagain:
>  
>  		if (iter->seq.len >= cnt)
>  			break;
> +
> +		/*
> +		 * Setting the full flag means we reached the trace_seq buffer
> +		 * size and we should leave by partial output condition above.
> +		 * One of the trace_seq_* functions is not used properly.
> +		 */
> +		WARN_ONCE(iter->seq.full, "full flag set for trace type %d",
> +			  iter->ent->type);
>  	}
>  	trace_access_unlock(iter->cpu_file);
>  	trace_event_read_unlock();
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index 456be90..cf535cc 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -830,6 +830,9 @@ EXPORT_SYMBOL_GPL(unregister_ftrace_event);
>  enum print_line_t trace_nop_print(struct trace_iterator *iter, int flags,
>  				  struct trace_event *event)
>  {
> +	if (!trace_seq_printf(&iter->seq, "type: %d\n", iter->ent->type))
> +		return TRACE_TYPE_PARTIAL_LINE;
> +
>  	return TRACE_TYPE_HANDLED;
>  }
>  
> -- 
> 1.7.1
> 

Re: [PATCHv2] tracing - avoid soft lockup in trace_pipe

[Steven Rostedt]

On Mon, 2011-03-21 at 13:10 +0100, Jiri Olsa wrote:
> On Mon, Mar 14, 2011 at 07:06:21PM +0100, Jiri Olsa wrote:
> > On Mon, Mar 14, 2011 at 11:20:57AM -0400, Steven Rostedt wrote:
> > > On Mon, 2011-03-14 at 16:07 +0100, Jiri Olsa wrote:
> > > > So we get back the the while loop with no data added and with
> > > > TRACE_TYPE_HANDLED return code, which will keep us in the loop.
> > > > 
> > > > Not sure this is bug or feature :)
> > > > 
> > > > 
> > > Most bugs are features ;)
> > > 
> > > honestly, I'd love to rip out all the "bin", "hex" etc formats as they
> > > are pretty much deprecated.
> > > 
> > > But as you pointed out that this can keep us in the inner loop, we need
> > > to fix that. I prefer to fix it within the nop print function. Perhaps
> > > we need to fill in something. "type: %d", iter->ent->type ?
> > 
> > sounds ok :) attaching v2 patch
> hi, any feedback?

Ah, sorry, as this was a reply to the original thread, it didn't pop up
immediately.

> > 
> > 
> > ---
> > running following commands:
> > 
> >   # enable the binary option
> >   echo 1 > ./options/bin
> >   # disable context info option
> >   echo 0 > ./options/context-info 
> >   # tracing only events
> >   echo 1 > ./events/enable
> >   cat trace_pipe
> > 
> > is causing lockup (in NON preemptive kernels) inside
> > tracing_read_pipe function.
> > 
> > The reason are:
> >  - bin/hex/raw output functions for events are set to
> >    trace_nop_print function, which prints nothing and
> >    returns TRACE_TYPE_HANDLED value
> >  - LOST EVENT trace do not handle trace_seq overflow
> > 
> > These reasons force the while loop in tracing_read_pipe
> > function never to break.
> > 
> > The attached patch fixies handling of lost event trace, and
> > changes trace_nop_print to print minimal info, which is needed
> > for the correct tracing_read_pipe processing.
> > 
> > v2 changes:
> >  - omit the cond_resched changes by trace_nop_print changes
> >  - WARN changed to WARN_ONCE and added info to be able
> >    to find out the culprit

So this replaces both patches, correct?

Thanks,

-- Steve

Re: [PATCHv2] tracing - avoid soft lockup in trace_pipe

[Steven Rostedt]

On Thu, 2011-03-24 at 22:23 -0400, Steven Rostedt wrote:

> > > 
> > > 
> > > ---
> > > running following commands:
> > > 
> > >   # enable the binary option
> > >   echo 1 > ./options/bin
> > >   # disable context info option
> > >   echo 0 > ./options/context-info 
> > >   # tracing only events
> > >   echo 1 > ./events/enable
> > >   cat trace_pipe

OK, I'm trying to reproduce this, but I'm not able to.

I disabled preemption, recompiled and rebooted, and I did the above and
all I get is the numbers printing. But I can exit out with a simple ^C.

No soft lockups or anything.


I'm not saying that your patch is useless, it does seem to clean things
up. But I'm not seeing any lockups here.

The while loop will always exit when the ring buffer is empty.

You mean if the events are filling quicker than the loop then we have
this issue. Perhaps I'm not triggering enough events?

-- Steve

> > > 
> > > is causing lockup (in NON preemptive kernels) inside
> > > tracing_read_pipe function.
> > > 
> > > The reason are:
> > >  - bin/hex/raw output functions for events are set to
> > >    trace_nop_print function, which prints nothing and
> > >    returns TRACE_TYPE_HANDLED value
> > >  - LOST EVENT trace do not handle trace_seq overflow
> > > 
> > > These reasons force the while loop in tracing_read_pipe
> > > function never to break.
> > > 
> > > The attached patch fixies handling of lost event trace, and
> > > changes trace_nop_print to print minimal info, which is needed
> > > for the correct tracing_read_pipe processing.
> > > 
> > > v2 changes:
> > >  - omit the cond_resched changes by trace_nop_print changes
> > >  - WARN changed to WARN_ONCE and added info to be able
> > >    to find out the culprit
> 

[PATCHv3] tracing - avoid soft lockup in trace_pipe

[Jiri Olsa]

On Thu, Mar 24, 2011 at 11:14:49PM -0400, Steven Rostedt wrote:
> On Thu, 2011-03-24 at 22:23 -0400, Steven Rostedt wrote:
> 
> > > > 
> > > > 
> > > > ---
> > > > running following commands:
> > > > 
> > > >   # enable the binary option
> > > >   echo 1 > ./options/bin
> > > >   # disable context info option
> > > >   echo 0 > ./options/context-info 
> > > >   # tracing only events
> > > >   echo 1 > ./events/enable
> > > >   cat trace_pipe
> 
> OK, I'm trying to reproduce this, but I'm not able to.
> 
> I disabled preemption, recompiled and rebooted, and I did the above and
> all I get is the numbers printing. But I can exit out with a simple ^C.
> 
> No soft lockups or anything.
> 
> 
> I'm not saying that your patch is useless, it does seem to clean things
> up. But I'm not seeing any lockups here.
> 
> The while loop will always exit when the ring buffer is empty.
> 
> You mean if the events are filling quicker than the loop then we have
> this issue. Perhaps I'm not triggering enough events?

right, I'm now able to trigger the issue when running setting the tracing
as said in the patch and plus running this in few instacies:

(while [ 1 ]; do find / > /dev/null ; done) &

It's strange I did not need this last time.. not sure why :)


anyway, the original reproducer I picked this issue from is ltp suite:
http://sourceforge.net/projects/ltp/files/LTP%20Source/ltp-20100131/ltp-full-20100131.tgz/download

and running following test:
ltp-full-20101031/testcases/kernel/tracing/ftrace_stress_test/ftrace_stress_test.sh 

reproduces the issue all the time for me, and the patch fixies it.
Attaching patch rebased to the current master with changed comment.

thanks,
jirka


---
running following commands:

  # enable the binary option
  echo 1 > ./options/bin
  # disable context info option
  echo 0 > ./options/context-info 
  # tracing only events
  echo 1 > ./events/enable
  cat trace_pipe

plus forcing system to generate many tracing events,
is causing lockup (in NON preemptive kernels) inside
tracing_read_pipe function.

The issue is also easily reproduced by running ltp stress test.
(ftrace_stress_test.sh)

The reasons are:
 - bin/hex/raw output functions for events are set to
   trace_nop_print function, which prints nothing and
   returns TRACE_TYPE_HANDLED value
 - LOST EVENT trace do not handle trace_seq overflow

These reasons force the while loop in tracing_read_pipe
function never to break.

The attached patch fixies handling of lost event trace, and
changes trace_nop_print to print minimal info, which is needed
for the correct tracing_read_pipe processing.

v2 changes:
 - omit the cond_resched changes by trace_nop_print changes
 - WARN changed to WARN_ONCE and added info to be able
   to find out the culprit

v3 changes:
 - make more accurate patch comment

wbr,
jirka


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 kernel/trace/trace.c        |   15 ++++++++++++---
 kernel/trace/trace_output.c |    3 +++
 2 files changed, 15 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 9541c27..5af42f4 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2013,9 +2013,10 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
 {
 	enum print_line_t ret;
 
-	if (iter->lost_events)
-		trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
-				 iter->cpu, iter->lost_events);
+	if (iter->lost_events &&
+	    !trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
+				 iter->cpu, iter->lost_events))
+		return TRACE_TYPE_PARTIAL_LINE;
 
 	if (iter->trace && iter->trace->print_line) {
 		ret = iter->trace->print_line(iter);
@@ -3229,6 +3230,14 @@ waitagain:
 
 		if (iter->seq.len >= cnt)
 			break;
+
+		/*
+		 * Setting the full flag means we reached the trace_seq buffer
+		 * size and we should leave by partial output condition above.
+		 * One of the trace_seq_* functions is not used properly.
+		 */
+		WARN_ONCE(iter->seq.full, "full flag set for trace type %d",
+			  iter->ent->type);
 	}
 	trace_access_unlock(iter->cpu_file);
 	trace_event_read_unlock();
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 456be90..cf535cc 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -830,6 +830,9 @@ EXPORT_SYMBOL_GPL(unregister_ftrace_event);
 enum print_line_t trace_nop_print(struct trace_iterator *iter, int flags,
 				  struct trace_event *event)
 {
+	if (!trace_seq_printf(&iter->seq, "type: %d\n", iter->ent->type))
+		return TRACE_TYPE_PARTIAL_LINE;
+
 	return TRACE_TYPE_HANDLED;
 }
 
-- 
1.7.1

Re: [PATCHv3] tracing - avoid soft lockup in trace_pipe

[Steven Rostedt]

On Fri, 2011-03-25 at 12:05 +0100, Jiri Olsa wrote:

> (while [ 1 ]; do find / > /dev/null ; done) &

Just an FYI,

while :; ... does the same as while [ 1 ]; ...

;)

-- Steve

Re: [PATCHv3] tracing - avoid soft lockup in trace_pipe

[Steven Rostedt]

On Fri, 2011-03-25 at 12:05 +0100, Jiri Olsa wrote:

> right, I'm now able to trigger the issue when running setting the tracing
> as said in the patch and plus running this in few instacies:
> 
> (while [ 1 ]; do find / > /dev/null ; done) &

That didn't work for me either. But if I run hackbench 50 on the box,
then the trace does hang while it is running.

> 
> It's strange I did not need this last time.. not sure why :)
> 
> 
> anyway, the original reproducer I picked this issue from is ltp suite:
> http://sourceforge.net/projects/ltp/files/LTP%20Source/ltp-20100131/ltp-full-20100131.tgz/download
> 
> and running following test:
> ltp-full-20101031/testcases/kernel/tracing/ftrace_stress_test/ftrace_stress_test.sh 
> 
> reproduces the issue all the time for me, and the patch fixies it.
> Attaching patch rebased to the current master with changed comment.

Thanks, I'll queue it up for 2.6.40, as I do not think this is that
critical of a bug.

-- Steve

Re: [PATCHv3] tracing - avoid soft lockup in trace_pipe

[Jiri Olsa]

On Fri, Mar 25, 2011 at 11:49:37AM -0400, Steven Rostedt wrote:
> On Fri, 2011-03-25 at 12:05 +0100, Jiri Olsa wrote:
> 
> > right, I'm now able to trigger the issue when running setting the tracing
> > as said in the patch and plus running this in few instacies:
> > 
> > (while [ 1 ]; do find / > /dev/null ; done) &
> 
> That didn't work for me either. But if I run hackbench 50 on the box,
> then the trace does hang while it is running.
> 
> > 
> > It's strange I did not need this last time.. not sure why :)
> > 
> > 
> > anyway, the original reproducer I picked this issue from is ltp suite:
> > http://sourceforge.net/projects/ltp/files/LTP%20Source/ltp-20100131/ltp-full-20100131.tgz/download
> > 
> > and running following test:
> > ltp-full-20101031/testcases/kernel/tracing/ftrace_stress_test/ftrace_stress_test.sh 
> > 
> > reproduces the issue all the time for me, and the patch fixies it.
> > Attaching patch rebased to the current master with changed comment.
> 
> Thanks, I'll queue it up for 2.6.40, as I do not think this is that
> critical of a bug.
great, thanks

jirka

[tip:perf/core] tracing: Avoid soft lockup in trace_pipe

[tip-bot for Jiri Olsa]

Commit-ID:  ee5e51f51be755830f57445e268ba50e88ccbdbb
Gitweb:     http://git.kernel.org/tip/ee5e51f51be755830f57445e268ba50e88ccbdbb
Author:     Jiri Olsa <jolsa@redhat.com>
AuthorDate: Fri, 25 Mar 2011 12:05:18 +0100
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Mon, 4 Apr 2011 12:18:24 -0400

tracing: Avoid soft lockup in trace_pipe

running following commands:

  # enable the binary option
  echo 1 > ./options/bin
  # disable context info option
  echo 0 > ./options/context-info
  # tracing only events
  echo 1 > ./events/enable
  cat trace_pipe

plus forcing system to generate many tracing events,
is causing lockup (in NON preemptive kernels) inside
tracing_read_pipe function.

The issue is also easily reproduced by running ltp stress test.
(ftrace_stress_test.sh)

The reasons are:
 - bin/hex/raw output functions for events are set to
   trace_nop_print function, which prints nothing and
   returns TRACE_TYPE_HANDLED value
 - LOST EVENT trace do not handle trace_seq overflow

These reasons force the while loop in tracing_read_pipe
function never to break.

The attached patch fixies handling of lost event trace, and
changes trace_nop_print to print minimal info, which is needed
for the correct tracing_read_pipe processing.

v2 changes:
 - omit the cond_resched changes by trace_nop_print changes
 - WARN changed to WARN_ONCE and added info to be able
   to find out the culprit

v3 changes:
 - make more accurate patch comment

Signed-off-by: Jiri Olsa <jolsa@redhat.com>
LKML-Reference: <20110325110518.GC1922@jolsa.brq.redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace.c        |   15 ++++++++++++---
 kernel/trace/trace_output.c |    3 +++
 2 files changed, 15 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 9541c27..5af42f4 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2013,9 +2013,10 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
 {
 	enum print_line_t ret;
 
-	if (iter->lost_events)
-		trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
-				 iter->cpu, iter->lost_events);
+	if (iter->lost_events &&
+	    !trace_seq_printf(&iter->seq, "CPU:%d [LOST %lu EVENTS]\n",
+				 iter->cpu, iter->lost_events))
+		return TRACE_TYPE_PARTIAL_LINE;
 
 	if (iter->trace && iter->trace->print_line) {
 		ret = iter->trace->print_line(iter);
@@ -3229,6 +3230,14 @@ waitagain:
 
 		if (iter->seq.len >= cnt)
 			break;
+
+		/*
+		 * Setting the full flag means we reached the trace_seq buffer
+		 * size and we should leave by partial output condition above.
+		 * One of the trace_seq_* functions is not used properly.
+		 */
+		WARN_ONCE(iter->seq.full, "full flag set for trace type %d",
+			  iter->ent->type);
 	}
 	trace_access_unlock(iter->cpu_file);
 	trace_event_read_unlock();
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 456be90..cf535cc 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -830,6 +830,9 @@ EXPORT_SYMBOL_GPL(unregister_ftrace_event);
 enum print_line_t trace_nop_print(struct trace_iterator *iter, int flags,
 				  struct trace_event *event)
 {
+	if (!trace_seq_printf(&iter->seq, "type: %d\n", iter->ent->type))
+		return TRACE_TYPE_PARTIAL_LINE;
+
 	return TRACE_TYPE_HANDLED;
 }