23 Feb, 2019

1 commit

  • Add a 'path' member to 'struct perf_data'. It will keep the configured
    path for the data (const char *). The path in struct perf_data_file is
    now dynamically allocated (duped) from it.

    This scheme is useful/used in following patches where struct
    perf_data::path holds the 'configure' directory path and struct
    perf_data_file::path holds the allocated path for specific files.

    Also it actually makes the code little simpler.

    Signed-off-by: Jiri Olsa
    Cc: Adrian Hunter
    Cc: Alexander Shishkin
    Cc: Alexey Budankov
    Cc: Andi Kleen
    Cc: Namhyung Kim
    Cc: Peter Zijlstra
    Cc: Stephane Eranian
    Link: http://lkml.kernel.org/r/20190221094145.9151-3-jolsa@kernel.org
    [ Fixup data-convert-bt.c missing conversion ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Jiri Olsa
     

25 Jan, 2019

1 commit

  • At the cost of an extra pointer, we can avoid the O(logN) cost of
    finding the first element in the tree (smallest node), which is
    something heavily required for perf-sched.

    Signed-off-by: Davidlohr Bueso
    Cc: Jiri Olsa
    Cc: Namhyung Kim
    Link: http://lkml.kernel.org/r/20181206191819.30182-8-dave@stgolabs.net
    Signed-off-by: Arnaldo Carvalho de Melo

    Davidlohr Bueso
     

22 Jan, 2019

1 commit

  • An automatic const char[] variable gets initialized at runtime, just
    like any other automatic variable. For long strings, that uses a lot of
    stack and wastes time building the string; e.g. for the "No %s
    allocation events..." case one has:

    444516: 48 b8 4e 6f 20 25 73 20 61 6c movabs $0x6c61207325206f4e,%rax # "No %s al"
    ...
    444674: 48 89 45 80 mov %rax,-0x80(%rbp)
    444678: 48 b8 6c 6f 63 61 74 69 6f 6e movabs $0x6e6f697461636f6c,%rax # "location"
    444682: 48 89 45 88 mov %rax,-0x78(%rbp)
    444686: 48 b8 20 65 76 65 6e 74 73 20 movabs $0x2073746e65766520,%rax # " events "
    444690: 66 44 89 55 c4 mov %r10w,-0x3c(%rbp)
    444695: 48 89 45 90 mov %rax,-0x70(%rbp)
    444699: 48 b8 66 6f 75 6e 64 2e 20 20 movabs $0x20202e646e756f66,%rax

    Make them all static so that the compiler just references objects in .rodata.

    Committer testing:

    Ok, using dwarves's codiff tool:

    $ codiff --functions /tmp/perf.before ~/bin/perf
    builtin-sched.c:
    cmd_sched | -48
    1 function changed, 48 bytes removed, diff: -48

    builtin-report.c:
    cmd_report | -32
    1 function changed, 32 bytes removed, diff: -32

    builtin-kmem.c:
    cmd_kmem | -64
    build_alloc_func_list | -50
    2 functions changed, 114 bytes removed, diff: -114

    builtin-c2c.c:
    perf_c2c__report | -390
    1 function changed, 390 bytes removed, diff: -390

    ui/browsers/header.c:
    tui__header_window | -104
    1 function changed, 104 bytes removed, diff: -104

    /home/acme/bin/perf:
    9 functions changed, 688 bytes removed, diff: -688

    Signed-off-by: Rasmus Villemoes
    Acked-by: Jiri Olsa
    Tested-by: Arnaldo Carvalho de Melo
    Cc: Alexander Shishkin
    Cc: Namhyung Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20181102230624.20064-1-linux@rasmusvillemoes.dk
    Signed-off-by: Arnaldo Carvalho de Melo

    Rasmus Villemoes
     

05 Jun, 2018

2 commits

  • Instead of using symbol_conf.use_callchain, reducing its usage a bit
    more.

    Cc: Adrian Hunter
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Namhyung Kim
    Cc: Wang Nan
    Link: https://lkml.kernel.org/n/tip-edgwb1b2mpbrdeg0w64wp7ms@git.kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Arnaldo Carvalho de Melo
     
  • Its common to have the (evsel->attr.sample_type & PERF_SAMPLE_CALLCHAIN),
    so add an evsel__has_callchain(evsel) helper.

    This will actually get more uses as we check that instead of
    symbol_conf.use_callchain in places where that produces the same result
    but makes this decision to be more fine grained, per evsel.

    Cc: Adrian Hunter
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Namhyung Kim
    Cc: Wang Nan
    Link: https://lkml.kernel.org/n/tip-145340oytbthatpfeaq1do18@git.kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Arnaldo Carvalho de Melo
     

07 Mar, 2018

2 commits

  • This is to show the real name of thread that created via fork-exec. See
    below example for shortname *A0*.

    $ sudo ./perf sched map
    *A0 80393.050639 secs A0 => perf:22368
    *. A0 80393.050748 secs . => swapper:0
    . *. 80393.050887 secs
    *B0 . . 80393.052735 secs B0 => rcu_sched:8
    *. . . 80393.052743 secs
    . *C0 . 80393.056264 secs C0 => kworker/2:1H:287
    . *A0 . 80393.056270 secs
    . *D0 . 80393.056769 secs D0 => ksoftirqd/2:22
    - . *A0 . 80393.056804 secs
    + . *A0 . 80393.056804 secs A0 => pi:22368
    . *. . 80393.056854 secs
    *B0 . . 80393.060727 secs
    ...

    Signed-off-by: Changbin Du
    Acked-by: Jiri Olsa
    Cc: Namhyung Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/1520307457-23668-3-git-send-email-changbin.du@intel.com
    [ Optimally pack struct thread_runtime when adding the new bool member ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Changbin Du
     
  • The thread::shortname only used by sched command, so move it to sched
    private structure.

    Signed-off-by: Changbin Du
    Acked-by: Jiri Olsa
    Cc: Namhyung Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/1520307457-23668-2-git-send-email-changbin.du@intel.com
    Signed-off-by: Arnaldo Carvalho de Melo

    Changbin Du
     

07 Nov, 2017

1 commit

  • Conflicts:
    tools/perf/arch/arm/annotate/instructions.c
    tools/perf/arch/arm64/annotate/instructions.c
    tools/perf/arch/powerpc/annotate/instructions.c
    tools/perf/arch/s390/annotate/instructions.c
    tools/perf/arch/x86/tests/intel-cqm.c
    tools/perf/ui/tui/progress.c
    tools/perf/util/zlib.c

    Signed-off-by: Ingo Molnar

    Ingo Molnar
     

02 Nov, 2017

1 commit

  • Many source files in the tree are missing licensing information, which
    makes it harder for compliance tools to determine the correct license.

    By default all files without license information are under the default
    license of the kernel, which is GPL version 2.

    Update the files which contain no license information with the 'GPL-2.0'
    SPDX license identifier. The SPDX identifier is a legally binding
    shorthand, which can be used instead of the full boiler plate text.

    This patch is based on work done by Thomas Gleixner and Kate Stewart and
    Philippe Ombredanne.

    How this work was done:

    Patches were generated and checked against linux-4.14-rc6 for a subset of
    the use cases:
    - file had no licensing information it it.
    - file was a */uapi/* one with no licensing information in it,
    - file was a */uapi/* one with existing licensing information,

    Further patches will be generated in subsequent months to fix up cases
    where non-standard license headers were used, and references to license
    had to be inferred by heuristics based on keywords.

    The analysis to determine which SPDX License Identifier to be applied to
    a file was done in a spreadsheet of side by side results from of the
    output of two independent scanners (ScanCode & Windriver) producing SPDX
    tag:value files created by Philippe Ombredanne. Philippe prepared the
    base worksheet, and did an initial spot review of a few 1000 files.

    The 4.13 kernel was the starting point of the analysis with 60,537 files
    assessed. Kate Stewart did a file by file comparison of the scanner
    results in the spreadsheet to determine which SPDX license identifier(s)
    to be applied to the file. She confirmed any determination that was not
    immediately clear with lawyers working with the Linux Foundation.

    Criteria used to select files for SPDX license identifier tagging was:
    - Files considered eligible had to be source code files.
    - Make and config files were included as candidates if they contained >5
    lines of source
    - File already had some variant of a license header in it (even if
    Reviewed-by: Philippe Ombredanne
    Reviewed-by: Thomas Gleixner
    Signed-off-by: Greg Kroah-Hartman

    Greg Kroah-Hartman
     

31 Oct, 2017

2 commits

  • Add struct perf_data_file to represent a single file within a perf_data
    struct.

    Signed-off-by: Jiri Olsa
    Cc: Andi Kleen
    Cc: Changbin Du
    Cc: David Ahern
    Cc: Jin Yao
    Cc: Namhyung Kim
    Cc: Peter Zijlstra
    Cc: Wang Nan
    Link: http://lkml.kernel.org/n/tip-c3f9p4xzykr845ktqcek6p4t@git.kernel.org
    [ Fixup recent changes in 'perf script --per-event-dump' ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Jiri Olsa
     
  • Rename struct perf_data_file to perf_data, because we will add the
    possibility to have multiple files under perf.data, so the 'perf_data'
    name fits better.

    Signed-off-by: Jiri Olsa
    Cc: Andi Kleen
    Cc: Changbin Du
    Cc: David Ahern
    Cc: Jin Yao
    Cc: Namhyung Kim
    Cc: Peter Zijlstra
    Cc: Wang Nan
    Link: http://lkml.kernel.org/n/tip-39wn4d77phel3dgkzo3lyan0@git.kernel.org
    [ Fixup recent changes in 'perf script --per-event-dump' ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Jiri Olsa
     

13 Sep, 2017

1 commit


27 Jun, 2017

1 commit


20 Apr, 2017

4 commits


27 Mar, 2017

1 commit

  • We got it from the git sources but never used it for anything, with the
    place where this would be somehow used remaining:

    static int run_builtin(struct cmd_struct *p, int argc, const char **argv)
    {
    prefix = NULL;
    if (p->option & RUN_SETUP)
    prefix = NULL; /* setup_perf_directory(); */

    Ditch it.

    Cc: Adrian Hunter
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Namhyung Kim
    Cc: Wang Nan
    Link: http://lkml.kernel.org/n/tip-uw5swz05vol0qpr32c5lpvus@git.kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Arnaldo Carvalho de Melo
     

15 Mar, 2017

1 commit

  • The --next option shows the next task for each context switch, providing
    more context for the sequence of scheduler events.

    $ perf sched timehist --next | head
    Samples do not have callchains.
    time cpu task name waittime schdelay run time
    [tid/pid] (msec) (msec) (msec)
    ---------- --- ---------- --------- ------ -----
    374.793792 [0] 0.000 0.000 0.000 next: rngd[1524]
    374.793801 [0] rngd[1524] 0.000 0.000 0.009 next: swapper/0[0]
    374.794048 [7] 0.000 0.000 0.000 next: yes[30884]
    374.794066 [7] yes[30884] 0.000 0.000 0.018 next: swapper/7[0]
    374.794126 [2] 0.000 0.000 0.000 next: rngd[1524]
    374.794140 [2] rngd[1524] 0.325 0.006 0.013 next: swapper/2[0]
    374.794281 [3] 0.000 0.000 0.000 next: perf[31070]

    Signed-off-by: Brendan Gregg
    Tested-by: Arnaldo Carvalho de Melo
    Cc: Alexander Shishkin
    Cc: Namhyung Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/1489456589-32555-1-git-send-email-bgregg@netflix.com
    Signed-off-by: Arnaldo Carvalho de Melo

    Brendan Gregg
     

14 Mar, 2017

1 commit

  • Introduce a new option to record PERF_RECORD_NAMESPACES events emitted
    by the kernel when fork, clone, setns or unshare are invoked. And update
    perf-record documentation with the new option to record namespace
    events.

    Committer notes:

    Combined it with a later patch to allow printing it via 'perf report -D'
    and be able to test the feature introduced in this patch. Had to move
    here also perf_ns__name(), that was introduced in another later patch.

    Also used PRIu64 and PRIx64 to fix the build in some enfironments wrt:

    util/event.c:1129:39: error: format '%lx' expects argument of type 'long unsigned int', but argument 6 has type 'long long unsigned int' [-Werror=format=]
    ret += fprintf(fp, "%u/%s: %lu/0x%lx%s", idx
    ^
    Testing it:

    # perf record --namespaces -a
    ^C[ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 1.083 MB perf.data (423 samples) ]
    #
    # perf report -D

    3 2028902078892 0x115140 [0xa0]: PERF_RECORD_NAMESPACES 14783/14783 - nr_namespaces: 7
    [0/net: 3/0xf0000081, 1/uts: 3/0xeffffffe, 2/ipc: 3/0xefffffff, 3/pid: 3/0xeffffffc,
    4/user: 3/0xeffffffd, 5/mnt: 3/0xf0000000, 6/cgroup: 3/0xeffffffb]

    0x1151e0 [0x30]: event: 9
    .
    . ... raw event: size 48 bytes
    . 0000: 09 00 00 00 02 00 30 00 c4 71 82 68 0c 7f 00 00 ......0..q.h....
    . 0010: a9 39 00 00 a9 39 00 00 94 28 fe 63 d8 01 00 00 .9...9...(.c....
    . 0020: 03 00 00 00 00 00 00 00 ce c4 02 00 00 00 00 00 ................

    NAMESPACES events: 1

    #

    Signed-off-by: Hari Bathini
    Acked-by: Jiri Olsa
    Tested-by: Arnaldo Carvalho de Melo
    Cc: Alexander Shishkin
    Cc: Alexei Starovoitov
    Cc: Ananth N Mavinakayanahalli
    Cc: Aravinda Prasad
    Cc: Brendan Gregg
    Cc: Daniel Borkmann
    Cc: Eric Biederman
    Cc: Peter Zijlstra
    Cc: Sargun Dhillon
    Cc: Steven Rostedt
    Link: http://lkml.kernel.org/r/148891930386.25309.18412039920746995488.stgit@hbathini.in.ibm.com
    Signed-off-by: Arnaldo Carvalho de Melo

    Hari Bathini
     

20 Feb, 2017

1 commit

  • It now can have negative value to suppress the message entirely. So it
    needs to check it being positive.

    Signed-off-by: Namhyung Kim
    Cc: Jiri Olsa
    Cc: Peter Zijlstra
    Cc: kernel-team@lge.com
    Link: http://lkml.kernel.org/r/20170217081742.17417-3-namhyung@kernel.org
    [ Adjust fuzz on tools/perf/util/pmu.c, add > 0 checks in many other places ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     

14 Feb, 2017

1 commit

  • As it is an array, so will always evaluate to 'true', as reported by
    clang:

    builtin-sched.c:2070:19: error: address of array 'sym->name' will always evaluate to 'true' [-Werror,-Wpointer-bool-conversion]
    if (sym && sym->name) {
    ~~ ~~~~~^~~~
    1 warning generated.

    So just ditch all those useless checks.

    Cc: Adrian Hunter
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Namhyung Kim
    Cc: Wang Nan
    Link: http://lkml.kernel.org/n/tip-ydpm927col06paixb775jjx5@git.kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Arnaldo Carvalho de Melo
     

17 Jan, 2017

3 commits

  • When --state option is given, the summary will show total run, sleep,
    iowait, preempt and delay time instead of statistics of runtime.

    $ perf sched timehist -s --state

    Wait-time summary
    comm parent sched-in run-time sleep iowait preempt delay
    (count) (msec) (msec) (msec) (msec) (msec)
    ---------------------------------------------------------------------
    systemd[1] 0 3 0.497 1.685 0.000 0.000 0.061
    ksoftirqd/0[3] 2 21 0.434 989.948 0.000 0.000 0.325
    rcu_preempt[7] 2 28 0.386 993.211 0.000 0.000 0.712
    migration/0[10] 2 12 0.126 50.174 0.000 0.000 0.044
    watchdog/0[11] 2 1 0.009 0.000 0.000 0.000 0.016
    migration/1[13] 2 2 0.029 11.755 0.000 0.000 0.007

    Signed-off-by: Namhyung Kim
    Tested-by: Arnaldo Carvalho de Melo
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20170113104523.31212-3-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • The --state option is to show task state when switched out. The state
    is printed as a single character like in the /proc but I added 'I' for
    idle state rather than 'R'.

    $ perf sched timehist --state | head
    Samples do not have callchains.
    time cpu task name wait time sch delay run time state
    [tid/pid] (msec) (msec) (msec)
    -------- --- ----------------------- -------- ------------------ -----
    1.753791 [3] 0.000 0.000 0.000 I
    1.753834 [1] perf[27469] 0.000 0.000 0.000 S
    1.753904 [3] perf[27470] 0.000 0.006 0.112 S
    1.753914 [1] 0.000 0.000 0.079 I
    1.753915 [3] migration/3[23] 0.000 0.002 0.011 S
    1.754287 [2] 0.000 0.000 0.000 I
    1.754335 [2] transmission[1773/1739] 0.000 0.004 0.047 S

    Signed-off-by: Namhyung Kim
    Tested-by: Arnaldo Carvalho de Melo
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20170113104523.31212-2-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • Separate thread wait time into 3 parts - sleep, iowait and preempt based
    on the prev_state of the last event.

    Signed-off-by: Namhyung Kim
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20170113104523.31212-1-namhyung@kernel.org
    [ Fix the build on centos:5 where 'wait' shadows a global declaration ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     

28 Dec, 2016

1 commit

  • Show length of analyzed sample time and rate of idle task running.
    This also takes care of time range given by --time option.

    $ perf sched timehist -sI | tail
    Samples do not have callchains.
    Idle stats:
    CPU 0 idle for 930.316 msec ( 92.93%)
    CPU 1 idle for 963.614 msec ( 96.25%)
    CPU 2 idle for 885.482 msec ( 88.45%)
    CPU 3 idle for 938.635 msec ( 93.76%)

    Total number of unique tasks: 118
    Total number of context switches: 2337
    Total run time (msec): 3718.048
    Total scheduling time (msec): 1001.131 (x 4)

    Suggested-by: David Ahern
    Signed-off-by: Namhyung Kim
    Cc: Jiri Olsa
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161222060350.17655-3-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     

23 Dec, 2016

4 commits

  • When --time option is given with a value outside recorded time, the last
    sample time (tprev) was set to that value and run time calculation might
    be incorrect. This is a problem of the first samples for each cpus
    since it would skip the runtime update when tprev is 0. But with --time
    option it had non-zero (which is invalid) value so the calculation is
    also incorrect.

    For example, let's see the followging:

    $ perf sched timehist
    time cpu task name wait time sch delay run time
    [tid/pid] (msec) (msec) (msec)
    --------------- ------ ------------------------------ --------- --------- ---------
    3195.968367 [0003] 0.000 0.000 0.000
    3195.968386 [0002] Timer[4306/4277] 0.000 0.000 0.018
    3195.968397 [0002] Web Content[4277] 0.000 0.000 0.000
    3195.968595 [0001] JS Helper[4302/4277] 0.000 0.000 0.000
    3195.969217 [0000] 0.000 0.000 0.621
    3195.969251 [0001] kworker/1:1H[291] 0.000 0.000 0.033

    The sample starts at 3195.968367 but when I gave a time interval from
    3194 to 3196 (in sec) it will calculate the whole 2 second as runtime.
    In below, 2 cpus accounted it as runtime, other 2 cpus accounted it as
    idle time.

    Before:

    $ perf sched timehist --time 3194,3196 -s | tail
    Idle stats:
    CPU 0 idle for 1995.991 msec
    CPU 1 idle for 20.793 msec
    CPU 2 idle for 30.191 msec
    CPU 3 idle for 1999.852 msec

    Total number of unique tasks: 23
    Total number of context switches: 128
    Total run time (msec): 3724.940

    After:

    $ perf sched timehist --time 3194,3196 -s | tail
    Idle stats:
    CPU 0 idle for 10.811 msec
    CPU 1 idle for 20.793 msec
    CPU 2 idle for 30.191 msec
    CPU 3 idle for 18.337 msec

    Total number of unique tasks: 23
    Total number of context switches: 128
    Total run time (msec): 18.139

    Committer notes:

    Further testing:

    Before:

    Idle stats:
    CPU 0 idle for 229.785 msec
    CPU 1 idle for 937.944 msec
    CPU 2 idle for 188.931 msec
    CPU 3 idle for 986.185 msec

    After:

    # perf sched timehist --time 40602,40603 -s | tail

    Idle stats:
    CPU 0 idle for 229.785 msec
    CPU 1 idle for 175.407 msec
    CPU 2 idle for 188.931 msec
    CPU 3 idle for 223.657 msec

    Total number of unique tasks: 68
    Total number of context switches: 814
    Total run time (msec): 97.688

    # for cpu in `seq 0 3` ; do echo -n "CPU $cpu idle for " ; perf sched timehist --time 40602,40603 | grep "\[000${cpu}\].*\" | tr -s ' ' | cut -d' ' -f7 | awk '{entries++ ; s+=$1} END {print s " msec (entries: " entries ")"}' ; done
    CPU 0 idle for 229.721 msec (entries: 123)
    CPU 1 idle for 175.381 msec (entries: 65)
    CPU 2 idle for 188.903 msec (entries: 56)
    CPU 3 idle for 223.61 msec (entries: 102)

    Difference due to the idle stats being accounted at nanoseconds precision while
    the entries in 'perf sched timehist' are trucated at msec.usec.

    Signed-off-by: Namhyung Kim
    Tested-by: Arnaldo Carvalho de Melo
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Peter Zijlstra
    Fixes: 853b74071110 ("perf sched timehist: Add option to specify time window of interest")
    Link: http://lkml.kernel.org/r/20161222060350.17655-2-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • Now that the default 'comm_width' value is 30, no need to check that at
    print_summary,

    Signed-off-by: Namhyung Kim
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161222060350.17655-1-namhyung@kernel.org
    [ Split from a larger patch ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • Current default value is 20 but it's easily changed to a bigger value as
    task has a long name and different tid and pid. And it makes the output
    not aligned. So change it to have a large value as summary shows.

    Committer notes:

    Before:

    # perf sched record
    ^C
    # perf sched timehist

    40602.770537 [0001] rcuos/2[29] 7.970 0.002 0.020
    40602.771512 [0003] 0.003 0.000 0.986
    40602.771586 [0001] 0.020 0.000 1.049
    40602.771606 [0001] qemu-system-x86[3593/3510] 0.000 0.002 0.020
    40602.771629 [0003] qemu-system-x86[3510] 0.000 0.003 0.116
    40602.771776 [0000] 0.001 0.000 1.892

    After:

    # perf sched timehist

    40602.770537 [0001] rcuos/2[29] 7.970 0.002 0.020
    40602.771512 [0003] 0.003 0.000 0.986
    40602.771586 [0001] 0.020 0.000 1.049
    40602.771606 [0001] qemu-system-x86[3593/3510] 0.000 0.002 0.020
    40602.771629 [0003] qemu-system-x86[3510] 0.000 0.003 0.116

    Signed-off-by: Namhyung Kim
    Tested-by: Arnaldo Carvalho de Melo
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161222060350.17655-1-namhyung@kernel.org
    [ Split from a larger patch ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • Current default value is 20, but that may change in the future, so make
    places where we have 20 hardcoded use 'comm_width'.

    Signed-off-by: Namhyung Kim
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161222060350.17655-1-namhyung@kernel.org
    [ Split from a larger patch ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     

16 Dec, 2016

6 commits

  • When --idle-hist option is used with --summary, it now shows idle stats
    with callchains like below:

    Idle stats by callchain:
    CPU 0: 902.195 msec
    Idle time (msec) Count Callchains
    ---------------- ------- --------------------------------------------------
    370.589 69 futex_wait_queue_me
    Idle stats by callchain:
    CPU 0: 13456.840 msec
    Idle time (msec) Count Callchains
    ---------------- ----- --------------------------------------------------
    5386.637 3283 schedule_hrtimeout_range_clock

    Signed-off-by: Namhyung Kim
    Tested-by: Arnaldo Carvalho de Melo
    Acked-by: David Ahern
    Cc: Andi Kleen
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161208144755.16673-7-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • The --idle-hist option is to analyze system idle state so which process
    makes cpu to go idle. If this option is specified, non-idle events will
    be skipped and processes switching to/from idle will be shown.

    This option is mostly useful when used with --summary(-only) option. In
    the idle-time summary view, idle time is accounted to previous thread
    which is run before idle task.

    The example output looks like following:

    Idle-time summary
    comm parent sched-out idle-time min-idle avg-idle max-idle stddev migrations
    (count) (msec) (msec) (msec) (msec) %
    --------------------------------------------------------------------------------------------
    rcu_preempt[7] 2 95 550.872 0.011 5.798 23.146 7.63 0
    migration/1[16] 2 1 15.558 15.558 15.558 15.558 0.00 0
    khugepaged[39] 2 1 3.062 3.062 3.062 3.062 0.00 0
    kworker/0:1H[124] 2 2 4.728 0.611 2.364 4.116 74.12 0
    systemd-journal[167] 1 1 4.510 4.510 4.510 4.510 0.00 0
    kworker/u16:3[558] 2 13 74.737 0.080 5.749 12.960 21.96 0
    irq/34-iwlwifi[628] 2 21 118.403 0.032 5.638 23.990 24.00 0
    kworker/u17:0[673] 2 1 3.523 3.523 3.523 3.523 0.00 0
    dbus-daemon[722] 1 1 6.743 6.743 6.743 6.743 0.00 0
    ifplugd[741] 1 1 58.826 58.826 58.826 58.826 0.00 0
    wpa_supplicant[1490] 1 1 13.302 13.302 13.302 13.302 0.00 0
    wpa_actiond[1492] 1 2 4.064 0.168 2.032 3.896 91.72 0
    dockerd[1500] 1 1 0.055 0.055 0.055 0.055 0.00 0
    ...

    Signed-off-by: Namhyung Kim
    Tested-by: Arnaldo Carvalho de Melo
    Acked-by: David Ahern
    Cc: Andi Kleen
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161208144755.16673-6-namhyung@kernel.org
    Link: http://lkml.kernel.org/r/20161213080632.19099-2-namhyung@kernel.org
    [ Merged fix sent by Namhyumg, as posted in the second Link: tag ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • Sometimes it only focuses on idle-related events like upcoming idle-hist
    feature. In this case we don't want to see other event to reduce noise.

    Signed-off-by: Namhyung Kim
    Acked-by: David Ahern
    Cc: Andi Kleen
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161208144755.16673-5-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • In order to investigate the idleness reason, it is necessary to keep the
    callchains when entering idle. This can be identified by the
    sched:sched_switch event having the next_pid field as 0.

    Signed-off-by: Namhyung Kim
    Acked-by: David Ahern
    Cc: Andi Kleen
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161208144755.16673-4-namhyung@kernel.org
    Link: http://lkml.kernel.org/r/20161213080632.19099-1-namhyung@kernel.org
    [ Merged fix from Namhyung, see second Link: tag ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • The struct idle_time_data is to keep idle stats with callchains entering
    to the idle task. The normal thread_runtime calculation is done
    transparently since it extends the struct thread_runtime.

    Signed-off-by: Namhyung Kim
    Acked-by: David Ahern
    Cc: Andi Kleen
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161208144755.16673-3-namhyung@kernel.org
    [ Align struct field names ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • The is_idle_sample() function actually does more than determining
    whether sample come from idle task. Split the callchain part into
    save_task_callchain() to make it clearer.

    Also checking prev_pid from trace data looks preferred than just
    checking sample->pid since it's possible, although rare, to have invalid
    0 pid/tid on scheduling an exiting task.

    Signed-off-by: Namhyung Kim
    Acked-by: David Ahern
    Cc: Andi Kleen
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161208144755.16673-2-namhyung@kernel.org
    [ Remove some needless () in some return statements ]
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     

07 Dec, 2016

4 commits

  • It treats the idle_max_cpu little bit confusingly IMHO. Let's make it
    more straight forward.

    Signed-off-by: Namhyung Kim
    Acked-by: David Ahern
    Cc: Andi Kleen
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161206034010.6499-6-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • Sometimes samples have tid of 0 but non-0 pid. It ends up having a new
    thread of 0 tid/pid (instead of referring idle task) since tid is used
    to search matching task. But I guess it's wrong to use 0 as a tid when
    pid is set. This patch uses tid only if it has a non-zero value or same
    as pid (of 0).

    Signed-off-by: Namhyung Kim
    Cc: Andi Kleen
    Cc: David Ahern
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161206034010.6499-4-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • The -D/--dump-raw-trace option is in the parent option so no need to
    repeat it. Also move -f/--force option to parent as it's common to
    handle data file.

    Signed-off-by: Namhyung Kim
    Acked-by: David Ahern
    Cc: Andi Kleen
    Cc: Jiri Olsa
    Cc: Minchan Kim
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/20161206034010.6499-2-namhyung@kernel.org
    Signed-off-by: Arnaldo Carvalho de Melo

    Namhyung Kim
     
  • Arnaldo reported an unhelpful error message when running perf sched
    timehist on a file that did not contain sched tracepoints:

    [root@jouet ~]# perf sched timehist
    No trace sample to read. Did you call 'perf record -R'?

    [root@jouet ~]# perf evlist -v
    cycles:ppp: size: 112, { sample_period, sample_freq }: 4000, sample_type: IP|TID|TIME|CALLCHAIN|CPU|PERIOD, disabled: 1, inherit: 1, mmap: 1, comm: 1, freq: 1, task: 1, precise_ip: 3, sample_id_all: 1, exclude_guest: 1, mmap2: 1, comm_exec: 1

    Change the has_traces check to look for the sched_switch event. Analysis
    for perf sched timehist requires at least this event.

    Now when analyzing a file without sched tracepoints you get:

    root@f21-vbox:/tmp$ perf sched timehist
    No sched_switch events found. Have you run 'perf sched record'?

    Signed-off-by: David Ahern
    Reported-and-Tested-by: Arnaldo Carvalho de Melo
    Acked-by: Namhyung Kim
    Cc: Jiri Olsa
    Cc: Peter Zijlstra
    Link: http://lkml.kernel.org/r/1480451988-43673-1-git-send-email-dsahern@gmail.com
    Signed-off-by: Arnaldo Carvalho de Melo

    David Ahern