From 172bf02d564bdb6df8410f64720fa2c68e755d1a Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Mon, 7 Jan 2019 16:24:27 -0300 Subject: perf trace: Fix ')' placement in "interrupted" syscall lines MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When we get the sys_enter for a syscall we check if the last one is still waiting for its matching sys_exit, if so we print this: 468.753 ( ): firefox/32382 poll(ufds: 0x7f3988d3dd00, nfds: 7, timeout_msecs: 4294967295) ... 449.575 ( 0.004 ms): Softwar~cThrea/32434 futex(uaddr: 0x7f39a18a9b70, op: WAKE|PRIVATE_FLAG, val: 1) = 0 At some point we'll get that poll sys_exit event and will print a "[continued]" line. While making the sizing of the alignment after the syscall arg list and its result configurable, so that we can mimic strace, which uses a smaller alingment by default, a bug was introduced where the closing parens appeared before the syscall name and its arg list, fix it. Fixes: 4b8a240ed5e0 ("perf trace: Add alignment spaces after the closing parens") Cc: Adrian Hunter Cc: Jiri Olsa Cc: Luis Cláudio Gonçalves Cc: Namhyung Kim Cc: Wang Nan Link: https://lkml.kernel.org/n/tip-oi45i54s59h1w1kmgpzrfuum@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-trace.c | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) (limited to 'tools/perf/builtin-trace.c') diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c index adbf28183560..b8bf5d025563 100644 --- a/tools/perf/builtin-trace.c +++ b/tools/perf/builtin-trace.c @@ -1758,6 +1758,7 @@ static int trace__printf_interrupted_entry(struct trace *trace) { struct thread_trace *ttrace; size_t printed; + int len; if (trace->failure_only || trace->current == NULL) return 0; @@ -1768,9 +1769,14 @@ static int trace__printf_interrupted_entry(struct trace *trace) return 0; printed = trace__fprintf_entry_head(trace, trace->current, 0, false, ttrace->entry_time, trace->output); - printed += fprintf(trace->output, ")%-*s ...\n", trace->args_alignment, ttrace->entry_str); - ttrace->entry_pending = false; + printed += len = fprintf(trace->output, "%s)", ttrace->entry_str); + + if (len < trace->args_alignment - 4) + printed += fprintf(trace->output, "%-*s", trace->args_alignment - 4 - len, " "); + printed += fprintf(trace->output, " ...\n"); + + ttrace->entry_pending = false; ++trace->nr_events_printed; return printed; -- cgit v1.2.3 From ac6e022cbfdce215ad545e91d9827060855da3d7 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Mon, 7 Jan 2019 16:54:38 -0300 Subject: perf trace: Fix alignment for [continued] lines MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit We were not taking into account the "... [continued]" printed characters, fix it. Cc: Adrian Hunter Cc: Jiri Olsa Cc: Luis Cláudio Gonçalves Cc: Namhyung Kim Cc: Wang Nan Link: https://lkml.kernel.org/n/tip-qt20y0acmf8k0bzisce8kw95@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-trace.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) (limited to 'tools/perf/builtin-trace.c') diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c index b8bf5d025563..ed4583128b9c 100644 --- a/tools/perf/builtin-trace.c +++ b/tools/perf/builtin-trace.c @@ -2032,9 +2032,10 @@ static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel, if (ttrace->entry_pending) { printed = fprintf(trace->output, "%s", ttrace->entry_str); } else { - fprintf(trace->output, " ... ["); + printed += fprintf(trace->output, " ... ["); color_fprintf(trace->output, PERF_COLOR_YELLOW, "continued"); - fprintf(trace->output, "]: %s()", sc->name); + printed += 9; + printed += fprintf(trace->output, "]: %s()", sc->name); } printed++; /* the closing ')' */ -- cgit v1.2.3 From 6ab3bc240ade47a0f52bc16d97edd9accbe0024e Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Tue, 29 Jan 2019 15:12:34 +0100 Subject: perf trace: Support multiple "vfs_getname" probes With a suitably defined "probe:vfs_getname" probe, 'perf trace' can "beautify" its output, so syscalls like open() or openat() can print the "filename" argument instead of just its hex address, like: $ perf trace -e open -- touch /dev/null [...] 0.590 ( 0.014 ms): touch/18063 open(filename: /dev/null, flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3 [...] The output without such beautifier looks like: 0.529 ( 0.011 ms): touch/18075 open(filename: 0xc78cf288, flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3 However, when the vfs_getname probe expands to multiple probes and it is not the first one that is hit, the beautifier fails, as following: 0.326 ( 0.010 ms): touch/18072 open(filename: , flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3 Fix it by hooking into all the expanded probes (inlines), now, for instance: [root@quaco ~]# perf probe -l probe:vfs_getname (on getname_flags:73@fs/namei.c with pathname) probe:vfs_getname_1 (on getname_flags:73@fs/namei.c with pathname) [root@quaco ~]# perf trace -e open* sleep 1 0.010 ( 0.005 ms): sleep/5588 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: RDONLY|CLOEXEC) = 3 0.029 ( 0.006 ms): sleep/5588 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: RDONLY|CLOEXEC) = 3 0.194 ( 0.008 ms): sleep/5588 openat(dfd: CWD, filename: /usr/lib/locale/locale-archive, flags: RDONLY|CLOEXEC) = 3 [root@quaco ~]# Works, further verified with: [root@quaco ~]# perf test vfs 65: Use vfs_getname probe to get syscall args filenames : Ok 66: Add vfs_getname probe to get syscall args filenames : Ok 67: Check open filename arg using perf trace + vfs_getname: Ok [root@quaco ~]# Reported-by: Michael Petlan Tested-by: Michael Petlan Cc: Adrian Hunter Cc: Jiri Olsa Cc: Namhyung Kim Link: https://lkml.kernel.org/n/tip-mv8kolk17xla1smvmp3qabv1@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-trace.c | 25 ++++++++++++++++++------- 1 file changed, 18 insertions(+), 7 deletions(-) (limited to 'tools/perf/builtin-trace.c') diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c index ed4583128b9c..b36061cd1ab8 100644 --- a/tools/perf/builtin-trace.c +++ b/tools/perf/builtin-trace.c @@ -2514,19 +2514,30 @@ static size_t trace__fprintf_thread_summary(struct trace *trace, FILE *fp); static bool perf_evlist__add_vfs_getname(struct perf_evlist *evlist) { - struct perf_evsel *evsel = perf_evsel__newtp("probe", "vfs_getname"); + bool found = false; + struct perf_evsel *evsel, *tmp; + struct parse_events_error err = { .idx = 0, }; + int ret = parse_events(evlist, "probe:vfs_getname*", &err); - if (IS_ERR(evsel)) + if (ret) return false; - if (perf_evsel__field(evsel, "pathname") == NULL) { + evlist__for_each_entry_safe(evlist, evsel, tmp) { + if (!strstarts(perf_evsel__name(evsel), "probe:vfs_getname")) + continue; + + if (perf_evsel__field(evsel, "pathname")) { + evsel->handler = trace__vfs_getname; + found = true; + continue; + } + + list_del_init(&evsel->node); + evsel->evlist = NULL; perf_evsel__delete(evsel); - return false; } - evsel->handler = trace__vfs_getname; - perf_evlist__add(evlist, evsel); - return true; + return found; } static struct perf_evsel *perf_evsel__new_pgfault(u64 config) -- cgit v1.2.3