From 21038f2baa05a0550f56f010f609a5c871b6a274 Mon Sep 17 00:00:00 2001 From: Song Liu Date: Mon, 25 Feb 2019 16:20:05 -0800 Subject: [PATCH 01/35] perf, bpf: Consider events with attr.bpf_event as side-band events Events with attr.bpf_event set should be considered as side-band events, as they carry information about BPF programs. Signed-off-by: Song Liu Cc: Alexei Starovoitov Cc: Daniel Borkmann Cc: Jiri Olsa Cc: Namhyung Kim Cc: Peter Zijlstra Cc: kernel-team@fb.com Cc: netdev@vger.kernel.org Fixes: 6ee52e2a3fe4 ("perf, bpf: Introduce PERF_RECORD_BPF_EVENT") Link: http://lkml.kernel.org/r/20190226002019.3748539-2-songliubraving@fb.com Signed-off-by: Arnaldo Carvalho de Melo --- kernel/events/core.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/kernel/events/core.c b/kernel/events/core.c index 5f59d848171e..dd9698ad3d66 100644 --- a/kernel/events/core.c +++ b/kernel/events/core.c @@ -4238,7 +4238,8 @@ static bool is_sb_event(struct perf_event *event) if (attr->mmap || attr->mmap_data || attr->mmap2 || attr->comm || attr->comm_exec || attr->task || attr->ksymbol || - attr->context_switch) + attr->context_switch || + attr->bpf_event) return true; return false; } From 4d6101f5fd5d996060eb59f7a01d3d1f842407c1 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Thu, 28 Feb 2019 11:22:45 -0300 Subject: [PATCH 02/35] perf probe: Clarify error message about not finding kernel modules debuginfo 'perf probe' supports using just the kernel module name, but that will work only when the module is loaded, or using the full pathname to the file with the DWARF debug info, but the warning was cryptic: Before: # perf probe -m cls_flower -L fl_change Failed to find the path for cls_flower: No such file or directory Error: Failed to show lines. # After: # perf probe -m cls_flower -L fl_change Module cls_flower is not loaded, please specify its full path name. Error: Failed to show lines. # perf probe -m /lib/modules/5.0.0-rc7+/kernel/net/sched/cls_flower.ko -L fl_change | head -7 0 static int fl_change(struct net *net, struct sk_buff *in_skb, struct tcf_proto *tp, unsigned long base, u32 handle, struct nlattr **tca, void **arg, bool ovr, struct netlink_ext_ack *extack) 4 { 5 struct cls_fl_head *head = rtnl_dereference(tp->root); # The behaviour doesn't change when the module is loaded: # modprobe cls_flower # perf probe -m cls_flower -L fl_change | head -7 0 static int fl_change(struct net *net, struct sk_buff *in_skb, struct tcf_proto *tp, unsigned long base, u32 handle, struct nlattr **tca, void **arg, bool ovr, struct netlink_ext_ack *extack) 4 { 5 struct cls_fl_head *head = rtnl_dereference(tp->root); # Cc: Adrian Hunter Cc: Jiri Olsa Cc: Marcelo Ricardo Leitner Cc: Masami Hiramatsu Cc: Namhyung Kim Link: https://lkml.kernel.org/n/tip-q4njvk9mshra00jacqjbzfn5@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/probe-event.c | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/tools/perf/util/probe-event.c b/tools/perf/util/probe-event.c index 0030f9b9bf7e..a1b8d9649ca7 100644 --- a/tools/perf/util/probe-event.c +++ b/tools/perf/util/probe-event.c @@ -472,9 +472,12 @@ static struct debuginfo *open_debuginfo(const char *module, struct nsinfo *nsi, strcpy(reason, "(unknown)"); } else dso__strerror_load(dso, reason, STRERR_BUFSIZE); - if (!silent) - pr_err("Failed to find the path for %s: %s\n", - module ?: "kernel", reason); + if (!silent) { + if (module) + pr_err("Module %s is not loaded, please specify its full path name.\n", module); + else + pr_err("Failed to find the path for the kernel: %s\n", reason); + } return NULL; } path = dso->long_name; From 7c5b019e3a638a5a290b0ec020f6ca83d2ec2aaa Mon Sep 17 00:00:00 2001 From: Tony Jones Date: Wed, 27 Feb 2019 17:55:32 -0800 Subject: [PATCH 03/35] tools lib traceevent: Fix buffer overflow in arg_eval Fix buffer overflow observed when running perf test. The overflow is when trying to evaluate "1ULL << (64 - 1)" which is resulting in -9223372036854775808 which overflows the 20 character buffer. If is possible this bug has been reported before but I still don't see any fix checked in: See: https://www.spinics.net/lists/linux-perf-users/msg07714.html Reported-by: Michael Sartain Reported-by: Mathias Krause Signed-off-by: Tony Jones Acked-by: Steven Rostedt (VMware) Cc: Frederic Weisbecker Fixes: f7d82350e597 ("tools/events: Add files to create libtraceevent.a") Link: http://lkml.kernel.org/r/20190228015532.8941-1-tonyj@suse.de Signed-off-by: Arnaldo Carvalho de Melo --- tools/lib/traceevent/event-parse.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c index abd4fa5d3088..87494c7c619d 100644 --- a/tools/lib/traceevent/event-parse.c +++ b/tools/lib/traceevent/event-parse.c @@ -2457,7 +2457,7 @@ static int arg_num_eval(struct tep_print_arg *arg, long long *val) static char *arg_eval (struct tep_print_arg *arg) { long long val; - static char buf[20]; + static char buf[24]; switch (arg->type) { case TEP_PRINT_ATOM: From 10c3405f060397e565e4f75c403859f9a074bfa5 Mon Sep 17 00:00:00 2001 From: "Gustavo A. R. Silva" Date: Tue, 12 Feb 2019 14:54:30 -0600 Subject: [PATCH 04/35] perf: Mark expected switch fall-through MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit In preparation to enabling -Wimplicit-fallthrough, mark switch cases where we are expecting to fall through. This patch fixes the following warning: kernel/events/core.c: In function ‘perf_event_parse_addr_filter’: kernel/events/core.c:9154:11: warning: this statement may fall through [-Wimplicit-fallthrough=] kernel = 1; ~~~~~~~^~~ kernel/events/core.c:9156:3: note: here case IF_SRC_FILEADDR: ^~~~ Warning level 3 was used: -Wimplicit-fallthrough=3 This patch is part of the ongoing efforts to enable -Wimplicit-fallthrough. Signed-off-by: Gustavo A. R. Silva Cc: Alexander Shishkin Cc: Gustavo A. R. Silva Cc: Jiri Olsa Cc: Kees Kook Cc: Namhyung Kim Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/20190212205430.GA8446@embeddedor Signed-off-by: Arnaldo Carvalho de Melo --- kernel/events/core.c | 1 + 1 file changed, 1 insertion(+) diff --git a/kernel/events/core.c b/kernel/events/core.c index dd9698ad3d66..6fb27b564730 100644 --- a/kernel/events/core.c +++ b/kernel/events/core.c @@ -9175,6 +9175,7 @@ perf_event_parse_addr_filter(struct perf_event *event, char *fstr, case IF_SRC_KERNELADDR: case IF_SRC_KERNEL: kernel = 1; + /* fall through */ case IF_SRC_FILEADDR: case IF_SRC_FILE: From 284c4e18f55e85155fbcbef5f88b6e62d2b1c29c Mon Sep 17 00:00:00 2001 From: Jin Yao Date: Fri, 1 Mar 2019 18:13:06 +0800 Subject: [PATCH 05/35] perf time-utils: Refactor time range parsing code Jiri points out that we don't need any time checking and time string parsing if the --time option is not set. That makes sense. This patch refactors the time range parsing code, move the duplicated code from perf report and perf script to time_utils and check if --time option is set before parsing the time string. This patch is no logic change expected. So the usage of --time is same as before. For example: Select the first and second 10% time slices: perf report --time 10%/1,10%/2 perf script --time 10%/1,10%/2 Select the slices from 0% to 10% and from 30% to 40%: perf report --time 0%-10%,30%-40% perf script --time 0%-10%,30%-40% Select the time slices from timestamp 3971 to 3973 perf report --time 3971,3973 perf script --time 3971,3973 Committer testing: Using the above examples, check before and after to see if it remains the same: $ perf record -F 10000 -- find . -name "*.[ch]" -exec cat {} + > /dev/null [ perf record: Woken up 3 times to write data ] [ perf record: Captured and wrote 1.626 MB perf.data (42392 samples) ] $ $ perf report --time 10%/1,10%/2 > /tmp/report.before.1 $ perf script --time 10%/1,10%/2 > /tmp/script.before.1 $ perf report --time 0%-10%,30%-40% > /tmp/report.before.2 $ perf script --time 0%-10%,30%-40% > /tmp/script.before.2 $ perf report --time 180457.375844,180457.377717 > /tmp/report.before.3 $ perf script --time 180457.375844,180457.377717 > /tmp/script.before.3 For example, the 3rd test produces this slice: $ cat /tmp/script.before.3 cat 3147 180457.375844: 2143 cycles:uppp: 7f79362590d9 cfree@GLIBC_2.2.5+0x9 (/usr/lib64/libc-2.28.so) cat 3147 180457.375986: 2245 cycles:uppp: 558b70f3d86e [unknown] (/usr/bin/cat) cat 3147 180457.376012: 2164 cycles:uppp: 7f7936257430 _int_malloc+0x8c0 (/usr/lib64/libc-2.28.so) cat 3147 180457.376140: 2921 cycles:uppp: 558b70f3a554 [unknown] (/usr/bin/cat) cat 3147 180457.376296: 2844 cycles:uppp: 7f7936258abe malloc+0x4e (/usr/lib64/libc-2.28.so) cat 3147 180457.376431: 2717 cycles:uppp: 558b70f3b0ca [unknown] (/usr/bin/cat) cat 3147 180457.376667: 2630 cycles:uppp: 558b70f3d86e [unknown] (/usr/bin/cat) cat 3147 180457.376795: 2442 cycles:uppp: 7f79362bff55 read+0x15 (/usr/lib64/libc-2.28.so) cat 3147 180457.376927: 2376 cycles:uppp: ffffffff9aa00163 [unknown] ([unknown]) cat 3147 180457.376954: 2307 cycles:uppp: 7f7936257438 _int_malloc+0x8c8 (/usr/lib64/libc-2.28.so) cat 3147 180457.377116: 3091 cycles:uppp: 7f7936258a70 malloc+0x0 (/usr/lib64/libc-2.28.so) cat 3147 180457.377362: 2945 cycles:uppp: 558b70f3a3b0 [unknown] (/usr/bin/cat) cat 3147 180457.377517: 2727 cycles:uppp: 558b70f3a9aa [unknown] (/usr/bin/cat) $ Install 'coreutils-debuginfo' to see cat's guts (symbols), but then, the above chunk translates into this 'perf report' output: $ cat /tmp/report.before.3 # To display the perf.data header info, please use --header/--header-only options. # # # Total Lost Samples: 0 # # Samples: 13 of event 'cycles:uppp' (time slices: 180457.375844,180457.377717) # Event count (approx.): 33552 # # Overhead Command Shared Object Symbol # ........ ....... ................ ...................... # 17.69% cat libc-2.28.so [.] malloc 14.53% cat cat [.] 0x000000000000586e 13.33% cat libc-2.28.so [.] _int_malloc 8.78% cat cat [.] 0x00000000000023b0 8.71% cat cat [.] 0x0000000000002554 8.13% cat cat [.] 0x00000000000029aa 8.10% cat cat [.] 0x00000000000030ca 7.28% cat libc-2.28.so [.] read 7.08% cat [unknown] [k] 0xffffffff9aa00163 6.39% cat libc-2.28.so [.] cfree@GLIBC_2.2.5 # # (Tip: Order by the overhead of source file name and line number: perf report -s srcline) # $ Now lets see after applying this patch, nothing should change: $ perf report --time 10%/1,10%/2 > /tmp/report.after.1 $ perf script --time 10%/1,10%/2 > /tmp/script.after.1 $ perf report --time 0%-10%,30%-40% > /tmp/report.after.2 $ perf script --time 0%-10%,30%-40% > /tmp/script.after.2 $ perf report --time 180457.375844,180457.377717 > /tmp/report.after.3 $ perf script --time 180457.375844,180457.377717 > /tmp/script.after.3 $ diff -u /tmp/report.before.1 /tmp/report.after.1 $ diff -u /tmp/script.before.1 /tmp/script.after.1 $ diff -u /tmp/report.before.2 /tmp/report.after.2 --- /tmp/report.before.2 2019-03-01 11:01:53.526094883 -0300 +++ /tmp/report.after.2 2019-03-01 11:09:18.231770467 -0300 @@ -352,5 +352,5 @@ # -# (Tip: Generate a script for your data: perf script -g ) +# (Tip: Treat branches as callchains: perf report --branch-history) # $ diff -u /tmp/script.before.2 /tmp/script.after.2 $ diff -u /tmp/report.before.3 /tmp/report.after.3 --- /tmp/report.before.3 2019-03-01 11:03:08.890045588 -0300 +++ /tmp/report.after.3 2019-03-01 11:09:40.660224002 -0300 @@ -22,5 +22,5 @@ # -# (Tip: Order by the overhead of source file name and line number: perf report -s srcline) +# (Tip: List events using substring match: perf list ) # $ diff -u /tmp/script.before.3 /tmp/script.after.3 $ Cool, just the 'perf report' tips changed, QED. Signed-off-by: Jin Yao Tested-by: Arnaldo Carvalho de Melo Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jin Yao Cc: Jiri Olsa Cc: Kan Liang Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/1551435186-6008-1-git-send-email-yao.jin@linux.intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-report.c | 38 ++++++--------------------- tools/perf/builtin-script.c | 39 ++++++--------------------- tools/perf/util/time-utils.c | 51 +++++++++++++++++++++++++++++++++++- tools/perf/util/time-utils.h | 6 +++++ 4 files changed, 72 insertions(+), 62 deletions(-) diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c index 1532ebde6c4b..ee93c18a6685 100644 --- a/tools/perf/builtin-report.c +++ b/tools/perf/builtin-report.c @@ -1375,36 +1375,13 @@ repeat: if (symbol__init(&session->header.env) < 0) goto error; - report.ptime_range = perf_time__range_alloc(report.time_str, - &report.range_size); - if (!report.ptime_range) { - ret = -ENOMEM; - goto error; - } - - if (perf_time__parse_str(report.ptime_range, report.time_str) != 0) { - if (session->evlist->first_sample_time == 0 && - session->evlist->last_sample_time == 0) { - pr_err("HINT: no first/last sample time found in perf data.\n" - "Please use latest perf binary to execute 'perf record'\n" - "(if '--buildid-all' is enabled, please set '--timestamp-boundary').\n"); - ret = -EINVAL; + if (report.time_str) { + ret = perf_time__parse_for_ranges(report.time_str, session, + &report.ptime_range, + &report.range_size, + &report.range_num); + if (ret < 0) goto error; - } - - report.range_num = perf_time__percent_parse_str( - report.ptime_range, report.range_size, - report.time_str, - session->evlist->first_sample_time, - session->evlist->last_sample_time); - - if (report.range_num < 0) { - pr_err("Invalid time string\n"); - ret = -EINVAL; - goto error; - } - } else { - report.range_num = 1; } if (session->tevent.pevent && @@ -1426,7 +1403,8 @@ repeat: ret = 0; error: - zfree(&report.ptime_range); + if (report.ptime_range) + zfree(&report.ptime_range); perf_session__delete(session); return ret; diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c index 2d8cb1d1682c..53f78cf3113f 100644 --- a/tools/perf/builtin-script.c +++ b/tools/perf/builtin-script.c @@ -3699,37 +3699,13 @@ int cmd_script(int argc, const char **argv) if (err < 0) goto out_delete; - script.ptime_range = perf_time__range_alloc(script.time_str, - &script.range_size); - if (!script.ptime_range) { - err = -ENOMEM; - goto out_delete; - } - - /* needs to be parsed after looking up reference time */ - if (perf_time__parse_str(script.ptime_range, script.time_str) != 0) { - if (session->evlist->first_sample_time == 0 && - session->evlist->last_sample_time == 0) { - pr_err("HINT: no first/last sample time found in perf data.\n" - "Please use latest perf binary to execute 'perf record'\n" - "(if '--buildid-all' is enabled, please set '--timestamp-boundary').\n"); - err = -EINVAL; + if (script.time_str) { + err = perf_time__parse_for_ranges(script.time_str, session, + &script.ptime_range, + &script.range_size, + &script.range_num); + if (err < 0) goto out_delete; - } - - script.range_num = perf_time__percent_parse_str( - script.ptime_range, script.range_size, - script.time_str, - session->evlist->first_sample_time, - session->evlist->last_sample_time); - - if (script.range_num < 0) { - pr_err("Invalid time string\n"); - err = -EINVAL; - goto out_delete; - } - } else { - script.range_num = 1; } err = __cmd_script(&script); @@ -3737,7 +3713,8 @@ int cmd_script(int argc, const char **argv) flush_scripting(); out_delete: - zfree(&script.ptime_range); + if (script.ptime_range) + zfree(&script.ptime_range); perf_evlist__free_stats(session->evlist); perf_session__delete(session); diff --git a/tools/perf/util/time-utils.c b/tools/perf/util/time-utils.c index 6193b46050a5..0f53baec660e 100644 --- a/tools/perf/util/time-utils.c +++ b/tools/perf/util/time-utils.c @@ -11,6 +11,8 @@ #include "perf.h" #include "debug.h" #include "time-utils.h" +#include "session.h" +#include "evlist.h" int parse_nsec_time(const char *str, u64 *ptime) { @@ -374,7 +376,7 @@ bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf, struct perf_time_interval *ptime; int i; - if ((timestamp == 0) || (num == 0)) + if ((!ptime_buf) || (timestamp == 0) || (num == 0)) return false; if (num == 1) @@ -396,6 +398,53 @@ bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf, return (i == num) ? true : false; } +int perf_time__parse_for_ranges(const char *time_str, + struct perf_session *session, + struct perf_time_interval **ranges, + int *range_size, int *range_num) +{ + struct perf_time_interval *ptime_range; + int size, num, ret; + + ptime_range = perf_time__range_alloc(time_str, &size); + if (!ptime_range) + return -ENOMEM; + + if (perf_time__parse_str(ptime_range, time_str) != 0) { + if (session->evlist->first_sample_time == 0 && + session->evlist->last_sample_time == 0) { + pr_err("HINT: no first/last sample time found in perf data.\n" + "Please use latest perf binary to execute 'perf record'\n" + "(if '--buildid-all' is enabled, please set '--timestamp-boundary').\n"); + ret = -EINVAL; + goto error; + } + + num = perf_time__percent_parse_str( + ptime_range, size, + time_str, + session->evlist->first_sample_time, + session->evlist->last_sample_time); + + if (num < 0) { + pr_err("Invalid time string\n"); + ret = -EINVAL; + goto error; + } + } else { + num = 1; + } + + *range_size = size; + *range_num = num; + *ranges = ptime_range; + return 0; + +error: + free(ptime_range); + return ret; +} + int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz) { u64 sec = timestamp / NSEC_PER_SEC; diff --git a/tools/perf/util/time-utils.h b/tools/perf/util/time-utils.h index 70b177d2b98c..b923de44e36f 100644 --- a/tools/perf/util/time-utils.h +++ b/tools/perf/util/time-utils.h @@ -23,6 +23,12 @@ bool perf_time__skip_sample(struct perf_time_interval *ptime, u64 timestamp); bool perf_time__ranges_skip_sample(struct perf_time_interval *ptime_buf, int num, u64 timestamp); +struct perf_session; + +int perf_time__parse_for_ranges(const char *str, struct perf_session *session, + struct perf_time_interval **ranges, + int *range_size, int *range_num); + int timestamp__scnprintf_usec(u64 timestamp, char *buf, size_t sz); int fetch_current_timestamp(char *buf, size_t sz); From c1c49204b0114daf210c79d66a5980c8e6f8f8fb Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Fri, 1 Mar 2019 14:29:02 +0200 Subject: [PATCH 06/35] perf auxtrace: Improve address filter error message when there is no DSO The message does not indicate the possibility that the symbol is not found because the file does not exist. Before: $ perf record -e intel_pt//u --filter 'filter strcmp / strcpy @ foo ' ls Symbol 'strcmp' not found. Note that symbols must be functions. Failed to parse address filter: 'filter strcmp / strcpy @ foo ' Filter format is: filter|start|stop|tracestop [/ ] [@] Where multiple filters are separated by space or comma. After: $ perf record -e intel_pt//u --filter 'filter strcmp / strcpy @ foo ' ls File 'foo' not found or has no symbols. Symbol 'strcmp' not found. Note that symbols must be functions. Failed to parse address filter: 'filter strcmp / strcpy @ foo ' Filter format is: filter|start|stop|tracestop [/ ] [@] Where multiple filters are separated by space or comma. Reported-by: Alexander Shishkin Signed-off-by: Adrian Hunter Tested-by: Arnaldo Carvalho de Melo Cc: Jiri Olsa Link: https://lkml.kernel.org/n/tip-dvngzxd0jkplzw1ary69dilb@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/auxtrace.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tools/perf/util/auxtrace.c b/tools/perf/util/auxtrace.c index 267e54df511b..fb76b6b232d4 100644 --- a/tools/perf/util/auxtrace.c +++ b/tools/perf/util/auxtrace.c @@ -1918,7 +1918,8 @@ static struct dso *load_dso(const char *name) if (!map) return NULL; - map__load(map); + if (map__load(map) < 0) + pr_err("File '%s' not found or has no symbols.\n", name); dso = dso__get(map->dso); From 076333870c2f5bdd9b6d31e7ca1909cf0c84cbfa Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Fri, 1 Mar 2019 12:35:36 +0200 Subject: [PATCH 07/35] perf intel-pt: Fix divide by zero when TSC is not available When TSC is not available, "timeless" decoding is used but a divide by zero occurs if perf_time_to_tsc() is called. Ensure the divisor is not zero. Signed-off-by: Adrian Hunter Cc: Jiri Olsa Cc: stable@vger.kernel.org # v4.9+ Link: https://lkml.kernel.org/n/tip-1i4j0wqoc8vlbkcizqqxpsf4@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/intel-pt.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index 3b497bab4324..6d288237887b 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -2531,6 +2531,8 @@ int intel_pt_process_auxtrace_info(union perf_event *event, } pt->timeless_decoding = intel_pt_timeless_decoding(pt); + if (pt->timeless_decoding && !pt->tc.time_mult) + pt->tc.time_mult = 1; pt->have_tsc = intel_pt_have_tsc(pt); pt->sampling_mode = false; pt->est_tsc = !pt->timeless_decoding; From f435887ec0c941b97301bd6ed1f3e4b5200df409 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Thu, 28 Feb 2019 15:00:24 +0200 Subject: [PATCH 08/35] perf db-export: Add calls parent_id to enable creation of call trees The call_path can be used to find the parent symbol for a call but not the exact parent call. To do that add parent_id to the call_return export. This enables the creation of a call tree from the exported data. Signed-off-by: Adrian Hunter Cc: Jiri Olsa Link: https://lkml.kernel.org/n/tip-6j7tzdxo67cox6kan7k22oo6@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/db-export.c | 15 ++++++++++----- tools/perf/util/db-export.h | 3 ++- .../util/scripting-engines/trace-event-python.c | 8 +++++--- tools/perf/util/thread-stack.c | 16 ++++++++++++++-- tools/perf/util/thread-stack.h | 6 ++++-- 5 files changed, 35 insertions(+), 13 deletions(-) diff --git a/tools/perf/util/db-export.c b/tools/perf/util/db-export.c index de9b4769d06c..d7315a00c731 100644 --- a/tools/perf/util/db-export.c +++ b/tools/perf/util/db-export.c @@ -510,18 +510,23 @@ int db_export__call_path(struct db_export *dbe, struct call_path *cp) return 0; } -int db_export__call_return(struct db_export *dbe, struct call_return *cr) +int db_export__call_return(struct db_export *dbe, struct call_return *cr, + u64 *parent_db_id) { int err; - if (cr->db_id) - return 0; - err = db_export__call_path(dbe, cr->cp); if (err) return err; - cr->db_id = ++dbe->call_return_last_db_id; + if (!cr->db_id) + cr->db_id = ++dbe->call_return_last_db_id; + + if (parent_db_id) { + if (!*parent_db_id) + *parent_db_id = ++dbe->call_return_last_db_id; + cr->parent_db_id = *parent_db_id; + } if (dbe->export_call_return) return dbe->export_call_return(dbe, cr); diff --git a/tools/perf/util/db-export.h b/tools/perf/util/db-export.h index 67bc6b8ad2d6..4e2424c89df9 100644 --- a/tools/perf/util/db-export.h +++ b/tools/perf/util/db-export.h @@ -104,6 +104,7 @@ int db_export__sample(struct db_export *dbe, union perf_event *event, int db_export__branch_types(struct db_export *dbe); int db_export__call_path(struct db_export *dbe, struct call_path *cp); -int db_export__call_return(struct db_export *dbe, struct call_return *cr); +int db_export__call_return(struct db_export *dbe, struct call_return *cr, + u64 *parent_db_id); #endif diff --git a/tools/perf/util/scripting-engines/trace-event-python.c b/tools/perf/util/scripting-engines/trace-event-python.c index 0e17db41b49b..09604c6508f0 100644 --- a/tools/perf/util/scripting-engines/trace-event-python.c +++ b/tools/perf/util/scripting-engines/trace-event-python.c @@ -1173,7 +1173,7 @@ static int python_export_call_return(struct db_export *dbe, u64 comm_db_id = cr->comm ? cr->comm->db_id : 0; PyObject *t; - t = tuple_new(11); + t = tuple_new(12); tuple_set_u64(t, 0, cr->db_id); tuple_set_u64(t, 1, cr->thread->db_id); @@ -1186,6 +1186,7 @@ static int python_export_call_return(struct db_export *dbe, tuple_set_u64(t, 8, cr->return_ref); tuple_set_u64(t, 9, cr->cp->parent->db_id); tuple_set_s32(t, 10, cr->flags); + tuple_set_u64(t, 11, cr->parent_db_id); call_object(tables->call_return_handler, t, "call_return_table"); @@ -1194,11 +1195,12 @@ static int python_export_call_return(struct db_export *dbe, return 0; } -static int python_process_call_return(struct call_return *cr, void *data) +static int python_process_call_return(struct call_return *cr, u64 *parent_db_id, + void *data) { struct db_export *dbe = data; - return db_export__call_return(dbe, cr); + return db_export__call_return(dbe, cr, parent_db_id); } static void python_process_general_event(struct perf_sample *sample, diff --git a/tools/perf/util/thread-stack.c b/tools/perf/util/thread-stack.c index a8b45168513c..41942c2aaa18 100644 --- a/tools/perf/util/thread-stack.c +++ b/tools/perf/util/thread-stack.c @@ -49,6 +49,7 @@ enum retpoline_state_t { * @timestamp: timestamp (if known) * @ref: external reference (e.g. db_id of sample) * @branch_count: the branch count when the entry was created + * @db_id: id used for db-export * @cp: call path * @no_call: a 'call' was not seen * @trace_end: a 'call' but trace ended @@ -59,6 +60,7 @@ struct thread_stack_entry { u64 timestamp; u64 ref; u64 branch_count; + u64 db_id; struct call_path *cp; bool no_call; bool trace_end; @@ -280,12 +282,14 @@ static int thread_stack__call_return(struct thread *thread, .comm = ts->comm, .db_id = 0, }; + u64 *parent_db_id; tse = &ts->stack[idx]; cr.cp = tse->cp; cr.call_time = tse->timestamp; cr.return_time = timestamp; cr.branch_count = ts->branch_count - tse->branch_count; + cr.db_id = tse->db_id; cr.call_ref = tse->ref; cr.return_ref = ref; if (tse->no_call) @@ -295,7 +299,14 @@ static int thread_stack__call_return(struct thread *thread, if (tse->non_call) cr.flags |= CALL_RETURN_NON_CALL; - return crp->process(&cr, crp->data); + /* + * The parent db_id must be assigned before exporting the child. Note + * it is not possible to export the parent first because its information + * is not yet complete because its 'return' has not yet been processed. + */ + parent_db_id = idx ? &(tse - 1)->db_id : NULL; + + return crp->process(&cr, parent_db_id, crp->data); } static int __thread_stack__flush(struct thread *thread, struct thread_stack *ts) @@ -484,7 +495,7 @@ void thread_stack__sample(struct thread *thread, int cpu, } struct call_return_processor * -call_return_processor__new(int (*process)(struct call_return *cr, void *data), +call_return_processor__new(int (*process)(struct call_return *cr, u64 *parent_db_id, void *data), void *data) { struct call_return_processor *crp; @@ -537,6 +548,7 @@ static int thread_stack__push_cp(struct thread_stack *ts, u64 ret_addr, tse->no_call = no_call; tse->trace_end = trace_end; tse->non_call = false; + tse->db_id = 0; return 0; } diff --git a/tools/perf/util/thread-stack.h b/tools/perf/util/thread-stack.h index b7c04e19ad41..9c45f947f5a9 100644 --- a/tools/perf/util/thread-stack.h +++ b/tools/perf/util/thread-stack.h @@ -55,6 +55,7 @@ enum { * @call_ref: external reference to 'call' sample (e.g. db_id) * @return_ref: external reference to 'return' sample (e.g. db_id) * @db_id: id used for db-export + * @parent_db_id: id of parent call used for db-export * @flags: Call/Return flags */ struct call_return { @@ -67,6 +68,7 @@ struct call_return { u64 call_ref; u64 return_ref; u64 db_id; + u64 parent_db_id; u32 flags; }; @@ -79,7 +81,7 @@ struct call_return { */ struct call_return_processor { struct call_path_root *cpr; - int (*process)(struct call_return *cr, void *data); + int (*process)(struct call_return *cr, u64 *parent_db_id, void *data); void *data; }; @@ -93,7 +95,7 @@ void thread_stack__free(struct thread *thread); size_t thread_stack__depth(struct thread *thread, int cpu); struct call_return_processor * -call_return_processor__new(int (*process)(struct call_return *cr, void *data), +call_return_processor__new(int (*process)(struct call_return *cr, u64 *parent_db_id, void *data), void *data); void call_return_processor__free(struct call_return_processor *crp); int thread_stack__process(struct thread *thread, struct comm *comm, From 8ce9a7251d110c7bbb43e30dd42f81d8e6286516 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Thu, 28 Feb 2019 15:00:25 +0200 Subject: [PATCH 09/35] perf scripts python: export-to-sqlite.py: Export calls parent_id Export to the 'calls' table the newly created 'parent_id'. Signed-off-by: Adrian Hunter Cc: Jiri Olsa Link: https://lkml.kernel.org/n/tip-b09oukl48rsl9azkp2wmh0bl@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/export-to-sqlite.py | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/tools/perf/scripts/python/export-to-sqlite.py b/tools/perf/scripts/python/export-to-sqlite.py index ed237f2ed03f..eb63e6c7107f 100644 --- a/tools/perf/scripts/python/export-to-sqlite.py +++ b/tools/perf/scripts/python/export-to-sqlite.py @@ -222,7 +222,8 @@ if perf_db_export_calls: 'call_id bigint,' 'return_id bigint,' 'parent_call_path_id bigint,' - 'flags integer)') + 'flags integer,' + 'parent_id bigint)') # printf was added to sqlite in version 3.8.3 sqlite_has_printf = False @@ -321,7 +322,8 @@ if perf_db_export_calls: 'call_id,' 'return_id,' 'CASE WHEN flags=0 THEN \'\' WHEN flags=1 THEN \'no call\' WHEN flags=2 THEN \'no return\' WHEN flags=3 THEN \'no call/return\' WHEN flags=6 THEN \'jump\' ELSE flags END AS flags,' - 'parent_call_path_id' + 'parent_call_path_id,' + 'parent_id' ' FROM calls INNER JOIN call_paths ON call_paths.id = call_path_id') do_query(query, 'CREATE VIEW samples_view AS ' @@ -373,7 +375,7 @@ if perf_db_export_calls or perf_db_export_callchains: call_path_query.prepare("INSERT INTO call_paths VALUES (?, ?, ?, ?)") if perf_db_export_calls: call_query = QSqlQuery(db) - call_query.prepare("INSERT INTO calls VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)") + call_query.prepare("INSERT INTO calls VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)") def trace_begin(): print datetime.datetime.today(), "Writing records..." @@ -388,6 +390,7 @@ def trace_begin(): sample_table(0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0) if perf_db_export_calls or perf_db_export_callchains: call_path_table(0, 0, 0, 0) + call_return_table(0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0) unhandled_count = 0 @@ -397,6 +400,7 @@ def trace_end(): print datetime.datetime.today(), "Adding indexes" if perf_db_export_calls: do_query(query, 'CREATE INDEX pcpid_idx ON calls (parent_call_path_id)') + do_query(query, 'CREATE INDEX pid_idx ON calls (parent_id)') if (unhandled_count): print datetime.datetime.today(), "Warning: ", unhandled_count, " unhandled events" @@ -452,4 +456,4 @@ def call_path_table(*x): bind_exec(call_path_query, 4, x) def call_return_table(*x): - bind_exec(call_query, 11, x) + bind_exec(call_query, 12, x) From 07c5ebead85f507271fb8e2a8b5814e486702518 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Thu, 28 Feb 2019 15:00:26 +0200 Subject: [PATCH 10/35] perf scripts python: export-to-postgresql.py: Fix invalid input syntax for integer error Fix SQL query error "invalid input syntax for integer": Traceback (most recent call last): File "tools/perf/scripts/python/export-to-postgresql.py", line 465, in do_query(query, 'CREATE VIEW calls_view AS ' File "tools/perf/scripts/python/export-to-postgresql.py", line 274, in do_query raise Exception("Query failed: " + q.lastError().text()) Exception: Query failed: ERROR: invalid input syntax for integer: "" LINE 1: ...ch_count,call_id,return_id,CASE WHEN flags=0 THEN '' WHEN fl... ^ (22P02) QPSQL: Unable to create query Error running python script tools/perf/scripts/python/export-to-postgresql.py Signed-off-by: Adrian Hunter Cc: Jiri Olsa Fixes: f08046cb3082 ("perf thread-stack: Represent jmps to the start of a different symbol") Link: https://lkml.kernel.org/n/tip-strfpdozrvg7bi1xzrivxzqt@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/export-to-postgresql.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/perf/scripts/python/export-to-postgresql.py b/tools/perf/scripts/python/export-to-postgresql.py index 30130213da7e..6358522a69f6 100644 --- a/tools/perf/scripts/python/export-to-postgresql.py +++ b/tools/perf/scripts/python/export-to-postgresql.py @@ -478,7 +478,7 @@ if perf_db_export_calls: 'branch_count,' 'call_id,' 'return_id,' - 'CASE WHEN flags=0 THEN \'\' WHEN flags=1 THEN \'no call\' WHEN flags=2 THEN \'no return\' WHEN flags=3 THEN \'no call/return\' WHEN flags=6 THEN \'jump\' ELSE flags END AS flags,' + 'CASE WHEN flags=0 THEN \'\' WHEN flags=1 THEN \'no call\' WHEN flags=2 THEN \'no return\' WHEN flags=3 THEN \'no call/return\' WHEN flags=6 THEN \'jump\' ELSE CAST ( flags AS VARCHAR(6) ) END AS flags,' 'parent_call_path_id' ' FROM calls INNER JOIN call_paths ON call_paths.id = call_path_id') From febce6dc1f5167e683d6e3c3d0f6ab7f98201ea8 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Thu, 28 Feb 2019 15:00:27 +0200 Subject: [PATCH 11/35] perf scripts python: export-to-postgresql.py: Export calls parent_id Export to the 'calls' table the newly created 'parent_id' and create an index for it. Signed-off-by: Adrian Hunter Cc: Jiri Olsa Link: https://lkml.kernel.org/n/tip-eybd6fnk6j9r7g643lsideoo@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/export-to-postgresql.py | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/tools/perf/scripts/python/export-to-postgresql.py b/tools/perf/scripts/python/export-to-postgresql.py index 6358522a69f6..390a351d15ea 100644 --- a/tools/perf/scripts/python/export-to-postgresql.py +++ b/tools/perf/scripts/python/export-to-postgresql.py @@ -394,7 +394,8 @@ if perf_db_export_calls: 'call_id bigint,' 'return_id bigint,' 'parent_call_path_id bigint,' - 'flags integer)') + 'flags integer,' + 'parent_id bigint)') do_query(query, 'CREATE VIEW machines_view AS ' 'SELECT ' @@ -479,7 +480,8 @@ if perf_db_export_calls: 'call_id,' 'return_id,' 'CASE WHEN flags=0 THEN \'\' WHEN flags=1 THEN \'no call\' WHEN flags=2 THEN \'no return\' WHEN flags=3 THEN \'no call/return\' WHEN flags=6 THEN \'jump\' ELSE CAST ( flags AS VARCHAR(6) ) END AS flags,' - 'parent_call_path_id' + 'parent_call_path_id,' + 'calls.parent_id' ' FROM calls INNER JOIN call_paths ON call_paths.id = call_path_id') do_query(query, 'CREATE VIEW samples_view AS ' @@ -575,6 +577,7 @@ def trace_begin(): sample_table(0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0) if perf_db_export_calls or perf_db_export_callchains: call_path_table(0, 0, 0, 0) + call_return_table(0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0) unhandled_count = 0 @@ -657,6 +660,7 @@ def trace_end(): 'ADD CONSTRAINT returnfk FOREIGN KEY (return_id) REFERENCES samples (id),' 'ADD CONSTRAINT parent_call_pathfk FOREIGN KEY (parent_call_path_id) REFERENCES call_paths (id)') do_query(query, 'CREATE INDEX pcpid_idx ON calls (parent_call_path_id)') + do_query(query, 'CREATE INDEX pid_idx ON calls (parent_id)') if (unhandled_count): print datetime.datetime.today(), "Warning: ", unhandled_count, " unhandled events" @@ -728,7 +732,7 @@ def call_path_table(cp_id, parent_id, symbol_id, ip, *x): value = struct.pack(fmt, 4, 8, cp_id, 8, parent_id, 8, symbol_id, 8, ip) call_path_file.write(value) -def call_return_table(cr_id, thread_id, comm_id, call_path_id, call_time, return_time, branch_count, call_id, return_id, parent_call_path_id, flags, *x): - fmt = "!hiqiqiqiqiqiqiqiqiqiqii" - value = struct.pack(fmt, 11, 8, cr_id, 8, thread_id, 8, comm_id, 8, call_path_id, 8, call_time, 8, return_time, 8, branch_count, 8, call_id, 8, return_id, 8, parent_call_path_id, 4, flags) +def call_return_table(cr_id, thread_id, comm_id, call_path_id, call_time, return_time, branch_count, call_id, return_id, parent_call_path_id, flags, parent_id, *x): + fmt = "!hiqiqiqiqiqiqiqiqiqiqiiiq" + value = struct.pack(fmt, 12, 8, cr_id, 8, thread_id, 8, comm_id, 8, call_path_id, 8, call_time, 8, return_time, 8, branch_count, 8, call_id, 8, return_id, 8, parent_call_path_id, 4, flags, 8, parent_id) call_file.write(value) From a731cc4c990a90d9d42a2081ca93fb4310680ae2 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Thu, 28 Feb 2019 15:00:28 +0200 Subject: [PATCH 12/35] perf scripts python: exported-sql-viewer.py: Factor out TreeWindowBase Factor out a base class TreeWindowBase from CallGraphWindow, so that TreeWindowBase can be reused. Signed-off-by: Adrian Hunter Cc: Jiri Olsa Link: https://lkml.kernel.org/n/tip-ifirw0c0mhkwxg6l12lk6k4p@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- .../scripts/python/exported-sql-viewer.py | 50 ++++++++++++------- 1 file changed, 31 insertions(+), 19 deletions(-) diff --git a/tools/perf/scripts/python/exported-sql-viewer.py b/tools/perf/scripts/python/exported-sql-viewer.py index 09ce73b07d35..df854f0a69f0 100755 --- a/tools/perf/scripts/python/exported-sql-viewer.py +++ b/tools/perf/scripts/python/exported-sql-viewer.py @@ -693,28 +693,16 @@ class VBox(): def Widget(self): return self.vbox -# Context-sensitive call graph window +# Tree window base -class CallGraphWindow(QMdiSubWindow): +class TreeWindowBase(QMdiSubWindow): - def __init__(self, glb, parent=None): - super(CallGraphWindow, self).__init__(parent) + def __init__(self, parent=None): + super(TreeWindowBase, self).__init__(parent) - self.model = LookupCreateModel("Context-Sensitive Call Graph", lambda x=glb: CallGraphModel(x)) - - self.view = QTreeView() - self.view.setModel(self.model) - - for c, w in ((0, 250), (1, 100), (2, 60), (3, 70), (4, 70), (5, 100)): - self.view.setColumnWidth(c, w) - - self.find_bar = FindBar(self, self) - - self.vbox = VBox(self.view, self.find_bar.Widget()) - - self.setWidget(self.vbox.Widget()) - - AddSubWindow(glb.mainwindow.mdi_area, self, "Context-Sensitive Call Graph") + self.model = None + self.view = None + self.find_bar = None def DisplayFound(self, ids): if not len(ids): @@ -747,6 +735,30 @@ class CallGraphWindow(QMdiSubWindow): if not found: self.find_bar.NotFound() + +# Context-sensitive call graph window + +class CallGraphWindow(TreeWindowBase): + + def __init__(self, glb, parent=None): + super(CallGraphWindow, self).__init__(parent) + + self.model = LookupCreateModel("Context-Sensitive Call Graph", lambda x=glb: CallGraphModel(x)) + + self.view = QTreeView() + self.view.setModel(self.model) + + for c, w in ((0, 250), (1, 100), (2, 60), (3, 70), (4, 70), (5, 100)): + self.view.setColumnWidth(c, w) + + self.find_bar = FindBar(self, self) + + self.vbox = VBox(self.view, self.find_bar.Widget()) + + self.setWidget(self.vbox.Widget()) + + AddSubWindow(glb.mainwindow.mdi_area, self, "Context-Sensitive Call Graph") + # Child data item finder class ChildDataItemFinder(): From a448ba232a5f0176c226df1bab8877ec06a7c771 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Thu, 28 Feb 2019 15:00:29 +0200 Subject: [PATCH 13/35] perf scripts python: exported-sql-viewer.py: Improve TreeModel abstraction Instead of passing the tree root, get it from a method that can be implemented in any derived class. Signed-off-by: Adrian Hunter Cc: Jiri Olsa Link: https://lkml.kernel.org/n/tip-ovcv28bg4mt9swk36ypdyz14@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- .../perf/scripts/python/exported-sql-viewer.py | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/tools/perf/scripts/python/exported-sql-viewer.py b/tools/perf/scripts/python/exported-sql-viewer.py index df854f0a69f0..b2a22525549d 100755 --- a/tools/perf/scripts/python/exported-sql-viewer.py +++ b/tools/perf/scripts/python/exported-sql-viewer.py @@ -167,9 +167,10 @@ class Thread(QThread): class TreeModel(QAbstractItemModel): - def __init__(self, root, parent=None): + def __init__(self, glb, parent=None): super(TreeModel, self).__init__(parent) - self.root = root + self.glb = glb + self.root = self.GetRoot() self.last_row_read = 0 def Item(self, parent): @@ -562,8 +563,10 @@ class CallGraphRootItem(CallGraphLevelItemBase): class CallGraphModel(TreeModel): def __init__(self, glb, parent=None): - super(CallGraphModel, self).__init__(CallGraphRootItem(glb), parent) - self.glb = glb + super(CallGraphModel, self).__init__(glb, parent) + + def GetRoot(self): + return CallGraphRootItem(self.glb) def columnCount(self, parent=None): return 7 @@ -1339,8 +1342,7 @@ class BranchModel(TreeModel): progress = Signal(object) def __init__(self, glb, event_id, where_clause, parent=None): - super(BranchModel, self).__init__(BranchRootItem(), parent) - self.glb = glb + super(BranchModel, self).__init__(glb, parent) self.event_id = event_id self.more = True self.populated = 0 @@ -1364,6 +1366,9 @@ class BranchModel(TreeModel): self.fetcher.done.connect(self.Update) self.fetcher.Fetch(glb_chunk_sz) + def GetRoot(self): + return BranchRootItem() + def columnCount(self, parent=None): return 8 From 254c0d820b86d7712e03750c58ab104e06e3655d Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Thu, 28 Feb 2019 15:00:30 +0200 Subject: [PATCH 14/35] perf scripts python: exported-sql-viewer.py: Factor out CallGraphModelBase Factor out a base class CallGraphModelBase from CallGraphModel, so that CallGraphModelBase can be reused. Signed-off-by: Adrian Hunter Cc: Jiri Olsa Link: https://lkml.kernel.org/n/tip-76eybebzjwvgnadkm2oufrqi@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- .../scripts/python/exported-sql-viewer.py | 100 ++++++++++-------- 1 file changed, 55 insertions(+), 45 deletions(-) diff --git a/tools/perf/scripts/python/exported-sql-viewer.py b/tools/perf/scripts/python/exported-sql-viewer.py index b2a22525549d..c4a2134d85f5 100755 --- a/tools/perf/scripts/python/exported-sql-viewer.py +++ b/tools/perf/scripts/python/exported-sql-viewer.py @@ -558,26 +558,12 @@ class CallGraphRootItem(CallGraphLevelItemBase): self.child_items.append(child_item) self.child_count += 1 -# Context-sensitive call graph data model +# Context-sensitive call graph data model base -class CallGraphModel(TreeModel): +class CallGraphModelBase(TreeModel): def __init__(self, glb, parent=None): - super(CallGraphModel, self).__init__(glb, parent) - - def GetRoot(self): - return CallGraphRootItem(self.glb) - - def columnCount(self, parent=None): - return 7 - - def columnHeader(self, column): - headers = ["Call Path", "Object", "Count ", "Time (ns) ", "Time (%) ", "Branch Count ", "Branch Count (%) "] - return headers[column] - - def columnAlignment(self, column): - alignment = [ Qt.AlignLeft, Qt.AlignLeft, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight ] - return alignment[column] + super(CallGraphModelBase, self).__init__(glb, parent) def FindSelect(self, value, pattern, query): if pattern: @@ -597,34 +583,7 @@ class CallGraphModel(TreeModel): match = " GLOB '" + str(value) + "'" else: match = " = '" + str(value) + "'" - QueryExec(query, "SELECT call_path_id, comm_id, thread_id" - " FROM calls" - " INNER JOIN call_paths ON calls.call_path_id = call_paths.id" - " INNER JOIN symbols ON call_paths.symbol_id = symbols.id" - " WHERE symbols.name" + match + - " GROUP BY comm_id, thread_id, call_path_id" - " ORDER BY comm_id, thread_id, call_path_id") - - def FindPath(self, query): - # Turn the query result into a list of ids that the tree view can walk - # to open the tree at the right place. - ids = [] - parent_id = query.value(0) - while parent_id: - ids.insert(0, parent_id) - q2 = QSqlQuery(self.glb.db) - QueryExec(q2, "SELECT parent_id" - " FROM call_paths" - " WHERE id = " + str(parent_id)) - if not q2.next(): - break - parent_id = q2.value(0) - # The call path root is not used - if ids[0] == 1: - del ids[0] - ids.insert(0, query.value(2)) - ids.insert(0, query.value(1)) - return ids + self.DoFindSelect(query, match) def Found(self, query, found): if found: @@ -678,6 +637,57 @@ class CallGraphModel(TreeModel): def FindDone(self, thread, callback, ids): callback(ids) +# Context-sensitive call graph data model + +class CallGraphModel(CallGraphModelBase): + + def __init__(self, glb, parent=None): + super(CallGraphModel, self).__init__(glb, parent) + + def GetRoot(self): + return CallGraphRootItem(self.glb) + + def columnCount(self, parent=None): + return 7 + + def columnHeader(self, column): + headers = ["Call Path", "Object", "Count ", "Time (ns) ", "Time (%) ", "Branch Count ", "Branch Count (%) "] + return headers[column] + + def columnAlignment(self, column): + alignment = [ Qt.AlignLeft, Qt.AlignLeft, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight ] + return alignment[column] + + def DoFindSelect(self, query, match): + QueryExec(query, "SELECT call_path_id, comm_id, thread_id" + " FROM calls" + " INNER JOIN call_paths ON calls.call_path_id = call_paths.id" + " INNER JOIN symbols ON call_paths.symbol_id = symbols.id" + " WHERE symbols.name" + match + + " GROUP BY comm_id, thread_id, call_path_id" + " ORDER BY comm_id, thread_id, call_path_id") + + def FindPath(self, query): + # Turn the query result into a list of ids that the tree view can walk + # to open the tree at the right place. + ids = [] + parent_id = query.value(0) + while parent_id: + ids.insert(0, parent_id) + q2 = QSqlQuery(self.glb.db) + QueryExec(q2, "SELECT parent_id" + " FROM call_paths" + " WHERE id = " + str(parent_id)) + if not q2.next(): + break + parent_id = q2.value(0) + # The call path root is not used + if ids[0] == 1: + del ids[0] + ids.insert(0, query.value(2)) + ids.insert(0, query.value(1)) + return ids + # Vertical widget layout class VBox(): From ae8b887c00d3fe4ca8c2cba16ae452b5df4c19e2 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Thu, 28 Feb 2019 15:00:31 +0200 Subject: [PATCH 15/35] perf scripts python: exported-sql-viewer.py: Add call tree Add a new report to display a call tree. The Call Tree report is very similar to the Context-Sensitive Call Graph, but the data is not aggregated. Also the 'Count' column, which would be always 1, is replaced by the 'Call Time'. Committer testing: $ cat simple-retpoline.c /* https://lkml.kernel.org/r/20190109091835.5570-6-adrian.hunter@intel.com $ gcc -ggdb3 -Wall -Wextra -O2 -o simple-retpoline simple-retpoline.c $ objdump -d simple-retpoline */ __attribute__((noinline)) int bar(void) { return -1; } int foo(void) { return bar() + 1; } __attribute__((indirect_branch("thunk"))) int main() { int (*volatile fn)(void) = foo; fn(); return fn(); } $ $ perf record -o simple-retpoline.perf.data -e intel_pt/cyc/u ./simple-retpoline $ perf script -i simple-retpoline.perf.data --itrace=be -s ~acme/libexec/perf-core/scripts/python/export-to-sqlite.py simple-retpoline.db branches calls $ python ~acme/libexec/perf-core/scripts/python/exported-sql-viewer.py simple-retpoline.db And in the GUI select: "Reports" "Call Tree" Call Path | Object | Call Time (ns) | Time (ns) | Time (%) | Branch Count | Brach Count (%) | > simple-retpolin > PID:TID > _start ld-2.28.so 2193855505777 156267 100.0 10602 100.0 unknown unknown 2193855506010 2276 1.5 1 0.0 > _dl_start ld-2.28.so 2193855508286 137047 87.7 10088 95.2 > _dl_init ld-2.28.so 2193855645444 9142 5.9 326 3.1 > _start simple-retpoline 2193855654587 7457 4.8 182 1.7 > __libc_start_main > main simple-retpoline 2193855657493 32 0.5 12 6.7 > foo simple-retpoline 2193855657493 14 43.8 5 41.7 Signed-off-by: Adrian Hunter Tested-by: Arnaldo Carvalho de Melo Cc: Jiri Olsa Link: https://lkml.kernel.org/n/tip-enf0w96gqzfpv4fi16pw9ovc@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- .../scripts/python/exported-sql-viewer.py | 195 +++++++++++++++++- 1 file changed, 186 insertions(+), 9 deletions(-) diff --git a/tools/perf/scripts/python/exported-sql-viewer.py b/tools/perf/scripts/python/exported-sql-viewer.py index c4a2134d85f5..afec9479ca7f 100755 --- a/tools/perf/scripts/python/exported-sql-viewer.py +++ b/tools/perf/scripts/python/exported-sql-viewer.py @@ -688,6 +688,150 @@ class CallGraphModel(CallGraphModelBase): ids.insert(0, query.value(1)) return ids +# Call tree data model level 2+ item base + +class CallTreeLevelTwoPlusItemBase(CallGraphLevelItemBase): + + def __init__(self, glb, row, comm_id, thread_id, calls_id, time, branch_count, parent_item): + super(CallTreeLevelTwoPlusItemBase, self).__init__(glb, row, parent_item) + self.comm_id = comm_id + self.thread_id = thread_id + self.calls_id = calls_id + self.branch_count = branch_count + self.time = time + + def Select(self): + self.query_done = True; + if self.calls_id == 0: + comm_thread = " AND comm_id = " + str(self.comm_id) + " AND thread_id = " + str(self.thread_id) + else: + comm_thread = "" + query = QSqlQuery(self.glb.db) + QueryExec(query, "SELECT calls.id, name, short_name, call_time, return_time - call_time, branch_count" + " FROM calls" + " INNER JOIN call_paths ON calls.call_path_id = call_paths.id" + " INNER JOIN symbols ON call_paths.symbol_id = symbols.id" + " INNER JOIN dsos ON symbols.dso_id = dsos.id" + " WHERE calls.parent_id = " + str(self.calls_id) + comm_thread + + " ORDER BY call_time, calls.id") + while query.next(): + child_item = CallTreeLevelThreeItem(self.glb, self.child_count, self.comm_id, self.thread_id, query.value(0), query.value(1), query.value(2), query.value(3), int(query.value(4)), int(query.value(5)), self) + self.child_items.append(child_item) + self.child_count += 1 + +# Call tree data model level three item + +class CallTreeLevelThreeItem(CallTreeLevelTwoPlusItemBase): + + def __init__(self, glb, row, comm_id, thread_id, calls_id, name, dso, count, time, branch_count, parent_item): + super(CallTreeLevelThreeItem, self).__init__(glb, row, comm_id, thread_id, calls_id, time, branch_count, parent_item) + dso = dsoname(dso) + self.data = [ name, dso, str(count), str(time), PercentToOneDP(time, parent_item.time), str(branch_count), PercentToOneDP(branch_count, parent_item.branch_count) ] + self.dbid = calls_id + +# Call tree data model level two item + +class CallTreeLevelTwoItem(CallTreeLevelTwoPlusItemBase): + + def __init__(self, glb, row, comm_id, thread_id, pid, tid, parent_item): + super(CallTreeLevelTwoItem, self).__init__(glb, row, comm_id, thread_id, 0, 0, 0, parent_item) + self.data = [str(pid) + ":" + str(tid), "", "", "", "", "", ""] + self.dbid = thread_id + + def Select(self): + super(CallTreeLevelTwoItem, self).Select() + for child_item in self.child_items: + self.time += child_item.time + self.branch_count += child_item.branch_count + for child_item in self.child_items: + child_item.data[4] = PercentToOneDP(child_item.time, self.time) + child_item.data[6] = PercentToOneDP(child_item.branch_count, self.branch_count) + +# Call tree data model level one item + +class CallTreeLevelOneItem(CallGraphLevelItemBase): + + def __init__(self, glb, row, comm_id, comm, parent_item): + super(CallTreeLevelOneItem, self).__init__(glb, row, parent_item) + self.data = [comm, "", "", "", "", "", ""] + self.dbid = comm_id + + def Select(self): + self.query_done = True; + query = QSqlQuery(self.glb.db) + QueryExec(query, "SELECT thread_id, pid, tid" + " FROM comm_threads" + " INNER JOIN threads ON thread_id = threads.id" + " WHERE comm_id = " + str(self.dbid)) + while query.next(): + child_item = CallTreeLevelTwoItem(self.glb, self.child_count, self.dbid, query.value(0), query.value(1), query.value(2), self) + self.child_items.append(child_item) + self.child_count += 1 + +# Call tree data model root item + +class CallTreeRootItem(CallGraphLevelItemBase): + + def __init__(self, glb): + super(CallTreeRootItem, self).__init__(glb, 0, None) + self.dbid = 0 + self.query_done = True; + query = QSqlQuery(glb.db) + QueryExec(query, "SELECT id, comm FROM comms") + while query.next(): + if not query.value(0): + continue + child_item = CallTreeLevelOneItem(glb, self.child_count, query.value(0), query.value(1), self) + self.child_items.append(child_item) + self.child_count += 1 + +# Call Tree data model + +class CallTreeModel(CallGraphModelBase): + + def __init__(self, glb, parent=None): + super(CallTreeModel, self).__init__(glb, parent) + + def GetRoot(self): + return CallTreeRootItem(self.glb) + + def columnCount(self, parent=None): + return 7 + + def columnHeader(self, column): + headers = ["Call Path", "Object", "Call Time", "Time (ns) ", "Time (%) ", "Branch Count ", "Branch Count (%) "] + return headers[column] + + def columnAlignment(self, column): + alignment = [ Qt.AlignLeft, Qt.AlignLeft, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight, Qt.AlignRight ] + return alignment[column] + + def DoFindSelect(self, query, match): + QueryExec(query, "SELECT calls.id, comm_id, thread_id" + " FROM calls" + " INNER JOIN call_paths ON calls.call_path_id = call_paths.id" + " INNER JOIN symbols ON call_paths.symbol_id = symbols.id" + " WHERE symbols.name" + match + + " ORDER BY comm_id, thread_id, call_time, calls.id") + + def FindPath(self, query): + # Turn the query result into a list of ids that the tree view can walk + # to open the tree at the right place. + ids = [] + parent_id = query.value(0) + while parent_id: + ids.insert(0, parent_id) + q2 = QSqlQuery(self.glb.db) + QueryExec(q2, "SELECT parent_id" + " FROM calls" + " WHERE id = " + str(parent_id)) + if not q2.next(): + break + parent_id = q2.value(0) + ids.insert(0, query.value(2)) + ids.insert(0, query.value(1)) + return ids + # Vertical widget layout class VBox(): @@ -772,6 +916,29 @@ class CallGraphWindow(TreeWindowBase): AddSubWindow(glb.mainwindow.mdi_area, self, "Context-Sensitive Call Graph") +# Call tree window + +class CallTreeWindow(TreeWindowBase): + + def __init__(self, glb, parent=None): + super(CallTreeWindow, self).__init__(parent) + + self.model = LookupCreateModel("Call Tree", lambda x=glb: CallTreeModel(x)) + + self.view = QTreeView() + self.view.setModel(self.model) + + for c, w in ((0, 230), (1, 100), (2, 100), (3, 70), (4, 70), (5, 100)): + self.view.setColumnWidth(c, w) + + self.find_bar = FindBar(self, self) + + self.vbox = VBox(self.view, self.find_bar.Widget()) + + self.setWidget(self.vbox.Widget()) + + AddSubWindow(glb.mainwindow.mdi_area, self, "Call Tree") + # Child data item finder class ChildDataItemFinder(): @@ -1890,10 +2057,10 @@ def GetEventList(db): # Is a table selectable -def IsSelectable(db, table): +def IsSelectable(db, table, sql = ""): query = QSqlQuery(db) try: - QueryExec(query, "SELECT * FROM " + table + " LIMIT 1") + QueryExec(query, "SELECT * FROM " + table + " " + sql + " LIMIT 1") except: return False return True @@ -2302,9 +2469,10 @@ p.c2 {

1. Reports

1.1 Context-Sensitive Call Graph

-

1.2 All branches

-

1.3 Selected branches

-

1.4 Top calls by elapsed time

+

1.2 Call Tree

+

1.3 All branches

+

1.4 Selected branches

+

1.5 Top calls by elapsed time

2. Tables

1. Reports

1.1 Context-Sensitive Call Graph

@@ -2340,7 +2508,10 @@ v- ls

Find

Ctrl-F displays a Find bar which finds function names by either an exact match or a pattern match. The pattern matching symbols are ? for any character and * for zero or more characters. -

1.2 All branches

+

1.2 Call Tree

+The Call Tree report is very similar to the Context-Sensitive Call Graph, but the data is not aggregated. +Also the 'Count' column, which would be always 1, is replaced by the 'Call Time'. +

1.3 All branches

The All branches report displays all branches in chronological order. Not all data is fetched immediately. More records can be fetched using the Fetch bar provided.

Disassembly

@@ -2366,10 +2537,10 @@ sudo ldconfig Ctrl-F displays a Find bar which finds substrings by either an exact match or a regular expression match. Refer to Python documentation for the regular expression syntax. All columns are searched, but only currently fetched rows are searched. -

1.3 Selected branches

+

1.4 Selected branches

This is the same as the All branches report but with the data reduced by various selection criteria. A dialog box displays available criteria which are AND'ed together. -

1.3.1 Time ranges

+

1.4.1 Time ranges

The time ranges hint text shows the total time range. Relative time ranges can also be entered in ms, us or ns. Also, negative values are relative to the end of trace. Examples: 
@@ -2380,7 +2551,7 @@ ms, us or ns. Also, negative values are relative to the end of trace.  Examples:
 	-10ms-			The last 10ms
N.B. Due to the granularity of timestamps, there could be no branches in any given time range. -

1.4 Top calls by elapsed time

+

1.5 Top calls by elapsed time

The Top calls by elapsed time report displays calls in descending order of time elapsed between when the function was called and when it returned. The data is reduced by various selection criteria. A dialog box displays available criteria which are AND'ed together. If not all data is fetched, a Fetch bar is provided. Ctrl-F displays a Find bar. @@ -2516,6 +2687,9 @@ class MainWindow(QMainWindow): if IsSelectable(glb.db, "calls"): reports_menu.addAction(CreateAction("Context-Sensitive Call &Graph", "Create a new window containing a context-sensitive call graph", self.NewCallGraph, self)) + if IsSelectable(glb.db, "calls", "WHERE parent_id >= 0"): + reports_menu.addAction(CreateAction("Call &Tree", "Create a new window containing a call tree", self.NewCallTree, self)) + self.EventMenu(GetEventList(glb.db), reports_menu) if IsSelectable(glb.db, "calls"): @@ -2576,6 +2750,9 @@ class MainWindow(QMainWindow): def NewCallGraph(self): CallGraphWindow(self.glb, self) + def NewCallTree(self): + CallTreeWindow(self.glb, self) + def NewTopCalls(self): dialog = TopCallsDialog(self.glb, self) ret = dialog.exec_() From c3b81a500f35241a4c16febe0a015e572cf2c492 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Fri, 1 Mar 2019 15:45:35 -0300 Subject: [PATCH 16/35] perf beauty msg_flags: Add missing %s lost when adding prefix suppression logic MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When the prefix suppresion/enabling logic was added, I forgot to add an extra %, which ended up chopping off the strings: Before: # perf trace -e *mmsg --map-dump syscalls [299] = 1, [307] = 1, DNS Res~ver #3/14587 sendmmsg(106, 0x7f252b0fcaf0, 2, MSG_) = 2 chronyd/1053 recvmmsg(4, 0x558542ca5740, 4, MSG_, NULL) = 1 DNS Res~ver #2/14445 sendmmsg(106, 0x7f252ab09af0, 2, MSG_) = 2 DNS Res~ver #2/14444 sendmmsg(146, 0x7f2521a7aaf0, 2, MSG_) = 2 DNS Res~ver #2/14445 sendmmsg(106, 0x7f252ab09af0, 2, MSG_) = 2 DNS Res~ver #3/14587 sendmmsg(148, 0x7f252b0fcaf0, 2, MSG_) = 2 DNS Res~ver #2/14444 sendmmsg(146, 0x7f2521a7aaf0, 2, MSG_) = 2 ^C# After: # perf trace -e *mmsg --map-dump syscalls [299] = 1, [307] = 1, NetworkManager/17467 sendmmsg(22, 0x7f28927f9bb0, 2, MSG_NOSIGNAL) = 2 pool/17478 sendmmsg(10, 0x7f2769f95e90, 2, MSG_NOSIGNAL) = 2 DNS Res~ver #3/14587 sendmmsg(121, 0x7f252b0fcaf0, 2, MSG_NOSIGNAL) = 2 chronyd/1053 recvmmsg(4, 0x558542ca5740, 4, MSG_DONTWAIT, NULL) = 1 Socket Thread/17433 sendmmsg(121, 0x7f252668baf0, 2, MSG_NOSIGNAL) = 2 ^C# Cc: Adrian Hunter Cc: Jiri Olsa Cc: Luis Cláudio Gonçalves Cc: Namhyung Kim Cc: Wang Nan Fixes: c65c83ffe904 ("perf trace: Allow asking for not suppressing common string prefixes") Link: https://lkml.kernel.org/n/tip-t2eu1rqx710k6jr4814mlzg7@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/trace/beauty/msg_flags.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/perf/trace/beauty/msg_flags.c b/tools/perf/trace/beauty/msg_flags.c index d66c66315987..ea68db08b8e7 100644 --- a/tools/perf/trace/beauty/msg_flags.c +++ b/tools/perf/trace/beauty/msg_flags.c @@ -29,7 +29,7 @@ static size_t syscall_arg__scnprintf_msg_flags(char *bf, size_t size, return scnprintf(bf, size, "NONE"); #define P_MSG_FLAG(n) \ if (flags & MSG_##n) { \ - printed += scnprintf(bf + printed, size - printed, "%s%s", printed ? "|" : "", show_prefix ? prefix : "", #n); \ + printed += scnprintf(bf + printed, size - printed, "%s%s%s", printed ? "|" : "", show_prefix ? prefix : "", #n); \ flags &= ~MSG_##n; \ } From 3163613c5bc805dadac8ea157648eefd46747cae Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Fri, 1 Mar 2019 16:09:31 -0300 Subject: [PATCH 17/35] perf bpf: Automatically add BTF ELF markers MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The libbpf loader expects that some __btf_map_ structs be in place with the keys and values types of maps so that one can store the struct definitions and have them sent to the kernel via sys_bpf(fd, cmd = BTF_LOAD) and then later be retrievable via sys_bpf(fd, cmd = BPF_OBJ_GET_INFO_BY_FD) for use by tools such as 'bpftool map dump id MAP_ID'. Since we already have this for defining maps in 'perf trace' BPF events: bpf_map(name, _type, type_key, type_val, _max_entries) As used in the tools/perf/examples/bpf/augmented_raw_syscalls.c: --- 8< --- struct syscall { bool enabled; }; bpf_map(syscalls, ARRAY, int, struct syscall, 512); --- 8< --- All we need is to get all that already available info, piggyback on the 'bpf_map' define in tools/perf/include/bpf/bpf.h, that is included by 'perf trace' BPF programs and do that without requiring changes to the BPF programs already defining maps using 'bpf_map()'. So this is what we have before this patch: 1) With this in ~/.perfconfig to dump .c events as .o, aka save a copy so that we can use the .o later as a pre-compiled BPF bytecode: # grep '\[llvm\]' -A2 ~/.perfconfig [llvm] dump-obj = true clang-opt = -g # # clang --version clang version 9.0.0 (https://git.llvm.org/git/clang.git/ 7906282d3afec5dfdc2b27943fd6c0309086c507) (https://git.llvm.org/git/llvm.git/ a1b5de1ff8ae8bc79dc8e86e1f82565229bd0500) Target: x86_64-unknown-linux-gnu Thread model: posix InstalledDir: /opt/llvm/bin 2) Note the -g there so that we get clang to generate debuginfo, and since the target is 'bpf' it will generate the BTF info in this clang version (9.0). 3) Run a simple 'perf record' specifiying as an event the augmented_raw_syscalls.c source code: # perf record -e /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c sleep 1 LLVM: dumping /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.025 MB perf.data ] # file /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o: ELF 64-bit LSB relocatable, eBPF, version 1 (SYSV), with debug_info, not stripped 4) Look at the BTF structs encoded in it: # pahole -F btf --sizes /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o syscall_enter_args 64 0 augmented_filename 264 0 syscall 1 0 syscall_exit_args 24 0 bpf_map 28 0 # # pahole -F btf -C syscalls /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o # pahole -F btf -C syscall /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o struct syscall { bool enabled; /* 0 1 */ /* size: 1, cachelines: 1, members: 1 */ /* last cacheline: 1 bytes */ }; # 5) Ok, with just this we don't have the markers expected by the libbpf loader and when we run with this BPF bytecode, because we have: # grep '\[trace\]' -A1 ~/.perfconfig [trace] add_events = /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o # 6) Lets do a 'perf trace' system wide session using this BPF program: # perf trace -e *mmsg,open* Cache2 I/O/6885 openat(AT_FDCWD, "/home/acme/.cache/mozilla/firefox/ina67tev.default/cache2/entries/BA220AB2914006A7AE96D27BE6EA13DD77519FCA", O_RDWR|O_CREAT|O_TRUNC, S_IRUSR|S_IWUSR) = 106 Cache2 I/O/6885 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY) = 121 Cache2 I/O/6885 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY) = 121 Cache2 I/O/6885 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY) = 121 Cache2 I/O/6885 openat(AT_FDCWD, "/proc/self/mountinfo", O_RDONLY) = 121 DNS Res~ver #3/23340 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 106 DNS Res~ver #3/23340 sendmmsg(106, 0x7f252f1fcaf0, 2, MSG_NOSIGNAL) = 2 Cache2 I/O/6885 openat(AT_FDCWD, "/home/acme/.cache/mozilla/firefox/ina67tev.default/cache2/entries/BA220AB2914006A7AE96D27BE6EA13DD77519FCA", O_RDWR) = 106 lighttpd/18915 openat(AT_FDCWD, "/proc/loadavg", O_RDONLY) = 12 7) While it runs lets see the maps that 'perf trace' + libbpf's BPF loader loaded into the kernel via sys_bpf(fd, BPF_BTF_LOAD, ...): # bpftool map list | tail -6 149: perf_event_array name __augmented_sys flags 0x0 key 4B value 4B max_entries 8 memlock 4096B 150: array name syscalls flags 0x0 key 4B value 1B max_entries 512 memlock 8192B 151: hash name pids_filtered flags 0x0 key 4B value 1B max_entries 64 memlock 8192B # 8) Dump the "pids_filtered", map, that will have one entry per PID that 'perf trace' wants filtered, which includes its own, to avoid a tracing feedback loop (perf trace shows the syscalls it does which generates more syscalls that it has to show that...), it also auto-filters the 'gnome-terminal' and 'sshd' parent PIDs, for the same reason: # bpftool map dump id 151 key: a5 0c 00 00 value: 01 key: 14 63 00 00 value: 01 Found 2 elements # 9) Since there is no BTF info available, it does a generic hex dump :-\ 10) Now, with this patch applied, we'll do steps 3 to 6 again and look with pahole if there are extra structs encoded in BTF: # pahole -F btf --sizes /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o syscall_enter_args 64 0 augmented_filename 264 0 syscall 1 0 syscall_exit_args 24 0 bpf_map 28 0 ____btf_map___augmented_syscalls__ 8 0 ____btf_map_syscalls 8 0 ____btf_map_pids_filtered 8 0 # 11) Yes, those __btf_map_ + the map names, lets see how they look like: # pahole -F btf -C ____btf_map_syscalls /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o struct ____btf_map_syscalls { int key; /* 0 4 */ struct syscall value; /* 4 1 */ /* size: 8, cachelines: 1, members: 2 */ /* padding: 3 */ /* last cacheline: 8 bytes */ }; # 12) Lets repeat step 7 to get the new map ids: # bpftool map list | tail -6 155: perf_event_array name __augmented_sys flags 0x0 key 4B value 4B max_entries 8 memlock 4096B 156: array name syscalls flags 0x0 key 4B value 1B max_entries 512 memlock 8192B 157: hash name pids_filtered flags 0x0 key 4B value 1B max_entries 64 memlock 8192B # 13) And finally lets dump the 'pids_filtered': # bpftool map dump id 157 [{ "key": 3237, "value": true },{ "key": 26435, "value": true } ] # Looks much better! BTF info was used to interpret the key as an integer and the value as a struct with just one boolean member, so to make it more compact, show just the 'true' value where we saw '01'. Now to make 'perf trace --dump-map' to use BTF! Cc: Adrian Hunter Cc: Alexei Starovoitov Cc: Andrii Nakryiko Cc: Daniel Borkmann Cc: Jiri Olsa Cc: Luis Cláudio Gonçalves Cc: Martin KaFai Lau Cc: Namhyung Kim Cc: Song Liu Cc: Wang Nan Cc: Yonghong Song Link: https://lkml.kernel.org/n/tip-ybuf9wpkm30xk28iq7jbwb40@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/include/bpf/bpf.h | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/tools/perf/include/bpf/bpf.h b/tools/perf/include/bpf/bpf.h index 5df7ed9d9020..2eac6d804b2d 100644 --- a/tools/perf/include/bpf/bpf.h +++ b/tools/perf/include/bpf/bpf.h @@ -24,7 +24,13 @@ struct bpf_map SEC("maps") name = { \ .key_size = sizeof(type_key), \ .value_size = sizeof(type_val), \ .max_entries = _max_entries, \ -} +}; \ +struct ____btf_map_##name { \ + type_key key; \ + type_val value; \ +}; \ +struct ____btf_map_##name __attribute__((section(".maps." #name), used)) \ + ____btf_map_##name = { } /* * FIXME: this should receive .max_entries as a parameter, as careful From a53837a5458c5b84588dfa3fa510c6a29b7bd4d7 Mon Sep 17 00:00:00 2001 From: Yang Wei Date: Mon, 4 Mar 2019 22:36:14 +0800 Subject: [PATCH 18/35] perf clang: Remove needless extra semicolon Delete a superfluous semicolon in getBPFObjectFromModule(). Signed-off-by: Yang Wei Cc: Alexander Shishkin Cc: Jiri Olsa Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Yang Wei Link: http://lkml.kernel.org/r/1551710174-3349-1-git-send-email-albin_yang@163.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/c++/clang.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/perf/util/c++/clang.cpp b/tools/perf/util/c++/clang.cpp index 39c0004f2886..fc361c3f8570 100644 --- a/tools/perf/util/c++/clang.cpp +++ b/tools/perf/util/c++/clang.cpp @@ -156,7 +156,7 @@ getBPFObjectFromModule(llvm::Module *Module) #endif if (NotAdded) { llvm::errs() << "TargetMachine can't emit a file of this type\n"; - return std::unique_ptr>(nullptr);; + return std::unique_ptr>(nullptr); } PM.run(*Module); From bc3bb795345891509b4a3cbff824cbef8c130f20 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Wed, 6 Mar 2019 16:40:15 -0300 Subject: [PATCH 19/35] perf annotate: Calculate the max instruction name, align column to that MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit We were hardcoding '6' as the max instruction name, and we have lots that are longer than that, see the diff from two 'P' printed TUI annotations for a libc function that uses instructions with long names, such as 'vpmovmskb' with its 9 chars: --- __strcmp_avx2.annotation.before 2019-03-06 16:31:39.368020425 -0300 +++ __strcmp_avx2.annotation 2019-03-06 16:32:12.079450508 -0300 @@ -2,284 +2,284 @@ Event: cycles:ppp Percent endbr64 - 0.10 mov %edi,%eax + 0.10 mov %edi,%eax - xor %edx,%edx + xor %edx,%edx - 3.54 vpxor %ymm7,%ymm7,%ymm7 + 3.54 vpxor %ymm7,%ymm7,%ymm7 - or %esi,%eax + or %esi,%eax - and $0xfff,%eax + and $0xfff,%eax - cmp $0xf80,%eax + cmp $0xf80,%eax - ↓ jg 370 + ↓ jg 370 - 27.07 vmovdqu (%rdi),%ymm1 + 27.07 vmovdqu (%rdi),%ymm1 - 7.97 vpcmpeqb (%rsi),%ymm1,%ymm0 + 7.97 vpcmpeqb (%rsi),%ymm1,%ymm0 - 2.15 vpminub %ymm1,%ymm0,%ymm0 + 2.15 vpminub %ymm1,%ymm0,%ymm0 - 4.09 vpcmpeqb %ymm7,%ymm0,%ymm0 + 4.09 vpcmpeqb %ymm7,%ymm0,%ymm0 - 0.43 vpmovmskb %ymm0,%ecx + 0.43 vpmovmskb %ymm0,%ecx - 1.53 test %ecx,%ecx + 1.53 test %ecx,%ecx - ↓ je b0 + ↓ je b0 - 5.26 tzcnt %ecx,%edx + 5.26 tzcnt %ecx,%edx - 18.40 movzbl (%rdi,%rdx,1),%eax + 18.40 movzbl (%rdi,%rdx,1),%eax - 7.09 movzbl (%rsi,%rdx,1),%edx + 7.09 movzbl (%rsi,%rdx,1),%edx - 3.34 sub %edx,%eax + 3.34 sub %edx,%eax 2.37 vzeroupper ← retq nop - 50: tzcnt %ecx,%edx + 50: tzcnt %ecx,%edx - movzbl 0x20(%rdi,%rdx,1),%eax + movzbl 0x20(%rdi,%rdx,1),%eax - movzbl 0x20(%rsi,%rdx,1),%edx + movzbl 0x20(%rsi,%rdx,1),%edx - sub %edx,%eax + sub %edx,%eax vzeroupper ← retq - data16 nopw %cs:0x0(%rax,%rax,1) + data16 nopw %cs:0x0(%rax,%rax,1) Reported-by: Travis Downs LPU-Reference: CAOBGo4z1KfmWeOm6Et0cnX5Z6DWsG2PQbAvRn1MhVPJmXHrc5g@mail.gmail.com Cc: Adrian Hunter Cc: Jiri Olsa Cc: Namhyung Kim Link: https://lkml.kernel.org/n/tip-89wsdd9h9g6bvq52sgp6d0u4@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/arch/arm64/annotate/instructions.c | 2 +- tools/perf/arch/s390/annotate/instructions.c | 2 +- tools/perf/util/annotate.c | 74 ++++++++++++------- tools/perf/util/annotate.h | 7 +- 4 files changed, 52 insertions(+), 33 deletions(-) diff --git a/tools/perf/arch/arm64/annotate/instructions.c b/tools/perf/arch/arm64/annotate/instructions.c index 76c6345a57d5..8f70a1b282df 100644 --- a/tools/perf/arch/arm64/annotate/instructions.c +++ b/tools/perf/arch/arm64/annotate/instructions.c @@ -58,7 +58,7 @@ out_free_source: } static int mov__scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops); + struct ins_operands *ops, int max_ins_name); static struct ins_ops arm64_mov_ops = { .parse = arm64_mov__parse, diff --git a/tools/perf/arch/s390/annotate/instructions.c b/tools/perf/arch/s390/annotate/instructions.c index de0dd66dbb48..89bb8f2c54ce 100644 --- a/tools/perf/arch/s390/annotate/instructions.c +++ b/tools/perf/arch/s390/annotate/instructions.c @@ -46,7 +46,7 @@ static int s390_call__parse(struct arch *arch, struct ins_operands *ops, } static int call__scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops); + struct ins_operands *ops, int max_ins_name); static struct ins_ops s390_call_ops = { .parse = s390_call__parse, diff --git a/tools/perf/util/annotate.c b/tools/perf/util/annotate.c index 11a8a447a3af..5f6dbbf5d749 100644 --- a/tools/perf/util/annotate.c +++ b/tools/perf/util/annotate.c @@ -198,18 +198,18 @@ static void ins__delete(struct ins_operands *ops) } static int ins__raw_scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops) + struct ins_operands *ops, int max_ins_name) { - return scnprintf(bf, size, "%-6s %s", ins->name, ops->raw); + return scnprintf(bf, size, "%-*s %s", max_ins_name, ins->name, ops->raw); } int ins__scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops) + struct ins_operands *ops, int max_ins_name) { if (ins->ops->scnprintf) - return ins->ops->scnprintf(ins, bf, size, ops); + return ins->ops->scnprintf(ins, bf, size, ops, max_ins_name); - return ins__raw_scnprintf(ins, bf, size, ops); + return ins__raw_scnprintf(ins, bf, size, ops, max_ins_name); } bool ins__is_fused(struct arch *arch, const char *ins1, const char *ins2) @@ -273,18 +273,18 @@ indirect_call: } static int call__scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops) + struct ins_operands *ops, int max_ins_name) { if (ops->target.sym) - return scnprintf(bf, size, "%-6s %s", ins->name, ops->target.sym->name); + return scnprintf(bf, size, "%-*s %s", max_ins_name, ins->name, ops->target.sym->name); if (ops->target.addr == 0) - return ins__raw_scnprintf(ins, bf, size, ops); + return ins__raw_scnprintf(ins, bf, size, ops, max_ins_name); if (ops->target.name) - return scnprintf(bf, size, "%-6s %s", ins->name, ops->target.name); + return scnprintf(bf, size, "%-*s %s", max_ins_name, ins->name, ops->target.name); - return scnprintf(bf, size, "%-6s *%" PRIx64, ins->name, ops->target.addr); + return scnprintf(bf, size, "%-*s *%" PRIx64, max_ins_name, ins->name, ops->target.addr); } static struct ins_ops call_ops = { @@ -388,15 +388,15 @@ static int jump__parse(struct arch *arch, struct ins_operands *ops, struct map_s } static int jump__scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops) + struct ins_operands *ops, int max_ins_name) { const char *c; if (!ops->target.addr || ops->target.offset < 0) - return ins__raw_scnprintf(ins, bf, size, ops); + return ins__raw_scnprintf(ins, bf, size, ops, max_ins_name); if (ops->target.outside && ops->target.sym != NULL) - return scnprintf(bf, size, "%-6s %s", ins->name, ops->target.sym->name); + return scnprintf(bf, size, "%-*s %s", max_ins_name, ins->name, ops->target.sym->name); c = strchr(ops->raw, ','); c = validate_comma(c, ops); @@ -415,7 +415,7 @@ static int jump__scnprintf(struct ins *ins, char *bf, size_t size, c++; } - return scnprintf(bf, size, "%-6s %.*s%" PRIx64, + return scnprintf(bf, size, "%-*s %.*s%" PRIx64, max_ins_name, ins->name, c ? c - ops->raw : 0, ops->raw, ops->target.offset); } @@ -483,16 +483,16 @@ out_free_ops: } static int lock__scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops) + struct ins_operands *ops, int max_ins_name) { int printed; if (ops->locked.ins.ops == NULL) - return ins__raw_scnprintf(ins, bf, size, ops); + return ins__raw_scnprintf(ins, bf, size, ops, max_ins_name); - printed = scnprintf(bf, size, "%-6s ", ins->name); + printed = scnprintf(bf, size, "%-*s ", max_ins_name, ins->name); return printed + ins__scnprintf(&ops->locked.ins, bf + printed, - size - printed, ops->locked.ops); + size - printed, ops->locked.ops, max_ins_name); } static void lock__delete(struct ins_operands *ops) @@ -564,9 +564,9 @@ out_free_source: } static int mov__scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops) + struct ins_operands *ops, int max_ins_name) { - return scnprintf(bf, size, "%-6s %s,%s", ins->name, + return scnprintf(bf, size, "%-*s %s,%s", max_ins_name, ins->name, ops->source.name ?: ops->source.raw, ops->target.name ?: ops->target.raw); } @@ -604,9 +604,9 @@ static int dec__parse(struct arch *arch __maybe_unused, struct ins_operands *ops } static int dec__scnprintf(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops) + struct ins_operands *ops, int max_ins_name) { - return scnprintf(bf, size, "%-6s %s", ins->name, + return scnprintf(bf, size, "%-*s %s", max_ins_name, ins->name, ops->target.name ?: ops->target.raw); } @@ -616,9 +616,9 @@ static struct ins_ops dec_ops = { }; static int nop__scnprintf(struct ins *ins __maybe_unused, char *bf, size_t size, - struct ins_operands *ops __maybe_unused) + struct ins_operands *ops __maybe_unused, int max_ins_name) { - return scnprintf(bf, size, "%-6s", "nop"); + return scnprintf(bf, size, "%-*s", max_ins_name, "nop"); } static struct ins_ops nop_ops = { @@ -1232,12 +1232,12 @@ void disasm_line__free(struct disasm_line *dl) annotation_line__delete(&dl->al); } -int disasm_line__scnprintf(struct disasm_line *dl, char *bf, size_t size, bool raw) +int disasm_line__scnprintf(struct disasm_line *dl, char *bf, size_t size, bool raw, int max_ins_name) { if (raw || !dl->ins.ops) - return scnprintf(bf, size, "%-6s %s", dl->ins.name, dl->ops.raw); + return scnprintf(bf, size, "%-*s %s", max_ins_name, dl->ins.name, dl->ops.raw); - return ins__scnprintf(&dl->ins, bf, size, &dl->ops); + return ins__scnprintf(&dl->ins, bf, size, &dl->ops, max_ins_name); } static void annotation_line__add(struct annotation_line *al, struct list_head *head) @@ -2414,12 +2414,30 @@ static inline int width_jumps(int n) return 1; } +static int annotation__max_ins_name(struct annotation *notes) +{ + int max_name = 0, len; + struct annotation_line *al; + + list_for_each_entry(al, ¬es->src->source, node) { + if (al->offset == -1) + continue; + + len = strlen(disasm_line(al)->ins.name); + if (max_name < len) + max_name = len; + } + + return max_name; +} + void annotation__init_column_widths(struct annotation *notes, struct symbol *sym) { notes->widths.addr = notes->widths.target = notes->widths.min_addr = hex_width(symbol__size(sym)); notes->widths.max_addr = hex_width(sym->end); notes->widths.jumps = width_jumps(notes->max_jump_sources); + notes->widths.max_ins_name = annotation__max_ins_name(notes); } void annotation__update_column_widths(struct annotation *notes) @@ -2583,7 +2601,7 @@ call_like: obj__printf(obj, " "); } - disasm_line__scnprintf(dl, bf, size, !notes->options->use_offset); + disasm_line__scnprintf(dl, bf, size, !notes->options->use_offset, notes->widths.max_ins_name); } static void ipc_coverage_string(char *bf, int size, struct annotation *notes) diff --git a/tools/perf/util/annotate.h b/tools/perf/util/annotate.h index 95053cab41fe..df34fe483164 100644 --- a/tools/perf/util/annotate.h +++ b/tools/perf/util/annotate.h @@ -59,14 +59,14 @@ struct ins_ops { void (*free)(struct ins_operands *ops); int (*parse)(struct arch *arch, struct ins_operands *ops, struct map_symbol *ms); int (*scnprintf)(struct ins *ins, char *bf, size_t size, - struct ins_operands *ops); + struct ins_operands *ops, int max_ins_name); }; bool ins__is_jump(const struct ins *ins); bool ins__is_call(const struct ins *ins); bool ins__is_ret(const struct ins *ins); bool ins__is_lock(const struct ins *ins); -int ins__scnprintf(struct ins *ins, char *bf, size_t size, struct ins_operands *ops); +int ins__scnprintf(struct ins *ins, char *bf, size_t size, struct ins_operands *ops, int max_ins_name); bool ins__is_fused(struct arch *arch, const char *ins1, const char *ins2); #define ANNOTATION__IPC_WIDTH 6 @@ -219,7 +219,7 @@ int __annotation__scnprintf_samples_period(struct annotation *notes, struct perf_evsel *evsel, bool show_freq); -int disasm_line__scnprintf(struct disasm_line *dl, char *bf, size_t size, bool raw); +int disasm_line__scnprintf(struct disasm_line *dl, char *bf, size_t size, bool raw, int max_ins_name); size_t disasm__fprintf(struct list_head *head, FILE *fp); void symbol__calc_percent(struct symbol *sym, struct perf_evsel *evsel); @@ -289,6 +289,7 @@ struct annotation { u8 target; u8 min_addr; u8 max_addr; + u8 max_ins_name; } widths; bool have_cycles; struct annotated_source *src; From 153259382633ecbbc0af4f3f0b6515757ebe2984 Mon Sep 17 00:00:00 2001 From: Andi Kleen Date: Wed, 6 Mar 2019 17:55:35 -0300 Subject: [PATCH 20/35] perf thread: Generalize function to copy from thread addr space from intel-bts code Add a utility function to fetch executable code. Convert one user over to it. There are more places doing that, but they do significantly different actions, so they are not easy to fit into a single library function. Committer changes: . No need to cast around, make 'buf' be a void pointer. . Rename it to thread__memcpy() to reflect the fact it is about copying a chunk of memory from a thread, i.e. from its address space. . No need to have it in a separate object file, move it to thread.[ch] . Check the return of map__load(), the original code didn't do it, but since we're moving this around, check that as well. Signed-off-by: Andi Kleen Cc: Jiri Olsa Cc: Namhyung Kim Link: https://lkml.kernel.org/r/20190305144758.12397-2-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/intel-bts.c | 20 ++------------------ tools/perf/util/thread.c | 23 +++++++++++++++++++++++ tools/perf/util/thread.h | 3 +++ 3 files changed, 28 insertions(+), 18 deletions(-) diff --git a/tools/perf/util/intel-bts.c b/tools/perf/util/intel-bts.c index 0c0180c67574..47025bc727e1 100644 --- a/tools/perf/util/intel-bts.c +++ b/tools/perf/util/intel-bts.c @@ -328,35 +328,19 @@ static int intel_bts_get_next_insn(struct intel_bts_queue *btsq, u64 ip) { struct machine *machine = btsq->bts->machine; struct thread *thread; - struct addr_location al; unsigned char buf[INTEL_PT_INSN_BUF_SZ]; ssize_t len; - int x86_64; - uint8_t cpumode; + bool x86_64; int err = -1; - if (machine__kernel_ip(machine, ip)) - cpumode = PERF_RECORD_MISC_KERNEL; - else - cpumode = PERF_RECORD_MISC_USER; - thread = machine__find_thread(machine, -1, btsq->tid); if (!thread) return -1; - if (!thread__find_map(thread, cpumode, ip, &al) || !al.map->dso) - goto out_put; - - len = dso__data_read_addr(al.map->dso, al.map, machine, ip, buf, - INTEL_PT_INSN_BUF_SZ); + len = thread__memcpy(thread, machine, buf, ip, INTEL_PT_INSN_BUF_SZ, &x86_64); if (len <= 0) goto out_put; - /* Load maps to ensure dso->is_64_bit has been updated */ - map__load(al.map); - - x86_64 = al.map->dso->is_64_bit; - if (intel_pt_get_insn(buf, len, x86_64, &btsq->intel_pt_insn)) goto out_put; diff --git a/tools/perf/util/thread.c b/tools/perf/util/thread.c index 4c179fef442d..50678d318185 100644 --- a/tools/perf/util/thread.c +++ b/tools/perf/util/thread.c @@ -12,6 +12,7 @@ #include "debug.h" #include "namespaces.h" #include "comm.h" +#include "map.h" #include "symbol.h" #include "unwind.h" @@ -393,3 +394,25 @@ struct thread *thread__main_thread(struct machine *machine, struct thread *threa return machine__find_thread(machine, thread->pid_, thread->pid_); } + +int thread__memcpy(struct thread *thread, struct machine *machine, + void *buf, u64 ip, int len, bool *is64bit) +{ + u8 cpumode = PERF_RECORD_MISC_USER; + struct addr_location al; + long offset; + + if (machine__kernel_ip(machine, ip)) + cpumode = PERF_RECORD_MISC_KERNEL; + + if (!thread__find_map(thread, cpumode, ip, &al) || !al.map->dso || + al.map->dso->data.status == DSO_DATA_STATUS_ERROR || + map__load(al.map) < 0) + return -1; + + offset = al.map->map_ip(al.map, ip); + if (is64bit) + *is64bit = al.map->dso->is_64_bit; + + return dso__data_read_offset(al.map->dso, machine, offset, buf, len); +} diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h index 8276ffeec556..cf8375c017a0 100644 --- a/tools/perf/util/thread.h +++ b/tools/perf/util/thread.h @@ -113,6 +113,9 @@ struct symbol *thread__find_symbol_fb(struct thread *thread, u8 cpumode, void thread__find_cpumode_addr_location(struct thread *thread, u64 addr, struct addr_location *al); +int thread__memcpy(struct thread *thread, struct machine *machine, + void *buf, u64 ip, int len, bool *is64bit); + static inline void *thread__priv(struct thread *thread) { return thread->priv; From 4802138d78caed36cee2a859f77fb2035f230018 Mon Sep 17 00:00:00 2001 From: Jin Yao Date: Tue, 5 Mar 2019 21:05:41 +0800 Subject: [PATCH 21/35] perf diff: Support --time filter option To improve 'perf diff', implement a --time filter option to diff the samples within given time window. It supports time percent with multiple time ranges. The time string format is 'a%/n,b%/m,...' or 'a%-b%,c%-%d,...'. For example: Select the second 10% time slice to diff: perf diff --time 10%/2 Select from 0% to 10% time slice to diff: perf diff --time 0%-10% Select the first and the second 10% time slices to diff: perf diff --time 10%/1,10%/2 Select from 0% to 10% and 30% to 40% slices to diff: perf diff --time 0%-10%,30%-40% It also supports analysing samples within a given time window ,. 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 the stop time is not given (i.e, time string is 'x.y,') then analysis goes to end of file. Time string is 'a1.b1,c1.d1:a2.b2,c2.d2'. Use ':' to separate timestamps for different perf.data files. For example, we get the timestamp information from perf script. perf script -i perf.data.old mgen 13940 [000] 3946.361400: ... perf script -i perf.data mgen 13940 [000] 3971.150589 ... perf diff --time 3946.361400,:3971.150589, It analyzes the perf.data.old from the timestamp 3946.361400 to the end of perf.data.old and analyzes the perf.data from the timestamp 3971.150589 to the end of perf.data. v4: --- Update abstime_str_dup(), let it return error if strdup is failed, and update __cmd_diff() accordingly. Signed-off-by: Jin Yao Acked-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jin Yao Cc: Kan Liang Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/1551791143-10334-2-git-send-email-yao.jin@linux.intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-diff.txt | 45 ++++++++ tools/perf/builtin-diff.c | 148 ++++++++++++++++++++++--- 2 files changed, 179 insertions(+), 14 deletions(-) diff --git a/tools/perf/Documentation/perf-diff.txt b/tools/perf/Documentation/perf-diff.txt index a79c84ae61aa..036d65bded51 100644 --- a/tools/perf/Documentation/perf-diff.txt +++ b/tools/perf/Documentation/perf-diff.txt @@ -118,6 +118,51 @@ OPTIONS sum of shown entries will be always 100%. "absolute" means it retains the original value before and after the filter is applied. +--time:: + Analyze samples within given time window. It supports time + percent with multiple time ranges. Time string is 'a%/n,b%/m,...' + or 'a%-b%,c%-%d,...'. + + For example: + + Select the second 10% time slice to diff: + + perf diff --time 10%/2 + + Select from 0% to 10% time slice to diff: + + perf diff --time 0%-10% + + Select the first and the second 10% time slices to diff: + + perf diff --time 10%/1,10%/2 + + Select from 0% to 10% and 30% to 40% slices to diff: + + perf diff --time 0%-10%,30%-40% + + It also supports analyzing samples within a given time window + ,. 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 the end of the file. Time string is + 'a1.b1,c1.d1:a2.b2,c2.d2'. Use ':' to separate timestamps for different + perf.data files. + + For example, we get the timestamp information from 'perf script'. + + perf script -i perf.data.old + mgen 13940 [000] 3946.361400: ... + + perf script -i perf.data + mgen 13940 [000] 3971.150589 ... + + perf diff --time 3946.361400,:3971.150589, + + It analyzes the perf.data.old from the timestamp 3946.361400 to + the end of perf.data.old and analyzes the perf.data from the + timestamp 3971.150589 to the end of perf.data. + COMPARISON ---------- The comparison is governed by the baseline file. The baseline perf.data diff --git a/tools/perf/builtin-diff.c b/tools/perf/builtin-diff.c index 58fe0e88215c..17cd898074c8 100644 --- a/tools/perf/builtin-diff.c +++ b/tools/perf/builtin-diff.c @@ -19,12 +19,21 @@ #include "util/util.h" #include "util/data.h" #include "util/config.h" +#include "util/time-utils.h" #include #include #include #include +struct perf_diff { + struct perf_tool tool; + const char *time_str; + struct perf_time_interval *ptime_range; + int range_size; + int range_num; +}; + /* Diff command specific HPP columns. */ enum { PERF_HPP_DIFF__BASELINE, @@ -323,16 +332,22 @@ static int formula_fprintf(struct hist_entry *he, struct hist_entry *pair, return -1; } -static int diff__process_sample_event(struct perf_tool *tool __maybe_unused, +static int diff__process_sample_event(struct perf_tool *tool, union perf_event *event, struct perf_sample *sample, struct perf_evsel *evsel, struct machine *machine) { + struct perf_diff *pdiff = container_of(tool, struct perf_diff, tool); struct addr_location al; struct hists *hists = evsel__hists(evsel); int ret = -1; + if (perf_time__ranges_skip_sample(pdiff->ptime_range, pdiff->range_num, + sample->time)) { + return 0; + } + if (machine__resolve(machine, &al, sample) < 0) { pr_warning("problem processing %d event, skipping it.\n", event->header.type); @@ -359,17 +374,19 @@ out_put: return ret; } -static struct perf_tool tool = { - .sample = diff__process_sample_event, - .mmap = perf_event__process_mmap, - .mmap2 = perf_event__process_mmap2, - .comm = perf_event__process_comm, - .exit = perf_event__process_exit, - .fork = perf_event__process_fork, - .lost = perf_event__process_lost, - .namespaces = perf_event__process_namespaces, - .ordered_events = true, - .ordering_requires_timestamps = true, +static struct perf_diff pdiff = { + .tool = { + .sample = diff__process_sample_event, + .mmap = perf_event__process_mmap, + .mmap2 = perf_event__process_mmap2, + .comm = perf_event__process_comm, + .exit = perf_event__process_exit, + .fork = perf_event__process_fork, + .lost = perf_event__process_lost, + .namespaces = perf_event__process_namespaces, + .ordered_events = true, + .ordering_requires_timestamps = true, + }, }; static struct perf_evsel *evsel_match(struct perf_evsel *evsel, @@ -771,19 +788,110 @@ static void data__free(struct data__file *d) } } +static int abstime_str_dup(char **pstr) +{ + char *str = NULL; + + if (pdiff.time_str && strchr(pdiff.time_str, ':')) { + str = strdup(pdiff.time_str); + if (!str) + return -ENOMEM; + } + + *pstr = str; + return 0; +} + +static int parse_absolute_time(struct data__file *d, char **pstr) +{ + char *p = *pstr; + int ret; + + /* + * Absolute timestamp for one file has the format: a.b,c.d + * For multiple files, the format is: a.b,c.d:a.b,c.d + */ + p = strchr(*pstr, ':'); + if (p) { + if (p == *pstr) { + pr_err("Invalid time string\n"); + return -EINVAL; + } + + *p = 0; + p++; + if (*p == 0) { + pr_err("Invalid time string\n"); + return -EINVAL; + } + } + + ret = perf_time__parse_for_ranges(*pstr, d->session, + &pdiff.ptime_range, + &pdiff.range_size, + &pdiff.range_num); + if (ret < 0) + return ret; + + if (!p || *p == 0) + *pstr = NULL; + else + *pstr = p; + + return ret; +} + +static int parse_percent_time(struct data__file *d) +{ + int ret; + + ret = perf_time__parse_for_ranges(pdiff.time_str, d->session, + &pdiff.ptime_range, + &pdiff.range_size, + &pdiff.range_num); + return ret; +} + +static int parse_time_str(struct data__file *d, char *abstime_ostr, + char **pabstime_tmp) +{ + int ret = 0; + + if (abstime_ostr) + ret = parse_absolute_time(d, pabstime_tmp); + else if (pdiff.time_str) + ret = parse_percent_time(d); + + return ret; +} + static int __cmd_diff(void) { struct data__file *d; - int ret = -EINVAL, i; + int ret, i; + char *abstime_ostr, *abstime_tmp; + + ret = abstime_str_dup(&abstime_ostr); + if (ret) + return ret; + + abstime_tmp = abstime_ostr; + ret = -EINVAL; data__for_each_file(i, d) { - d->session = perf_session__new(&d->data, false, &tool); + d->session = perf_session__new(&d->data, false, &pdiff.tool); if (!d->session) { pr_err("Failed to open %s\n", d->data.path); ret = -1; goto out_delete; } + if (pdiff.time_str) { + ret = parse_time_str(d, abstime_ostr, &abstime_tmp); + if (ret < 0) + goto out_delete; + } + ret = perf_session__process_events(d->session); if (ret) { pr_err("Failed to process %s\n", d->data.path); @@ -791,6 +899,9 @@ static int __cmd_diff(void) } perf_evlist__collapse_resort(d->session->evlist); + + if (pdiff.ptime_range) + zfree(&pdiff.ptime_range); } data_process(); @@ -802,6 +913,13 @@ static int __cmd_diff(void) } free(data__files); + + if (pdiff.ptime_range) + zfree(&pdiff.ptime_range); + + if (abstime_ostr) + free(abstime_ostr); + return ret; } @@ -849,6 +967,8 @@ static const struct option options[] = { OPT_UINTEGER('o', "order", &sort_compute, "Specify compute sorting."), OPT_CALLBACK(0, "percentage", NULL, "relative|absolute", "How to display percentage of filtered entries", parse_filter_percentage), + OPT_STRING(0, "time", &pdiff.time_str, "str", + "Time span (time percent or absolute timestamp)"), OPT_END() }; From daca23b2007595b6a48255ca08c763f56050d1c5 Mon Sep 17 00:00:00 2001 From: Jin Yao Date: Tue, 5 Mar 2019 21:05:42 +0800 Subject: [PATCH 22/35] perf diff: Support --cpu filter option To improve 'perf diff', implement a --cpu filter option. Multiple CPUs can be provided as a comma-separated list with no space: 0,1. Ranges of CPUs are specified with -: 0-2. Default is to report samples on all CPUs. For example, perf diff --cpu 0,1 It only diff the samples for CPU0 and CPU1. Signed-off-by: Jin Yao Acked-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jin Yao Cc: Kan Liang Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/1551791143-10334-3-git-send-email-yao.jin@linux.intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-diff.txt | 5 +++++ tools/perf/builtin-diff.c | 16 ++++++++++++++++ 2 files changed, 21 insertions(+) diff --git a/tools/perf/Documentation/perf-diff.txt b/tools/perf/Documentation/perf-diff.txt index 036d65bded51..8c2c229faf50 100644 --- a/tools/perf/Documentation/perf-diff.txt +++ b/tools/perf/Documentation/perf-diff.txt @@ -163,6 +163,11 @@ OPTIONS the end of perf.data.old and analyzes the perf.data from the timestamp 3971.150589 to the end of perf.data. +--cpu:: Only diff samples for the list of CPUs provided. Multiple CPUs can + be provided as a comma-separated list with no space: 0,1. Ranges of + CPUs are specified with -: 0-2. Default is to report samples on all + CPUs. + COMPARISON ---------- The comparison is governed by the baseline file. The baseline perf.data diff --git a/tools/perf/builtin-diff.c b/tools/perf/builtin-diff.c index 17cd898074c8..dfe6c7606f5a 100644 --- a/tools/perf/builtin-diff.c +++ b/tools/perf/builtin-diff.c @@ -83,6 +83,9 @@ static unsigned int sort_compute = 1; static s64 compute_wdiff_w1; static s64 compute_wdiff_w2; +static const char *cpu_list; +static DECLARE_BITMAP(cpu_bitmap, MAX_NR_CPUS); + enum { COMPUTE_DELTA, COMPUTE_RATIO, @@ -354,6 +357,11 @@ static int diff__process_sample_event(struct perf_tool *tool, return -1; } + if (cpu_list && !test_bit(sample->cpu, cpu_bitmap)) { + ret = 0; + goto out_put; + } + if (!hists__add_entry(hists, &al, NULL, NULL, NULL, sample, true)) { pr_warning("problem incrementing symbol period, skipping event\n"); goto out_put; @@ -892,6 +900,13 @@ static int __cmd_diff(void) goto out_delete; } + if (cpu_list) { + ret = perf_session__cpu_bitmap(d->session, cpu_list, + cpu_bitmap); + if (ret < 0) + goto out_delete; + } + ret = perf_session__process_events(d->session); if (ret) { pr_err("Failed to process %s\n", d->data.path); @@ -969,6 +984,7 @@ static const struct option options[] = { "How to display percentage of filtered entries", parse_filter_percentage), OPT_STRING(0, "time", &pdiff.time_str, "str", "Time span (time percent or absolute timestamp)"), + OPT_STRING(0, "cpu", &cpu_list, "cpu", "list of cpus to profile"), OPT_END() }; From c1d3e633e16db3eb64f519c7099171bfcef94b20 Mon Sep 17 00:00:00 2001 From: Jin Yao Date: Tue, 5 Mar 2019 21:05:43 +0800 Subject: [PATCH 23/35] perf diff: Support --pid/--tid filter options Using the existing symbol_conf.pid_list_str and symbol_conf.tid_list_str logic. For example: perf diff --tid 13965 It'll only diff the samples for thread 13965. Signed-off-by: Jin Yao Acked-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jin Yao Cc: Kan Liang Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/1551791143-10334-4-git-send-email-yao.jin@linux.intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-diff.txt | 6 ++++++ tools/perf/builtin-diff.c | 4 ++++ 2 files changed, 10 insertions(+) diff --git a/tools/perf/Documentation/perf-diff.txt b/tools/perf/Documentation/perf-diff.txt index 8c2c229faf50..da7809b15cc9 100644 --- a/tools/perf/Documentation/perf-diff.txt +++ b/tools/perf/Documentation/perf-diff.txt @@ -168,6 +168,12 @@ OPTIONS CPUs are specified with -: 0-2. Default is to report samples on all CPUs. +--pid=:: + Only diff samples for given process ID (comma separated list). + +--tid=:: + Only diff samples for given thread ID (comma separated list). + COMPARISON ---------- The comparison is governed by the baseline file. The baseline perf.data diff --git a/tools/perf/builtin-diff.c b/tools/perf/builtin-diff.c index dfe6c7606f5a..6e7920793729 100644 --- a/tools/perf/builtin-diff.c +++ b/tools/perf/builtin-diff.c @@ -985,6 +985,10 @@ static const struct option options[] = { OPT_STRING(0, "time", &pdiff.time_str, "str", "Time span (time percent or absolute timestamp)"), OPT_STRING(0, "cpu", &cpu_list, "cpu", "list of cpus to profile"), + OPT_STRING(0, "pid", &symbol_conf.pid_list_str, "pid[,pid...]", + "only consider symbols in these pids"), + OPT_STRING(0, "tid", &symbol_conf.tid_list_str, "tid[,tid...]", + "only consider symbols in these tids"), OPT_END() }; From b504d7f6876515b74c8e27a44ccdb22372616d97 Mon Sep 17 00:00:00 2001 From: Tony Jones Date: Fri, 1 Mar 2019 17:18:57 -0800 Subject: [PATCH 24/35] perf script python: Remove mixed indentation Remove mixed indentation in Python scripts. Revert to either all tabs (most common form) or all spaces (4 or 8) depending on what was the intent of the original commit. This is necessary to complete Python3 support as it will flag an error if it encounters mixed indentation. Signed-off-by: Tony Jones Link: http://lkml.kernel.org/r/20190302011903.2416-2-tonyj@suse.de Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/check-perf-trace.py | 65 +++++++++---------- tools/perf/scripts/python/compaction-times.py | 8 +-- .../scripts/python/event_analyzing_sample.py | 6 +- .../scripts/python/failed-syscalls-by-pid.py | 34 +++++----- tools/perf/scripts/python/futex-contention.py | 2 +- tools/perf/scripts/python/intel-pt-events.py | 28 ++++---- tools/perf/scripts/python/mem-phys-addr.py | 7 +- tools/perf/scripts/python/net_dropmonitor.py | 2 +- tools/perf/scripts/python/netdev-times.py | 12 ++-- tools/perf/scripts/python/sched-migration.py | 6 +- tools/perf/scripts/python/sctop.py | 13 ++-- tools/perf/scripts/python/stackcollapse.py | 2 +- .../scripts/python/syscall-counts-by-pid.py | 43 ++++++------ tools/perf/scripts/python/syscall-counts.py | 27 ++++---- 14 files changed, 128 insertions(+), 127 deletions(-) diff --git a/tools/perf/scripts/python/check-perf-trace.py b/tools/perf/scripts/python/check-perf-trace.py index 334599c6032c..f4838db3e518 100644 --- a/tools/perf/scripts/python/check-perf-trace.py +++ b/tools/perf/scripts/python/check-perf-trace.py @@ -23,60 +23,59 @@ def trace_begin(): pass def trace_end(): - print_unhandled() + print_unhandled() def irq__softirq_entry(event_name, context, common_cpu, - common_secs, common_nsecs, common_pid, common_comm, - common_callchain, vec): - print_header(event_name, common_cpu, common_secs, common_nsecs, - common_pid, common_comm) + common_secs, common_nsecs, common_pid, common_comm, + common_callchain, vec): + print_header(event_name, common_cpu, common_secs, common_nsecs, + common_pid, common_comm) - print_uncommon(context) + print_uncommon(context) - print "vec=%s\n" % \ - (symbol_str("irq__softirq_entry", "vec", vec)), + print "vec=%s\n" % (symbol_str("irq__softirq_entry", "vec", vec)), def kmem__kmalloc(event_name, context, common_cpu, - common_secs, common_nsecs, common_pid, common_comm, - common_callchain, call_site, ptr, bytes_req, bytes_alloc, - gfp_flags): - print_header(event_name, common_cpu, common_secs, common_nsecs, - common_pid, common_comm) + common_secs, common_nsecs, common_pid, common_comm, + common_callchain, call_site, ptr, bytes_req, bytes_alloc, + gfp_flags): + print_header(event_name, common_cpu, common_secs, common_nsecs, + common_pid, common_comm) - print_uncommon(context) + print_uncommon(context) - print "call_site=%u, ptr=%u, bytes_req=%u, " \ + print "call_site=%u, ptr=%u, bytes_req=%u, " \ "bytes_alloc=%u, gfp_flags=%s\n" % \ (call_site, ptr, bytes_req, bytes_alloc, - flag_str("kmem__kmalloc", "gfp_flags", gfp_flags)), def trace_unhandled(event_name, context, event_fields_dict): - try: - unhandled[event_name] += 1 - except TypeError: - unhandled[event_name] = 1 + try: + unhandled[event_name] += 1 + except TypeError: + unhandled[event_name] = 1 def print_header(event_name, cpu, secs, nsecs, pid, comm): print "%-20s %5u %05u.%09u %8u %-20s " % \ - (event_name, cpu, secs, nsecs, pid, comm), + (event_name, cpu, secs, nsecs, pid, comm), # print trace fields not included in handler args def print_uncommon(context): - print "common_preempt_count=%d, common_flags=%s, common_lock_depth=%d, " \ - % (common_pc(context), trace_flag_str(common_flags(context)), \ - common_lock_depth(context)) + print "common_preempt_count=%d, common_flags=%s, " \ + "common_lock_depth=%d, " % \ + (common_pc(context), trace_flag_str(common_flags(context)), + common_lock_depth(context)) def print_unhandled(): - keys = unhandled.keys() - if not keys: - return + keys = unhandled.keys() + if not keys: + return - print "\nunhandled events:\n\n", + print "\nunhandled events:\n\n", - print "%-40s %10s\n" % ("event", "count"), - print "%-40s %10s\n" % ("----------------------------------------", \ - "-----------"), + print "%-40s %10s\n" % ("event", "count"), + print "%-40s %10s\n" % ("----------------------------------------", \ + "-----------"), - for event_name in keys: - print "%-40s %10d\n" % (event_name, unhandled[event_name]) + for event_name in keys: + print "%-40s %10d\n" % (event_name, unhandled[event_name]) diff --git a/tools/perf/scripts/python/compaction-times.py b/tools/perf/scripts/python/compaction-times.py index 239cb0568ec3..2560a042dc6f 100644 --- a/tools/perf/scripts/python/compaction-times.py +++ b/tools/perf/scripts/python/compaction-times.py @@ -216,15 +216,15 @@ def compaction__mm_compaction_migratepages(event_name, context, common_cpu, pair(nr_migrated, nr_failed), None, None) def compaction__mm_compaction_isolate_freepages(event_name, context, common_cpu, - common_secs, common_nsecs, common_pid, common_comm, - common_callchain, start_pfn, end_pfn, nr_scanned, nr_taken): + common_secs, common_nsecs, common_pid, common_comm, + common_callchain, start_pfn, end_pfn, nr_scanned, nr_taken): chead.increment_pending(common_pid, None, pair(nr_scanned, nr_taken), None) def compaction__mm_compaction_isolate_migratepages(event_name, context, common_cpu, - common_secs, common_nsecs, common_pid, common_comm, - common_callchain, start_pfn, end_pfn, nr_scanned, nr_taken): + common_secs, common_nsecs, common_pid, common_comm, + common_callchain, start_pfn, end_pfn, nr_scanned, nr_taken): chead.increment_pending(common_pid, None, None, pair(nr_scanned, nr_taken)) diff --git a/tools/perf/scripts/python/event_analyzing_sample.py b/tools/perf/scripts/python/event_analyzing_sample.py index 4e843b9864ec..2ec8915b74c5 100644 --- a/tools/perf/scripts/python/event_analyzing_sample.py +++ b/tools/perf/scripts/python/event_analyzing_sample.py @@ -37,7 +37,7 @@ con = sqlite3.connect("/dev/shm/perf.db") con.isolation_level = None def trace_begin(): - print "In trace_begin:\n" + print "In trace_begin:\n" # # Will create several tables at the start, pebs_ll is for PEBS data with @@ -102,7 +102,7 @@ def insert_db(event): event.ip, event.status, event.dse, event.dla, event.lat)) def trace_end(): - print "In trace_end:\n" + print "In trace_end:\n" # We show the basic info for the 2 type of event classes show_general_events() show_pebs_ll() @@ -187,4 +187,4 @@ def show_pebs_ll(): print "%32s %8d %s" % (row[0], row[1], num2sym(row[1])) def trace_unhandled(event_name, context, event_fields_dict): - print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())]) + print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())]) diff --git a/tools/perf/scripts/python/failed-syscalls-by-pid.py b/tools/perf/scripts/python/failed-syscalls-by-pid.py index 3648e8b986ec..310efe5e7e23 100644 --- a/tools/perf/scripts/python/failed-syscalls-by-pid.py +++ b/tools/perf/scripts/python/failed-syscalls-by-pid.py @@ -58,22 +58,22 @@ def syscalls__sys_exit(event_name, context, common_cpu, raw_syscalls__sys_exit(**locals()) def print_error_totals(): - if for_comm is not None: - print("\nsyscall errors for %s:\n" % (for_comm)) - else: - print("\nsyscall errors:\n") + if for_comm is not None: + print("\nsyscall errors for %s:\n" % (for_comm)) + else: + print("\nsyscall errors:\n") - print("%-30s %10s" % ("comm [pid]", "count")) - print("%-30s %10s" % ("------------------------------", "----------")) + print("%-30s %10s" % ("comm [pid]", "count")) + print("%-30s %10s" % ("------------------------------", "----------")) - comm_keys = syscalls.keys() - for comm in comm_keys: - pid_keys = syscalls[comm].keys() - for pid in pid_keys: - print("\n%s [%d]" % (comm, pid)) - id_keys = syscalls[comm][pid].keys() - for id in id_keys: - print(" syscall: %-16s" % syscall_name(id)) - ret_keys = syscalls[comm][pid][id].keys() - for ret, val in sorted(syscalls[comm][pid][id].items(), key = lambda kv: (kv[1], kv[0]), reverse = True): - print(" err = %-20s %10d" % (strerror(ret), val)) + comm_keys = syscalls.keys() + for comm in comm_keys: + pid_keys = syscalls[comm].keys() + for pid in pid_keys: + print("\n%s [%d]" % (comm, pid)) + id_keys = syscalls[comm][pid].keys() + for id in id_keys: + print(" syscall: %-16s" % syscall_name(id)) + ret_keys = syscalls[comm][pid][id].keys() + for ret, val in sorted(syscalls[comm][pid][id].items(), key = lambda kv: (kv[1], kv[0]), reverse = True): + print(" err = %-20s %10d" % (strerror(ret), val)) diff --git a/tools/perf/scripts/python/futex-contention.py b/tools/perf/scripts/python/futex-contention.py index 0f5cf437b602..f221c62e0a10 100644 --- a/tools/perf/scripts/python/futex-contention.py +++ b/tools/perf/scripts/python/futex-contention.py @@ -46,5 +46,5 @@ def trace_end(): for (tid, lock) in lock_waits: min, max, avg, count = lock_waits[tid, lock] print "%s[%d] lock %x contended %d times, %d avg ns" % \ - (process_names[tid], tid, lock, count, avg) + (process_names[tid], tid, lock, count, avg) diff --git a/tools/perf/scripts/python/intel-pt-events.py b/tools/perf/scripts/python/intel-pt-events.py index b19172d673af..2177722f509e 100644 --- a/tools/perf/scripts/python/intel-pt-events.py +++ b/tools/perf/scripts/python/intel-pt-events.py @@ -85,22 +85,22 @@ def print_common_ip(sample, symbol, dso): print "%16x %s (%s)" % (ip, symbol, dso) def process_event(param_dict): - event_attr = param_dict["attr"] - sample = param_dict["sample"] - raw_buf = param_dict["raw_buf"] - comm = param_dict["comm"] - name = param_dict["ev_name"] + event_attr = param_dict["attr"] + sample = param_dict["sample"] + raw_buf = param_dict["raw_buf"] + comm = param_dict["comm"] + name = param_dict["ev_name"] - # Symbol and dso info are not always resolved - if (param_dict.has_key("dso")): - dso = param_dict["dso"] - else: - dso = "[unknown]" + # Symbol and dso info are not always resolved + if (param_dict.has_key("dso")): + dso = param_dict["dso"] + else: + dso = "[unknown]" - if (param_dict.has_key("symbol")): - symbol = param_dict["symbol"] - else: - symbol = "[unknown]" + if (param_dict.has_key("symbol")): + symbol = param_dict["symbol"] + else: + symbol = "[unknown]" if name == "ptwrite": print_common_start(comm, sample, name) diff --git a/tools/perf/scripts/python/mem-phys-addr.py b/tools/perf/scripts/python/mem-phys-addr.py index fb0bbcbfa0f0..1f332e72b9b0 100644 --- a/tools/perf/scripts/python/mem-phys-addr.py +++ b/tools/perf/scripts/python/mem-phys-addr.py @@ -44,12 +44,13 @@ def print_memory_type(): print("%-40s %10s %10s\n" % ("Memory type", "count", "percentage"), end='') print("%-40s %10s %10s\n" % ("----------------------------------------", "-----------", "-----------"), - end=''); + end=''); total = sum(load_mem_type_cnt.values()) for mem_type, count in sorted(load_mem_type_cnt.most_common(), \ key = lambda kv: (kv[1], kv[0]), reverse = True): - print("%-40s %10d %10.1f%%\n" % (mem_type, count, 100 * count / total), - end='') + print("%-40s %10d %10.1f%%\n" % + (mem_type, count, 100 * count / total), + end='') def trace_begin(): parse_iomem() diff --git a/tools/perf/scripts/python/net_dropmonitor.py b/tools/perf/scripts/python/net_dropmonitor.py index 212557a02c50..101059971738 100755 --- a/tools/perf/scripts/python/net_dropmonitor.py +++ b/tools/perf/scripts/python/net_dropmonitor.py @@ -7,7 +7,7 @@ import os import sys sys.path.append(os.environ['PERF_EXEC_PATH'] + \ - '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') + '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') from perf_trace_context import * from Core import * diff --git a/tools/perf/scripts/python/netdev-times.py b/tools/perf/scripts/python/netdev-times.py index 267bda49325d..ea0c8b90a783 100644 --- a/tools/perf/scripts/python/netdev-times.py +++ b/tools/perf/scripts/python/netdev-times.py @@ -124,14 +124,16 @@ def print_receive(hunk): event = event_list[i] if event['event_name'] == 'napi_poll': print(PF_NAPI_POLL % - (diff_msec(base_t, event['event_t']), event['dev'])) + (diff_msec(base_t, event['event_t']), + event['dev'])) if i == len(event_list) - 1: print("") else: print(PF_JOINT) else: print(PF_NET_RECV % - (diff_msec(base_t, event['event_t']), event['skbaddr'], + (diff_msec(base_t, event['event_t']), + event['skbaddr'], event['len'])) if 'comm' in event.keys(): print(PF_WJOINT) @@ -256,7 +258,7 @@ def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, callchain, i all_event_list.append(event_info) def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, callchain, napi, - dev_name, work=None, budget=None): + dev_name, work=None, budget=None): event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, napi, dev_name, work, budget) all_event_list.append(event_info) @@ -353,7 +355,7 @@ def handle_irq_softirq_exit(event_info): if irq_list == [] or event_list == 0: return rec_data = {'sirq_ent_t':sirq_ent_t, 'sirq_ext_t':time, - 'irq_list':irq_list, 'event_list':event_list} + 'irq_list':irq_list, 'event_list':event_list} # merge information realted to a NET_RX softirq receive_hunk_list.append(rec_data) @@ -390,7 +392,7 @@ def handle_netif_receive_skb(event_info): skbaddr, skblen, dev_name) = event_info if cpu in net_rx_dic.keys(): rec_data = {'event_name':'netif_receive_skb', - 'event_t':time, 'skbaddr':skbaddr, 'len':skblen} + 'event_t':time, 'skbaddr':skbaddr, 'len':skblen} event_list = net_rx_dic[cpu]['event_list'] event_list.append(rec_data) rx_skb_list.insert(0, rec_data) diff --git a/tools/perf/scripts/python/sched-migration.py b/tools/perf/scripts/python/sched-migration.py index 3984bf51f3c5..8196e3087c9e 100644 --- a/tools/perf/scripts/python/sched-migration.py +++ b/tools/perf/scripts/python/sched-migration.py @@ -14,10 +14,10 @@ import sys from collections import defaultdict try: - from UserList import UserList + from UserList import UserList except ImportError: - # Python 3: UserList moved to the collections package - from collections import UserList + # Python 3: UserList moved to the collections package + from collections import UserList sys.path.append(os.environ['PERF_EXEC_PATH'] + \ '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') diff --git a/tools/perf/scripts/python/sctop.py b/tools/perf/scripts/python/sctop.py index 987ffae7c8ca..6e0278dcb092 100644 --- a/tools/perf/scripts/python/sctop.py +++ b/tools/perf/scripts/python/sctop.py @@ -13,9 +13,9 @@ from __future__ import print_function import os, sys, time try: - import thread + import thread except ImportError: - import _thread as thread + import _thread as thread sys.path.append(os.environ['PERF_EXEC_PATH'] + \ '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') @@ -75,11 +75,12 @@ def print_syscall_totals(interval): print("%-40s %10s" % ("event", "count")) print("%-40s %10s" % - ("----------------------------------------", - "----------")) + ("----------------------------------------", + "----------")) - for id, val in sorted(syscalls.items(), key = lambda kv: (kv[1], kv[0]), \ - reverse = True): + for id, val in sorted(syscalls.items(), + key = lambda kv: (kv[1], kv[0]), + reverse = True): try: print("%-40s %10d" % (syscall_name(id), val)) except TypeError: diff --git a/tools/perf/scripts/python/stackcollapse.py b/tools/perf/scripts/python/stackcollapse.py index 5e703efaddcc..b1c4def1410a 100755 --- a/tools/perf/scripts/python/stackcollapse.py +++ b/tools/perf/scripts/python/stackcollapse.py @@ -27,7 +27,7 @@ from collections import defaultdict from optparse import OptionParser, make_option sys.path.append(os.environ['PERF_EXEC_PATH'] + \ - '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') + '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') from perf_trace_context import * from Core import * diff --git a/tools/perf/scripts/python/syscall-counts-by-pid.py b/tools/perf/scripts/python/syscall-counts-by-pid.py index 42782487b0e9..f254e40c6f0f 100644 --- a/tools/perf/scripts/python/syscall-counts-by-pid.py +++ b/tools/perf/scripts/python/syscall-counts-by-pid.py @@ -39,11 +39,10 @@ def trace_end(): print_syscall_totals() def raw_syscalls__sys_enter(event_name, context, common_cpu, - common_secs, common_nsecs, common_pid, common_comm, - common_callchain, id, args): - + common_secs, common_nsecs, common_pid, common_comm, + common_callchain, id, args): if (for_comm and common_comm != for_comm) or \ - (for_pid and common_pid != for_pid ): + (for_pid and common_pid != for_pid ): return try: syscalls[common_comm][common_pid][id] += 1 @@ -51,26 +50,26 @@ def raw_syscalls__sys_enter(event_name, context, common_cpu, syscalls[common_comm][common_pid][id] = 1 def syscalls__sys_enter(event_name, context, common_cpu, - common_secs, common_nsecs, common_pid, common_comm, - id, args): + common_secs, common_nsecs, common_pid, common_comm, + id, args): raw_syscalls__sys_enter(**locals()) def print_syscall_totals(): - if for_comm is not None: - print("\nsyscall events for %s:\n" % (for_comm)) - else: - print("\nsyscall events by comm/pid:\n") + if for_comm is not None: + print("\nsyscall events for %s:\n" % (for_comm)) + else: + print("\nsyscall events by comm/pid:\n") - print("%-40s %10s" % ("comm [pid]/syscalls", "count")) - print("%-40s %10s" % ("----------------------------------------", - "----------")) + print("%-40s %10s" % ("comm [pid]/syscalls", "count")) + print("%-40s %10s" % ("----------------------------------------", + "----------")) - comm_keys = syscalls.keys() - for comm in comm_keys: - pid_keys = syscalls[comm].keys() - for pid in pid_keys: - print("\n%s [%d]" % (comm, pid)) - id_keys = syscalls[comm][pid].keys() - for id, val in sorted(syscalls[comm][pid].items(), \ - key = lambda kv: (kv[1], kv[0]), reverse = True): - print(" %-38s %10d" % (syscall_name(id), val)) + comm_keys = syscalls.keys() + for comm in comm_keys: + pid_keys = syscalls[comm].keys() + for pid in pid_keys: + print("\n%s [%d]" % (comm, pid)) + id_keys = syscalls[comm][pid].keys() + for id, val in sorted(syscalls[comm][pid].items(), + key = lambda kv: (kv[1], kv[0]), reverse = True): + print(" %-38s %10d" % (syscall_name(id), val)) diff --git a/tools/perf/scripts/python/syscall-counts.py b/tools/perf/scripts/python/syscall-counts.py index 0ebd89cfd42c..8adb95ff1664 100644 --- a/tools/perf/scripts/python/syscall-counts.py +++ b/tools/perf/scripts/python/syscall-counts.py @@ -36,8 +36,8 @@ def trace_end(): print_syscall_totals() def raw_syscalls__sys_enter(event_name, context, common_cpu, - common_secs, common_nsecs, common_pid, common_comm, - common_callchain, id, args): + common_secs, common_nsecs, common_pid, common_comm, + common_callchain, id, args): if for_comm is not None: if common_comm != for_comm: return @@ -47,20 +47,19 @@ def raw_syscalls__sys_enter(event_name, context, common_cpu, syscalls[id] = 1 def syscalls__sys_enter(event_name, context, common_cpu, - common_secs, common_nsecs, common_pid, common_comm, - id, args): + common_secs, common_nsecs, common_pid, common_comm, id, args): raw_syscalls__sys_enter(**locals()) def print_syscall_totals(): - if for_comm is not None: - print("\nsyscall events for %s:\n" % (for_comm)) - else: - print("\nsyscall events:\n") + if for_comm is not None: + print("\nsyscall events for %s:\n" % (for_comm)) + else: + print("\nsyscall events:\n") - print("%-40s %10s" % ("event", "count")) - print("%-40s %10s" % ("----------------------------------------", - "-----------")) + print("%-40s %10s" % ("event", "count")) + print("%-40s %10s" % ("----------------------------------------", + "-----------")) - for id, val in sorted(syscalls.items(), key = lambda kv: (kv[1], kv[0]), \ - reverse = True): - print("%-40s %10d" % (syscall_name(id), val)) + for id, val in sorted(syscalls.items(), + key = lambda kv: (kv[1], kv[0]), reverse = True): + print("%-40s %10d" % (syscall_name(id), val)) From de2ec16bd438945813198d4de2339a396904c206 Mon Sep 17 00:00:00 2001 From: Tony Jones Date: Fri, 1 Mar 2019 17:18:58 -0800 Subject: [PATCH 25/35] perf script python: Add Python3 support to futex-contention.py Support both Python2 and Python3 in the futex-contention.py script There may be differences in the ordering of output lines due to differences in dictionary ordering etc. However the format within lines should be unchanged. The use of 'from __future__' implies the minimum supported Python2 version is now v2.6 Signed-off-by: Tony Jones Link: http://lkml.kernel.org/r/20190302011903.2416-3-tonyj@suse.de Signed-off-by: Seeteena Thoufeek Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/futex-contention.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/tools/perf/scripts/python/futex-contention.py b/tools/perf/scripts/python/futex-contention.py index f221c62e0a10..0c4841acf75d 100644 --- a/tools/perf/scripts/python/futex-contention.py +++ b/tools/perf/scripts/python/futex-contention.py @@ -10,6 +10,8 @@ # # Measures futex contention +from __future__ import print_function + import os, sys sys.path.append(os.environ['PERF_EXEC_PATH'] + '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') from Util import * @@ -33,18 +35,18 @@ def syscalls__sys_enter_futex(event, ctxt, cpu, s, ns, tid, comm, callchain, def syscalls__sys_exit_futex(event, ctxt, cpu, s, ns, tid, comm, callchain, nr, ret): - if thread_blocktime.has_key(tid): + if tid in thread_blocktime: elapsed = nsecs(s, ns) - thread_blocktime[tid] add_stats(lock_waits, (tid, thread_thislock[tid]), elapsed) del thread_blocktime[tid] del thread_thislock[tid] def trace_begin(): - print "Press control+C to stop and show the summary" + print("Press control+C to stop and show the summary") def trace_end(): for (tid, lock) in lock_waits: min, max, avg, count = lock_waits[tid, lock] - print "%s[%d] lock %x contended %d times, %d avg ns" % \ - (process_names[tid], tid, lock, count, avg) + print("%s[%d] lock %x contended %d times, %d avg ns" % + (process_names[tid], tid, lock, count, avg)) From 57e604b16362273af6a517abaa6cd1133a7fc732 Mon Sep 17 00:00:00 2001 From: Tony Jones Date: Fri, 1 Mar 2019 17:18:59 -0800 Subject: [PATCH 26/35] perf script python: add Python3 support to check-perf-trace.py Support both Python 2 and Python 3 in the check-perf-trace.py script. There may be differences in the ordering of output lines due to differences in dictionary ordering etc. However the format within lines should be unchanged. The use of from __future__ implies the minimum supported version of Python2 is now v2.6 Signed-off-by: Tony Jones Cc: Tom Zanussi Link: http://lkml.kernel.org/r/20190302011903.2416-4-tonyj@suse.de Signed-off-by: Seeteena Thoufeek Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/check-perf-trace.py | 31 ++++++++++--------- 1 file changed, 17 insertions(+), 14 deletions(-) diff --git a/tools/perf/scripts/python/check-perf-trace.py b/tools/perf/scripts/python/check-perf-trace.py index f4838db3e518..d2c22954800d 100644 --- a/tools/perf/scripts/python/check-perf-trace.py +++ b/tools/perf/scripts/python/check-perf-trace.py @@ -7,6 +7,8 @@ # events, etc. Basically, if this script runs successfully and # displays expected results, Python scripting support should be ok. +from __future__ import print_function + import os import sys @@ -19,7 +21,7 @@ from perf_trace_context import * unhandled = autodict() def trace_begin(): - print "trace_begin" + print("trace_begin") pass def trace_end(): @@ -33,7 +35,7 @@ def irq__softirq_entry(event_name, context, common_cpu, print_uncommon(context) - print "vec=%s\n" % (symbol_str("irq__softirq_entry", "vec", vec)), + print("vec=%s" % (symbol_str("irq__softirq_entry", "vec", vec))) def kmem__kmalloc(event_name, context, common_cpu, common_secs, common_nsecs, common_pid, common_comm, @@ -44,10 +46,10 @@ def kmem__kmalloc(event_name, context, common_cpu, print_uncommon(context) - print "call_site=%u, ptr=%u, bytes_req=%u, " \ - "bytes_alloc=%u, gfp_flags=%s\n" % \ + print("call_site=%u, ptr=%u, bytes_req=%u, " + "bytes_alloc=%u, gfp_flags=%s" % (call_site, ptr, bytes_req, bytes_alloc, - flag_str("kmem__kmalloc", "gfp_flags", gfp_flags)), + flag_str("kmem__kmalloc", "gfp_flags", gfp_flags))) def trace_unhandled(event_name, context, event_fields_dict): try: @@ -56,26 +58,27 @@ def trace_unhandled(event_name, context, event_fields_dict): unhandled[event_name] = 1 def print_header(event_name, cpu, secs, nsecs, pid, comm): - print "%-20s %5u %05u.%09u %8u %-20s " % \ + print("%-20s %5u %05u.%09u %8u %-20s " % (event_name, cpu, secs, nsecs, pid, comm), + end=' ') # print trace fields not included in handler args def print_uncommon(context): - print "common_preempt_count=%d, common_flags=%s, " \ - "common_lock_depth=%d, " % \ + print("common_preempt_count=%d, common_flags=%s, " + "common_lock_depth=%d, " % (common_pc(context), trace_flag_str(common_flags(context)), - common_lock_depth(context)) + common_lock_depth(context))) def print_unhandled(): keys = unhandled.keys() if not keys: return - print "\nunhandled events:\n\n", + print("\nunhandled events:\n") - print "%-40s %10s\n" % ("event", "count"), - print "%-40s %10s\n" % ("----------------------------------------", \ - "-----------"), + print("%-40s %10s" % ("event", "count")) + print("%-40s %10s" % ("----------------------------------------", + "-----------")) for event_name in keys: - print "%-40s %10d\n" % (event_name, unhandled[event_name]) + print("%-40s %10d\n" % (event_name, unhandled[event_name])) From c253c72e9d6723c8b078beb362f050059ef5de39 Mon Sep 17 00:00:00 2001 From: Tony Jones Date: Fri, 1 Mar 2019 17:19:00 -0800 Subject: [PATCH 27/35] perf script python: Add Python3 support to event_analyzing_sample.py Support both Python2 and Python3 in the event_analyzing_sample.py script There may be differences in the ordering of output lines due to differences in dictionary ordering etc. However the format within lines should be unchanged. The use of 'from __future__' implies the minimum supported Python2 version is now v2.6 Signed-off-by: Tony Jones Cc: Feng Tang Link: http://lkml.kernel.org/r/20190302011903.2416-5-tonyj@suse.de Signed-off-by: Seeteena Thoufeek Signed-off-by: Arnaldo Carvalho de Melo --- .../scripts/python/event_analyzing_sample.py | 48 ++++++++++--------- 1 file changed, 25 insertions(+), 23 deletions(-) diff --git a/tools/perf/scripts/python/event_analyzing_sample.py b/tools/perf/scripts/python/event_analyzing_sample.py index 2ec8915b74c5..aa1e2cfa26a6 100644 --- a/tools/perf/scripts/python/event_analyzing_sample.py +++ b/tools/perf/scripts/python/event_analyzing_sample.py @@ -15,6 +15,8 @@ # for a x86 HW PMU event: PEBS with load latency data. # +from __future__ import print_function + import os import sys import math @@ -37,7 +39,7 @@ con = sqlite3.connect("/dev/shm/perf.db") con.isolation_level = None def trace_begin(): - print "In trace_begin:\n" + print("In trace_begin:\n") # # Will create several tables at the start, pebs_ll is for PEBS data with @@ -76,12 +78,12 @@ def process_event(param_dict): name = param_dict["ev_name"] # Symbol and dso info are not always resolved - if (param_dict.has_key("dso")): + if ("dso" in param_dict): dso = param_dict["dso"] else: dso = "Unknown_dso" - if (param_dict.has_key("symbol")): + if ("symbol" in param_dict): symbol = param_dict["symbol"] else: symbol = "Unknown_symbol" @@ -102,7 +104,7 @@ def insert_db(event): event.ip, event.status, event.dse, event.dla, event.lat)) def trace_end(): - print "In trace_end:\n" + print("In trace_end:\n") # We show the basic info for the 2 type of event classes show_general_events() show_pebs_ll() @@ -123,29 +125,29 @@ def show_general_events(): # Check the total record number in the table count = con.execute("select count(*) from gen_events") for t in count: - print "There is %d records in gen_events table" % t[0] + print("There is %d records in gen_events table" % t[0]) if t[0] == 0: return - print "Statistics about the general events grouped by thread/symbol/dso: \n" + print("Statistics about the general events grouped by thread/symbol/dso: \n") # Group by thread commq = con.execute("select comm, count(comm) from gen_events group by comm order by -count(comm)") - print "\n%16s %8s %16s\n%s" % ("comm", "number", "histogram", "="*42) + print("\n%16s %8s %16s\n%s" % ("comm", "number", "histogram", "="*42)) for row in commq: - print "%16s %8d %s" % (row[0], row[1], num2sym(row[1])) + print("%16s %8d %s" % (row[0], row[1], num2sym(row[1]))) # Group by symbol - print "\n%32s %8s %16s\n%s" % ("symbol", "number", "histogram", "="*58) + print("\n%32s %8s %16s\n%s" % ("symbol", "number", "histogram", "="*58)) symbolq = con.execute("select symbol, count(symbol) from gen_events group by symbol order by -count(symbol)") for row in symbolq: - print "%32s %8d %s" % (row[0], row[1], num2sym(row[1])) + print("%32s %8d %s" % (row[0], row[1], num2sym(row[1]))) # Group by dso - print "\n%40s %8s %16s\n%s" % ("dso", "number", "histogram", "="*74) + print("\n%40s %8s %16s\n%s" % ("dso", "number", "histogram", "="*74)) dsoq = con.execute("select dso, count(dso) from gen_events group by dso order by -count(dso)") for row in dsoq: - print "%40s %8d %s" % (row[0], row[1], num2sym(row[1])) + print("%40s %8d %s" % (row[0], row[1], num2sym(row[1]))) # # This function just shows the basic info, and we could do more with the @@ -156,35 +158,35 @@ def show_pebs_ll(): count = con.execute("select count(*) from pebs_ll") for t in count: - print "There is %d records in pebs_ll table" % t[0] + print("There is %d records in pebs_ll table" % t[0]) if t[0] == 0: return - print "Statistics about the PEBS Load Latency events grouped by thread/symbol/dse/latency: \n" + print("Statistics about the PEBS Load Latency events grouped by thread/symbol/dse/latency: \n") # Group by thread commq = con.execute("select comm, count(comm) from pebs_ll group by comm order by -count(comm)") - print "\n%16s %8s %16s\n%s" % ("comm", "number", "histogram", "="*42) + print("\n%16s %8s %16s\n%s" % ("comm", "number", "histogram", "="*42)) for row in commq: - print "%16s %8d %s" % (row[0], row[1], num2sym(row[1])) + print("%16s %8d %s" % (row[0], row[1], num2sym(row[1]))) # Group by symbol - print "\n%32s %8s %16s\n%s" % ("symbol", "number", "histogram", "="*58) + print("\n%32s %8s %16s\n%s" % ("symbol", "number", "histogram", "="*58)) symbolq = con.execute("select symbol, count(symbol) from pebs_ll group by symbol order by -count(symbol)") for row in symbolq: - print "%32s %8d %s" % (row[0], row[1], num2sym(row[1])) + print("%32s %8d %s" % (row[0], row[1], num2sym(row[1]))) # Group by dse dseq = con.execute("select dse, count(dse) from pebs_ll group by dse order by -count(dse)") - print "\n%32s %8s %16s\n%s" % ("dse", "number", "histogram", "="*58) + print("\n%32s %8s %16s\n%s" % ("dse", "number", "histogram", "="*58)) for row in dseq: - print "%32s %8d %s" % (row[0], row[1], num2sym(row[1])) + print("%32s %8d %s" % (row[0], row[1], num2sym(row[1]))) # Group by latency latq = con.execute("select lat, count(lat) from pebs_ll group by lat order by lat") - print "\n%32s %8s %16s\n%s" % ("latency", "number", "histogram", "="*58) + print("\n%32s %8s %16s\n%s" % ("latency", "number", "histogram", "="*58)) for row in latq: - print "%32s %8d %s" % (row[0], row[1], num2sym(row[1])) + print("%32s %8d %s" % (row[0], row[1], num2sym(row[1]))) def trace_unhandled(event_name, context, event_fields_dict): - print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())]) + print (' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])) From fdf2460c297f1bb2f3bd20b3b52903b267af9050 Mon Sep 17 00:00:00 2001 From: Tony Jones Date: Tue, 5 Mar 2019 08:19:02 -0800 Subject: [PATCH 28/35] perf script python: Add Python3 support to intel-pt-events.py Support both Python2 and Python3 in the intel-pt-events.py script There may be differences in the ordering of output lines due to differences in dictionary ordering etc. However the format within lines should be unchanged. The use of 'from __future__' implies the minimum supported Python2 version is now v2.6 Signed-off-by: Tony Jones Acked-by: Adrian Hunter Link: http://lkml.kernel.org/r/fd26acf9-0c0f-717f-9664-a3c33043ce19@suse.de Signed-off-by: Seeteena Thoufeek Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/intel-pt-events.py | 32 ++++++++++++-------- 1 file changed, 19 insertions(+), 13 deletions(-) diff --git a/tools/perf/scripts/python/intel-pt-events.py b/tools/perf/scripts/python/intel-pt-events.py index 2177722f509e..a73847c8f548 100644 --- a/tools/perf/scripts/python/intel-pt-events.py +++ b/tools/perf/scripts/python/intel-pt-events.py @@ -10,6 +10,8 @@ # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for # more details. +from __future__ import print_function + import os import sys import struct @@ -22,34 +24,34 @@ sys.path.append(os.environ['PERF_EXEC_PATH'] + \ #from Core import * def trace_begin(): - print "Intel PT Power Events and PTWRITE" + print("Intel PT Power Events and PTWRITE") def trace_end(): - print "End" + print("End") def trace_unhandled(event_name, context, event_fields_dict): - print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())]) + print(' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])) def print_ptwrite(raw_buf): data = struct.unpack_from("> 32) & 0x3 - print "hints: %#x extensions: %#x" % (hints, extensions), + print("hints: %#x extensions: %#x" % (hints, extensions), end=' ') def print_pwre(raw_buf): data = struct.unpack_from("> 7) & 1 cstate = (payload >> 12) & 0xf subcstate = (payload >> 8) & 0xf - print "hw: %u cstate: %u sub-cstate: %u" % (hw, cstate, subcstate), + print("hw: %u cstate: %u sub-cstate: %u" % (hw, cstate, subcstate), + end=' ') def print_exstop(raw_buf): data = struct.unpack_from("> 4) & 0xf wake_reason = (payload >> 8) & 0xf - print "deepest cstate: %u last cstate: %u wake reason: %#x" % (deepest_cstate, last_cstate, wake_reason), + print("deepest cstate: %u last cstate: %u wake reason: %#x" % + (deepest_cstate, last_cstate, wake_reason), end=' ') def print_common_start(comm, sample, name): ts = sample["time"] cpu = sample["cpu"] pid = sample["pid"] tid = sample["tid"] - print "%16s %5u/%-5u [%03u] %9u.%09u %7s:" % (comm, pid, tid, cpu, ts / 1000000000, ts %1000000000, name), + print("%16s %5u/%-5u [%03u] %9u.%09u %7s:" % + (comm, pid, tid, cpu, ts / 1000000000, ts %1000000000, name), + end=' ') def print_common_ip(sample, symbol, dso): ip = sample["ip"] - print "%16x %s (%s)" % (ip, symbol, dso) + print("%16x %s (%s)" % (ip, symbol, dso)) def process_event(param_dict): event_attr = param_dict["attr"] @@ -92,12 +98,12 @@ def process_event(param_dict): name = param_dict["ev_name"] # Symbol and dso info are not always resolved - if (param_dict.has_key("dso")): + if "dso" in param_dict: dso = param_dict["dso"] else: dso = "[unknown]" - if (param_dict.has_key("symbol")): + if "symbol" in param_dict: symbol = param_dict["symbol"] else: symbol = "[unknown]" From e34c940245437f36d2c492edd1f8237eff391064 Mon Sep 17 00:00:00 2001 From: Jiri Olsa Date: Tue, 5 Mar 2019 16:25:29 +0100 Subject: [PATCH 29/35] perf c2c: Fix c2c report for empty numa node Ravi Bangoria reported that we fail with an empty NUMA node with the following message: $ lscpu NUMA node0 CPU(s): NUMA node1 CPU(s): 0-4 $ sudo ./perf c2c report node/cpu topology bugFailed setup nodes Fix this by detecting the empty node and keeping its CPU set empty. Reported-by: Nageswara R Sastry Signed-off-by: Jiri Olsa Tested-by: Ravi Bangoria Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jonas Rabenstein Cc: Namhyung Kim Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/20190305152536.21035-2-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-c2c.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/tools/perf/builtin-c2c.c b/tools/perf/builtin-c2c.c index 4272763a5e96..9e6cc868bdb4 100644 --- a/tools/perf/builtin-c2c.c +++ b/tools/perf/builtin-c2c.c @@ -2056,6 +2056,12 @@ static int setup_nodes(struct perf_session *session) if (!set) return -ENOMEM; + nodes[node] = set; + + /* empty node, skip */ + if (cpu_map__empty(map)) + continue; + for (cpu = 0; cpu < map->nr; cpu++) { set_bit(map->map[cpu], set); @@ -2064,8 +2070,6 @@ static int setup_nodes(struct perf_session *session) cpu2node[map->map[cpu]] = node; } - - nodes[node] = set; } setup_nodes_header(); From c57589106fd6d996dbf3757708baa4a3fb91850f Mon Sep 17 00:00:00 2001 From: Jiri Olsa Date: Tue, 5 Mar 2019 16:25:30 +0100 Subject: [PATCH 30/35] perf hist: Add error path into hist_entry__init Adding error path into hist_entry__init to unify error handling, so every new member does not need to free everything else. Signed-off-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jonas Rabenstein Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Ravi Bangoria Cc: nageswara r sastry Link: http://lkml.kernel.org/r/20190305152536.21035-3-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/hist.c | 39 +++++++++++++++++++-------------------- 1 file changed, 19 insertions(+), 20 deletions(-) diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c index 669f961316f0..74e307d17c49 100644 --- a/tools/perf/util/hist.c +++ b/tools/perf/util/hist.c @@ -396,11 +396,8 @@ static int hist_entry__init(struct hist_entry *he, * adding new entries. So we need to save a copy. */ he->branch_info = malloc(sizeof(*he->branch_info)); - if (he->branch_info == NULL) { - map__zput(he->ms.map); - free(he->stat_acc); - return -ENOMEM; - } + if (he->branch_info == NULL) + goto err; memcpy(he->branch_info, template->branch_info, sizeof(*he->branch_info)); @@ -419,21 +416,8 @@ static int hist_entry__init(struct hist_entry *he, if (he->raw_data) { he->raw_data = memdup(he->raw_data, he->raw_size); - - if (he->raw_data == NULL) { - map__put(he->ms.map); - if (he->branch_info) { - map__put(he->branch_info->from.map); - map__put(he->branch_info->to.map); - free(he->branch_info); - } - if (he->mem_info) { - map__put(he->mem_info->iaddr.map); - map__put(he->mem_info->daddr.map); - } - free(he->stat_acc); - return -ENOMEM; - } + if (he->raw_data == NULL) + goto err_infos; } INIT_LIST_HEAD(&he->pairs.node); thread__get(he->thread); @@ -444,6 +428,21 @@ static int hist_entry__init(struct hist_entry *he, he->leaf = true; return 0; + +err_infos: + if (he->branch_info) { + map__put(he->branch_info->from.map); + map__put(he->branch_info->to.map); + free(he->branch_info); + } + if (he->mem_info) { + map__put(he->mem_info->iaddr.map); + map__put(he->mem_info->daddr.map); + } +err: + map__zput(he->ms.map); + free(he->stat_acc); + return -ENOMEM; } static void *hist_entry__zalloc(size_t size) From 2634958586368dcbf09c0d2a17dee02d1fc53e0d Mon Sep 17 00:00:00 2001 From: Jiri Olsa Date: Tue, 5 Mar 2019 16:25:31 +0100 Subject: [PATCH 31/35] perf hist: Fix memory leak of srcline We can't allocate he->srcline unconditionaly, only when new hist_entry is created. Moving he->srcline allocation into hist_entry__init function. Original-patch-by: Jonas Rabenstein Suggested-by: Namhyung Kim Signed-off-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Nageswara R Sastry Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Ravi Bangoria Link: http://lkml.kernel.org/r/20190305152536.21035-4-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/hist.c | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/tools/perf/util/hist.c b/tools/perf/util/hist.c index 74e307d17c49..f9eb95bf3938 100644 --- a/tools/perf/util/hist.c +++ b/tools/perf/util/hist.c @@ -419,6 +419,13 @@ static int hist_entry__init(struct hist_entry *he, if (he->raw_data == NULL) goto err_infos; } + + if (he->srcline) { + he->srcline = strdup(he->srcline); + if (he->srcline == NULL) + goto err_rawdata; + } + INIT_LIST_HEAD(&he->pairs.node); thread__get(he->thread); he->hroot_in = RB_ROOT_CACHED; @@ -429,6 +436,9 @@ static int hist_entry__init(struct hist_entry *he, return 0; +err_rawdata: + free(he->raw_data); + err_infos: if (he->branch_info) { map__put(he->branch_info->from.map); @@ -605,7 +615,7 @@ __hists__add_entry(struct hists *hists, .map = al->map, .sym = al->sym, }, - .srcline = al->srcline ? strdup(al->srcline) : NULL, + .srcline = (char *) al->srcline, .socket = al->socket, .cpu = al->cpu, .cpumode = al->cpumode, @@ -962,7 +972,7 @@ iter_add_next_cumulative_entry(struct hist_entry_iter *iter, .map = al->map, .sym = al->sym, }, - .srcline = al->srcline ? strdup(al->srcline) : NULL, + .srcline = (char *) al->srcline, .parent = iter->parent, .raw_data = sample->raw_data, .raw_size = sample->raw_size, From 90a86bde97ba050cb3c9ccb215252ee2d2d705fa Mon Sep 17 00:00:00 2001 From: Jiri Olsa Date: Tue, 5 Mar 2019 16:25:32 +0100 Subject: [PATCH 32/35] perf tools: Read and store caps/max_precise in perf_pmu Read the caps/max_precise value and store it in struct perf_pmu to be used when setting the maximum precise_ip field in following patch. Signed-off-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jonas Rabenstein Cc: Nageswara R Sastry Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Ravi Bangoria Link: http://lkml.kernel.org/r/20190305152536.21035-5-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/pmu.c | 14 ++++++++++++++ tools/perf/util/pmu.h | 1 + 2 files changed, 15 insertions(+) diff --git a/tools/perf/util/pmu.c b/tools/perf/util/pmu.c index 51d437f55d18..6199a3174ab9 100644 --- a/tools/perf/util/pmu.c +++ b/tools/perf/util/pmu.c @@ -752,6 +752,19 @@ perf_pmu__get_default_config(struct perf_pmu *pmu __maybe_unused) return NULL; } +static int pmu_max_precise(const char *name) +{ + char path[PATH_MAX]; + int max_precise = -1; + + scnprintf(path, PATH_MAX, + "bus/event_source/devices/%s/caps/max_precise", + name); + + sysfs__read_int(path, &max_precise); + return max_precise; +} + static struct perf_pmu *pmu_lookup(const char *name) { struct perf_pmu *pmu; @@ -784,6 +797,7 @@ static struct perf_pmu *pmu_lookup(const char *name) pmu->name = strdup(name); pmu->type = type; pmu->is_uncore = pmu_is_uncore(name); + pmu->max_precise = pmu_max_precise(name); pmu_add_cpu_aliases(&aliases, pmu); INIT_LIST_HEAD(&pmu->format); diff --git a/tools/perf/util/pmu.h b/tools/perf/util/pmu.h index 47253c3daf55..bd9ec2704a57 100644 --- a/tools/perf/util/pmu.h +++ b/tools/perf/util/pmu.h @@ -26,6 +26,7 @@ struct perf_pmu { __u32 type; bool selectable; bool is_uncore; + int max_precise; struct perf_event_attr *default_config; struct cpu_map *cpus; struct list_head format; /* HEAD struct perf_pmu_format -> list */ From 5b61adb16599be04346e7e943c1b5113b57485ad Mon Sep 17 00:00:00 2001 From: Jiri Olsa Date: Tue, 5 Mar 2019 16:25:34 +0100 Subject: [PATCH 33/35] perf evsel: Probe for precise_ip with simple attr Currently we probe for precise_ip with user specified perf_event_attr, which might fail because of unsupported kernel features, which would get disabled during the open time anyway. Switching the probe to take place on simple hw cycles, so the following record sets proper precise_ip: # perf record -e cycles:P ls # perf evlist -v cycles:P: size: 112, ... precise_ip: 3, ... Signed-off-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jonas Rabenstein Cc: Nageswara R Sastry Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Ravi Bangoria Link: http://lkml.kernel.org/r/20190305152536.21035-7-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/evlist.c | 25 ++++++++++++++++++++----- tools/perf/util/evsel.c | 8 -------- 2 files changed, 20 insertions(+), 13 deletions(-) diff --git a/tools/perf/util/evlist.c b/tools/perf/util/evlist.c index 08cedb643ea6..ed20f4379956 100644 --- a/tools/perf/util/evlist.c +++ b/tools/perf/util/evlist.c @@ -230,18 +230,33 @@ void perf_evlist__set_leader(struct perf_evlist *evlist) } } -void perf_event_attr__set_max_precise_ip(struct perf_event_attr *attr) +void perf_event_attr__set_max_precise_ip(struct perf_event_attr *pattr) { - attr->precise_ip = 3; + struct perf_event_attr attr = { + .type = PERF_TYPE_HARDWARE, + .config = PERF_COUNT_HW_CPU_CYCLES, + .exclude_kernel = 1, + .precise_ip = 3, + }; - while (attr->precise_ip != 0) { - int fd = sys_perf_event_open(attr, 0, -1, -1, 0); + event_attr_init(&attr); + + /* + * Unnamed union member, not supported as struct member named + * initializer in older compilers such as gcc 4.4.7 + */ + attr.sample_period = 1; + + while (attr.precise_ip != 0) { + int fd = sys_perf_event_open(&attr, 0, -1, -1, 0); if (fd != -1) { close(fd); break; } - --attr->precise_ip; + --attr.precise_ip; } + + pattr->precise_ip = attr.precise_ip; } int __perf_evlist__add_default(struct perf_evlist *evlist, bool precise) diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c index dfe2958e6287..3bbf73e979c0 100644 --- a/tools/perf/util/evsel.c +++ b/tools/perf/util/evsel.c @@ -294,20 +294,12 @@ struct perf_evsel *perf_evsel__new_cycles(bool precise) if (!precise) goto new_event; - /* - * Unnamed union member, not supported as struct member named - * initializer in older compilers such as gcc 4.4.7 - * - * Just for probing the precise_ip: - */ - attr.sample_period = 1; perf_event_attr__set_max_precise_ip(&attr); /* * Now let the usual logic to set up the perf_event_attr defaults * to kick in when we return and before perf_evsel__open() is called. */ - attr.sample_period = 0; new_event: evsel = perf_evsel__new(&attr); if (evsel == NULL) From befa09b61f8bf1d7c34b8e6405f08d804640573c Mon Sep 17 00:00:00 2001 From: Jiri Olsa Date: Tue, 5 Mar 2019 16:25:35 +0100 Subject: [PATCH 34/35] perf session: Fix double free in perf_data__close We can't call perf_data__close and subsequently perf_session__delete, because it will call perf_data__close again and cause double free for data->file.path. $ perf report -i . incompatible file format (rerun with -v to learn more) free(): double free detected in tcache 2 Aborted (core dumped) In fact we don't need to call perf_data__close at all, because at the time the got out_close is reached, session->data is already initialized, so the perf_data__close call will be triggered from perf_session__delete. Signed-off-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jonas Rabenstein Cc: Nageswara R Sastry Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Ravi Bangoria Fixes: 2d4f27999b88 ("perf data: Add global path holder") Link: http://lkml.kernel.org/r/20190305152536.21035-8-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/session.c | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c index c764bbc91009..db643f3c2b95 100644 --- a/tools/perf/util/session.c +++ b/tools/perf/util/session.c @@ -140,7 +140,7 @@ struct perf_session *perf_session__new(struct perf_data *data, if (perf_data__is_read(data)) { if (perf_session__open(session) < 0) - goto out_close; + goto out_delete; /* * set session attributes that are present in perf.data @@ -181,8 +181,6 @@ struct perf_session *perf_session__new(struct perf_data *data, return session; - out_close: - perf_data__close(data); out_delete: perf_session__delete(session); out: From b8f7d86b5849ea7bb84bddc0345a3799049764d4 Mon Sep 17 00:00:00 2001 From: Jiri Olsa Date: Tue, 5 Mar 2019 16:25:36 +0100 Subject: [PATCH 35/35] perf data: Force perf_data__open|close zero data->file.path Making sure the data->file.path is zeroed on perf_data__open error path and in perf_data__close, so we don't double free it in case someone call it twice. Signed-off-by: Jiri Olsa Cc: Alexander Shishkin Cc: Andi Kleen Cc: Jonas Rabenstein Cc: Nageswara R Sastry Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Ravi Bangoria Link: http://lkml.kernel.org/r/20190305152536.21035-9-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/data.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tools/perf/util/data.c b/tools/perf/util/data.c index 7bd5ddeb7a41..e098e189f93e 100644 --- a/tools/perf/util/data.c +++ b/tools/perf/util/data.c @@ -237,7 +237,7 @@ static int open_file(struct perf_data *data) open_file_read(data) : open_file_write(data); if (fd < 0) { - free(data->file.path); + zfree(&data->file.path); return -1; } @@ -270,7 +270,7 @@ int perf_data__open(struct perf_data *data) void perf_data__close(struct perf_data *data) { - free(data->file.path); + zfree(&data->file.path); close(data->file.fd); }