lkml.org 
[lkml]   [2014]   [Sep]   [12]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    SubjectRe: perf top -g -U --sort=symbol --children == lalalalala?
    From
    Date
    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




    \
     
     \ /
      Last update: 2014-09-12 11:21    [W:4.752 / U:0.012 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site