1. 17 1月, 2017 3 次提交
    • M
      perf probe: Fix to probe on gcc generated functions in modules · 613f050d
      Masami Hiramatsu 提交于
      Fix to probe on gcc generated functions on modules. Since
      probing on a module is based on its symbol name, it should
      be adjusted on actual symbols.
      
      E.g. without this fix, perf probe shows probe definition
      on non-exist symbol as below.
      
        $ perf probe -m build-x86_64/net/netfilter/nf_nat.ko -F in_range*
        in_range.isra.12
        $ perf probe -m build-x86_64/net/netfilter/nf_nat.ko -D in_range
        p:probe/in_range nf_nat:in_range+0
      
      With this fix, perf probe correctly shows a probe on
      gcc-generated symbol.
      
        $ perf probe -m build-x86_64/net/netfilter/nf_nat.ko -D in_range
        p:probe/in_range nf_nat:in_range.isra.12+0
      
      This also fixes same problem on online module as below.
      
        $ perf probe -m i915 -D assert_plane
        p:probe/assert_plane i915:assert_plane.constprop.134+0
      Signed-off-by: NMasami Hiramatsu <mhiramat@kernel.org>
      Tested-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      Cc: Jiri Olsa <jolsa@redhat.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Peter Zijlstra <peterz@infradead.org>
      Link: http://lkml.kernel.org/r/148411450673.9978.14905987549651656075.stgit@devboxSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      613f050d
    • M
      perf probe: Add error checks to offline probe post-processing · 3e96dac7
      Masami Hiramatsu 提交于
      Add error check codes on post processing and improve it for offline
      probe events as:
      
       - post processing fails if no matched symbol found in map(-ENOENT)
         or strdup() failed(-ENOMEM).
      
       - Even if the symbol name is the same, it updates symbol address
         and offset.
      Signed-off-by: NMasami Hiramatsu <mhiramat@kernel.org>
      Cc: Jiri Olsa <jolsa@redhat.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Peter Zijlstra <peterz@infradead.org>
      Link: http://lkml.kernel.org/r/148411443738.9978.4617979132625405545.stgit@devboxSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      3e96dac7
    • M
      perf probe: Fix to show correct locations for events on modules · d2d4edbe
      Masami Hiramatsu 提交于
      Fix to show correct locations for events on modules by relocating given
      address instead of retrying after failure.
      
      This happens when the module text size is big enough, bigger than
      sh_addr, because the original code retries with given address + sh_addr
      if it failed to find CU DIE at the given address.
      
      Any address smaller than sh_addr always fails and it retries with the
      correct address, but addresses bigger than sh_addr will get a CU DIE
      which is on the given address (not adjusted by sh_addr).
      
      In my environment(x86-64), the sh_addr of ".text" section is 0x10030.
      Since i915 is a huge kernel module, we can see this issue as below.
      
        $ grep "[Tt] .*\[i915\]" /proc/kallsyms | sort | head -n1
        ffffffffc0270000 t i915_switcheroo_can_switch	[i915]
      
      ffffffffc0270000 + 0x10030 = ffffffffc0280030, so we'll check
      symbols cross this boundary.
      
        $ grep "[Tt] .*\[i915\]" /proc/kallsyms | grep -B1 ^ffffffffc028\
        | head -n 2
        ffffffffc027ff80 t haswell_init_clock_gating	[i915]
        ffffffffc0280110 t valleyview_init_clock_gating	[i915]
      
      So setup probes on both function and see what happen.
      
        $ sudo ./perf probe -m i915 -a haswell_init_clock_gating \
              -a valleyview_init_clock_gating
        Added new events:
          probe:haswell_init_clock_gating (on haswell_init_clock_gating in i915)
          probe:valleyview_init_clock_gating (on valleyview_init_clock_gating in i915)
      
        You can now use it in all perf tools, such as:
      
        	perf record -e probe:valleyview_init_clock_gating -aR sleep 1
      
        $ sudo ./perf probe -l
          probe:haswell_init_clock_gating (on haswell_init_clock_gating@gpu/drm/i915/intel_pm.c in i915)
          probe:valleyview_init_clock_gating (on i915_vga_set_decode:4@gpu/drm/i915/i915_drv.c in i915)
      
      As you can see, haswell_init_clock_gating is correctly shown,
      but valleyview_init_clock_gating is not.
      
      With this patch, both events are shown correctly.
      
        $ sudo ./perf probe -l
          probe:haswell_init_clock_gating (on haswell_init_clock_gating@gpu/drm/i915/intel_pm.c in i915)
          probe:valleyview_init_clock_gating (on valleyview_init_clock_gating@gpu/drm/i915/intel_pm.c in i915)
      
      Committer notes:
      
      In my case:
      
        # perf probe -m i915 -a haswell_init_clock_gating -a valleyview_init_clock_gating
        Added new events:
          probe:haswell_init_clock_gating (on haswell_init_clock_gating in i915)
          probe:valleyview_init_clock_gating (on valleyview_init_clock_gating in i915)
      
        You can now use it in all perf tools, such as:
      
      	  perf record -e probe:valleyview_init_clock_gating -aR sleep 1
      
        # perf probe -l
          probe:haswell_init_clock_gating (on i915_getparam+432@gpu/drm/i915/i915_drv.c in i915)
          probe:valleyview_init_clock_gating (on __i915_printk+240@gpu/drm/i915/i915_drv.c in i915)
        #
      
        # readelf -SW /lib/modules/4.9.0+/build/vmlinux | egrep -w '.text|Name'
         [Nr] Name   Type      Address          Off    Size   ES Flg Lk Inf Al
         [ 1] .text  PROGBITS  ffffffff81000000 200000 822fd3 00  AX  0   0 4096
        #
      
        So both are b0rked, now with the fix:
      
        # perf probe -m i915 -a haswell_init_clock_gating -a valleyview_init_clock_gating
        Added new events:
          probe:haswell_init_clock_gating (on haswell_init_clock_gating in i915)
          probe:valleyview_init_clock_gating (on valleyview_init_clock_gating in i915)
      
        You can now use it in all perf tools, such as:
      
      	perf record -e probe:valleyview_init_clock_gating -aR sleep 1
      
        # perf probe -l
          probe:haswell_init_clock_gating (on haswell_init_clock_gating@gpu/drm/i915/intel_pm.c in i915)
          probe:valleyview_init_clock_gating (on valleyview_init_clock_gating@gpu/drm/i915/intel_pm.c in i915)
        #
      
      Both looks correct.
      Signed-off-by: NMasami Hiramatsu <mhiramat@kernel.org>
      Tested-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      Cc: Jiri Olsa <jolsa@redhat.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Peter Zijlstra <peterz@infradead.org>
      Link: http://lkml.kernel.org/r/148411436777.9978.1440275861947194930.stgit@devboxSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      d2d4edbe
  2. 11 1月, 2017 1 次提交
  3. 04 1月, 2017 4 次提交
  4. 03 1月, 2017 3 次提交
  5. 28 12月, 2016 1 次提交
  6. 23 12月, 2016 4 次提交
    • N
      perf sched timehist: Fix invalid period calculation · bdd75729
      Namhyung Kim 提交于
      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]  <idle>                              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]  <idle>                              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}\].*\<idle\>" | 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 <idle> entries in 'perf sched timehist' are trucated at msec.usec.
      Signed-off-by: NNamhyung Kim <namhyung@kernel.org>
      Tested-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
      Fixes: 853b7407 ("perf sched timehist: Add option to specify time window of interest")
      Link: http://lkml.kernel.org/r/20161222060350.17655-2-namhyung@kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      bdd75729
    • N
      perf sched timehist: Remove hardcoded 'comm_width' check at print_summary · 4fa0d1aa
      Namhyung Kim 提交于
      Now that the default 'comm_width' value is 30, no need to check that at
      print_summary,
      Signed-off-by: NNamhyung Kim <namhyung@kernel.org>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
      Link: http://lkml.kernel.org/r/20161222060350.17655-1-namhyung@kernel.org
      [ Split from a larger patch ]
      Signed-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      4fa0d1aa
    • N
      perf sched timehist: Enlarge default 'comm_width' · 9b8087d7
      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
        <SNIP>
          40602.770537 [0001]  rcuos/2[29]               7.970      0.002      0.020
          40602.771512 [0003]  <idle>                    0.003      0.000      0.986
          40602.771586 [0001]  <idle>                    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]  <idle>                          0.001      0.000      1.892
        <SNIP>
      
      After:
      
        # perf sched timehist
        <SNIP>
         40602.770537 [0001]  rcuos/2[29]                         7.970      0.002      0.020
         40602.771512 [0003]  <idle>                              0.003      0.000      0.986
         40602.771586 [0001]  <idle>                              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
        <SNIP>
      Signed-off-by: NNamhyung Kim <namhyung@kernel.org>
      Tested-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
      Link: http://lkml.kernel.org/r/20161222060350.17655-1-namhyung@kernel.org
      [ Split from a larger patch ]
      Signed-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      9b8087d7
    • N
      perf sched timehist: Honour 'comm_width' when aligning the headers · 0e6758e8
      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: NNamhyung Kim <namhyung@kernel.org>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
      Link: http://lkml.kernel.org/r/20161222060350.17655-1-namhyung@kernel.org
      [ Split from a larger patch ]
      Signed-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      0e6758e8
  7. 20 12月, 2016 4 次提交
  8. 16 12月, 2016 15 次提交
  9. 11 12月, 2016 1 次提交
  10. 07 12月, 2016 4 次提交