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

[Mike Galbraith <umgwanakikbuti@gmail.com>]

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