aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorDavid Ahern <dsa@cumulusnetworks.com>2016-11-29 12:15:46 -0500
committerArnaldo Carvalho de Melo <acme@redhat.com>2016-12-01 11:03:10 -0500
commit46690a8051e4b5901a49080443a17a270e0bd8a2 (patch)
treefcdedd95bdb5f61a5b66e89468bd0bdb99888a76
parent2a865bd8dddd44315c88bf922761e4fd3374d046 (diff)
perf report: Add option to specify time window of interest
Add option to allow user to control analysis window. e.g., collect data for time window and analyze a segment of interest within that window. Committer notes: Testing it: Using the perf.data file captured via 'perf kmem record': # perf report --header-only # ======== # captured on: Tue Nov 29 16:01:53 2016 # hostname : jouet # os release : 4.8.8-300.fc25.x86_64 # perf version : 4.9.rc6.g5a6aca # arch : x86_64 # nrcpus online : 4 # nrcpus avail : 4 # cpudesc : Intel(R) Core(TM) i7-5600U CPU @ 2.60GHz # cpuid : GenuineIntel,6,61,4 # total memory : 20254660 kB # cmdline : /home/acme/bin/perf kmem record usleep 1 # event : name = kmem:kmalloc, , id = { 931980, 931981, 931982, 931983 }, type = 2, size = 112, config = 0x1b9, { sample_period, sample_freq } = 1, sample_typ # event : name = kmem:kmalloc_node, , id = { 931984, 931985, 931986, 931987 }, type = 2, size = 112, config = 0x1b7, { sample_period, sample_freq } = 1, sampl # event : name = kmem:kfree, , id = { 931988, 931989, 931990, 931991 }, type = 2, size = 112, config = 0x1b5, { sample_period, sample_freq } = 1, sample_type # event : name = kmem:kmem_cache_alloc, , id = { 931992, 931993, 931994, 931995 }, type = 2, size = 112, config = 0x1b8, { sample_period, sample_freq } = 1, s # event : name = kmem:kmem_cache_alloc_node, , id = { 931996, 931997, 931998, 931999 }, type = 2, size = 112, config = 0x1b6, { sample_period, sample_freq } = # event : name = kmem:kmem_cache_free, , id = { 932000, 932001, 932002, 932003 }, type = 2, size = 112, config = 0x1b4, { sample_period, sample_freq } = 1, sa # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, intel_pt = 7, intel_bts = 6, uncore_arb = 13, cstate_pkg = 15, breakpoint = 5, uncore_cbox_1 = 12, power = 9, software = 1, uncore_im # HEADER_CACHE info available, use -I to display # missing features: HEADER_BRANCH_STACK HEADER_GROUP_DESC HEADER_AUXTRACE HEADER_STAT # ======== # # # Looking at just the histogram entries for the first event: # # perf report | head -33 # To display the perf.data header info, please use --header/--header-only options. # # # Total Lost Samples: 0 # # Samples: 40 of event 'kmem:kmalloc' # Event count (approx.): 40 # # Overhead Trace output # ........ ............................................................................................................... # 37.50% call_site=ffffffffb91ad3c7 ptr=0xffff88895fc05000 bytes_req=4096 bytes_alloc=4096 gfp_flags=GFP_KERNEL 10.00% call_site=ffffffffb9258416 ptr=0xffff888a1dc61f00 bytes_req=240 bytes_alloc=256 gfp_flags=GFP_KERNEL|__GFP_ZERO 7.50% call_site=ffffffffb9258416 ptr=0xffff888a2640ac00 bytes_req=240 bytes_alloc=256 gfp_flags=GFP_KERNEL|__GFP_ZERO 2.50% call_site=ffffffffb92759ba ptr=0xffff888a26776000 bytes_req=4096 bytes_alloc=4096 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb9276864 ptr=0xffff8886f6b82600 bytes_req=136 bytes_alloc=192 gfp_flags=GFP_KERNEL|__GFP_ZERO 2.50% call_site=ffffffffb9276903 ptr=0xffff888aefcf0460 bytes_req=32 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb92ad0ce ptr=0xffff888756c98a00 bytes_req=392 bytes_alloc=512 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb92ad0ce ptr=0xffff888756c9ba00 bytes_req=504 bytes_alloc=512 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb92ad301 ptr=0xffff888a31747600 bytes_req=128 bytes_alloc=128 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb92ad511 ptr=0xffff888a9d26a2a0 bytes_req=28 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb936a7fb ptr=0xffff88873e8c11a0 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb936a7fb ptr=0xffff88873e8c12c0 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb936a7fb ptr=0xffff88873e8c1540 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb936a7fb ptr=0xffff88873e8c15a0 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb936a7fb ptr=0xffff88873e8c15e0 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb936a7fb ptr=0xffff88873e8c16e0 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb936a7fb ptr=0xffff88873e8c1c20 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb936a7fb ptr=0xffff888a9d26a2a0 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL 2.50% call_site=ffffffffb9373e66 ptr=0xffff8889f1931240 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_ATOMIC|__GFP_ZERO 2.50% call_site=ffffffffb9373e66 ptr=0xffff8889f1931980 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_ATOMIC|__GFP_ZERO 2.50% call_site=ffffffffb9373e66 ptr=0xffff8889f1931a00 bytes_req=64 bytes_alloc=64 gfp_flags=GFP_ATOMIC|__GFP_ZERO # # # And then limiting using the example for 'perf kmem stat --time' used # # in the previous changeset committer note we see that there were no # # kmem:kmalloc in that last part of the file, but there were some # # kmem:kmem_cache_alloc ones: # # perf report --time 20119.782088, --stdio # # Total Lost Samples: 0 # # Samples: 0 of event 'kmem:kmalloc' # Event count (approx.): 0 # # Overhead Trace output # ........ ............ # # Samples: 0 of event 'kmem:kmalloc_node' # Event count (approx.): 0 # # Overhead Trace output # ........ ............ # # Samples: 0 of event 'kmem:kfree' # Event count (approx.): 0 # # Overhead Trace output # ........ ............ # # Samples: 8 of event 'kmem:kmem_cache_alloc' # Event count (approx.): 8 # # Overhead Trace output # ........ .................................................................................................................. # 75.00% call_site=ffffffffb9333b42 ptr=0xffff888bdf1a39c0 bytes_req=48 bytes_alloc=48 gfp_flags=GFP_NOFS|__GFP_ZERO 12.50% call_site=ffffffffb90ad33a ptr=0xffff8889f071f6e0 bytes_req=160 bytes_alloc=160 gfp_flags=GFP_ATOMIC|__GFP_NOTRACK 12.50% call_site=ffffffffb9287cc1 ptr=0xffff8889b12722d8 bytes_req=104 bytes_alloc=104 gfp_flags=GFP_NOFS|__GFP_ZERO # Signed-off-by: David Ahern <dsahern@gmail.com> Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com> Acked-by: Namhyung Kim <namhyung@kernel.org> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Peter Zijlstra <peterz@infradead.org> Link: http://lkml.kernel.org/r/1480439746-42695-7-git-send-email-dsahern@gmail.com Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
-rw-r--r--tools/perf/Documentation/perf-report.txt7
-rw-r--r--tools/perf/builtin-report.c14
2 files changed, 20 insertions, 1 deletions
diff --git a/tools/perf/Documentation/perf-report.txt b/tools/perf/Documentation/perf-report.txt
index 2d1746295abf..3a166ae4a4d3 100644
--- a/tools/perf/Documentation/perf-report.txt
+++ b/tools/perf/Documentation/perf-report.txt
@@ -382,6 +382,13 @@ OPTIONS
382--header-only:: 382--header-only::
383 Show only perf.data header (forces --stdio). 383 Show only perf.data header (forces --stdio).
384 384
385--time::
386 Only analyze samples within given time window: <start>,<stop>. Times
387 have the format seconds.microseconds. If start is not given (i.e., time
388 string is ',x.y') then analysis starts at the beginning of the file. If
389 stop time is not given (i.e, time string is 'x.y,') then analysis goes
390 to end of file.
391
385--itrace:: 392--itrace::
386 Options for decoding instruction tracing data. The options are: 393 Options for decoding instruction tracing data. The options are:
387 394
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 3dfbfffe2ecd..d2afbe4a240d 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -36,7 +36,7 @@
36#include "util/hist.h" 36#include "util/hist.h"
37#include "util/data.h" 37#include "util/data.h"
38#include "arch/common.h" 38#include "arch/common.h"
39 39#include "util/time-utils.h"
40#include "util/auxtrace.h" 40#include "util/auxtrace.h"
41 41
42#include <dlfcn.h> 42#include <dlfcn.h>
@@ -59,6 +59,8 @@ struct report {
59 const char *pretty_printing_style; 59 const char *pretty_printing_style;
60 const char *cpu_list; 60 const char *cpu_list;
61 const char *symbol_filter_str; 61 const char *symbol_filter_str;
62 const char *time_str;
63 struct perf_time_interval ptime;
62 float min_percent; 64 float min_percent;
63 u64 nr_entries; 65 u64 nr_entries;
64 u64 queue_size; 66 u64 queue_size;
@@ -158,6 +160,9 @@ static int process_sample_event(struct perf_tool *tool,
158 }; 160 };
159 int ret = 0; 161 int ret = 0;
160 162
163 if (perf_time__skip_sample(&rep->ptime, sample->time))
164 return 0;
165
161 if (machine__resolve(machine, &al, sample) < 0) { 166 if (machine__resolve(machine, &al, sample) < 0) {
162 pr_debug("problem processing %d event, skipping it.\n", 167 pr_debug("problem processing %d event, skipping it.\n",
163 event->header.type); 168 event->header.type);
@@ -830,6 +835,8 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
830 OPT_CALLBACK_DEFAULT(0, "stdio-color", NULL, "mode", 835 OPT_CALLBACK_DEFAULT(0, "stdio-color", NULL, "mode",
831 "'always' (default), 'never' or 'auto' only applicable to --stdio mode", 836 "'always' (default), 'never' or 'auto' only applicable to --stdio mode",
832 stdio__config_color, "always"), 837 stdio__config_color, "always"),
838 OPT_STRING(0, "time", &report.time_str, "str",
839 "Time span of interest (start,stop)"),
833 OPT_END() 840 OPT_END()
834 }; 841 };
835 struct perf_data_file file = { 842 struct perf_data_file file = {
@@ -1015,6 +1022,11 @@ repeat:
1015 if (symbol__init(&session->header.env) < 0) 1022 if (symbol__init(&session->header.env) < 0)
1016 goto error; 1023 goto error;
1017 1024
1025 if (perf_time__parse_str(&report.ptime, report.time_str) != 0) {
1026 pr_err("Invalid time string\n");
1027 return -EINVAL;
1028 }
1029
1018 sort__setup_elide(stdout); 1030 sort__setup_elide(stdout);
1019 1031
1020 ret = __cmd_report(&report); 1032 ret = __cmd_report(&report);