perf top -g -U --sort=symbol --children == lalalalala?

perf top -g -U --sort=symbol --children == lalalalala?

[Mike Galbraith]

Seems the now default on --children thingy doesn't like -U much. 

Samples: 5K of event 'cycles', Event count (approx.): 2268660922
  Children      Self  Symbol
+   46.42%     0.04%  [k] system_call_fastpath
+   27.12%     0.80%  [k] apic_timer_interrupt
+   26.26%     0.23%  [k] smp_apic_timer_interrupt
+   20.43%     0.13%  [k] local_apic_timer_interrupt
+   20.20%     0.74%  [k] hrtimer_interrupt
+   18.01%     0.39%  [k] __run_hrtimer
+   14.43%     0.35%  [k] tick_sched_timer
+   13.60%     0.05%  [k] sys_poll
+   13.09%     1.16%  [k] do_sys_poll
+   12.16%     0.08%  [k] tick_sched_handle.isra.16
+   11.70%     0.32%  [k] update_process_times
+   11.41%     0.03%  [k] sys_read
+   11.17%     0.11%  [k] vfs_read
+   10.85%     0.09%  [k] seq_read
+    8.27%     0.09%  [k] proc_single_show
+    7.79%     1.19%  [k] page_fault
+    7.01%     0.25%  [k] scheduler_tick
+    6.26%     0.11%  [k] __do_page_fault
+    5.97%     1.33%  [k] do_task_stat
+    5.91%     0.23%  [k] handle_mm_fault
+    5.40%     0.20%  [k] do_sys_open
+    5.02%     0.09%  [k] ret_from_intr
+    4.94%     0.05%  [k] do_IRQ
+    4.70%     0.14%  [k] path_openat
+    4.69%     0.62%  [k] tty_poll
+    4.69%     0.16%  [k] irq_exit
+    4.49%     0.63%  [k] __do_softirq
+    4.27%     0.12%  [k] __alloc_pages_nodemask
+    3.95%     0.03%  [k] handle_irq_event_percpu
+    3.51%     0.71%  [k] __fget_light
+    3.47%     0.04%  [k] sys_select
+    3.39%     0.08%  [k] seq_printf
+    3.37%     0.07%  [k] sys_open
+    3.34%     0.11%  [k] seq_vprintf
+    3.22%     0.02%  [k] core_sys_select
+    3.15%     0.26%  [k] do_select
+    3.15%     3.15%  [k] _raw_spin_lock

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Arnaldo Carvalho de Melo]

Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
> Seems the now default on --children thingy doesn't like -U much. 

Namhyung, can you please take a look at this?

- Arnaldo
 
> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
>   Children      Self  Symbol
> +   46.42%     0.04%  [k] system_call_fastpath
> +   27.12%     0.80%  [k] apic_timer_interrupt
> +   26.26%     0.23%  [k] smp_apic_timer_interrupt
> +   20.43%     0.13%  [k] local_apic_timer_interrupt
> +   20.20%     0.74%  [k] hrtimer_interrupt
> +   18.01%     0.39%  [k] __run_hrtimer
> +   14.43%     0.35%  [k] tick_sched_timer
> +   13.60%     0.05%  [k] sys_poll
> +   13.09%     1.16%  [k] do_sys_poll
> +   12.16%     0.08%  [k] tick_sched_handle.isra.16
> +   11.70%     0.32%  [k] update_process_times
> +   11.41%     0.03%  [k] sys_read
> +   11.17%     0.11%  [k] vfs_read
> +   10.85%     0.09%  [k] seq_read
> +    8.27%     0.09%  [k] proc_single_show
> +    7.79%     1.19%  [k] page_fault
> +    7.01%     0.25%  [k] scheduler_tick
> +    6.26%     0.11%  [k] __do_page_fault
> +    5.97%     1.33%  [k] do_task_stat
> +    5.91%     0.23%  [k] handle_mm_fault
> +    5.40%     0.20%  [k] do_sys_open
> +    5.02%     0.09%  [k] ret_from_intr
> +    4.94%     0.05%  [k] do_IRQ
> +    4.70%     0.14%  [k] path_openat
> +    4.69%     0.62%  [k] tty_poll
> +    4.69%     0.16%  [k] irq_exit
> +    4.49%     0.63%  [k] __do_softirq
> +    4.27%     0.12%  [k] __alloc_pages_nodemask
> +    3.95%     0.03%  [k] handle_irq_event_percpu
> +    3.51%     0.71%  [k] __fget_light
> +    3.47%     0.04%  [k] sys_select
> +    3.39%     0.08%  [k] seq_printf
> +    3.37%     0.07%  [k] sys_open
> +    3.34%     0.11%  [k] seq_vprintf
> +    3.22%     0.02%  [k] core_sys_select
> +    3.15%     0.26%  [k] do_select
> +    3.15%     3.15%  [k] _raw_spin_lock
> 
> 

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Namhyung Kim]

On Tue, Sep 9, 2014 at 10:37 PM, Arnaldo Carvalho de Melo
<acme@ghostprotocols.net> wrote:
> Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
>> Seems the now default on --children thingy doesn't like -U much.
>
> Namhyung, can you please take a look at this?

So what is the problem here?


>
>> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
>>   Children      Self  Symbol
>> +   46.42%     0.04%  [k] system_call_fastpath
>> +   27.12%     0.80%  [k] apic_timer_interrupt
>> +   26.26%     0.23%  [k] smp_apic_timer_interrupt
>> +   20.43%     0.13%  [k] local_apic_timer_interrupt
>> +   20.20%     0.74%  [k] hrtimer_interrupt
>> +   18.01%     0.39%  [k] __run_hrtimer
>> +   14.43%     0.35%  [k] tick_sched_timer
>> +   13.60%     0.05%  [k] sys_poll
>> +   13.09%     1.16%  [k] do_sys_poll
>> +   12.16%     0.08%  [k] tick_sched_handle.isra.16
>> +   11.70%     0.32%  [k] update_process_times
>> +   11.41%     0.03%  [k] sys_read
>> +   11.17%     0.11%  [k] vfs_read
>> +   10.85%     0.09%  [k] seq_read
>> +    8.27%     0.09%  [k] proc_single_show
>> +    7.79%     1.19%  [k] page_fault
>> +    7.01%     0.25%  [k] scheduler_tick
>> +    6.26%     0.11%  [k] __do_page_fault
>> +    5.97%     1.33%  [k] do_task_stat
>> +    5.91%     0.23%  [k] handle_mm_fault
>> +    5.40%     0.20%  [k] do_sys_open
>> +    5.02%     0.09%  [k] ret_from_intr
>> +    4.94%     0.05%  [k] do_IRQ
>> +    4.70%     0.14%  [k] path_openat
>> +    4.69%     0.62%  [k] tty_poll
>> +    4.69%     0.16%  [k] irq_exit
>> +    4.49%     0.63%  [k] __do_softirq
>> +    4.27%     0.12%  [k] __alloc_pages_nodemask
>> +    3.95%     0.03%  [k] handle_irq_event_percpu
>> +    3.51%     0.71%  [k] __fget_light
>> +    3.47%     0.04%  [k] sys_select
>> +    3.39%     0.08%  [k] seq_printf
>> +    3.37%     0.07%  [k] sys_open
>> +    3.34%     0.11%  [k] seq_vprintf
>> +    3.22%     0.02%  [k] core_sys_select
>> +    3.15%     0.26%  [k] do_select
>> +    3.15%     3.15%  [k] _raw_spin_lock
>>
>>



-- 
Thanks,
Namhyung Kim

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Mike Galbraith]

On Thu, 2014-09-11 at 17:09 +0900, Namhyung Kim wrote: 
> On Tue, Sep 9, 2014 at 10:37 PM, Arnaldo Carvalho de Melo
> <acme@ghostprotocols.net> wrote:
> > Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
> >> Seems the now default on --children thingy doesn't like -U much.
> >
> > Namhyung, can you please take a look at this?
> 
> So what is the problem here?

Well, if you don't see anything wrong, I guess nothing at all.

> >> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
> >>   Children      Self  Symbol
> >> +   46.42%     0.04%  [k] system_call_fastpath

I'll just turn it off until I figure out what cool stuff this is telling
me. why that symbol becomes the number one hit, and why total% > 100.

To me, it looks like top smoked it's breakfast, went to lala land ;-)

-Mike

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Arnaldo Carvalho de Melo]

Em Thu, Sep 11, 2014 at 02:43:12PM +0200, Mike Galbraith escreveu:
> On Thu, 2014-09-11 at 17:09 +0900, Namhyung Kim wrote: 
> > On Tue, Sep 9, 2014 at 10:37 PM, Arnaldo Carvalho de Melo
> > <acme@ghostprotocols.net> wrote:
> > > Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
> > >> Seems the now default on --children thingy doesn't like -U much.
> > >
> > > Namhyung, can you please take a look at this?
> > 
> > So what is the problem here?
> 
> Well, if you don't see anything wrong, I guess nothing at all.

:-)

I think that when we decide that it is so better to change defaults like
we did this time, we should be required to add a big fat warning (a
--tui popup, use the first lines on --stdio, etc) about why the default
was changed and allow quick, easy opt out, restoring previous behaviour
after the user, being warned, knows what to expect, tries it, and then
is in a better position to decide if keeping the new default is what is
desired.

- Arnaldo
 
> > >> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
> > >>   Children      Self  Symbol
> > >> +   46.42%     0.04%  [k] system_call_fastpath
 
> I'll just turn it off until I figure out what cool stuff this is telling
> me. why that symbol becomes the number one hit, and why total% > 100.
 
> To me, it looks like top smoked it's breakfast, went to lala land ;-)

Yeah, its confusing, I'll let Namhyung explain it ;-)

:-)

- Arnaldo

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Arnaldo Carvalho de Melo]

Em Thu, Sep 11, 2014 at 10:43:38AM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Thu, Sep 11, 2014 at 02:43:12PM +0200, Mike Galbraith escreveu:
> > On Thu, 2014-09-11 at 17:09 +0900, Namhyung Kim wrote: 
> > > On Tue, Sep 9, 2014 at 10:37 PM, Arnaldo Carvalho de Melo
> > > <acme@ghostprotocols.net> wrote:
> > > > Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
> > > >> Seems the now default on --children thingy doesn't like -U much.

> > > > Namhyung, can you please take a look at this?

> > > So what is the problem here?

> > Well, if you don't see anything wrong, I guess nothing at all.
 
> :-)
 
> I think that when we decide that it is so better to change defaults like
> we did this time, we should be required to add a big fat warning (a
> --tui popup, use the first lines on --stdio, etc) about why the default
> was changed and allow quick, easy opt out, restoring previous behaviour
> after the user, being warned, knows what to expect, tries it, and then
> is in a better position to decide if keeping the new default is what is
> desired.

Also, looking at the changelog entries and at tools/perf/Documentation/
the only description for --children, the default, is:

----------------
--children::
        Accumulate callchain of children to parent entry so that then can
        show up in the output.  The output will have a new "Children" column
        and will be sorted on the data.  It requires callchains are recorded.
----------------

I think that a longer/clearer entry in the 'perf record' man page is
required.

Perhaps the description got lost in a --cover-letter for the patch
series implementing it?

- Arnaldo

>  
> > > >> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
> > > >>   Children      Self  Symbol
> > > >> +   46.42%     0.04%  [k] system_call_fastpath
>  
> > I'll just turn it off until I figure out what cool stuff this is telling
> > me. why that symbol becomes the number one hit, and why total% > 100.
>  
> > To me, it looks like top smoked it's breakfast, went to lala land ;-)
> 
> Yeah, its confusing, I'll let Namhyung explain it ;-)
> 
> :-)
> 
> - Arnaldo

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Mike Galbraith]

On Thu, 2014-09-11 at 18:30 -0300, Arnaldo Carvalho de Melo wrote:

> Also, looking at the changelog entries and at tools/perf/Documentation/
> the only description for --children, the default, is:
> 
> ----------------
> --children::
>         Accumulate callchain of children to parent entry so that then can
>         show up in the output.  The output will have a new "Children" column
>         and will be sorted on the data.  It requires callchains are recorded.
> ----------------

grep of course found that, and git log found more, but nothing told me
what the heck it's sweeping up that's so darn plentiful in my box that
there's more than 100% of it laying about :)

> I think that a longer/clearer entry in the 'perf record' man page is
> required.
> 
> Perhaps the description got lost in a --cover-letter for the patch
> series implementing it?

If it ever existed, I can't find it.  A little blurb would be helpful.

-Mike

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Namhyung Kim]

Hi Arnaldo and Mike,

On Thu, 11 Sep 2014 10:43:38 -0300, Arnaldo Carvalho de Melo wrote:
> Em Thu, Sep 11, 2014 at 02:43:12PM +0200, Mike Galbraith escreveu:
>> On Thu, 2014-09-11 at 17:09 +0900, Namhyung Kim wrote: 
>> > On Tue, Sep 9, 2014 at 10:37 PM, Arnaldo Carvalho de Melo
>> > <acme@ghostprotocols.net> wrote:
>> > > Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
>> > >> Seems the now default on --children thingy doesn't like -U much.
>> > >
>> > > Namhyung, can you please take a look at this?
>> > 
>> > So what is the problem here?
>> 
>> Well, if you don't see anything wrong, I guess nothing at all.
>
> :-)
>
> I think that when we decide that it is so better to change defaults like
> we did this time, we should be required to add a big fat warning (a
> --tui popup, use the first lines on --stdio, etc) about why the default
> was changed and allow quick, easy opt out, restoring previous behaviour
> after the user, being warned, knows what to expect, tries it, and then
> is in a better position to decide if keeping the new default is what is
> desired.

So the problem is that why it turned on --children option by default,
right?  I thought you mentioned there's a problem with -U option and I
couldn't figure out what it is.


>  
>> > >> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
>> > >>   Children      Self  Symbol
>> > >> +   46.42%     0.04%  [k] system_call_fastpath
>  
>> I'll just turn it off until I figure out what cool stuff this is telling
>> me. why that symbol becomes the number one hit, and why total% > 100.
>  
>> To me, it looks like top smoked it's breakfast, went to lala land ;-)
>
> Yeah, its confusing, I'll let Namhyung explain it ;-)

Now I have three persion yell at me for this change. :)

When this change was developping, Ingo said it'd be better if it looks
like output of sysprof as it's more popular for most (userland?) guys.
You can see the discussion in the following links:

  https://lkml.org/lkml/2013/10/31/97
  https://lkml.org/lkml/2013/11/1/85

The children field is a cumulative total overhead (for its all
children/callee) so sum of them would be more than 100%.  And as Ingo
requested it sorts the output entries using children overhead so that
one can easily see higher level view of performance bottle-neck.

Thanks,
Namhyung

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Mike Galbraith]

On Fri, 2014-09-12 at 16:24 +0900, Namhyung Kim wrote: 
> Hi Arnaldo and Mike,
> 
> On Thu, 11 Sep 2014 10:43:38 -0300, Arnaldo Carvalho de Melo wrote:
> > Em Thu, Sep 11, 2014 at 02:43:12PM +0200, Mike Galbraith escreveu:
> >> On Thu, 2014-09-11 at 17:09 +0900, Namhyung Kim wrote: 
> >> > On Tue, Sep 9, 2014 at 10:37 PM, Arnaldo Carvalho de Melo
> >> > <acme@ghostprotocols.net> wrote:
> >> > > Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
> >> > >> Seems the now default on --children thingy doesn't like -U much.
> >> > >
> >> > > Namhyung, can you please take a look at this?
> >> > 
> >> > So what is the problem here?
> >> 
> >> Well, if you don't see anything wrong, I guess nothing at all.
> >
> > :-)
> >
> > I think that when we decide that it is so better to change defaults like
> > we did this time, we should be required to add a big fat warning (a
> > --tui popup, use the first lines on --stdio, etc) about why the default
> > was changed and allow quick, easy opt out, restoring previous behaviour
> > after the user, being warned, knows what to expect, tries it, and then
> > is in a better position to decide if keeping the new default is what is
> > desired.
> 
> So the problem is that why it turned on --children option by default,
> right?  I thought you mentioned there's a problem with -U option and I
> couldn't figure out what it is.
> 
> 
> >  
> >> > >> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
> >> > >>   Children      Self  Symbol
> >> > >> +   46.42%     0.04%  [k] system_call_fastpath
> >  
> >> I'll just turn it off until I figure out what cool stuff this is telling
> >> me. why that symbol becomes the number one hit, and why total% > 100.
> >  
> >> To me, it looks like top smoked it's breakfast, went to lala land ;-)
> >
> > Yeah, its confusing, I'll let Namhyung explain it ;-)
> 
> Now I have three persion yell at me for this change. :)
> 
> When this change was developping, Ingo said it'd be better if it looks
> like output of sysprof as it's more popular for most (userland?) guys.
> You can see the discussion in the following links:
> 
>   https://lkml.org/lkml/2013/10/31/97
>   https://lkml.org/lkml/2013/11/1/85
> 
> The children field is a cumulative total overhead (for its all
> children/callee) so sum of them would be more than 100%.  And as Ingo
> requested it sorts the output entries using children overhead so that
> one can easily see higher level view of performance bottle-neck.

I still don't get why my #1 _KERNEL_ (-U) overhead in the below changes
from __schedule() to system_call().  The thing that's consuming the most
cycles remains __schedule().  It doesn't really matter much I 'spose,
turning it off in .perfconfig works fine.

(seems top wants to learn to ignore cpu_startup_entry too [see hmm
below], and maybe grow an option to _not_ ignore idle stuff)

--no-children
-    6.52%  [k] __schedule
   - __schedule
      - 56.95% schedule
           99.88% pipe_wait
              pipe_read
              new_sync_read
              vfs_read
              sys_read
              system_call
              __read_nocancel
              __libc_start_main
      + 40.63% schedule_preempt_disabled
      + 1.03% __read_nocancel
        0.78% pipe_wait
           pipe_read
           new_sync_read
           vfs_read
           sys_read
           system_call
           __read_nocancel
           __libc_start_main
      + 0.62% cpu_startup_entry <== hmm
+    5.13%  [k] native_sched_clock
+    4.80%  [k] system_call
+    4.36%  [k] resched_curr
+    3.59%  [k] _raw_spin_lock_irqsave
+    3.34%  [k] __switch_to


--children
+   68.49%     4.92%  [k] system_call
+   32.75%     0.42%  [k] sys_write
+   31.85%     0.86%  [k] vfs_write
+   30.20%     0.43%  [k] sys_read
+   29.34%     0.74%  [k] new_sync_write
+   29.22%     0.62%  [k] vfs_read
+   27.88%     0.70%  [k] new_sync_read
+   27.65%     1.70%  [k] pipe_write
+   26.62%     2.86%  [k] cpu_startup_entry  <== hmm
+   26.23%     2.05%  [k] pipe_read
+   22.38%     0.45%  [k] __wake_up_sync_key
-   21.92%     6.61%  [k] __schedule
   - __schedule
      - 62.95% schedule
           99.88% pipe_wait
              pipe_read
              new_sync_read
              vfs_read
              sys_read
              system_call
              __read_nocancel
      + 35.27% schedule_preempt_disabled
      + 1.38% __read_nocancel
+   20.53%     0.81%  [k] __wake_up_common
+   19.72%     0.17%  [k] autoremove_wake_function
+   19.55%     0.09%  [k] default_wake_function
+   19.01%     1.44%  [k] try_to_wake_up
+   18.65%     0.84%  [k] pipe_wait
+   15.07%     1.06%  [k] schedule

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Arnaldo Carvalho de Melo]

Em Fri, Sep 12, 2014 at 10:41:33AM +0200, Mike Galbraith escreveu:
> On Fri, 2014-09-12 at 16:24 +0900, Namhyung Kim wrote: 
> > Hi Arnaldo and Mike,
> > 
> > On Thu, 11 Sep 2014 10:43:38 -0300, Arnaldo Carvalho de Melo wrote:
> > > Em Thu, Sep 11, 2014 at 02:43:12PM +0200, Mike Galbraith escreveu:
> > >> On Thu, 2014-09-11 at 17:09 +0900, Namhyung Kim wrote: 
> > >> > On Tue, Sep 9, 2014 at 10:37 PM, Arnaldo Carvalho de Melo
> > >> > <acme@ghostprotocols.net> wrote:
> > >> > > Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
> > >> > >> Seems the now default on --children thingy doesn't like -U much.
> > >> > >
> > >> > > Namhyung, can you please take a look at this?
> > >> > 
> > >> > So what is the problem here?
> > >> 
> > >> Well, if you don't see anything wrong, I guess nothing at all.
> > >
> > > :-)
> > >
> > > I think that when we decide that it is so better to change defaults like
> > > we did this time, we should be required to add a big fat warning (a
> > > --tui popup, use the first lines on --stdio, etc) about why the default
> > > was changed and allow quick, easy opt out, restoring previous behaviour
> > > after the user, being warned, knows what to expect, tries it, and then
> > > is in a better position to decide if keeping the new default is what is
> > > desired.
> > 
> > So the problem is that why it turned on --children option by default,
> > right?  I thought you mentioned there's a problem with -U option and I
> > couldn't figure out what it is.
> > 
> > 
> > >  
> > >> > >> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
> > >> > >>   Children      Self  Symbol
> > >> > >> +   46.42%     0.04%  [k] system_call_fastpath
> > >  
> > >> I'll just turn it off until I figure out what cool stuff this is telling
> > >> me. why that symbol becomes the number one hit, and why total% > 100.
> > >  
> > >> To me, it looks like top smoked it's breakfast, went to lala land ;-)
> > >
> > > Yeah, its confusing, I'll let Namhyung explain it ;-)
> > 
> > Now I have three persion yell at me for this change. :)
> > 
> > When this change was developping, Ingo said it'd be better if it looks
> > like output of sysprof as it's more popular for most (userland?) guys.
> > You can see the discussion in the following links:
> > 
> >   https://lkml.org/lkml/2013/10/31/97
> >   https://lkml.org/lkml/2013/11/1/85
> > 
> > The children field is a cumulative total overhead (for its all
> > children/callee) so sum of them would be more than 100%.  And as Ingo
> > requested it sorts the output entries using children overhead so that
> > one can easily see higher level view of performance bottle-neck.
> 
> I still don't get why my #1 _KERNEL_ (-U) overhead in the below changes
> from __schedule() to system_call().  The thing that's consuming the most
> cycles remains __schedule().  It doesn't really matter much I 'spose,
> turning it off in .perfconfig works fine.
> 
> (seems top wants to learn to ignore cpu_startup_entry too [see hmm
> below], and maybe grow an option to _not_ ignore idle stuff)

yeah, ideally we would have some flag from the kernel stating that it is
idle context, so that we don't have to keep this list of idle functions.

Until then we can try to get this more manageable by having a file where
people can add idle functions and as well as not just discard entries
for these functions, but instead mark them as idle.

And as well have a key in interactive tools to toggle them on/off and
somethile like -U/-K to set the initial value of this toggle from the
command line.
 
> --no-children
> -    6.52%  [k] __schedule
>    - __schedule
>       - 56.95% schedule
>            99.88% pipe_wait
>               pipe_read
>               new_sync_read
>               vfs_read
>               sys_read
>               system_call
>               __read_nocancel
>               __libc_start_main
>       + 40.63% schedule_preempt_disabled
>       + 1.03% __read_nocancel
>         0.78% pipe_wait
>            pipe_read
>            new_sync_read
>            vfs_read
>            sys_read
>            system_call
>            __read_nocancel
>            __libc_start_main
>       + 0.62% cpu_startup_entry <== hmm
> +    5.13%  [k] native_sched_clock
> +    4.80%  [k] system_call
> +    4.36%  [k] resched_curr
> +    3.59%  [k] _raw_spin_lock_irqsave
> +    3.34%  [k] __switch_to
> 
> 
> --children
> +   68.49%     4.92%  [k] system_call
> +   32.75%     0.42%  [k] sys_write
> +   31.85%     0.86%  [k] vfs_write
> +   30.20%     0.43%  [k] sys_read
> +   29.34%     0.74%  [k] new_sync_write
> +   29.22%     0.62%  [k] vfs_read
> +   27.88%     0.70%  [k] new_sync_read
> +   27.65%     1.70%  [k] pipe_write
> +   26.62%     2.86%  [k] cpu_startup_entry  <== hmm
> +   26.23%     2.05%  [k] pipe_read
> +   22.38%     0.45%  [k] __wake_up_sync_key
> -   21.92%     6.61%  [k] __schedule
>    - __schedule
>       - 62.95% schedule
>            99.88% pipe_wait
>               pipe_read
>               new_sync_read
>               vfs_read
>               sys_read
>               system_call
>               __read_nocancel
>       + 35.27% schedule_preempt_disabled
>       + 1.38% __read_nocancel
> +   20.53%     0.81%  [k] __wake_up_common
> +   19.72%     0.17%  [k] autoremove_wake_function
> +   19.55%     0.09%  [k] default_wake_function
> +   19.01%     1.44%  [k] try_to_wake_up
> +   18.65%     0.84%  [k] pipe_wait
> +   15.07%     1.06%  [k] schedule
> 

Re: perf top -g -U --sort=symbol --children == lalalalala?

[Arnaldo Carvalho de Melo]

Em Fri, Sep 12, 2014 at 04:24:54PM +0900, Namhyung Kim escreveu:
> Hi Arnaldo and Mike,
> 
> On Thu, 11 Sep 2014 10:43:38 -0300, Arnaldo Carvalho de Melo wrote:
> > Em Thu, Sep 11, 2014 at 02:43:12PM +0200, Mike Galbraith escreveu:
> >> On Thu, 2014-09-11 at 17:09 +0900, Namhyung Kim wrote: 
> >> > On Tue, Sep 9, 2014 at 10:37 PM, Arnaldo Carvalho de Melo
> >> > <acme@ghostprotocols.net> wrote:
> >> > > Em Tue, Sep 09, 2014 at 01:54:01PM +0200, Mike Galbraith escreveu:
> >> > >> Seems the now default on --children thingy doesn't like -U much.
> >> > >
> >> > > Namhyung, can you please take a look at this?
> >> > 
> >> > So what is the problem here?
> >> 
> >> Well, if you don't see anything wrong, I guess nothing at all.
> >
> > :-)
> >
> > I think that when we decide that it is so better to change defaults like
> > we did this time, we should be required to add a big fat warning (a
> > --tui popup, use the first lines on --stdio, etc) about why the default
> > was changed and allow quick, easy opt out, restoring previous behaviour
> > after the user, being warned, knows what to expect, tries it, and then
> > is in a better position to decide if keeping the new default is what is
> > desired.
> 
> So the problem is that why it turned on --children option by default,
> right?  I thought you mentioned there's a problem with -U option and I
> couldn't figure out what it is.

Yeah, at that point I thought the problem was that -U wasn't honoured in
--children mode, but after I looked again at the output, it was all [k],
so I thought that it was something else but didn't got back to the
thread :-)
 
> >> > >> Samples: 5K of event 'cycles', Event count (approx.): 2268660922
> >> > >>   Children      Self  Symbol
> >> > >> +   46.42%     0.04%  [k] system_call_fastpath
> >  
> >> I'll just turn it off until I figure out what cool stuff this is telling
> >> me. why that symbol becomes the number one hit, and why total% > 100.
> >  
> >> To me, it looks like top smoked it's breakfast, went to lala land ;-)
> >
> > Yeah, its confusing, I'll let Namhyung explain it ;-)
> 
> Now I have three persion yell at me for this change. :)

Hey, its not "yell" or something, I just think that it is under
documented, and hey, perf is world renowned for being under developed,
we don't need any further efforts in that area :-P
 
> When this change was developping, Ingo said it'd be better if it looks
> like output of sysprof as it's more popular for most (userland?) guys.
> You can see the discussion in the following links:
> 
>   https://lkml.org/lkml/2013/10/31/97
>   https://lkml.org/lkml/2013/11/1/85
> 
> The children field is a cumulative total overhead (for its all
> children/callee) so sum of them would be more than 100%.  And as Ingo
> requested it sorts the output entries using children overhead so that
> one can easily see higher level view of performance bottle-neck.

yeah, yeah, but please have all this in the documentation :-)

- Arnaldo