[Patch 1/2] ksym_tracer:Fix line-wrapping after removal of ksym tracer entry

[Patch 1/2] ksym_tracer:Fix line-wrapping after removal of ksym tracer entry

[K.Prasad]

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

Removal of a ksym entry results in missing information and an early return with
TRACE_TYPE_PARTIAL_LINE code (minus the line return). This patch modifies the
output function to unconditionally add a line return irrespective of the
return code. 

Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
---
 kernel/trace/trace_ksym.c |   27 +++++++++++++++------------
 1 file changed, 15 insertions(+), 12 deletions(-)

Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
===================================================================
--- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
+++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
@@ -391,29 +391,32 @@ static enum print_line_t ksym_trace_outp
 
 	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ", field->p_name,
 				entry->pid, iter->cpu, field->ksym_name);
-	if (!ret)
-		return TRACE_TYPE_PARTIAL_LINE;
+	if (!ret) {
+		ret = TRACE_TYPE_PARTIAL_LINE;
+		goto err_ret;
+	}
 
+	ret = TRACE_TYPE_PARTIAL_LINE;
 	switch (field->ksym_hbp->info.type) {
 	case HW_BREAKPOINT_WRITE:
-		ret = trace_seq_printf(s, " W  ");
+		if (!trace_seq_printf(s, " W  "))
+			goto err_ret;
 		break;
 	case HW_BREAKPOINT_RW:
-		ret = trace_seq_printf(s, " RW ");
+		if (!trace_seq_printf(s, " RW  "))
+			goto err_ret;
 		break;
 	default:
-		return TRACE_TYPE_PARTIAL_LINE;
+		goto err_ret;
 	}
 
-	if (!ret)
-		return TRACE_TYPE_PARTIAL_LINE;
-
 	sprint_symbol(str, field->ip);
 	ret = trace_seq_printf(s, "%-20s\n", str);
-	if (!ret)
-		return TRACE_TYPE_PARTIAL_LINE;
-
-	return TRACE_TYPE_HANDLED;
+	if (ret)
+		return TRACE_TYPE_HANDLED;
+err_ret:
+	trace_seq_printf(s, "\n");
+	return ret;
 }
 
 struct tracer ksym_tracer __read_mostly =

[Patch 2/2] ksym_tracer:Handle machine stall when cat trace_pipe for ksym tracer

[K.Prasad]

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

'trace_pipe' does not handle a TRACE_TYPE_PARTIAL_LINE well and causes the
machine to stall. While a TRACE_TYPE_UNHANDLED return causes the tracer to
output unrelated data, a TRACE_TYPE_HANDLED return presents a clean output
(minus all partial traces).

Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
---
 kernel/trace/trace_ksym.c |    6 ++++++
 1 file changed, 6 insertions(+)

Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
===================================================================
--- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
+++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
@@ -389,6 +389,12 @@ static enum print_line_t ksym_trace_outp
 
 	trace_assign_type(field, entry);
 
+	/*
+	 * Return early without any output if we don't have sufficient
+	 * information
+	 */
+	if ((!field->ksym_hbp->info.type) || (!field->ip))
+		return TRACE_TYPE_HANDLED;
 	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ", field->p_name,
 				entry->pid, iter->cpu, field->ksym_name);
 	if (!ret) {

Re: [Patch 1/2] ksym_tracer:Fix line-wrapping after removal of ksym tracer entry

[Frederic Weisbecker]

On Wed, Jun 17, 2009 at 04:35:04AM +0530, K.Prasad wrote:
> Removal of a ksym entry results in missing information and an early return with
> TRACE_TYPE_PARTIAL_LINE code (minus the line return). This patch modifies the
> output function to unconditionally add a line return irrespective of the
> return code. 
> 
> Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
> ---
>  kernel/trace/trace_ksym.c |   27 +++++++++++++++------------
>  1 file changed, 15 insertions(+), 12 deletions(-)
> 
> Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> ===================================================================
> --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> @@ -391,29 +391,32 @@ static enum print_line_t ksym_trace_outp
>  
>  	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ", field->p_name,
>  				entry->pid, iter->cpu, field->ksym_name);
> -	if (!ret)
> -		return TRACE_TYPE_PARTIAL_LINE;
> +	if (!ret) {
> +		ret = TRACE_TYPE_PARTIAL_LINE;
> +		goto err_ret;
> +	}
>  
> +	ret = TRACE_TYPE_PARTIAL_LINE;
>  	switch (field->ksym_hbp->info.type) {
>  	case HW_BREAKPOINT_WRITE:
> -		ret = trace_seq_printf(s, " W  ");
> +		if (!trace_seq_printf(s, " W  "))
> +			goto err_ret;
>  		break;
>  	case HW_BREAKPOINT_RW:
> -		ret = trace_seq_printf(s, " RW ");
> +		if (!trace_seq_printf(s, " RW  "))
> +			goto err_ret;
>  		break;
>  	default:
> -		return TRACE_TYPE_PARTIAL_LINE;
> +		goto err_ret;
>  	}
>  
> -	if (!ret)
> -		return TRACE_TYPE_PARTIAL_LINE;
> -
>  	sprint_symbol(str, field->ip);
>  	ret = trace_seq_printf(s, "%-20s\n", str);
> -	if (!ret)
> -		return TRACE_TYPE_PARTIAL_LINE;
> -
> -	return TRACE_TYPE_HANDLED;
> +	if (ret)
> +		return TRACE_TYPE_HANDLED;
> +err_ret:
> +	trace_seq_printf(s, "\n");
> +	return ret;


As told in my email just before, TRACE_TYPE_PARTIAL_LINE
won't print a truncated line or a partial line. Instead, it
will be ignored and entirely retried later.
Then your newline will be ignored.

..unless we have a bug in trace.c

I'm not sure what it the origin of the concatenated printed entries
Ingo has reported.

Did you reproduce it and then this patch fixed it?



>  }
>  
>  struct tracer ksym_tracer __read_mostly =
> 

Re: [Patch 2/2] ksym_tracer:Handle machine stall when cat trace_pipe for ksym tracer

[Frederic Weisbecker]

On Wed, Jun 17, 2009 at 04:35:27AM +0530, K.Prasad wrote:
> 'trace_pipe' does not handle a TRACE_TYPE_PARTIAL_LINE well and causes the
> machine to stall.



No, if it stalls here, it means it handles it well :)



> While a TRACE_TYPE_UNHANDLED return causes the tracer to
> output unrelated data, a TRACE_TYPE_HANDLED return presents a clean output
> (minus all partial traces).
> 
> Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
> ---
>  kernel/trace/trace_ksym.c |    6 ++++++
>  1 file changed, 6 insertions(+)
> 
> Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> ===================================================================
> --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> @@ -389,6 +389,12 @@ static enum print_line_t ksym_trace_outp
>  
>  	trace_assign_type(field, entry);
>  
> +	/*
> +	 * Return early without any output if we don't have sufficient
> +	 * information
> +	 */
> +	if ((!field->ksym_hbp->info.type) || (!field->ip))
> +		return TRACE_TYPE_HANDLED;



Yeah that seems a good fix. But such silent ignored traces may
hide bugs (current or futures).
Is it a common situation to have a zero ip or an undefined
breakpoint type? How can that happen?

Thanks.



>  	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ", field->p_name,
>  				entry->pid, iter->cpu, field->ksym_name);
>  	if (!ret) {
> 

Re: [Patch 1/2] ksym_tracer:Fix line-wrapping after removal of ksym tracer entry

[K.Prasad]

On Wed, Jun 17, 2009 at 07:06:07AM +0200, Frederic Weisbecker wrote:
> On Wed, Jun 17, 2009 at 04:35:04AM +0530, K.Prasad wrote:
> > Removal of a ksym entry results in missing information and an early return with
> > TRACE_TYPE_PARTIAL_LINE code (minus the line return). This patch modifies the
> > output function to unconditionally add a line return irrespective of the
> > return code. 
> > 
> > Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
> > ---
> >  kernel/trace/trace_ksym.c |   27 +++++++++++++++------------
> >  1 file changed, 15 insertions(+), 12 deletions(-)
> > 
> > Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > ===================================================================
> > --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> > +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > @@ -391,29 +391,32 @@ static enum print_line_t ksym_trace_outp
> >  
> >  	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ", field->p_name,
> >  				entry->pid, iter->cpu, field->ksym_name);
> > -	if (!ret)
> > -		return TRACE_TYPE_PARTIAL_LINE;
> > +	if (!ret) {
> > +		ret = TRACE_TYPE_PARTIAL_LINE;
> > +		goto err_ret;
> > +	}
> >  
> > +	ret = TRACE_TYPE_PARTIAL_LINE;
> >  	switch (field->ksym_hbp->info.type) {
> >  	case HW_BREAKPOINT_WRITE:
> > -		ret = trace_seq_printf(s, " W  ");
> > +		if (!trace_seq_printf(s, " W  "))
> > +			goto err_ret;
> >  		break;
> >  	case HW_BREAKPOINT_RW:
> > -		ret = trace_seq_printf(s, " RW ");
> > +		if (!trace_seq_printf(s, " RW  "))
> > +			goto err_ret;
> >  		break;
> >  	default:
> > -		return TRACE_TYPE_PARTIAL_LINE;
> > +		goto err_ret;
> >  	}
> >  
> > -	if (!ret)
> > -		return TRACE_TYPE_PARTIAL_LINE;
> > -
> >  	sprint_symbol(str, field->ip);
> >  	ret = trace_seq_printf(s, "%-20s\n", str);
> > -	if (!ret)
> > -		return TRACE_TYPE_PARTIAL_LINE;
> > -
> > -	return TRACE_TYPE_HANDLED;
> > +	if (ret)
> > +		return TRACE_TYPE_HANDLED;
> > +err_ret:
> > +	trace_seq_printf(s, "\n");
> > +	return ret;
> 
> 
> As told in my email just before, TRACE_TYPE_PARTIAL_LINE
> won't print a truncated line or a partial line. Instead, it
> will be ignored and entirely retried later.
> Then your newline will be ignored.
> 
> ..unless we have a bug in trace.c
> 

Yes, I see that TRACE_TYPE_PARTIAL_LINE isn't the cause but the early
return that happens (without printing the \n character) because of
missing data.

> I'm not sure what it the origin of the concatenated printed entries
> Ingo has reported.
> 

The existing code in -tip reads like this:

397         switch (field->ksym_hbp->info.type) {
398         case HW_BREAKPOINT_WRITE:
399                 ret = trace_seq_printf(s, " W  ");
400                 break;
401         case HW_BREAKPOINT_RW:
402                 ret = trace_seq_printf(s, " RW ");
403                 break;
404         default:
405                 return TRACE_TYPE_PARTIAL_LINE;
406         }
407 
408         if (!ret)
409                 return TRACE_TYPE_PARTIAL_LINE;
410 
411         sprint_symbol(str, field->ip);
412         ret = trace_seq_printf(s, "%-20s\n", str);
413         if (!ret)
414                 return TRACE_TYPE_PARTIAL_LINE;
415 

Si, if the control returns early at line 405 it skips the line at 412
which prints a newline character. Line 405 is executed if
field->ksym_hbp->info.type is 0 which is true for an entry that is
removed from the filter (e.g. echo jiffies:--- > ksym_trace_filter) and
no amount of retries will help it get some new data (as it is already
free-ed).

> Did you reproduce it and then this patch fixed it?
>

Yes, it was reproduced and tested but actually it is the second patch that
helps resolve this. The "trace_seq_printf(s, "\n");" isn't required at
all.

I will re-send a new patch to you which fixes the line concatenation and
machine stall issue (after symbol removal in ksym_tracer).

Thanks,
K.Prasad

Re: [Patch 2/2] ksym_tracer:Handle machine stall when cat trace_pipe for ksym tracer

[K.Prasad]

On Wed, Jun 17, 2009 at 07:12:36AM +0200, Frederic Weisbecker wrote:
> On Wed, Jun 17, 2009 at 04:35:27AM +0530, K.Prasad wrote:
> > 'trace_pipe' does not handle a TRACE_TYPE_PARTIAL_LINE well and causes the
> > machine to stall.
> 
> 
> 
> No, if it stalls here, it means it handles it well :)
>

Okay. As stated earlier, the cause is an incorrect
TRACE_TYPE_PARTIAL_LINE return.
 
> > While a TRACE_TYPE_UNHANDLED return causes the tracer to
> > output unrelated data, a TRACE_TYPE_HANDLED return presents a clean output
> > (minus all partial traces).
> > 
> > Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
> > ---
> >  kernel/trace/trace_ksym.c |    6 ++++++
> >  1 file changed, 6 insertions(+)
> > 
> > Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > ===================================================================
> > --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> > +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > @@ -389,6 +389,12 @@ static enum print_line_t ksym_trace_outp
> >  
> >  	trace_assign_type(field, entry);
> >  
> > +	/*
> > +	 * Return early without any output if we don't have sufficient
> > +	 * information
> > +	 */
> > +	if ((!field->ksym_hbp->info.type) || (!field->ip))
> > +		return TRACE_TYPE_HANDLED;
> 
> 
> 
> Yeah that seems a good fix. But such silent ignored traces may
> hide bugs (current or futures).
> Is it a common situation to have a zero ip or an undefined
> breakpoint type? How can that happen?
> 
> Thanks.
>

When a symbol is removed from ksym's trace list, it causes
unregistration of the breakpoints and the breakpoint structure is
kfree()-ed.

Now, looking at the relevant code in ksym_hbp_handler() in trace_ksym.c

 88         entry = ring_buffer_event_data(event);
 89         strlcpy(entry->ksym_name, hbp->info.name, KSYM_SYMBOL_LEN);
 90         entry->ksym_hbp = hbp;
 91         entry->ip = instruction_pointer(regs);
 92         strlcpy(entry->p_name, current->comm, TASK_COMM_LEN);

While the ksym_name and p_name fields are copied into the ring buffer,
only a pointer to the structure is provided (in line 90). So, when
ksym_hbp is unregistered the fields contained in it, namely 'type' and
'ip' are lost (I'm not sure how the fields beyond 'field->ksym_hbp' is
accessible in ksym_trace_output() when it is supposed to be already
free).

This patch would cause an early return when such is the case. I also
plan to remove the 'default case' in ksym_trace_output() as it was meant
to handle a zero value for type (other values are eliminated at the time
of breakpoint registration itself).

Please find a patch below that eliminates the two issues of output
concatenation and machine stall, excepting for one issue which I'm
unable to reason out.

A 'cat trace_pipe' done immediately after removal of an entry (without a
preceding 'cat trace') terminates only with a SIGTERM (kill <pid>) and
not a SIGINT (Ctrl+C). However, if the trace buffer receives any new
data subsequently, it responds to the Ctrl+C signal. I would be glad to
receive your suggestions in this regard.

===================================================================
--- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
+++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
@@ -388,6 +388,12 @@ static enum print_line_t ksym_trace_outp
 		return TRACE_TYPE_UNHANDLED;
 
 	trace_assign_type(field, entry);
+	/*
+	 * Return early without any output if we don't have sufficient
+	 * information
+	 */
+	if ((!field->ksym_hbp->info.type) || (!field->ip))
+		return TRACE_TYPE_HANDLED;
 
 	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ",
field->p_name,
 				entry->pid, iter->cpu,
field->ksym_name);
@@ -401,10 +407,7 @@ static enum print_line_t ksym_trace_outp
 	case HW_BREAKPOINT_RW:
 		ret = trace_seq_printf(s, " RW ");
 		break;
-	default:
-		return TRACE_TYPE_PARTIAL_LINE;
 	}
-
 	if (!ret)
 		return TRACE_TYPE_PARTIAL_LINE;
 
Thanks,
K.Prasad

Re: [Patch 1/2] ksym_tracer:Fix line-wrapping after removal of ksym tracer entry

[Frederic Weisbecker]

On Thu, Jun 18, 2009 at 02:08:52PM +0530, K.Prasad wrote:
> On Wed, Jun 17, 2009 at 07:06:07AM +0200, Frederic Weisbecker wrote:
> > On Wed, Jun 17, 2009 at 04:35:04AM +0530, K.Prasad wrote:
> > > Removal of a ksym entry results in missing information and an early return with
> > > TRACE_TYPE_PARTIAL_LINE code (minus the line return). This patch modifies the
> > > output function to unconditionally add a line return irrespective of the
> > > return code. 
> > > 
> > > Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
> > > ---
> > >  kernel/trace/trace_ksym.c |   27 +++++++++++++++------------
> > >  1 file changed, 15 insertions(+), 12 deletions(-)
> > > 
> > > Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > > ===================================================================
> > > --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> > > +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > > @@ -391,29 +391,32 @@ static enum print_line_t ksym_trace_outp
> > >  
> > >  	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ", field->p_name,
> > >  				entry->pid, iter->cpu, field->ksym_name);
> > > -	if (!ret)
> > > -		return TRACE_TYPE_PARTIAL_LINE;
> > > +	if (!ret) {
> > > +		ret = TRACE_TYPE_PARTIAL_LINE;
> > > +		goto err_ret;
> > > +	}
> > >  
> > > +	ret = TRACE_TYPE_PARTIAL_LINE;
> > >  	switch (field->ksym_hbp->info.type) {
> > >  	case HW_BREAKPOINT_WRITE:
> > > -		ret = trace_seq_printf(s, " W  ");
> > > +		if (!trace_seq_printf(s, " W  "))
> > > +			goto err_ret;
> > >  		break;
> > >  	case HW_BREAKPOINT_RW:
> > > -		ret = trace_seq_printf(s, " RW ");
> > > +		if (!trace_seq_printf(s, " RW  "))
> > > +			goto err_ret;
> > >  		break;
> > >  	default:
> > > -		return TRACE_TYPE_PARTIAL_LINE;
> > > +		goto err_ret;
> > >  	}
> > >  
> > > -	if (!ret)
> > > -		return TRACE_TYPE_PARTIAL_LINE;
> > > -
> > >  	sprint_symbol(str, field->ip);
> > >  	ret = trace_seq_printf(s, "%-20s\n", str);
> > > -	if (!ret)
> > > -		return TRACE_TYPE_PARTIAL_LINE;
> > > -
> > > -	return TRACE_TYPE_HANDLED;
> > > +	if (ret)
> > > +		return TRACE_TYPE_HANDLED;
> > > +err_ret:
> > > +	trace_seq_printf(s, "\n");
> > > +	return ret;
> > 
> > 
> > As told in my email just before, TRACE_TYPE_PARTIAL_LINE
> > won't print a truncated line or a partial line. Instead, it
> > will be ignored and entirely retried later.
> > Then your newline will be ignored.
> > 
> > ..unless we have a bug in trace.c
> > 
> 
> Yes, I see that TRACE_TYPE_PARTIAL_LINE isn't the cause but the early
> return that happens (without printing the \n character) because of
> missing data.
> 
> > I'm not sure what it the origin of the concatenated printed entries
> > Ingo has reported.
> > 
> 
> The existing code in -tip reads like this:
> 
> 397         switch (field->ksym_hbp->info.type) {
> 398         case HW_BREAKPOINT_WRITE:
> 399                 ret = trace_seq_printf(s, " W  ");
> 400                 break;
> 401         case HW_BREAKPOINT_RW:
> 402                 ret = trace_seq_printf(s, " RW ");
> 403                 break;
> 404         default:
> 405                 return TRACE_TYPE_PARTIAL_LINE;
> 406         }
> 407 
> 408         if (!ret)
> 409                 return TRACE_TYPE_PARTIAL_LINE;
> 410 
> 411         sprint_symbol(str, field->ip);
> 412         ret = trace_seq_printf(s, "%-20s\n", str);
> 413         if (!ret)
> 414                 return TRACE_TYPE_PARTIAL_LINE;
> 415 
> 
> Si, if the control returns early at line 405 it skips the line at 412
> which prints a newline character. Line 405 is executed if
> field->ksym_hbp->info.type is 0 which is true for an entry that is
> removed from the filter (e.g. echo jiffies:--- > ksym_trace_filter) and
> no amount of retries will help it get some new data (as it is already
> free-ed).



Ok, I guess a straightforward copy to the ring buffer (and not
a pointer to your info) would solve it.


 
> > Did you reproduce it and then this patch fixed it?
> >
> 
> Yes, it was reproduced and tested but actually it is the second patch that
> helps resolve this. The "trace_seq_printf(s, "\n");" isn't required at
> all.
> 
> I will re-send a new patch to you which fixes the line concatenation and
> machine stall issue (after symbol removal in ksym_tracer).


Ok.

Thanks.


> Thanks,
> K.Prasad
> 

Re: [Patch 2/2] ksym_tracer:Handle machine stall when cat trace_pipe for ksym tracer

[Frederic Weisbecker]

On Thu, Jun 18, 2009 at 10:55:22PM +0530, K.Prasad wrote:
> On Wed, Jun 17, 2009 at 07:12:36AM +0200, Frederic Weisbecker wrote:
> > On Wed, Jun 17, 2009 at 04:35:27AM +0530, K.Prasad wrote:
> > > 'trace_pipe' does not handle a TRACE_TYPE_PARTIAL_LINE well and causes the
> > > machine to stall.
> > 
> > 
> > 
> > No, if it stalls here, it means it handles it well :)
> >
> 
> Okay. As stated earlier, the cause is an incorrect
> TRACE_TYPE_PARTIAL_LINE return.
>  
> > > While a TRACE_TYPE_UNHANDLED return causes the tracer to
> > > output unrelated data, a TRACE_TYPE_HANDLED return presents a clean output
> > > (minus all partial traces).
> > > 
> > > Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
> > > ---
> > >  kernel/trace/trace_ksym.c |    6 ++++++
> > >  1 file changed, 6 insertions(+)
> > > 
> > > Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > > ===================================================================
> > > --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> > > +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > > @@ -389,6 +389,12 @@ static enum print_line_t ksym_trace_outp
> > >  
> > >  	trace_assign_type(field, entry);
> > >  
> > > +	/*
> > > +	 * Return early without any output if we don't have sufficient
> > > +	 * information
> > > +	 */
> > > +	if ((!field->ksym_hbp->info.type) || (!field->ip))
> > > +		return TRACE_TYPE_HANDLED;
> > 
> > 
> > 
> > Yeah that seems a good fix. But such silent ignored traces may
> > hide bugs (current or futures).
> > Is it a common situation to have a zero ip or an undefined
> > breakpoint type? How can that happen?
> > 
> > Thanks.
> >
> 
> When a symbol is removed from ksym's trace list, it causes
> unregistration of the breakpoints and the breakpoint structure is
> kfree()-ed.
> 
> Now, looking at the relevant code in ksym_hbp_handler() in trace_ksym.c
> 
>  88         entry = ring_buffer_event_data(event);
>  89         strlcpy(entry->ksym_name, hbp->info.name, KSYM_SYMBOL_LEN);
>  90         entry->ksym_hbp = hbp;
>  91         entry->ip = instruction_pointer(regs);
>  92         strlcpy(entry->p_name, current->comm, TASK_COMM_LEN);
> 
> While the ksym_name and p_name fields are copied into the ring buffer,
> only a pointer to the structure is provided (in line 90). So, when
> ksym_hbp is unregistered the fields contained in it, namely 'type' and
> 'ip' are lost (I'm not sure how the fields beyond 'field->ksym_hbp' is
> accessible in ksym_trace_output() when it is supposed to be already
> free).



If they are freed, they could still be available if the memory place
hasn't been touched by someone else since you kfree'ed it.

But that's buggy and dangerous :)



> This patch would cause an early return when such is the case. I also
> plan to remove the 'default case' in ksym_trace_output() as it was meant
> to handle a zero value for type (other values are eliminated at the time
> of breakpoint registration itself).
> 
> Please find a patch below that eliminates the two issues of output
> concatenation and machine stall, excepting for one issue which I'm
> unable to reason out.
> 
> A 'cat trace_pipe' done immediately after removal of an entry (without a
> preceding 'cat trace') terminates only with a SIGTERM (kill <pid>) and
> not a SIGINT (Ctrl+C). However, if the trace buffer receives any new
> data subsequently, it responds to the Ctrl+C signal. I would be glad to
> receive your suggestions in this regard.


Hmm, weird...


> 
> ===================================================================
> --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> @@ -388,6 +388,12 @@ static enum print_line_t ksym_trace_outp
>  		return TRACE_TYPE_UNHANDLED;
>  
>  	trace_assign_type(field, entry);
> +	/*
> +	 * Return early without any output if we don't have sufficient
> +	 * information
> +	 */
> +	if ((!field->ksym_hbp->info.type) || (!field->ip))
> +		return TRACE_TYPE_HANDLED;
>  



No I still think it's dangerous, it may dereference a freed pointer.



>  	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ",
> field->p_name,
>  				entry->pid, iter->cpu,
> field->ksym_name);
> @@ -401,10 +407,7 @@ static enum print_line_t ksym_trace_outp
>  	case HW_BREAKPOINT_RW:
>  		ret = trace_seq_printf(s, " RW ");
>  		break;
> -	default:
> -		return TRACE_TYPE_PARTIAL_LINE;
>  	}
> -
>  	if (!ret)
>  		return TRACE_TYPE_PARTIAL_LINE;
>  
> Thanks,
> K.Prasad
> 


What do you think about the full copy I suggested before?
That would solve these issues in a simple way and would be
_much_ more safe.

If you try this, tell me if you still have such signal issue.

Thanks.

Re: [Patch 2/2] ksym_tracer:Handle machine stall when cat trace_pipe for ksym tracer

[K.Prasad]

On Fri, Jun 19, 2009 at 05:30:31AM +0200, Frederic Weisbecker wrote:
> On Thu, Jun 18, 2009 at 10:55:22PM +0530, K.Prasad wrote:
> > On Wed, Jun 17, 2009 at 07:12:36AM +0200, Frederic Weisbecker wrote:
> > > On Wed, Jun 17, 2009 at 04:35:27AM +0530, K.Prasad wrote:
> > > > 'trace_pipe' does not handle a TRACE_TYPE_PARTIAL_LINE well and causes the
> > > > machine to stall.
> > > 
> > > 
> > > 
> > > No, if it stalls here, it means it handles it well :)
> > >
> > 
> > Okay. As stated earlier, the cause is an incorrect
> > TRACE_TYPE_PARTIAL_LINE return.
> >  
> > > > While a TRACE_TYPE_UNHANDLED return causes the tracer to
> > > > output unrelated data, a TRACE_TYPE_HANDLED return presents a clean output
> > > > (minus all partial traces).
> > > > 
> > > > Signed-off-by: K.Prasad <prasad@linux.vnet.ibm.com>
> > > > ---
> > > >  kernel/trace/trace_ksym.c |    6 ++++++
> > > >  1 file changed, 6 insertions(+)
> > > > 
> > > > Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > > > ===================================================================
> > > > --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> > > > +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > > > @@ -389,6 +389,12 @@ static enum print_line_t ksym_trace_outp
> > > >  
> > > >  	trace_assign_type(field, entry);
> > > >  
> > > > +	/*
> > > > +	 * Return early without any output if we don't have sufficient
> > > > +	 * information
> > > > +	 */
> > > > +	if ((!field->ksym_hbp->info.type) || (!field->ip))
> > > > +		return TRACE_TYPE_HANDLED;
> > > 
> > > 
> > > 
> > > Yeah that seems a good fix. But such silent ignored traces may
> > > hide bugs (current or futures).
> > > Is it a common situation to have a zero ip or an undefined
> > > breakpoint type? How can that happen?
> > > 
> > > Thanks.
> > >
> > 
> > When a symbol is removed from ksym's trace list, it causes
> > unregistration of the breakpoints and the breakpoint structure is
> > kfree()-ed.
> > 
> > Now, looking at the relevant code in ksym_hbp_handler() in trace_ksym.c
> > 
> >  88         entry = ring_buffer_event_data(event);
> >  89         strlcpy(entry->ksym_name, hbp->info.name, KSYM_SYMBOL_LEN);
> >  90         entry->ksym_hbp = hbp;
> >  91         entry->ip = instruction_pointer(regs);
> >  92         strlcpy(entry->p_name, current->comm, TASK_COMM_LEN);
> > 
> > While the ksym_name and p_name fields are copied into the ring buffer,
> > only a pointer to the structure is provided (in line 90). So, when
> > ksym_hbp is unregistered the fields contained in it, namely 'type' and
> > 'ip' are lost (I'm not sure how the fields beyond 'field->ksym_hbp' is
> > accessible in ksym_trace_output() when it is supposed to be already
> > free).
> 
> 
> 
> If they are freed, they could still be available if the memory place
> hasn't been touched by someone else since you kfree'ed it.
> 
> But that's buggy and dangerous :)
> 
> 
> 
> > This patch would cause an early return when such is the case. I also
> > plan to remove the 'default case' in ksym_trace_output() as it was meant
> > to handle a zero value for type (other values are eliminated at the time
> > of breakpoint registration itself).
> > 
> > Please find a patch below that eliminates the two issues of output
> > concatenation and machine stall, excepting for one issue which I'm
> > unable to reason out.
> > 
> > A 'cat trace_pipe' done immediately after removal of an entry (without a
> > preceding 'cat trace') terminates only with a SIGTERM (kill <pid>) and
> > not a SIGINT (Ctrl+C). However, if the trace buffer receives any new
> > data subsequently, it responds to the Ctrl+C signal. I would be glad to
> > receive your suggestions in this regard.
> 
> 
> Hmm, weird...
> 
> 
> > 
> > ===================================================================
> > --- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
> > +++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
> > @@ -388,6 +388,12 @@ static enum print_line_t ksym_trace_outp
> >  		return TRACE_TYPE_UNHANDLED;
> >  
> >  	trace_assign_type(field, entry);
> > +	/*
> > +	 * Return early without any output if we don't have sufficient
> > +	 * information
> > +	 */
> > +	if ((!field->ksym_hbp->info.type) || (!field->ip))
> > +		return TRACE_TYPE_HANDLED;
> >  
> 
> 
> 
> No I still think it's dangerous, it may dereference a freed pointer.
> 
> 
> 
> >  	ret = trace_seq_printf(s, "%-15s %-5d %-3d %-20s ",
> > field->p_name,
> >  				entry->pid, iter->cpu,
> > field->ksym_name);
> > @@ -401,10 +407,7 @@ static enum print_line_t ksym_trace_outp
> >  	case HW_BREAKPOINT_RW:
> >  		ret = trace_seq_printf(s, " RW ");
> >  		break;
> > -	default:
> > -		return TRACE_TYPE_PARTIAL_LINE;
> >  	}
> > -
> >  	if (!ret)
> >  		return TRACE_TYPE_PARTIAL_LINE;
> >  
> > Thanks,
> > K.Prasad
> > 
> 
> 
> What do you think about the full copy I suggested before?
> That would solve these issues in a simple way and would be
> _much_ more safe.
> 
> If you try this, tell me if you still have such signal issue.
> 
> Thanks.
>

I introduced a new structure to contain the data for the ring buffer and
did a copy operation. But I am able to still re-create the issue. Here's
a patch that does a copy of the trace data (when a breakpoint exception
is hit).

I will formally send this patch for inclusion into -tip tree after some
more testing (and yes, it indeed solves the problem of output
concatenation and machine stall!).


Index: linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
===================================================================
--- linux-2.6-tip.hbkpt.orig/kernel/trace/trace_ksym.c
+++ linux-2.6-tip.hbkpt/kernel/trace/trace_ksym.c
@@ -71,7 +71,7 @@ void ksym_hbp_handler(struct hw_breakpoi
 {
 	struct ring_buffer_event *event;
 	struct trace_array *tr;
-	struct trace_ksym *entry;
+	struct trace_ksym_rb *entry;
 	int pc;
 
 	if (!ksym_tracing_enabled)
@@ -87,7 +87,7 @@ void ksym_hbp_handler(struct hw_breakpoi
 
 	entry = ring_buffer_event_data(event);
 	strlcpy(entry->ksym_name, hbp->info.name, KSYM_SYMBOL_LEN);
-	entry->ksym_hbp = hbp;
+	memcpy(&(entry->ksym_hbp), hbp, sizeof(struct hw_breakpoint));
 	entry->ip = instruction_pointer(regs);
 	strlcpy(entry->p_name, current->comm, TASK_COMM_LEN);
 #ifdef CONFIG_PROFILE_KSYM_TRACER
@@ -380,7 +380,7 @@ static enum print_line_t ksym_trace_outp
 {
 	struct trace_entry *entry = iter->ent;
 	struct trace_seq *s = &iter->seq;
-	struct trace_ksym *field;
+	struct trace_ksym_rb *field;
 	char str[KSYM_SYMBOL_LEN];
 	int ret;
 
@@ -394,17 +394,14 @@ static enum print_line_t ksym_trace_outp
 	if (!ret)
 		return TRACE_TYPE_PARTIAL_LINE;
 
-	switch (field->ksym_hbp->info.type) {
+	switch (field->ksym_hbp.info.type) {
 	case HW_BREAKPOINT_WRITE:
 		ret = trace_seq_printf(s, " W  ");
 		break;
 	case HW_BREAKPOINT_RW:
 		ret = trace_seq_printf(s, " RW ");
 		break;
-	default:
-		return TRACE_TYPE_PARTIAL_LINE;
 	}
-
 	if (!ret)
 		return TRACE_TYPE_PARTIAL_LINE;
 
Index: linux-2.6-tip.hbkpt/kernel/trace/trace.h
===================================================================
--- linux-2.6-tip.hbkpt.orig/kernel/trace/trace.h
+++ linux-2.6-tip.hbkpt/kernel/trace/trace.h
@@ -216,15 +216,21 @@ struct syscall_trace_exit {
 extern int process_new_ksym_entry(char *ksymname, int op, unsigned long addr);
 
 struct trace_ksym {
-	struct trace_entry	ent;
 	struct hw_breakpoint	*ksym_hbp;
 	unsigned long		ksym_addr;
-	unsigned long		ip;
 #ifdef CONFIG_PROFILE_KSYM_TRACER
 	unsigned long		counter;
 #endif
 	struct hlist_node	ksym_hlist;
 	char			ksym_name[KSYM_NAME_LEN];
+};
+
+/* Ring buffer's copy of the breakpoint data */
+struct trace_ksym_rb {
+	struct trace_entry	ent;
+	struct hw_breakpoint	ksym_hbp;
+	unsigned long		ip;
+	char			ksym_name[KSYM_NAME_LEN];
 	char			p_name[TASK_COMM_LEN];
 };
 
@@ -343,7 +349,7 @@ extern void __ftrace_bad_type(void);
 			  TRACE_SYSCALL_ENTER);				\
 		IF_ASSIGN(var, ent, struct syscall_trace_exit,		\
 			  TRACE_SYSCALL_EXIT);				\
-		IF_ASSIGN(var, ent, struct trace_ksym, TRACE_KSYM);	\
+		IF_ASSIGN(var, ent, struct trace_ksym_rb, TRACE_KSYM);	\
 		__ftrace_bad_type();					\
 	} while (0)