[PATCH 0/3] trace-cmd fixes for latency tracing record and report

[PATCH 0/3] trace-cmd fixes for latency tracing record and report

[Mark Asselstine]

The following three patches are for the latency-cmd tree.

trace-cmd latency tracing is broken due to segfaults and disappearing 'trace'
logs. Recent commits seem to have broken latency tracers by changing when things are
being initialized or leaving some things uninitialized since they are unused in certain
circumstances. The first two patches address segfaults when running both the record and
report commands caused by attempts to access uninitialized pointers. The last patch
avoids empty reports due to the premature clearing of the 'trace' log caused by resetting
the current_tracer to 'nop'. We still set the 'current_tracer' to 'nop', just after we
have grabbed the data we want.

These changes have been tested on top of the latest trace-cmd tree as well as
on top of the trace-cmd-v1.2 tag point in conjunction with the latest mainline
kernel as well as an older 2.6.34 vintage kernel.

Tests were done with
# ./trace-cmd record -p irqsoff ls /bin
# ./trace-cmd report

Regards,
Mark Asselstine

[PATCH 1/3] trace-cmd: add checks for invalid pointers to fix segfaults

[Mark Asselstine]

Running 'trace-cmd report' after running latency tracers will cause a
segfault due to invalid pointers. Adding checks to ensure
pointers/lists are initialized before attempting to use them prevents
these segfaults.

Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
---
 trace-input.c |   12 +++++++++---
 1 files changed, 9 insertions(+), 3 deletions(-)

diff --git a/trace-input.c b/trace-input.c
index b6af1e6..5151c1e 100644
--- a/trace-input.c
+++ b/trace-input.c
@@ -695,7 +695,8 @@ static void __free_page(struct tracecmd_input *handle, struct page *page)
 
 static void free_page(struct tracecmd_input *handle, int cpu)
 {
-	if (!handle->cpu_data[cpu].page)
+	if (!handle->cpu_data || cpu >= handle->cpus ||
+	    !handle->cpu_data[cpu].page)
 		return;
 
 	__free_page(handle, handle->cpu_data[cpu].page);
@@ -746,8 +747,12 @@ void tracecmd_record_ref(struct record *record)
 
 static void free_next(struct tracecmd_input *handle, int cpu)
 {
-	struct record *record = handle->cpu_data[cpu].next;
+	struct record *record;
+
+	if (!handle->cpu_data || cpu >= handle->cpus)
+		return;
 
+	record = handle->cpu_data[cpu].next;
 	if (!record)
 		return;
 
@@ -2337,7 +2342,8 @@ void tracecmd_close(struct tracecmd_input *handle)
 		/* The tracecmd_peek_data may have cached a record */
 		free_next(handle, cpu);
 		free_page(handle, cpu);
-		if (!list_empty(&handle->cpu_data[cpu].pages))
+		if (handle->cpu_data &&
+		    !list_empty(&handle->cpu_data[cpu].pages))
 			warning("pages still allocated on cpu %d%s",
 				cpu, show_records(&handle->cpu_data[cpu].pages));
 	}
-- 
1.7.5.4

[PATCH 2/3] trace-cmd: don't call stop_threads() if doing latency tracing

[Mark Asselstine]

If we are using a latency tracer we do not call start_threads() we
should therefore not call stop_threads() if 'latency'. Attempting
to call stop_threads() without first calling start_threads() will
cause a segfault since pids will be uninitialized.

Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
---
 trace-record.c |    3 ++-
 1 files changed, 2 insertions(+), 1 deletions(-)

diff --git a/trace-record.c b/trace-record.c
index fcec28b..1c56fa9 100644
--- a/trace-record.c
+++ b/trace-record.c
@@ -2216,7 +2216,8 @@ void trace_record (int argc, char **argv)
 		}
 
 		disable_tracing();
-		stop_threads();
+		if (!latency)
+			stop_threads();
 	}
 
 	for (cpu = 0; cpu < cpu_count; cpu++) {
-- 
1.7.5.4

[PATCH 3/3] trace-cmd: setting plugin to 'nop' clears data before its recorded

[Mark Asselstine]

commit e09a5db1a929ab668c273b87c4f0a32b81e1c21a
[trace-cmd: Add trace-cmd record --date option]

moved the call to disable_all() in trace_record() from after record_data()
to before it. disable_all() sets 'nop' in 'current_tracer' which has the
side affect of clearing 'trace', thus all the latency tracer reports are
empty/useless. By moving set_plugin() out of disable_all() and rather
calling it after record_data() we still achieve the desired goals of
commit e09a5db1a9 while fixing latency tracing reports.

Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
---
 trace-record.c |   13 ++++++++++---
 1 files changed, 10 insertions(+), 3 deletions(-)

diff --git a/trace-record.c b/trace-record.c
index 1c56fa9..6887874 100644
--- a/trace-record.c
+++ b/trace-record.c
@@ -897,11 +897,10 @@ static void disable_tracing(void)
 	write_tracing_on(0);
 }
 
-static void disable_all(void)
+static void disable_all_but_plugin(void)
 {
 	disable_tracing();
 
-	set_plugin("nop");
 	reset_events();
 
 	/* Force close and reset of ftrace pid file */
@@ -911,6 +910,12 @@ static void disable_all(void)
 	clear_trace();
 }
 
+static void disable_all(void)
+{
+	disable_all_but_plugin();
+	set_plugin("nop");
+}
+
 static void
 update_sched_event(struct event_list **event, const char *file,
 		   const char *pid_filter, const char *field_filter)
@@ -2227,7 +2232,7 @@ void trace_record (int argc, char **argv)
 	}
 
 	if (!keep)
-		disable_all();
+		disable_all_but_plugin();
 
 	printf("Kernel buffer statistics:\n"
 	       "  Note: \"entries\" are the entries left in the kernel ring buffer and are not\n"
@@ -2245,6 +2250,8 @@ void trace_record (int argc, char **argv)
 
 	record_data(date2ts);
 	delete_thread_data();
+	if (!keep)
+		set_plugin("nop");
 
 	if (keep)
 		exit(0);
-- 
1.7.5.4

Re: [PATCH 3/3] trace-cmd: setting plugin to 'nop' clears data before its recorded

[Steven Rostedt]

On Thu, 2012-04-05 at 15:19 -0400, Mark Asselstine wrote:

Hi Mark,

Thanks for the updates.

> commit e09a5db1a929ab668c273b87c4f0a32b81e1c21a
> [trace-cmd: Add trace-cmd record --date option]
> 
> moved the call to disable_all() in trace_record() from after record_data()
> to before it. disable_all() sets 'nop' in 'current_tracer' which has the
> side affect of clearing 'trace', thus all the latency tracer reports are
> empty/useless. By moving set_plugin() out of disable_all() and rather
> calling it after record_data() we still achieve the desired goals of
> commit e09a5db1a9 while fixing latency tracing reports.
> 
> Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
> ---
>  trace-record.c |   13 ++++++++++---
>  1 files changed, 10 insertions(+), 3 deletions(-)
> 
> diff --git a/trace-record.c b/trace-record.c
> index 1c56fa9..6887874 100644
> --- a/trace-record.c
> +++ b/trace-record.c
> @@ -897,11 +897,10 @@ static void disable_tracing(void)
>  	write_tracing_on(0);
>  }
>  
> -static void disable_all(void)
> +static void disable_all_but_plugin(void)

Hmm, I don't really care for this name. Maybe it would be better to have
this take a parameter called "plugins", and if it is set, then you
disable plugins, otherwise you don't. This keeps it a single function
and not two different ones where one is slightly different than the
other. That is usually only done when a function is used by lots of
other areas and it is just simpler to make another function do something
slightly different and have the original call it. But this isn't used
much, so just changing the way it works, I think would be better.

Also, and this has nothing to do with you or your patches, I simply hate
the fact that I called these plugins. They should have been called
"tracers" but I think I'm stuck with it. The term now is ambiguous as it
means both a tracer (as it does here) and it means actual plugins that
you can load into trace-cmd itself.

>  {
>  	disable_tracing();
>  
> -	set_plugin("nop");
>  	reset_events();
>  
>  	/* Force close and reset of ftrace pid file */
> @@ -911,6 +910,12 @@ static void disable_all(void)
>  	clear_trace();
>  }
>  
> +static void disable_all(void)
> +{
> +	disable_all_but_plugin();
> +	set_plugin("nop");
> +}
> +
>  static void
>  update_sched_event(struct event_list **event, const char *file,
>  		   const char *pid_filter, const char *field_filter)
> @@ -2227,7 +2232,7 @@ void trace_record (int argc, char **argv)
>  	}
>  
>  	if (!keep)
> -		disable_all();
> +		disable_all_but_plugin();
>  
>  	printf("Kernel buffer statistics:\n"
>  	       "  Note: \"entries\" are the entries left in the kernel ring buffer and are not\n"
> @@ -2245,6 +2250,8 @@ void trace_record (int argc, char **argv)
>  
>  	record_data(date2ts);
>  	delete_thread_data();
> +	if (!keep)
> +		set_plugin("nop");
>  
>  	if (keep)
>  		exit(0);

I think the above would have been better if you did:

	if (keep)
		exit(0);
	else
		set_plugin(nop);

-- Steve

Re: [PATCH 3/3] trace-cmd: setting plugin to 'nop' clears data before its recorded

[Mark Asselstine]

On Thursday 05 April 2012 17:37:46 Steven Rostedt wrote:
> On Thu, 2012-04-05 at 15:19 -0400, Mark Asselstine wrote:
> 
> Hi Mark,
> 
> Thanks for the updates.
> 
> > commit e09a5db1a929ab668c273b87c4f0a32b81e1c21a
> > [trace-cmd: Add trace-cmd record --date option]
> > 
> > moved the call to disable_all() in trace_record() from after
> > record_data() to before it. disable_all() sets 'nop' in
> > 'current_tracer' which has the side affect of clearing 'trace', thus
> > all the latency tracer reports are empty/useless. By moving
> > set_plugin() out of disable_all() and rather calling it after
> > record_data() we still achieve the desired goals of commit e09a5db1a9
> > while fixing latency tracing reports.
> > 
> > Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
> > ---
> > 
> >  trace-record.c |   13 ++++++++++---
> >  1 files changed, 10 insertions(+), 3 deletions(-)
> > 
> > diff --git a/trace-record.c b/trace-record.c
> > index 1c56fa9..6887874 100644
> > --- a/trace-record.c
> > +++ b/trace-record.c
> > @@ -897,11 +897,10 @@ static void disable_tracing(void)
> > 
> >  	write_tracing_on(0);
> >  
> >  }
> > 
> > -static void disable_all(void)
> > +static void disable_all_but_plugin(void)
> 
> Hmm, I don't really care for this name. Maybe it would be better to have
> this take a parameter called "plugins", and if it is set, then you
> disable plugins, otherwise you don't. This keeps it a single function
> and not two different ones where one is slightly different than the
> other. That is usually only done when a function is used by lots of
> other areas and it is just simpler to make another function do something
> slightly different and have the original call it. But this isn't used
> much, so just changing the way it works, I think would be better.
> 

Works for me. I see you make use of gboolean elsewhere so I assume you prefer 
the use of this rather than using int?

> Also, and this has nothing to do with you or your patches, I simply hate
> the fact that I called these plugins. They should have been called
> "tracers" but I think I'm stuck with it. The term now is ambiguous as it
> means both a tracer (as it does here) and it means actual plugins that
> you can load into trace-cmd itself.
>

To stop the proliferation do you want me to name the bool 
'disable_current_tracer' rather than 'disable_plugin' or 'plugin'?

 
> >  {
> >  
> >  	disable_tracing();
> > 
> > -	set_plugin("nop");
> > 
> >  	reset_events();
> >  	
> >  	/* Force close and reset of ftrace pid file */
> > 
> > @@ -911,6 +910,12 @@ static void disable_all(void)
> > 
> >  	clear_trace();
> >  
> >  }
> > 
> > +static void disable_all(void)
> > +{
> > +	disable_all_but_plugin();
> > +	set_plugin("nop");
> > +}
> > +
> > 
> >  static void
> >  update_sched_event(struct event_list **event, const char *file,
> >  
> >  		   const char *pid_filter, const char *field_filter)
> > 
> > @@ -2227,7 +2232,7 @@ void trace_record (int argc, char **argv)
> > 
> >  	}
> >  	
> >  	if (!keep)
> > 
> > -		disable_all();
> > +		disable_all_but_plugin();
> > 
> >  	printf("Kernel buffer statistics:\n"
> >  	
> >  	       "  Note: \"entries\" are the entries left in the
> >  	       kernel ring buffer and are not\n"> 
> > @@ -2245,6 +2250,8 @@ void trace_record (int argc, char **argv)
> > 
> >  	record_data(date2ts);
> >  	delete_thread_data();
> > 
> > +	if (!keep)
> > +		set_plugin("nop");
> > 
> >  	if (keep)
> >  	
> >  		exit(0);
> 
> I think the above would have been better if you did:
> 
> 	if (keep)
> 		exit(0);
> 	else
> 		set_plugin(nop);
> 
> -- Steve

Wow, I wasn't being too bright there was I? Agreed and the 'else' isn't 
necessary either, so this is a good cleanup.

I will get this fixed up later today. Do you want a V2 of the full patch series 
or just an update of this one patch?

Regards,
Mark

Re: [PATCH 3/3] trace-cmd: setting plugin to 'nop' clears data before its recorded

[Steven Rostedt]

On Fri, 2012-04-06 at 08:06 -0400, Mark Asselstine wrote:

> Works for me. I see you make use of gboolean elsewhere so I assume you prefer 
> the use of this rather than using int?

Sure.

> 
> > Also, and this has nothing to do with you or your patches, I simply hate
> > the fact that I called these plugins. They should have been called
> > "tracers" but I think I'm stuck with it. The term now is ambiguous as it
> > means both a tracer (as it does here) and it means actual plugins that
> > you can load into trace-cmd itself.
> >
> 
> To stop the proliferation do you want me to name the bool 
> 'disable_current_tracer' rather than 'disable_plugin' or 'plugin'?

disable_tracer would due.

> 
>  
> > >  {
> > >  
> > >  	disable_tracing();
> > > 
> > > -	set_plugin("nop");
> > > 
> > >  	reset_events();
> > >  	
> > >  	/* Force close and reset of ftrace pid file */
> > > 
> > > @@ -911,6 +910,12 @@ static void disable_all(void)
> > > 
> > >  	clear_trace();
> > >  
> > >  }
> > > 
> > > +static void disable_all(void)
> > > +{
> > > +	disable_all_but_plugin();
> > > +	set_plugin("nop");
> > > +}
> > > +
> > > 
> > >  static void
> > >  update_sched_event(struct event_list **event, const char *file,
> > >  
> > >  		   const char *pid_filter, const char *field_filter)
> > > 
> > > @@ -2227,7 +2232,7 @@ void trace_record (int argc, char **argv)
> > > 
> > >  	}
> > >  	
> > >  	if (!keep)
> > > 
> > > -		disable_all();
> > > +		disable_all_but_plugin();
> > > 
> > >  	printf("Kernel buffer statistics:\n"
> > >  	
> > >  	       "  Note: \"entries\" are the entries left in the
> > >  	       kernel ring buffer and are not\n"> 
> > > @@ -2245,6 +2250,8 @@ void trace_record (int argc, char **argv)
> > > 
> > >  	record_data(date2ts);
> > >  	delete_thread_data();
> > > 
> > > +	if (!keep)
> > > +		set_plugin("nop");
> > > 
> > >  	if (keep)
> > >  	
> > >  		exit(0);
> > 
> > I think the above would have been better if you did:
> > 
> > 	if (keep)
> > 		exit(0);
> > 	else
> > 		set_plugin(nop);
> > 
> > -- Steve
> 
> Wow, I wasn't being too bright there was I? Agreed and the 'else' isn't 
> necessary either, so this is a good cleanup.
> 
> I will get this fixed up later today. Do you want a V2 of the full patch series 
> or just an update of this one patch?

You can just update this patch with a v2 on it. I'm currently traveling
home from a conference and wont be back to work till Tuesday. Please,
take your time.

Thanks!

-- Steve

[PATCH v2 3/3] trace-cmd: setting plugin to 'nop' clears data before it's recorded

[Mark Asselstine]

commit e09a5db1a929ab668c273b87c4f0a32b81e1c21a
[trace-cmd: Add trace-cmd record --date option]

moved the call to disable_all() in trace_record() from after record_data()
to before it. Unfortunately disable_all() sets 'nop' in 'current_tracer'
which has the side affect of clearing 'trace', thus all the latency tracer
reports are empty/useless. Here we make disable_all() optionally call
set_plugin() thus, where we need to, we can delay the disabling of the tracer
until we have had a chance to capture 'trace'. We have added this delayed
behavior to trace_record() to fix the latency reports, for all other calls to
disable_all() we continue to have set_plugin() called.

Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
---
[v2] * remove redundant conditional usage
     * add conditional param for disable_all() instead of adding new func
     * used int and not gboolean to avoid gtk includes where not needed

 trace-record.c |   16 ++++++++++------
 1 files changed, 10 insertions(+), 6 deletions(-)

diff --git a/trace-record.c b/trace-record.c
index 1c56fa9..95d4a2a 100644
--- a/trace-record.c
+++ b/trace-record.c
@@ -897,11 +897,13 @@ static void disable_tracing(void)
 	write_tracing_on(0);
 }
 
-static void disable_all(void)
+static void disable_all(int disable_tracer)
 {
 	disable_tracing();
 
-	set_plugin("nop");
+	if (disable_tracer)
+		set_plugin("nop");
+
 	reset_events();
 
 	/* Force close and reset of ftrace pid file */
@@ -1573,7 +1575,7 @@ static void set_funcs(void)
 	/* make sure we are filtering functions */
 	if (func_stack) {
 		if (!functions_filtered()) {
-			disable_all();
+			disable_all(1);
 			die("Function stack trace set, but functions not filtered");
 		}
 		save_option(FUNC_STACK_TRACE);
@@ -1938,7 +1940,7 @@ void trace_record (int argc, char **argv)
 				break;
 			}
 		}
-		disable_all();
+		disable_all(1);
 		set_buffer_size();
 		exit(0);
 	} else
@@ -2147,7 +2149,7 @@ void trace_record (int argc, char **argv)
 
 	if (!extract) {
 		fset = set_ftrace(!disable);
-		disable_all();
+		disable_all(1);
 
 		/* Record records the date first */
 		if (record && date)
@@ -2227,7 +2229,7 @@ void trace_record (int argc, char **argv)
 	}
 
 	if (!keep)
-		disable_all();
+		disable_all(0);
 
 	printf("Kernel buffer statistics:\n"
 	       "  Note: \"entries\" are the entries left in the kernel ring buffer and are not\n"
@@ -2249,6 +2251,8 @@ void trace_record (int argc, char **argv)
 	if (keep)
 		exit(0);
 
+	set_plugin("nop");
+
 	/* If tracing_on was enabled before we started, set it on now */
 	if (tracing_on_init_val)
 		write_tracing_on(tracing_on_init_val);
-- 
1.7.5.4

Re: [PATCH v2 3/3] trace-cmd: setting plugin to 'nop' clears data before it's recorded

[Steven Rostedt]

On Sun, 2012-04-08 at 11:38 -0400, Mark Asselstine wrote:
> commit e09a5db1a929ab668c273b87c4f0a32b81e1c21a
> [trace-cmd: Add trace-cmd record --date option]
> 
> moved the call to disable_all() in trace_record() from after record_data()
> to before it. Unfortunately disable_all() sets 'nop' in 'current_tracer'
> which has the side affect of clearing 'trace', thus all the latency tracer
> reports are empty/useless. Here we make disable_all() optionally call
> set_plugin() thus, where we need to, we can delay the disabling of the tracer
> until we have had a chance to capture 'trace'. We have added this delayed
> behavior to trace_record() to fix the latency reports, for all other calls to
> disable_all() we continue to have set_plugin() called.
> 

Just letting you know that I just pushed your changes to my repo. Sorry
for being late, I got side-tracked, and forgot about your changes.

-- Steve

Re: [PATCH v2 3/3] trace-cmd: setting plugin to 'nop' clears data before it's recorded

[Mark Asselstine]

On May 23, 2012 05:33:12 Steven Rostedt wrote:
> On Sun, 2012-04-08 at 11:38 -0400, Mark Asselstine wrote:
> > commit e09a5db1a929ab668c273b87c4f0a32b81e1c21a
> > [trace-cmd: Add trace-cmd record --date option]
> > 
> > moved the call to disable_all() in trace_record() from after record_data()
> > to before it. Unfortunately disable_all() sets 'nop' in 'current_tracer'
> > which has the side affect of clearing 'trace', thus all the latency tracer
> > reports are empty/useless. Here we make disable_all() optionally call
> > set_plugin() thus, where we need to, we can delay the disabling of the
> > tracer until we have had a chance to capture 'trace'. We have added this
> > delayed behavior to trace_record() to fix the latency reports, for all
> > other calls to disable_all() we continue to have set_plugin() called.
> 
> Just letting you know that I just pushed your changes to my repo. Sorry
> for being late, I got side-tracked, and forgot about your changes.
> 
> -- Steve

No problem, happy to help.

Mark