diff options
author | Adrian Hunter <adrian.hunter@intel.com> | 2020-09-09 10:49:22 +0200 |
---|---|---|
committer | Arnaldo Carvalho de Melo <acme@redhat.com> | 2020-09-17 21:06:22 +0200 |
commit | fc18380fb9d2f2f0f16b04e3fbaa1fa286776b01 (patch) | |
tree | d167ab0c2e204db557cffb64dfc9e3659c8fe4ea /tools | |
parent | perf docs: Improve help information in perf.txt (diff) | |
download | linux-fc18380fb9d2f2f0f16b04e3fbaa1fa286776b01.tar.xz linux-fc18380fb9d2f2f0f16b04e3fbaa1fa286776b01.zip |
perf script: Display negative tid in non-sample events
The kernel can release tasks while they are still running. This can
result in a task having no tid, in which case perf records a tid of -1.
Improve the perf script output in that case.
Example:
Before:
# cat ./autoreap.c
#include <sys/types.h>
#include <unistd.h>
#include <sys/wait.h>
#include <signal.h>
struct sigaction act = {
.sa_handler = SIG_IGN,
};
int main()
{
pid_t child;
int status = 0;
sigaction(SIGCHLD, &act, NULL);
child = fork();
if (child == 0)
return 123;
wait(&status);
return 0;
}
# gcc -o autoreap autoreap.c
# ./perf record -a -e dummy --switch-events ./autoreap
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.948 MB perf.data ]
# ./perf script --show-task-events --show-switch-events | grep -C2 'autoreap\|4294967295\|-1'
swapper 0 [004] 18462.673613: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 25189/25189
perf 25189 [004] 18462.673614: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
autoreap 25189 [004] 18462.673800: PERF_RECORD_COMM exec: autoreap:25189/25189
autoreap 25189 [004] 18462.674042: PERF_RECORD_FORK(25191:25191):(25189:25189)
autoreap 25189 [004] 18462.674050: PERF_RECORD_SWITCH_CPU_WIDE OUT next pid/tid: 0/0
swapper 0 [004] 18462.674051: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 25189/25189
swapper 0 [005] 18462.674083: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 25191/25191
autoreap 25191 [005] 18462.674084: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
swapper 0 [003] 18462.674121: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 11/11
rcu_preempt 11 [003] 18462.674121: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
rcu_preempt 11 [003] 18462.674124: PERF_RECORD_SWITCH_CPU_WIDE OUT next pid/tid: 0/0
swapper 0 [003] 18462.674124: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 11/11
autoreap 25191 [005] 18462.674138: PERF_RECORD_EXIT(25191:25191):(25189:25189)
PERF_RECORD_SWITCH_CPU_WIDE OUT next pid/tid: 0/0
swapper 0 [005] 18462.674149: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 4294967295/4294967295
swapper 0 [004] 18462.674182: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 25189/25189
autoreap 25189 [004] 18462.674183: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
autoreap 25189 [004] 18462.674218: PERF_RECORD_EXIT(25189:25189):(25188:25188)
autoreap 25189 [004] 18462.674225: PERF_RECORD_SWITCH_CPU_WIDE OUT next pid/tid: 0/0
swapper 0 [004] 18462.674226: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 25189/25189
swapper 0 [007] 18462.674257: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 25188/25188
After:
# ./perf script --show-task-events --show-switch-events | grep -C2 'autoreap\|4294967295\|-1'
swapper 0 [004] 18462.673613: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 25189/25189
perf 25189 [004] 18462.673614: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
autoreap 25189 [004] 18462.673800: PERF_RECORD_COMM exec: autoreap:25189/25189
autoreap 25189 [004] 18462.674042: PERF_RECORD_FORK(25191:25191):(25189:25189)
autoreap 25189 [004] 18462.674050: PERF_RECORD_SWITCH_CPU_WIDE OUT next pid/tid: 0/0
swapper 0 [004] 18462.674051: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 25189/25189
swapper 0 [005] 18462.674083: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 25191/25191
autoreap 25191 [005] 18462.674084: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
swapper 0 [003] 18462.674121: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 11/11
rcu_preempt 11 [003] 18462.674121: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
rcu_preempt 11 [003] 18462.674124: PERF_RECORD_SWITCH_CPU_WIDE OUT next pid/tid: 0/0
swapper 0 [003] 18462.674124: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 11/11
autoreap 25191 [005] 18462.674138: PERF_RECORD_EXIT(25191:25191):(25189:25189)
:-1 -1 [005] 18462.674149: PERF_RECORD_SWITCH_CPU_WIDE OUT next pid/tid: 0/0
swapper 0 [005] 18462.674149: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: -1/-1
swapper 0 [004] 18462.674182: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 25189/25189
autoreap 25189 [004] 18462.674183: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
autoreap 25189 [004] 18462.674218: PERF_RECORD_EXIT(25189:25189):(25188:25188)
autoreap 25189 [004] 18462.674225: PERF_RECORD_SWITCH_CPU_WIDE OUT next pid/tid: 0/0
swapper 0 [004] 18462.674226: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 25189/25189
swapper 0 [007] 18462.674257: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt next pid/tid: 25188/25188
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Yu-cheng Yu <yu-cheng.yu@intel.com>
Link: http://lore.kernel.org/lkml/20200909084923.9096-2-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Diffstat (limited to 'tools')
-rw-r--r-- | tools/perf/builtin-script.c | 10 | ||||
-rw-r--r-- | tools/perf/util/event.c | 2 |
2 files changed, 7 insertions, 5 deletions
diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c index 484ce6067d23..48588ccf902e 100644 --- a/tools/perf/builtin-script.c +++ b/tools/perf/builtin-script.c @@ -702,12 +702,14 @@ static int perf_sample__fprintf_start(struct perf_script *script, char tstr[128]; if (PRINT_FIELD(COMM)) { + const char *comm = thread ? thread__comm_str(thread) : ":-1"; + if (latency_format) - printed += fprintf(fp, "%8.8s ", thread__comm_str(thread)); + printed += fprintf(fp, "%8.8s ", comm); else if (PRINT_FIELD(IP) && evsel__has_callchain(evsel) && symbol_conf.use_callchain) - printed += fprintf(fp, "%s ", thread__comm_str(thread)); + printed += fprintf(fp, "%s ", comm); else - printed += fprintf(fp, "%16s ", thread__comm_str(thread)); + printed += fprintf(fp, "%16s ", comm); } if (PRINT_FIELD(PID) && PRINT_FIELD(TID)) @@ -2238,7 +2240,7 @@ static int print_event_with_time(struct perf_tool *tool, if (tid != -1) thread = machine__findnew_thread(machine, pid, tid); - if (thread && evsel) { + if (evsel) { perf_sample__fprintf_start(script, sample, thread, evsel, event->header.type, stdout); } diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c index 317a26571845..05616d4138a9 100644 --- a/tools/perf/util/event.c +++ b/tools/perf/util/event.c @@ -398,7 +398,7 @@ size_t perf_event__fprintf_switch(union perf_event *event, FILE *fp) if (event->header.type == PERF_RECORD_SWITCH) return fprintf(fp, " %s\n", in_out); - return fprintf(fp, " %s %s pid/tid: %5u/%-5u\n", + return fprintf(fp, " %s %s pid/tid: %5d/%-5d\n", in_out, out ? "next" : "prev", event->context_switch.next_prev_pid, event->context_switch.next_prev_tid); |