[Bug] ARM 'perf' regression by commit a43cb95d5

[Bug] ARM 'perf' regression by commit a43cb95d5

[Ming Lei]

Hi,

The commit a43cb95d5(dump_stack: unify debug information printed by show_regs())
caused ARM perf regression, then 'perf top' outputs mistakenly, see
[1].  The correct
output should be [2], which can be got after reverting the commit or
doing it partly
by the one line change below:

diff --git a/arch/arm/kernel/process.c b/arch/arm/kernel/process.c
index f219703..89bc3a4 100644
--- a/arch/arm/kernel/process.c
+++ b/arch/arm/kernel/process.c
@@ -225,7 +225,7 @@ void __show_regs(struct pt_regs *regs)
        unsigned long flags;
        char buf[64];

-       show_regs_print_info(KERN_DEFAULT);
+       //show_regs_print_info(KERN_DEFAULT);


Looks a bit weird, anyone can give a hint?


Thanks,
--
Ming Lei

[1], 'perf top' mistaken output
Samples: 17K of event 'cpu-clock', Event count (approx.): 3516532661
 97.51%  [smsc95xx]            [k] 0x013645b8
  0.21%  libc-2.15.so          [.] strstr
  0.14%  libc-2.15.so          [.] strchr
  0.12%  libc-2.15.so          [.] strcmp
  0.12%  perf                  [.] perf_evsel__parse_sample
  0.09%  perf                  [.] symbols__insert
  0.09%  perf                  [.] dso__load_sym
  0.08%  perf                  [.] perf_top__mmap_read_idx
  0.08%  perf                  [.] symbol_filter
  0.07%  libc-2.15.so          [.] memchr
  0.07%  libc-2.15.so          [.] memset
  0.07%  perf                  [.] internal_cplus_demangle
  0.06%  perf                  [.] sort__dso_cmp
  0.06%  libc-2.15.so          [.] strncmp
  0.06%  perf                  [.] add_hist_entry.isra.2
  0.06%  perf                  [.] dso__find_symbol
  0.06%  libc-2.15.so          [.] _int_malloc
  0.05%  perf                  [.] 0x00010d60
  0.04%  libc-2.15.so          [.] memcpy
  0.04%  perf                  [.] map__find_symbol
  0.04%  perf                  [.] rb_next
  0.04%  libelf-0.154.so       [.] gelf_getsym


[2], 'perf top' correct output
Samples: 46K of event 'cpu-clock', Event count (approx.): 937128704
 96.44%  [kernel]            [k] cpuidle_enter_state
  0.19%  libc-2.15.so        [.] strstr
  0.16%  [kernel]            [k] kallsyms_expand_symbol.clone.0
  0.13%  [kernel]            [k] _raw_spin_unlock_irq
  0.13%  [kernel]            [k] _raw_spin_unlock_irqrestore
  0.10%  [kernel]            [k] format_decode
  0.10%  perf                [.] perf_top__mmap_read_idx
  0.10%  perf                [.] rb_next
  0.09%  perf                [.] dso__find_symbol
  0.08%  [kernel]            [k] vsnprintf
  0.08%  perf                [.] add_hist_entry.isra.2
  0.08%  libc-2.15.so        [.] strcmp
  0.08%  libc-2.15.so        [.] memchr
  0.07%  perf                [.] sort__dso_cmp
  0.07%  libc-2.15.so        [.] strchr
  0.07%  [kernel]            [k] number.clone.1
  0.07%  perf                [.] map__process_kallsym_symbol
  0.06%  [kernel]            [k] memcpy
  0.05%  perf                [.] perf_evsel__parse_sample
  0.05%  libc-2.15.so        [.] _int_malloc
  0.05%  libc-2.15.so        [.] memcpy
  0.05%  perf                [.] perf_event__preprocess_sample

[Bug] ARM 'perf' regression by commit a43cb95d5

[Ming Lei]

On Fri, May 17, 2013 at 10:16 AM, Ming Lei <ming.lei@canonical.com> wrote:
> diff --git a/arch/arm/kernel/process.c b/arch/arm/kernel/process.c
> index f219703..89bc3a4 100644
> --- a/arch/arm/kernel/process.c
> +++ b/arch/arm/kernel/process.c
> @@ -225,7 +225,7 @@ void __show_regs(struct pt_regs *regs)
>         unsigned long flags;
>         char buf[64];
>
> -       show_regs_print_info(KERN_DEFAULT);
> +       //show_regs_print_info(KERN_DEFAULT);

Forget to mention, __show_regs() isn't run under both cases.

Thanks,
--
Ming Lei

[Bug] ARM 'perf' regression by commit a43cb95d5

[Will Deacon]

On Fri, May 17, 2013 at 03:16:40AM +0100, Ming Lei wrote:
> Hi,

Hello,

> The commit a43cb95d5(dump_stack: unify debug information printed by show_regs())
> caused ARM perf regression, then 'perf top' outputs mistakenly, see
> [1].  The correct
> output should be [2], which can be got after reverting the commit or
> doing it partly
> by the one line change below:
> 
> diff --git a/arch/arm/kernel/process.c b/arch/arm/kernel/process.c
> index f219703..89bc3a4 100644
> --- a/arch/arm/kernel/process.c
> +++ b/arch/arm/kernel/process.c
> @@ -225,7 +225,7 @@ void __show_regs(struct pt_regs *regs)
>         unsigned long flags;
>         char buf[64];
> 
> -       show_regs_print_info(KERN_DEFAULT);
> +       //show_regs_print_info(KERN_DEFAULT);
> 
> 
> Looks a bit weird, anyone can give a hint?

So it's still the morning and I haven't had my coffee yet, but I'm really
struggling to see what you're getting at. Why does this have anything to do
with perf?

> [1], 'perf top' mistaken output
> Samples: 17K of event 'cpu-clock', Event count (approx.): 3516532661
>  97.51%  [smsc95xx]            [k] 0x013645b8
>   0.21%  libc-2.15.so          [.] strstr
>   0.14%  libc-2.15.so          [.] strchr
>   0.12%  libc-2.15.so          [.] strcmp

[...]

> [2], 'perf top' correct output
> Samples: 46K of event 'cpu-clock', Event count (approx.): 937128704
>  96.44%  [kernel]            [k] cpuidle_enter_state
>   0.19%  libc-2.15.so        [.] strstr
>   0.16%  [kernel]            [k] kallsyms_expand_symbol.clone.0
>   0.13%  [kernel]            [k] _raw_spin_unlock_irq

[...]

Are you saying that the profile you're seeing is radically different,
rather than there being some formatting error that I can't spot? If so, that
sounds really strange and I can't see how the patch you mention is to
blame...

If we want to persue this, I guess other obvious questions are: which kernel
are you running? Does this affect multiple architectures (your diff only
changes ARM)? What's the workload which you are profiling?

Will

[Bug] ARM 'perf' regression by commit a43cb95d5

[Ming Lei]

On Fri, May 17, 2013 at 4:55 PM, Will Deacon <will.deacon@arm.com> wrote:
>
> So it's still the morning and I haven't had my coffee yet, but I'm really
> struggling to see what you're getting at. Why does this have anything to do
> with perf?

I don't know, and I just report it out, :-)

I found the problem days ago, and until yesterday I had one more hours to
git-bisect it, but the result is very frustrated.

>
>> [1], 'perf top' mistaken output
>> Samples: 17K of event 'cpu-clock', Event count (approx.): 3516532661
>>  97.51%  [smsc95xx]            [k] 0x013645b8
>>   0.21%  libc-2.15.so          [.] strstr
>>   0.14%  libc-2.15.so          [.] strchr
>>   0.12%  libc-2.15.so          [.] strcmp
>
> [...]
>
>> [2], 'perf top' correct output
>> Samples: 46K of event 'cpu-clock', Event count (approx.): 937128704
>>  96.44%  [kernel]            [k] cpuidle_enter_state
>>   0.19%  libc-2.15.so        [.] strstr
>>   0.16%  [kernel]            [k] kallsyms_expand_symbol.clone.0
>>   0.13%  [kernel]            [k] _raw_spin_unlock_irq
>
> [...]
>
> Are you saying that the profile you're seeing is radically different,
> rather than there being some formatting error that I can't spot? If so, that

Yes.

> sounds really strange and I can't see how the patch you mention is to
> blame...
>
> If we want to persue this, I guess other obvious questions are: which kernel
> are you running? Does this affect multiple architectures (your diff only

Either 3.10-rc1 or today's -next tree(3.10.0-rc1-next-20130516).

> changes ARM)? What's the workload which you are profiling?

I only tested it on Pandaboard, and no real workload, so you can see
cpuidle_enter_state is the top frequent symbol.

Or could anyone else try to verify the problem on their own environment?

Thanks,
--
Ming Lei

[Bug] ARM 'perf' regression by commit a43cb95d5

[Will Deacon]

On Fri, May 17, 2013 at 10:27:05AM +0100, Ming Lei wrote:
> On Fri, May 17, 2013 at 4:55 PM, Will Deacon <will.deacon@arm.com> wrote:
> >
> > So it's still the morning and I haven't had my coffee yet, but I'm really
> > struggling to see what you're getting at. Why does this have anything to do
> > with perf?
> 
> I don't know, and I just report it out, :-)
> 
> I found the problem days ago, and until yesterday I had one more hours to
> git-bisect it, but the result is very frustrated.
> 
> >
> >> [1], 'perf top' mistaken output
> >> Samples: 17K of event 'cpu-clock', Event count (approx.): 3516532661
> >>  97.51%  [smsc95xx]            [k] 0x013645b8
> >>   0.21%  libc-2.15.so          [.] strstr
> >>   0.14%  libc-2.15.so          [.] strchr
> >>   0.12%  libc-2.15.so          [.] strcmp
> >
> > [...]
> >
> >> [2], 'perf top' correct output
> >> Samples: 46K of event 'cpu-clock', Event count (approx.): 937128704
> >>  96.44%  [kernel]            [k] cpuidle_enter_state
> >>   0.19%  libc-2.15.so        [.] strstr
> >>   0.16%  [kernel]            [k] kallsyms_expand_symbol.clone.0
> >>   0.13%  [kernel]            [k] _raw_spin_unlock_irq
> >
> > [...]
> >
> > Are you saying that the profile you're seeing is radically different,
> > rather than there being some formatting error that I can't spot? If so, that
> 
> Yes.
> 
> > sounds really strange and I can't see how the patch you mention is to
> > blame...
> >
> > If we want to persue this, I guess other obvious questions are: which kernel
> > are you running? Does this affect multiple architectures (your diff only
> 
> Either 3.10-rc1 or today's -next tree(3.10.0-rc1-next-20130516).
> 
> > changes ARM)? What's the workload which you are profiling?
> 
> I only tested it on Pandaboard, and no real workload, so you can see
> cpuidle_enter_state is the top frequent symbol.

It's probably easier if you choose a workload, otherwise it's difficult to
see what is `correct' and what is broken. For example, your broken output
seems to be in the smsc95xx driver, so assumedly there's a bunch of
networking going on whereas your other output is in cpuidle_enter_state.

We need an apples-for-apples comparison if you think there's a bug in the
kernel. Can you try profiling hackbench or something?

> Or could anyone else try to verify the problem on their own environment?

How are you running perf top?

Will

[Bug] ARM 'perf' regression by commit a43cb95d5

[Ming Lei]

On Fri, May 17, 2013 at 5:36 PM, Will Deacon <will.deacon@arm.com> wrote:
>
> It's probably easier if you choose a workload, otherwise it's difficult to
> see what is `correct' and what is broken. For example, your broken output
> seems to be in the smsc95xx driver, so assumedly there's a bunch of
> networking going on whereas your other output is in cpuidle_enter_state.

If all modules are removed, the result will become OK. And if I only insert one
module, the top sample will fall inside the only module, but I am sure
nothing is working on the symbols of the module.

>
> We need an apples-for-apples comparison if you think there's a bug in the
> kernel. Can you try profiling hackbench or something?
>
>> Or could anyone else try to verify the problem on their own environment?
>
> How are you running perf top?

sudo perf top

Thanks
--
Ming Lei

[Bug] ARM 'perf' regression by commit a43cb95d5

[Will Deacon]

On Fri, May 17, 2013 at 10:48:23AM +0100, Ming Lei wrote:
> On Fri, May 17, 2013 at 5:36 PM, Will Deacon <will.deacon@arm.com> wrote:
> >
> > It's probably easier if you choose a workload, otherwise it's difficult to
> > see what is `correct' and what is broken. For example, your broken output
> > seems to be in the smsc95xx driver, so assumedly there's a bunch of
> > networking going on whereas your other output is in cpuidle_enter_state.
> 
> If all modules are removed, the result will become OK. And if I only insert one
> module, the top sample will fall inside the only module, but I am sure
> nothing is working on the symbols of the module.

Can you check your dmesg please? I suppose the smsc95xx driver might be
screaming about something and somehow the changes to the reg printing have
made it get stuck.

> >
> > We need an apples-for-apples comparison if you think there's a bug in the
> > kernel. Can you try profiling hackbench or something?
> >
> >> Or could anyone else try to verify the problem on their own environment?
> >
> > How are you running perf top?
> 
> sudo perf top

... and did hackbench make any difference (i.e. is the profile more stable)?

Will

[Bug] ARM 'perf' regression by commit a43cb95d5

[Ming Lei]

On Fri, May 17, 2013 at 5:54 PM, Will Deacon <will.deacon@arm.com> wrote:
> On Fri, May 17, 2013 at 10:48:23AM +0100, Ming Lei wrote:
>> On Fri, May 17, 2013 at 5:36 PM, Will Deacon <will.deacon@arm.com> wrote:
>> >
>> > It's probably easier if you choose a workload, otherwise it's difficult to
>> > see what is `correct' and what is broken. For example, your broken output
>> > seems to be in the smsc95xx driver, so assumedly there's a bunch of
>> > networking going on whereas your other output is in cpuidle_enter_state.
>>
>> If all modules are removed, the result will become OK. And if I only insert one
>> module, the top sample will fall inside the only module, but I am sure
>> nothing is working on the symbols of the module.
>
> Can you check your dmesg please? I suppose the smsc95xx driver might be
> screaming about something and somehow the changes to the reg printing have
> made it get stuck.

If I insert only one useless module(such as, spi-altera.ko) on Pandaboard,
the top sample will fall inside the module of spi-altera, so it is nothing to
do with smsc95xx, also you can see the sampled top IP is an invalid address.

>
>> >
>> > We need an apples-for-apples comparison if you think there's a bug in the
>> > kernel. Can you try profiling hackbench or something?
>> >
>> >> Or could anyone else try to verify the problem on their own environment?
>> >
>> > How are you running perf top?
>>
>> sudo perf top
>
> ... and did hackbench make any difference (i.e. is the profile more stable)?

When hackbench is started, there is no much change compared with idle,
only another sample( 2.49%  [unknown]            [.] 0xb6f618a0) comes and
becomes top 2.

Thanks,
--
Ming Lei

[Bug] ARM 'perf' regression by commit a43cb95d5

[Will Deacon]

On Fri, May 17, 2013 at 11:07:37AM +0100, Ming Lei wrote:
> On Fri, May 17, 2013 at 5:54 PM, Will Deacon <will.deacon@arm.com> wrote:
> > On Fri, May 17, 2013 at 10:48:23AM +0100, Ming Lei wrote:
> >> On Fri, May 17, 2013 at 5:36 PM, Will Deacon <will.deacon@arm.com> wrote:
> >> >
> >> > It's probably easier if you choose a workload, otherwise it's difficult to
> >> > see what is `correct' and what is broken. For example, your broken output
> >> > seems to be in the smsc95xx driver, so assumedly there's a bunch of
> >> > networking going on whereas your other output is in cpuidle_enter_state.
> >>
> >> If all modules are removed, the result will become OK. And if I only insert one
> >> module, the top sample will fall inside the only module, but I am sure
> >> nothing is working on the symbols of the module.

Ok, I tried to reproduce this on my TC2 with 3.10-rc1 and perf top looks
fine. I also tried loading your spi-altera module and it made no difference.

I'm using a fairly old perf tool (reports its version as 3.5.5).

Will

[Bug] ARM 'perf' regression by commit a43cb95d5

[Ming Lei]

On Fri, May 17, 2013 at 11:59 PM, Will Deacon <will.deacon@arm.com> wrote:
>
> Ok, I tried to reproduce this on my TC2 with 3.10-rc1 and perf top looks
> fine. I also tried loading your spi-altera module and it made no difference.
>
> I'm using a fairly old perf tool (reports its version as 3.5.5).

It isn't related with perf tool.

Finally, looks the problem disappeared after upgrading gcc to "gcc version
4.7.3 (Sourcery CodeBench Lite 2013.05-24)" from "gcc version 4.5.1
(Sourcery G++ Lite 2010.09-50)", so it should be caused by compiler.


Thanks,
--
Ming Lei