[Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Frédéric Weisbecker]

[-- Attachment #1: Type: text/plain, Size: 798 bytes --]

Hi!

I tried to figure out the origin of the bug reported by Pekka Paalanen
about the broken pipe:
http://kerneltrap.org/mailarchive/linux-kernel/2008/9/15/3305224

When I add a trace_mark with the boot tracer, I had this same problem
but this time it was easy to reproduce.

When it calls a tracer's print_line callback, the print_trace_line function 
in trace.c returns whithout verifying if it could handle the entry properly.
And actually the seq could be empty.

For example the boot_tracer don't handle TRACE_PRINT. Nevertheless it
wants them to be printed as a default way.

So print_trace_line function should relay on the other functions which could handle
an output if one of them fail.

Reported-by: Pekka Paalanen <pq@iki.fi>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---

[-- Attachment #2: 1.diff --]
[-- Type: text/plain, Size: 1016 bytes --]

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 6ada059..50ac334 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1904,20 +1904,27 @@ static int trace_empty(struct trace_iterator *iter)
 
 static int print_trace_line(struct trace_iterator *iter)
 {
+	int ret;
+
 	if (iter->trace && iter->trace->print_line)
-		return iter->trace->print_line(iter);
+		if ((ret = iter->trace->print_line(iter)))
+			return ret;
 
 	if (trace_flags & TRACE_ITER_BIN)
-		return print_bin_fmt(iter);
+		if ((ret = print_bin_fmt(iter)))
+			return ret;
 
 	if (trace_flags & TRACE_ITER_HEX)
-		return print_hex_fmt(iter);
+		if ((ret = print_hex_fmt(iter)))
+			return ret;
 
 	if (trace_flags & TRACE_ITER_RAW)
-		return print_raw_fmt(iter);
+		if ((ret = print_raw_fmt(iter)))
+			return ret;
 
 	if (iter->iter_flags & TRACE_FILE_LAT_FMT)
-		return print_lat_fmt(iter, iter->idx, iter->cpu);
+		if ((ret = print_lat_fmt(iter, iter->idx, iter->cpu)))
+			return ret;
 
 	return print_trace_fmt(iter);
 }

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> Hi!
> 
> I tried to figure out the origin of the bug reported by Pekka Paalanen
> about the broken pipe:
> http://kerneltrap.org/mailarchive/linux-kernel/2008/9/15/3305224
> 
> When I add a trace_mark with the boot tracer, I had this same problem
> but this time it was easy to reproduce.
> 
> When it calls a tracer's print_line callback, the print_trace_line function 
> in trace.c returns whithout verifying if it could handle the entry properly.
> And actually the seq could be empty.
> 
> For example the boot_tracer don't handle TRACE_PRINT. Nevertheless it
> wants them to be printed as a default way.
> 
> So print_trace_line function should relay on the other functions which could handle
> an output if one of them fail.
> 
> Reported-by: Pekka Paalanen <pq@iki.fi>
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>

ah, nice! Applied to tip/tracing/ftrace.

Small nit: could you please send another patch on top of this patch that 
cleans up the checkpatch failures below?

checkpatch usage: you can run it like this:

  scripts/checkpatch.pl --file kernel/trace/*.c

and/or you can run it over patches as well before you submit them.

	Ingo

------------->
ERROR: do not use assignment in if condition
#43: FILE: kernel/trace/trace.c:1910:
+		if ((ret = iter->trace->print_line(iter)))

ERROR: do not use assignment in if condition
#48: FILE: kernel/trace/trace.c:1914:
+		if ((ret = print_bin_fmt(iter)))

ERROR: do not use assignment in if condition
#53: FILE: kernel/trace/trace.c:1918:
+		if ((ret = print_hex_fmt(iter)))

ERROR: do not use assignment in if condition
#58: FILE: kernel/trace/trace.c:1922:
+		if ((ret = print_raw_fmt(iter)))

ERROR: do not use assignment in if condition
#63: FILE: kernel/trace/trace.c:1926:
+		if ((ret = print_lat_fmt(iter, iter->idx, iter->cpu)))

total: 5 errors, 0 warnings, 0 checks, 32 lines checked

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Frédéric Weisbecker]

[-- Attachment #1: Type: text/plain, Size: 999 bytes --]

Ingo Molnar a écrit :
> ERROR: do not use assignment in if condition
> #43: FILE: kernel/trace/trace.c:1910:
> +		if ((ret = iter->trace->print_line(iter)))
> 
> ERROR: do not use assignment in if condition
> #48: FILE: kernel/trace/trace.c:1914:
> +		if ((ret = print_bin_fmt(iter)))
> 
> ERROR: do not use assignment in if condition
> #53: FILE: kernel/trace/trace.c:1918:
> +		if ((ret = print_hex_fmt(iter)))
> 
> ERROR: do not use assignment in if condition
> #58: FILE: kernel/trace/trace.c:1922:
> +		if ((ret = print_raw_fmt(iter)))
> 
> ERROR: do not use assignment in if condition
> #63: FILE: kernel/trace/trace.c:1926:
> +		if ((ret = print_lat_fmt(iter, iter->idx, iter->cpu)))
> 
> total: 5 errors, 0 warnings, 0 checks, 32 lines checked
> 
>

Oops sorry. Here it is:

Correct the coding style in the commit 
803294369973b740f4c346553850b56e4b0c3c8a
And remove the ret variable since print functions
only return 0 or 1.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---

 


[-- Attachment #2: 1.diff --]
[-- Type: text/plain, Size: 1071 bytes --]

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 50ac334..e845664 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1904,27 +1904,25 @@ static int trace_empty(struct trace_iterator *iter)
 
 static int print_trace_line(struct trace_iterator *iter)
 {
-	int ret;
-
 	if (iter->trace && iter->trace->print_line)
-		if ((ret = iter->trace->print_line(iter)))
-			return ret;
+		if (iter->trace->print_line(iter))
+			return 1;
 
 	if (trace_flags & TRACE_ITER_BIN)
-		if ((ret = print_bin_fmt(iter)))
-			return ret;
+		if (print_bin_fmt(iter))
+			return 1;
 
 	if (trace_flags & TRACE_ITER_HEX)
-		if ((ret = print_hex_fmt(iter)))
-			return ret;
+		if (print_hex_fmt(iter))
+			return 1;
 
 	if (trace_flags & TRACE_ITER_RAW)
-		if ((ret = print_raw_fmt(iter)))
-			return ret;
+		if (print_raw_fmt(iter))
+			return 1;
 
 	if (iter->iter_flags & TRACE_FILE_LAT_FMT)
-		if ((ret = print_lat_fmt(iter, iter->idx, iter->cpu)))
-			return ret;
+		if (print_lat_fmt(iter, iter->idx, iter->cpu))
+			return 1;
 
 	return print_trace_fmt(iter);
 }

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Pekka Paalanen]

On Thu, 25 Sep 2008 15:56:03 +0100
Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> Correct the coding style in the commit 
> 803294369973b740f4c346553850b56e4b0c3c8a
> And remove the ret variable since print functions
> only return 0 or 1.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---

Frederic, in the future, could you just copy the patch
into the email body (watch out for line wraps and other damage),
attachments are not usually included in "reply with quote",
so commenting on them is a tiny bit harder. Thanks.

> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 6ada059..50ac334 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -1904,20 +1904,27 @@ static int trace_empty(struct trace_iterator *iter)
>  
>  static int print_trace_line(struct trace_iterator *iter)
>  {
> +	int ret;
> +
>  	if (iter->trace && iter->trace->print_line)
> -		return iter->trace->print_line(iter);
> +		if ((ret = iter->trace->print_line(iter)))
> +			return ret;

NACK.

IMHO this breaks the trace_seq handling. trace_seq may contain
the output of several entries, as far as they fit in it as a whole.
E.g. trace_seq_printf() does not print partial lines but returns 0,
so that the entry is not consumed right now. The user space reader
must consume trace_seq content, before trace_seq_printf()
is attempted again, hopefully with enough space in trace_seq to
succeed. See tracing_read_pipe().

print_line() callback works the same way. Returning 0 means "could
not print it this time, call me back later". You can't use that to
say "use the default output function instead". Note, that possibly
the default output function will fail, too, so it could actually
try many of the default output functions and still fail, eventually
leading by luck to the correct behaviour in most cases.

Note, that mmiotrace follows this convention: it deliberatly
returns 1 without processing when it wants the entry discarded, and
it returns 0 when there was not enough space to process the entry.
This is explained in my other email.

What is the supposed return value of print_trace_line(), I do not
know. Looks like it is used as boolean, so maybe the type should be
changed to bool. Unless we want three options:
- 0: could not print now, try again
- 1: success, entry processed, it can be thrown away
- 2: fall back to the default output formatting
Cases 0 and 1 must exist like that, I do not know how useful 2 is,
but it must be distinct from the first two.


Thanks.

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Frédéric Weisbecker]

2008/9/25 Pekka Paalanen <pq@iki.fi>:
> Frederic, in the future, could you just copy the patch
> into the email body (watch out for line wraps and other damage),
> attachments are not usually included in "reply with quote",
> so commenting on them is a tiny bit harder. Thanks.

Ok. I think I have to change my email client. I'm starting to get rid of all
these blank lines or other issues with the patches...
I will think about it...

> IMHO this breaks the trace_seq handling. trace_seq may contain
> the output of several entries, as far as they fit in it as a whole.
> E.g. trace_seq_printf() does not print partial lines but returns 0,
> so that the entry is not consumed right now. The user space reader
> must consume trace_seq content, before trace_seq_printf()
> is attempted again, hopefully with enough space in trace_seq to
> succeed. See tracing_read_pipe().
> print_line() callback works the same way. Returning 0 means "could
> not print it this time, call me back later". You can't use that to
> say "use the default output function instead". Note, that possibly
> the default output function will fail, too, so it could actually
> try many of the default output functions and still fail, eventually
> leading by luck to the correct behaviour in most cases.
> Note, that mmiotrace follows this convention: it deliberatly
> returns 1 without processing when it wants the entry discarded, and
> it returns 0 when there was not enough space to process the entry.
> This is explained in my other email.

Hmm you're right. I didn't thought about the partial line which must
not be printed.
The problem is that with this convention, 0 means two things: "I will
handle this entry
later" or "I can't handle it".
But if you return 0 because you can't handle it, and if the current
len of the seq is 0, the
pipe will be broken.

> What is the supposed return value of print_trace_line(), I do not
> know. Looks like it is used as boolean, so maybe the type should be
> changed to bool. Unless we want three options:
> - 0: could not print now, try again
> - 1: success, entry processed, it can be thrown away
> - 2: fall back to the default output formatting
> Cases 0 and 1 must exist like that, I do not know how useful 2 is,
> but it must be distinct from the first two.

I think it's a good solution.

Thanks to you! I didn't see these issues.

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Pekka Paalanen]

On Thu, 25 Sep 2008 17:33:02 +0200
"Frédéric Weisbecker" <fweisbec@gmail.com> wrote:

> 2008/9/25 Pekka Paalanen <pq@iki.fi>:
> > IMHO this breaks the trace_seq handling. trace_seq may contain
> > the output of several entries, as far as they fit in it as a whole.
> > E.g. trace_seq_printf() does not print partial lines but returns 0,
> > so that the entry is not consumed right now. The user space reader
> > must consume trace_seq content, before trace_seq_printf()
> > is attempted again, hopefully with enough space in trace_seq to
> > succeed. See tracing_read_pipe().
> > print_line() callback works the same way. Returning 0 means "could
> > not print it this time, call me back later". You can't use that to
> > say "use the default output function instead". Note, that possibly
> > the default output function will fail, too, so it could actually
> > try many of the default output functions and still fail, eventually
> > leading by luck to the correct behaviour in most cases.
> > Note, that mmiotrace follows this convention: it deliberatly
> > returns 1 without processing when it wants the entry discarded, and
> > it returns 0 when there was not enough space to process the entry.
> > This is explained in my other email.
> 
> Hmm you're right. I didn't thought about the partial line which must
> not be printed.
> The problem is that with this convention, 0 means two things: "I will
> handle this entry
> later" or "I can't handle it".
> But if you return 0 because you can't handle it, and if the current
> len of the seq is 0, the
> pipe will be broken.

My understanding is that the pipe will be broken only, if the trace
framework believes tracing is disabled. Recall the discussion about
tracer_enabled = 0. Which is a bug, and I hoped Steven would have
commented on how to fix that properly.

Or was it fixed already, and this is a different issue?
I didn't notice.

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Frédéric Weisbecker]

2008/9/25 Pekka Paalanen <pq@iki.fi>:
> My understanding is that the pipe will be broken only, if the trace
> framework believes tracing is disabled. Recall the discussion about
> tracer_enabled = 0. Which is a bug, and I hoped Steven would have
> commented on how to fix that properly.
>
> Or was it fixed already, and this is a different issue?
> I didn't notice.

Actually there was two bugs which broke the pipe:
_ As you say the old one when none tracer put tracer_enabled = 0
_ And the new one I described here.

I think the first is fixed since none tracer has been replaced by "nop
tracer" (a recently implemented) which doesn't touch
tracer_enabled at all.

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Pekka Paalanen]

On Thu, 25 Sep 2008 17:56:32 +0200
"Frédéric Weisbecker" <fweisbec@gmail.com> wrote:

> 2008/9/25 Pekka Paalanen <pq@iki.fi>:
> > My understanding is that the pipe will be broken only, if the trace
> > framework believes tracing is disabled. Recall the discussion about
> > tracer_enabled = 0. Which is a bug, and I hoped Steven would have
> > commented on how to fix that properly.
> >
> > Or was it fixed already, and this is a different issue?
> > I didn't notice.
> 
> Actually there was two bugs which broke the pipe:
> _ As you say the old one when none tracer put tracer_enabled = 0
> _ And the new one I described here.
> 
> I think the first is fixed since none tracer has been replaced by "nop
> tracer" (a recently implemented) which doesn't touch
> tracer_enabled at all.

Oh cool, sounds like I should try linux-next when I can.

-- 
Pekka Paalanen
http://www.iki.fi/pq/

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Frédéric Weisbecker]

2008/9/25 Pekka Paalanen <pq@iki.fi>:
> Oh cool, sounds like I should try linux-next when I can.


It is on -tip if you want :)

So, unless someone is opposed to. I will send a patch which define
three possible values
for the print_line callback. I will define these values on trace.h
Why not:

#define TRACE_TYPE_PARTIAL_LINE 0
#define TRACE_TYPE_HANDLED 1
#define TRACE_TYPE_UNHANDLED 2   => will relay on default functions

Hmm I'm questionning about the relevance of this kind of patch since
the tracing API is in refactoring...

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> 2008/9/25 Pekka Paalanen <pq@iki.fi>:
> > Oh cool, sounds like I should try linux-next when I can.
> 
> 
> It is on -tip if you want :)
> 
> So, unless someone is opposed to. I will send a patch which define
> three possible values
> for the print_line callback. I will define these values on trace.h
> Why not:
> 
> #define TRACE_TYPE_PARTIAL_LINE 0
> #define TRACE_TYPE_HANDLED 1
> #define TRACE_TYPE_UNHANDLED 2   => will relay on default functions
> 
> Hmm I'm questionning about the relevance of this kind of patch since 
> the tracing API is in refactoring...

dont worry about that aspect too much, the ring buffer API will be a 
transparent replacement, so try to iterate whatever is there at the 
moment towards perfection :)

	Ingo

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> So, unless someone is opposed to. I will send a patch which define 
> three possible values for the print_line callback. I will define these 
> values on trace.h Why not:
> 
> #define TRACE_TYPE_PARTIAL_LINE 0
> #define TRACE_TYPE_HANDLED 1
> #define TRACE_TYPE_UNHANDLED 2   => will relay on default functions
> 
> Hmm I'm questionning about the relevance of this kind of patch since 
> the tracing API is in refactoring...

btw., i removed the 2 patches that got NAK-ed by Pekka from tip/master - 
could you please re-send whatever consensus patch you come up with 
Pekka?

	Ingo

Re: [Patch -tip 1/3] Tracing/ftrace: Relay unhandled entry output

[Frédéric Weisbecker]

> dont worry about that aspect too much, the ring buffer API will be a
> transparent replacement, so try to iterate whatever is there at the
> moment towards perfection :)

Ok Thanks Ingo :-)