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>

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 484ce60..48588cc 100644 (file)
--- 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 317a265..05616d4 100644 (file)
--- 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);