perf kmem: Add option to specify time window of interest
authorDavid Ahern <dsa@cumulusnetworks.com>
Tue, 29 Nov 2016 17:15:45 +0000 (10:15 -0700)
committerArnaldo Carvalho de Melo <acme@redhat.com>
Thu, 1 Dec 2016 16:03:02 +0000 (13:03 -0300)
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:

  # perf kmem record usleep 1
  [ perf record: Woken up 0 times to write data ]
  [ perf record: Captured and wrote 1.540 MB perf.data (2049 samples) ]
  # perf evlist
  kmem:kmalloc
  kmem:kmalloc_node
  kmem:kfree
  kmem:kmem_cache_alloc
  kmem:kmem_cache_alloc_node
  kmem:kmem_cache_free
  # Tip: use 'perf evlist --trace-fields' to show fields for tracepoint events
  #
  # # Use 'perf script' to get a first approach, select a chunk for then using
  # # with 'perf kmem stat --time'
  #
  # perf script | tail -15
    usleep 9889 [0] 20119.782088:  kmem:kmem_cache_free: (selinux_file_free_security+0x27) call_site=ffffffffb936aa07 ptr=0xffff888a1df49fc0
      perf 9888 [3] 20119.782088:  kmem:kmem_cache_free: (jbd2_journal_stop+0x1a1) call_site=ffffffffb9334581 ptr=0xffff888bdf1a39c0
      perf 9888 [3] 20119.782089: kmem:kmem_cache_alloc: (jbd2__journal_start+0x72) call_site=ffffffffb9333b42 ptr=0xffff888bdf1a39c0 bytes_req=48 bytes_alloc=48 gfp_flags=GFP_NOFS|__GFP_ZERO
      perf 9888 [3] 20119.782090:  kmem:kmem_cache_free: (jbd2_journal_stop+0x1a1) call_site=ffffffffb9334581 ptr=0xffff888bdf1a39c0
      perf 9888 [3] 20119.782090: kmem:kmem_cache_alloc: (jbd2__journal_start+0x72) call_site=ffffffffb9333b42 ptr=0xffff888bdf1a39c0 bytes_req=48 bytes_alloc=48 gfp_flags=GFP_NOFS|__GFP_ZERO
    usleep 9889 [0] 20119.782091: kmem:kmem_cache_alloc: (__sigqueue_alloc+0x4a) call_site=ffffffffb90ad33a ptr=0xffff8889f071f6e0 bytes_req=160 bytes_alloc=160 gfp_flags=GFP_ATOMIC|__GFP_NOTRACK
      perf 9888 [3] 20119.782091:  kmem:kmem_cache_free: (jbd2_journal_stop+0x1a1) call_site=ffffffffb9334581 ptr=0xffff888bdf1a39c0
      perf 9888 [3] 20119.782093:  kmem:kmem_cache_free: (__sigqueue_free.part.17+0x33) call_site=ffffffffb90ad3f3 ptr=0xffff8889f071f6e0
      perf 9888 [3] 20119.782098: kmem:kmem_cache_alloc: (jbd2__journal_start+0x72) call_site=ffffffffb9333b42 ptr=0xffff888bdf1a39c0 bytes_req=48 bytes_alloc=48 gfp_flags=GFP_NOFS|__GFP_ZERO
      perf 9888 [3] 20119.782098:  kmem:kmem_cache_free: (jbd2_journal_stop+0x1a1) call_site=ffffffffb9334581 ptr=0xffff888bdf1a39c0
      perf 9888 [3] 20119.782099: kmem:kmem_cache_alloc: (jbd2__journal_start+0x72) call_site=ffffffffb9333b42 ptr=0xffff888bdf1a39c0 bytes_req=48 bytes_alloc=48 gfp_flags=GFP_NOFS|__GFP_ZERO
      perf 9888 [3] 20119.782100: kmem:kmem_cache_alloc: (alloc_buffer_head+0x21) call_site=ffffffffb9287cc1 ptr=0xffff8889b12722d8 bytes_req=104 bytes_alloc=104 gfp_flags=GFP_NOFS|__GFP_ZERO
      perf 9888 [3] 20119.782101:  kmem:kmem_cache_free: (jbd2_journal_stop+0x1a1) call_site=ffffffffb9334581 ptr=0xffff888bdf1a39c0
      perf 9888 [3] 20119.782102: kmem:kmem_cache_alloc: (jbd2__journal_start+0x72) call_site=ffffffffb9333b42 ptr=0xffff888bdf1a39c0 bytes_req=48 bytes_alloc=48 gfp_flags=GFP_NOFS|__GFP_ZERO
      perf 9888 [3] 20119.782103:  kmem:kmem_cache_free: (jbd2_journal_stop+0x1a1) call_site=ffffffffb9334581 ptr=0xffff888bdf1a39c0
  #
  # # stats for the whole perf.data file, i.e. no interval specified
  #
  # perf kmem stat

  SUMMARY (SLAB allocator)
  ========================
  Total bytes requested: 172,628
  Total bytes allocated: 173,088
  Total bytes freed:     161,280
  Net total bytes allocated: 11,808
  Total bytes wasted on internal fragmentation: 460
  Internal fragmentation: 0.265761%
  Cross CPU allocations: 0/851
  #
  # # stats for an end open interval, after a certain time:
  #
  # perf kmem stat --time 20119.782088,

  SUMMARY (SLAB allocator)
  ========================
  Total bytes requested: 552
  Total bytes allocated: 552
  Total bytes freed:     448
  Net total bytes allocated: 104
  Total bytes wasted on internal fragmentation: 0
  Internal fragmentation: 0.000000%
  Cross CPU allocations: 0/8
  #

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-6-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
tools/perf/Documentation/perf-kmem.txt
tools/perf/builtin-kmem.c

index ff0f433b3fce1ee402a375b62703d7034c468e34..479fc3261a5035ea3e9a6c6d0898c371355c72bb 100644 (file)
@@ -61,6 +61,13 @@ OPTIONS
        default, but this option shows live (currently allocated) pages
        instead.  (This option works with --page option only)
 
+--time::
+       Only analyze samples within given time window: <start>,<stop>. Times
+       have the format seconds.microseconds. If start is not given (i.e., time
+       string is ',x.y') then analysis starts at the beginning of the file. If
+       stop time is not given (i.e, time string is 'x.y,') then analysis goes
+       to end of file.
+
 SEE ALSO
 --------
 linkperf:perf-record[1]
index 7fd6f1e1e29352a70479e0c015f55797dcffdd34..35a02f8e5a4aa90548c643c0de80e85b07a0b3bb 100644 (file)
@@ -11,6 +11,7 @@
 #include "util/session.h"
 #include "util/tool.h"
 #include "util/callchain.h"
+#include "util/time-utils.h"
 
 #include <subcmd/parse-options.h>
 #include "util/trace-event.h"
@@ -66,6 +67,10 @@ static struct rb_root root_caller_sorted;
 static unsigned long total_requested, total_allocated, total_freed;
 static unsigned long nr_allocs, nr_cross_allocs;
 
+/* filters for controlling start and stop of time of analysis */
+static struct perf_time_interval ptime;
+const char *time_str;
+
 static int insert_alloc_stat(unsigned long call_site, unsigned long ptr,
                             int bytes_req, int bytes_alloc, int cpu)
 {
@@ -912,6 +917,15 @@ static int perf_evsel__process_page_free_event(struct perf_evsel *evsel,
        return 0;
 }
 
+static bool perf_kmem__skip_sample(struct perf_sample *sample)
+{
+       /* skip sample based on time? */
+       if (perf_time__skip_sample(&ptime, sample->time))
+               return true;
+
+       return false;
+}
+
 typedef int (*tracepoint_handler)(struct perf_evsel *evsel,
                                  struct perf_sample *sample);
 
@@ -931,6 +945,9 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused,
                return -1;
        }
 
+       if (perf_kmem__skip_sample(sample))
+               return 0;
+
        dump_printf(" ... thread: %s:%d\n", thread__comm_str(thread), thread->tid);
 
        if (evsel->handler != NULL) {
@@ -1894,6 +1911,8 @@ int cmd_kmem(int argc, const char **argv, const char *prefix __maybe_unused)
        OPT_CALLBACK_NOOPT(0, "page", NULL, NULL, "Analyze page allocator",
                           parse_page_opt),
        OPT_BOOLEAN(0, "live", &live_page, "Show live page stat"),
+       OPT_STRING(0, "time", &time_str, "str",
+                  "Time span of interest (start,stop)"),
        OPT_END()
        };
        const char *const kmem_subcommands[] = { "record", "stat", NULL };
@@ -1954,6 +1973,11 @@ int cmd_kmem(int argc, const char **argv, const char *prefix __maybe_unused)
 
        symbol__init(&session->header.env);
 
+       if (perf_time__parse_str(&ptime, time_str) != 0) {
+               pr_err("Invalid time string\n");
+               return -EINVAL;
+       }
+
        if (!strcmp(argv[0], "stat")) {
                setlocale(LC_ALL, "");