Re: perf timechart broken

Re: perf timechart broken

[Frederic Weisbecker]

On Fri, Jan 07, 2011 at 11:04:37AM +0100, Thomas Renninger wrote:
> Hi,
> 
> Latest x86 tip has another perf timechart issue introduce
> by latest commits.
> 
> ./perf timechart
> gives me:
> "no trace data in the file"
> 
> I reverted  the latest changes and things seem to break
> between d854861c4292a4e675a5d3bfd862c5f7421c81e8
> and
> 69aad6f1ee69546dea8535ab8f3da9f445d57328
> (linux-2.6-x86 tree ids)
> 
> Be aware that ./perf timechart is currently broken
> and segfaults on idle events (in 2.6.36 and 2.6.37).

You mean .36 perf tools faults on .37 kernel? or the opposite?
Is it because power_idle events weren't present on old tools?

Do you have a pointer to those patches?

> I submitted a patch to stable@ but it did not get accepted,
> becaust it's not mainline yet.
> I concentrated on my latest patches instead of making sure
> the tiny fix gets into 2.6.37 first.
> 
> Ingo: It's a bit late for 2.6.37, if there is any chance
> to still get it in, the patch below is against linus master...
> otherwise I'll submit it for stable 36+37 asap.

It's too late for .37, but it's fine, we just need to add
a "Cc: stable@kernel.org" tag in the patch for it to be
backported.

> 
> Anyway to test above regression this mail is about, first
> apply below patch otherwise you get a segfault if idle
> (power_start/end) events got logged.
> 
> Thanks,
> 
>    Thomas
> 
> ---
> perf timechart: Fix segfault on cpu idle (power_start/end) events
> 
> power_end event does not have type and other attributes and thus does
> not match struct power_event.
> Another struct could be created, but data.cpu is fine for fixing the segfault
> and will work as long as C-states got initiated on the same CPU the idle state
> takes place which is the case for all recent HW.
> 
> The power_start/end events get deprecated anyway, thus this is an easy,
> riskless and sufficient solution for the segfault problem.
> 
> Signed-off-by: Thomas Renninger <trenn@suse.de>
> CC: mingo@elte.hu
> CC: arjan@linux.intel.com
> 
> ---
>  tools/perf/builtin-timechart.c |    2 +-
>  1 files changed, 1 insertions(+), 1 deletions(-)
> 
> diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c
> index 9bcc38f..b3028eb 100644
> --- a/tools/perf/builtin-timechart.c
> +++ b/tools/perf/builtin-timechart.c
> @@ -502,7 +502,7 @@ static int process_sample_event(event_t *event, struct perf_session *session)
>  			c_state_start(pe->cpu_id, data.time, pe->value);
>  
>  		if (strcmp(event_str, "power:power_end") == 0)
> -			c_state_end(pe->cpu_id, data.time);
> +			c_state_end(data.cpu, data.time);

On which tree is this based of?

What I have by looking at tip/master is:

		else if (strcmp(event_str, "power:power_end") == 0)
			c_state_end(sample->cpu, sample->time);

>  
>  		if (strcmp(event_str, "power:power_frequency") == 0)
>  			p_state_change(pe->cpu_id, data.time, pe->value);
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: perf timechart broken

[Thomas Renninger]

On Tuesday 11 January 2011 02:36:28 Frederic Weisbecker wrote:
> On Fri, Jan 07, 2011 at 11:04:37AM +0100, Thomas Renninger wrote:
> > Hi,
> > 
> > Latest x86 tip has another perf timechart issue introduce
> > by latest commits.
> > 
> > ./perf timechart
> > gives me:
> > "no trace data in the file"
> > 
> > I reverted  the latest changes and things seem to break
> > between d854861c4292a4e675a5d3bfd862c5f7421c81e8
> > and
> > 69aad6f1ee69546dea8535ab8f3da9f445d57328
> > (linux-2.6-x86 tree ids)
> > 
> > Be aware that ./perf timechart is currently broken
> > and segfaults on idle events (in 2.6.36 and 2.6.37).
> 
> You mean .36 perf tools faults on .37 kernel? or the opposite?
> Is it because power_idle events weren't present on old tools?
> Do you have a pointer to those patches?
perf timechart
will segfault if perf.data has power_{start,end} events included
on 2.6.36 and 2.6.37 kernels.

> > I submitted a patch to stable@ but it did not get accepted,
> > becaust it's not mainline yet.
> > I concentrated on my latest patches instead of making sure
> > the tiny fix gets into 2.6.37 first.
> > 
> > Ingo: It's a bit late for 2.6.37, if there is any chance
> > to still get it in, the patch below is against linus master...
> > otherwise I'll submit it for stable 36+37 asap.
> 
> It's too late for .37, but it's fine, we just need to add
> a "Cc: stable@kernel.org" tag in the patch for it to be
> backported.
I'll submit it to stable@ (it wasn't taken because
the patch which included the fix wasn't mainline yet and I
forgot to submit it for 2.6.37-rcX). 

I can take care of that, but it would be great if someone
could look at the issue that perf timechart shows:
"no trace data in the file"
in x86/tip which seems introduced by one of Arnaldo's latest
commits. Reverting some of his latest patches, solved it for
me.

> > Anyway to test above regression this mail is about, first
> > apply below patch otherwise you get a segfault if idle
> > (power_start/end) events got logged.
> > 
> > Thanks,
> > 
> >    Thomas
> > 
> > ---
> > perf timechart: Fix segfault on cpu idle (power_start/end) events
> > 
> > power_end event does not have type and other attributes and thus does
> > not match struct power_event.
> > Another struct could be created, but data.cpu is fine for fixing the segfault
> > and will work as long as C-states got initiated on the same CPU the idle state
> > takes place which is the case for all recent HW.
> > 
> > The power_start/end events get deprecated anyway, thus this is an easy,
> > riskless and sufficient solution for the segfault problem.
> > 
> > Signed-off-by: Thomas Renninger <trenn@suse.de>
> > CC: mingo@elte.hu
> > CC: arjan@linux.intel.com
> > 
> > ---
> >  tools/perf/builtin-timechart.c |    2 +-
> >  1 files changed, 1 insertions(+), 1 deletions(-)
> > 
> > diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c
> > index 9bcc38f..b3028eb 100644
> > --- a/tools/perf/builtin-timechart.c
> > +++ b/tools/perf/builtin-timechart.c
> > @@ -502,7 +502,7 @@ static int process_sample_event(event_t *event, struct perf_session *session)
> >  			c_state_start(pe->cpu_id, data.time, pe->value);
> >  
> >  		if (strcmp(event_str, "power:power_end") == 0)
> > -			c_state_end(pe->cpu_id, data.time);
> > +			c_state_end(data.cpu, data.time);
> 
> On which tree is this based of?
Linus master (2.6.37-rc8).

> What I have by looking at tip/master is:
Yes, this commit includes the patch (should have been a seperate one...):
20c457b8587bee4644d998331d9e13be82e05b4c
perf timechart: Adjust perf timechart to the new power events

   Thomas

> 
> 		else if (strcmp(event_str, "power:power_end") == 0)
> 			c_state_end(sample->cpu, sample->time);
> 
> >  
> >  		if (strcmp(event_str, "power:power_frequency") == 0)
> >  			p_state_change(pe->cpu_id, data.time, pe->value);
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

Re: perf timechart broken

[Arnaldo Carvalho de Melo]

Em Tue, Jan 11, 2011 at 09:55:36AM +0100, Thomas Renninger escreveu:
> On Tuesday 11 January 2011 02:36:28 Frederic Weisbecker wrote:
> > It's too late for .37, but it's fine, we just need to add
> > a "Cc: stable@kernel.org" tag in the patch for it to be
> > backported.
> I'll submit it to stable@ (it wasn't taken because
> the patch which included the fix wasn't mainline yet and I
> forgot to submit it for 2.6.37-rcX). 
 
> I can take care of that, but it would be great if someone could look
> at the issue that perf timechart shows: "no trace data in the file" in
> x86/tip which seems introduced by one of Arnaldo's latest commits.
> Reverting some of his latest patches, solved it for me.

Looking at it now.

- Arnaldo

Re: perf timechart broken

[Arnaldo Carvalho de Melo]

Em Tue, Jan 11, 2011 at 09:49:51AM -0200, Arnaldo Carvalho de Melo escreveu:
> Em Tue, Jan 11, 2011 at 09:55:36AM +0100, Thomas Renninger escreveu:
> > On Tuesday 11 January 2011 02:36:28 Frederic Weisbecker wrote:
> > > It's too late for .37, but it's fine, we just need to add
> > > a "Cc: stable@kernel.org" tag in the patch for it to be
> > > backported.
> > I'll submit it to stable@ (it wasn't taken because
> > the patch which included the fix wasn't mainline yet and I
> > forgot to submit it for 2.6.37-rcX). 
>  
> > I can take care of that, but it would be great if someone could look
> > at the issue that perf timechart shows: "no trace data in the file" in
> > x86/tip which seems introduced by one of Arnaldo's latest commits.
> > Reverting some of his latest patches, solved it for me.
> 
> Looking at it now.

Can you try with this patch applied? We need a better way of specifying
ordering of __exit and __init routines :-\

- Arnaldo

commit 7116fe5e13ff978676d96bcea79ec1b8f87b2f9d
Author: Arnaldo Carvalho de Melo <acme@redhat.com>
Date:   Tue Jan 11 12:42:00 2011 -0200

    perf evsel: Fix order of event list deletion
    
    We need to defer calling perf_evsel_list__delete() till after atexit
    registered routines, because we need to traverse the events being
    recorded at that time at least on 'perf record'.
    
    This fixes the problem reported by Thomas Renninger where cmd_record
    called by cmd_timechart would not write the tracing data to the perf.data
    file header because the evsel_list at atexit (control+C on 'perf timechart
    record') time would be empty, being already deleted by run_builtin(),
    and thus 'perf timechart' when trying to process such perf.data file would
    die with:
    
    "no trace data in the file"

    Problem introduced in 70d544d.
    
    Reported-by: Thomas Renninger <trenn@suse.de>
    Cc: Frederic Weisbecker <fweisbec@gmail.com>
    Cc: Ingo Molnar <mingo@elte.hu>
    Cc: Mike Galbraith <efault@gmx.de>
    Cc: Paul Mackerras <paulus@samba.org>
    Cc: Peter Zijlstra <peterz@infradead.org>
    Cc: Stephane Eranian <eranian@google.com>
    Cc: Thomas Renninger <trenn@suse.de>
    Cc: Tom Zanussi <tzanussi@gmail.com>
    LKML-Reference: <new-submission>
    Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 7069bd3..aa7ece3 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -480,6 +480,7 @@ static void atexit_header(void)
 			process_buildids();
 		perf_header__write(&session->header, output, true);
 		perf_session__delete(session);
+		perf_evsel_list__delete();
 		symbol__exit();
 	}
 }
diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index c385a63..0ff11d9 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -743,6 +743,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 out_free_fd:
 	list_for_each_entry(pos, &evsel_list, node)
 		perf_evsel__free_stat_priv(pos);
+	perf_evsel_list__delete();
 out:
 	thread_map__delete(threads);
 	threads = NULL;
diff --git a/tools/perf/builtin-top.c b/tools/perf/builtin-top.c
index 6ce4042..4b995ee 100644
--- a/tools/perf/builtin-top.c
+++ b/tools/perf/builtin-top.c
@@ -1490,6 +1490,7 @@ int cmd_top(int argc, const char **argv, const char *prefix __used)
 out_free_fd:
 	list_for_each_entry(pos, &evsel_list, node)
 		perf_evsel__free_mmap(pos);
+	perf_evsel_list__delete();
 
 	return status;
 }
diff --git a/tools/perf/perf.c b/tools/perf/perf.c
index 5b1ecd6..595d0f4 100644
--- a/tools/perf/perf.c
+++ b/tools/perf/perf.c
@@ -286,8 +286,6 @@ static int run_builtin(struct cmd_struct *p, int argc, const char **argv)
 	status = p->fn(argc, argv, prefix);
 	exit_browser(status);
 
-	perf_evsel_list__delete();
-
 	if (status)
 		return status & 0xff;
 

Re: perf timechart broken

[Thomas Renninger]

On Tuesday 11 January 2011 15:51:34 Arnaldo Carvalho de Melo wrote:
> Em Tue, Jan 11, 2011 at 09:49:51AM -0200, Arnaldo Carvalho de Melo escreveu:
> > Em Tue, Jan 11, 2011 at 09:55:36AM +0100, Thomas Renninger escreveu:
> > > On Tuesday 11 January 2011 02:36:28 Frederic Weisbecker wrote:
> > > > It's too late for .37, but it's fine, we just need to add
> > > > a "Cc: stable@kernel.org" tag in the patch for it to be
> > > > backported.
> > > I'll submit it to stable@ (it wasn't taken because
> > > the patch which included the fix wasn't mainline yet and I
> > > forgot to submit it for 2.6.37-rcX). 
> >  
> > > I can take care of that, but it would be great if someone could look
> > > at the issue that perf timechart shows: "no trace data in the file" in
> > > x86/tip which seems introduced by one of Arnaldo's latest commits.
> > > Reverting some of his latest patches, solved it for me.
> > 
> > Looking at it now.
> 
> Can you try with this patch applied? We need a better way of specifying
> ordering of __exit and __init routines :-\
I tested on x86/tip and it is fixed.
I explicitly reverted your fix and run into it again.

Thanks!

   Thomas

Re: perf timechart broken

[Arnaldo Carvalho de Melo]

Em Fri, Jan 14, 2011 at 05:49:36PM +0100, Thomas Renninger escreveu:
> On Tuesday 11 January 2011 15:51:34 Arnaldo Carvalho de Melo wrote:
> > Em Tue, Jan 11, 2011 at 09:49:51AM -0200, Arnaldo Carvalho de Melo escreveu:
> > > Looking at it now.
> > 
> > Can you try with this patch applied? We need a better way of specifying
> > ordering of __exit and __init routines :-\
> I tested on x86/tip and it is fixed.
> I explicitly reverted your fix and run into it again.
> 
> Thanks!

Thanks a lot for reporting and retesting,

- Arnaldo

Re: perf timechart broken

[David Ahern]

On 01/11/11 01:55, Thomas Renninger wrote:
> On Tuesday 11 January 2011 02:36:28 Frederic Weisbecker wrote:
>> On Fri, Jan 07, 2011 at 11:04:37AM +0100, Thomas Renninger wrote:
>>> Hi,
>>>
>>> Latest x86 tip has another perf timechart issue introduce
>>> by latest commits.
>>>
>>> ./perf timechart
>>> gives me:
>>> "no trace data in the file"
>>>
>>> I reverted  the latest changes and things seem to break
>>> between d854861c4292a4e675a5d3bfd862c5f7421c81e8
>>> and
>>> 69aad6f1ee69546dea8535ab8f3da9f445d57328
>>> (linux-2.6-x86 tree ids)
>>>
>>> Be aware that ./perf timechart is currently broken
>>> and segfaults on idle events (in 2.6.36 and 2.6.37).
>>
>> You mean .36 perf tools faults on .37 kernel? or the opposite?
>> Is it because power_idle events weren't present on old tools?
>> Do you have a pointer to those patches?
> perf timechart
> will segfault if perf.data has power_{start,end} events included
> on 2.6.36 and 2.6.37 kernels.

Is this the same segfault you are seeing?

http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00057.html

David


> 
>>> I submitted a patch to stable@ but it did not get accepted,
>>> becaust it's not mainline yet.
>>> I concentrated on my latest patches instead of making sure
>>> the tiny fix gets into 2.6.37 first.
>>>
>>> Ingo: It's a bit late for 2.6.37, if there is any chance
>>> to still get it in, the patch below is against linus master...
>>> otherwise I'll submit it for stable 36+37 asap.
>>
>> It's too late for .37, but it's fine, we just need to add
>> a "Cc: stable@kernel.org" tag in the patch for it to be
>> backported.
> I'll submit it to stable@ (it wasn't taken because
> the patch which included the fix wasn't mainline yet and I
> forgot to submit it for 2.6.37-rcX). 
> 
> I can take care of that, but it would be great if someone
> could look at the issue that perf timechart shows:
> "no trace data in the file"
> in x86/tip which seems introduced by one of Arnaldo's latest
> commits. Reverting some of his latest patches, solved it for
> me.
> 
>>> Anyway to test above regression this mail is about, first
>>> apply below patch otherwise you get a segfault if idle
>>> (power_start/end) events got logged.
>>>
>>> Thanks,
>>>
>>>    Thomas
>>>
>>> ---
>>> perf timechart: Fix segfault on cpu idle (power_start/end) events
>>>
>>> power_end event does not have type and other attributes and thus does
>>> not match struct power_event.
>>> Another struct could be created, but data.cpu is fine for fixing the segfault
>>> and will work as long as C-states got initiated on the same CPU the idle state
>>> takes place which is the case for all recent HW.
>>>
>>> The power_start/end events get deprecated anyway, thus this is an easy,
>>> riskless and sufficient solution for the segfault problem.
>>>
>>> Signed-off-by: Thomas Renninger <trenn@suse.de>
>>> CC: mingo@elte.hu
>>> CC: arjan@linux.intel.com
>>>
>>> ---
>>>  tools/perf/builtin-timechart.c |    2 +-
>>>  1 files changed, 1 insertions(+), 1 deletions(-)
>>>
>>> diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c
>>> index 9bcc38f..b3028eb 100644
>>> --- a/tools/perf/builtin-timechart.c
>>> +++ b/tools/perf/builtin-timechart.c
>>> @@ -502,7 +502,7 @@ static int process_sample_event(event_t *event, struct perf_session *session)
>>>  			c_state_start(pe->cpu_id, data.time, pe->value);
>>>  
>>>  		if (strcmp(event_str, "power:power_end") == 0)
>>> -			c_state_end(pe->cpu_id, data.time);
>>> +			c_state_end(data.cpu, data.time);
>>
>> On which tree is this based of?
> Linus master (2.6.37-rc8).
> 
>> What I have by looking at tip/master is:
> Yes, this commit includes the patch (should have been a seperate one...):
> 20c457b8587bee4644d998331d9e13be82e05b4c
> perf timechart: Adjust perf timechart to the new power events
> 
>    Thomas
> 
>>
>> 		else if (strcmp(event_str, "power:power_end") == 0)
>> 			c_state_end(sample->cpu, sample->time);
>>
>>>  
>>>  		if (strcmp(event_str, "power:power_frequency") == 0)
>>>  			p_state_change(pe->cpu_id, data.time, pe->value);
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: perf timechart broken

[Thomas Renninger]

On Tuesday 11 January 2011 19:56:22 David Ahern wrote:
> 
> On 01/11/11 01:55, Thomas Renninger wrote:
> > On Tuesday 11 January 2011 02:36:28 Frederic Weisbecker wrote:
> >> On Fri, Jan 07, 2011 at 11:04:37AM +0100, Thomas Renninger wrote:
> >>> Hi,
> >>>
> >>> Latest x86 tip has another perf timechart issue introduce
> >>> by latest commits.
> >>>
> >>> ./perf timechart
> >>> gives me:
> >>> "no trace data in the file"
> >>>
> >>> I reverted  the latest changes and things seem to break
> >>> between d854861c4292a4e675a5d3bfd862c5f7421c81e8
> >>> and
> >>> 69aad6f1ee69546dea8535ab8f3da9f445d57328
> >>> (linux-2.6-x86 tree ids)
> >>>
> >>> Be aware that ./perf timechart is currently broken
> >>> and segfaults on idle events (in 2.6.36 and 2.6.37).
> >>
> >> You mean .36 perf tools faults on .37 kernel? or the opposite?
> >> Is it because power_idle events weren't present on old tools?
> >> Do you have a pointer to those patches?
> > perf timechart
> > will segfault if perf.data has power_{start,end} events included
> > on 2.6.36 and 2.6.37 kernels.
> 
> Is this the same segfault you are seeing?
> 
> http://www.mail-archive.com/linux-perf-
users@vger.kernel.org/msg00057.html
Looks slightly different, the segfault should happen in:
process_sample_event
But looks very much related, possibly it has not been made/make with 
DEBUG=1
and -O6 was added and the backtrace is not 100% correct?

I still did not have time to send it out, will do so on Mo.

    Thomas

Re: perf timechart broken

[David Ahern]

On 01/14/11 10:00, Thomas Renninger wrote:
>> http://www.mail-archive.com/linux-perf-
> users@vger.kernel.org/msg00057.html
> Looks slightly different, the segfault should happen in:
> process_sample_event
> But looks very much related, possibly it has not been made/make with 
> DEBUG=1
> and -O6 was added and the backtrace is not 100% correct?

perf was built with DEBUG=1; that's how I got the pretty backtrace
versus having the arguments optimized out. The cpu=6291457 is the
garbage causing the segfault (there are only 2 cores in the system).
6291457 = 0x600001. Perhaps a mask is missing?

David

> 
> I still did not have time to send it out, will do so on Mo.
> 
>     Thomas

Re: perf timechart broken

[Thomas Renninger]

On Friday 14 January 2011 18:09:05 David Ahern wrote:
> 
> On 01/14/11 10:00, Thomas Renninger wrote:
> >> http://www.mail-archive.com/linux-perf-
> > users@vger.kernel.org/msg00057.html
> > Looks slightly different, the segfault should happen in:
> > process_sample_event
> > But looks very much related, possibly it has not been made/make with 
> > DEBUG=1
> > and -O6 was added and the backtrace is not 100% correct?
> 
> perf was built with DEBUG=1; that's how I got the pretty backtrace
> versus having the arguments optimized out. The cpu=6291457 is the
> garbage causing the segfault
Then it's the same issue.

> (there are only 2 cores in the system).
> 6291457 = 0x600001. Perhaps a mask is missing?
No, the power_start and power_end event have different kernel
structures, but in builtin-timechart.c the same struct is used.
cpu is at the end.
Therefore pe->cpu_id (in power_end case) accesses uninitialized
data.

But using the cpu data from the event itself (data.cpu, the cpu on
which the event got emited) for fixing this is fine.
It's the way it was done before the bug got introduced.
As said, this won't work if the kernel code triggering the C-state
is executed on a different CPU than the CPU which is affected by
the C-state change. But such HW does not yet exist on X86 afaik and the
power_start event dies out anyway.

I resubmitted the fix for 2.6.3{6,7} stable kernels and added you
to CC.

   Thomas