linux/tools/perf
Adrian Hunter 1b4aa9313f perf intel-pt: Fix "context_switch event has no tid" error
[ Upstream commit 7d537a8d2e ]

A context_switch event can have no tid because pids can be detached from
a task while the task is still running (in do_exit()). Note this won't
happen with per-task contexts because then tracing stops at
perf_event_exit_task()

If a task with no tid gets preempted, or a dying task gets preempted and
its parent releases it, when it subsequently gets switched back in,
Intel PT will not be able to determine what task is running and prints
an error "context_switch event has no tid". However, it is not really an
error because the task is in kernel space and the decoder can continue
to decode successfully. Fix by changing the error to be only a logged
message, and make allowance for tid == -1.

Example:

  Using 5.9-rc4 with Preemptible Kernel (Low-Latency Desktop) e.g.
  $ uname -r
  5.9.0-rc4
  $ grep PREEMPT .config
  # CONFIG_PREEMPT_NONE is not set
  # CONFIG_PREEMPT_VOLUNTARY is not set
  CONFIG_PREEMPT=y
  CONFIG_PREEMPT_COUNT=y
  CONFIG_PREEMPTION=y
  CONFIG_PREEMPT_RCU=y
  CONFIG_PREEMPT_NOTIFIERS=y
  CONFIG_DRM_I915_PREEMPT_TIMEOUT=640
  CONFIG_DEBUG_PREEMPT=y
  # CONFIG_PREEMPT_TRACER is not set
  # CONFIG_PREEMPTIRQ_DELAY_TEST is not set

Before:

  $ cat forkit.c

  #include <sys/types.h>
  #include <unistd.h>
  #include <sys/wait.h>

  int main()
  {
          pid_t child;
          int status = 0;

          child = fork();
          if (child == 0)
                  return 123;
          wait(&status);
          return 0;
  }

  $ gcc -o forkit forkit.c
  $ sudo ~/bin/perf record --kcore -a -m,64M -e intel_pt/cyc/k &
  [1] 11016
  $ taskset 2 ./forkit
  $ sudo pkill perf
  $ [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 17.262 MB perf.data ]

  [1]+  Terminated              sudo ~/bin/perf record --kcore -a -m,64M -e intel_pt/cyc/k
  $ sudo ~/bin/perf script --show-task-events --show-switch-events --itrace=iqqe-o -C 1 --ns | grep -C 2 forkit
  context_switch event has no tid
           taskset 11019 [001] 66663.270045029:          1 instructions:k:  ffffffffb1d9f844 strnlen_user+0xb4 ([kernel.kallsyms])
           taskset 11019 [001] 66663.270201816:          1 instructions:k:  ffffffffb1a83121 unmap_page_range+0x561 ([kernel.kallsyms])
            forkit 11019 [001] 66663.270327553: PERF_RECORD_COMM exec: forkit:11019/11019
            forkit 11019 [001] 66663.270420028:          1 instructions:k:  ffffffffb1db9537 __clear_user+0x27 ([kernel.kallsyms])
            forkit 11019 [001] 66663.270648704:          1 instructions:k:  ffffffffb18829e6 do_user_addr_fault+0xf6 ([kernel.kallsyms])
            forkit 11019 [001] 66663.270833163:          1 instructions:k:  ffffffffb230a825 irqentry_exit_to_user_mode+0x15 ([kernel.kallsyms])
            forkit 11019 [001] 66663.271092359:          1 instructions:k:  ffffffffb1aea3d9 lock_page_memcg+0x9 ([kernel.kallsyms])
            forkit 11019 [001] 66663.271207092: PERF_RECORD_FORK(11020:11020):(11019:11019)
            forkit 11019 [001] 66663.271234775: PERF_RECORD_SWITCH_CPU_WIDE OUT          next pid/tid: 11020/11020
            forkit 11020 [001] 66663.271238407: PERF_RECORD_SWITCH_CPU_WIDE IN           prev pid/tid: 11019/11019
            forkit 11020 [001] 66663.271312066:          1 instructions:k:  ffffffffb1a88140 handle_mm_fault+0x10 ([kernel.kallsyms])
            forkit 11020 [001] 66663.271476225: PERF_RECORD_EXIT(11020:11020):(11019:11019)
            forkit 11020 [001] 66663.271497488: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt  next pid/tid: 11019/11019
            forkit 11019 [001] 66663.271500523: PERF_RECORD_SWITCH_CPU_WIDE IN           prev pid/tid: 11020/11020
            forkit 11019 [001] 66663.271517241:          1 instructions:k:  ffffffffb24012cd error_entry+0x6d ([kernel.kallsyms])
            forkit 11019 [001] 66663.271664080: PERF_RECORD_EXIT(11019:11019):(1386:1386)

After:

  $ sudo ~/bin/perf script --show-task-events --show-switch-events --itrace=iqqe-o -C 1 --ns | grep -C 2 forkit
           taskset 11019 [001] 66663.270045029:          1 instructions:k:  ffffffffb1d9f844 strnlen_user+0xb4 ([kernel.kallsyms])
           taskset 11019 [001] 66663.270201816:          1 instructions:k:  ffffffffb1a83121 unmap_page_range+0x561 ([kernel.kallsyms])
            forkit 11019 [001] 66663.270327553: PERF_RECORD_COMM exec: forkit:11019/11019
            forkit 11019 [001] 66663.270420028:          1 instructions:k:  ffffffffb1db9537 __clear_user+0x27 ([kernel.kallsyms])
            forkit 11019 [001] 66663.270648704:          1 instructions:k:  ffffffffb18829e6 do_user_addr_fault+0xf6 ([kernel.kallsyms])
            forkit 11019 [001] 66663.270833163:          1 instructions:k:  ffffffffb230a825 irqentry_exit_to_user_mode+0x15 ([kernel.kallsyms])
            forkit 11019 [001] 66663.271092359:          1 instructions:k:  ffffffffb1aea3d9 lock_page_memcg+0x9 ([kernel.kallsyms])
            forkit 11019 [001] 66663.271207092: PERF_RECORD_FORK(11020:11020):(11019:11019)
            forkit 11019 [001] 66663.271234775: PERF_RECORD_SWITCH_CPU_WIDE OUT          next pid/tid: 11020/11020
            forkit 11020 [001] 66663.271238407: PERF_RECORD_SWITCH_CPU_WIDE IN           prev pid/tid: 11019/11019
            forkit 11020 [001] 66663.271312066:          1 instructions:k:  ffffffffb1a88140 handle_mm_fault+0x10 ([kernel.kallsyms])
            forkit 11020 [001] 66663.271476225: PERF_RECORD_EXIT(11020:11020):(11019:11019)
            forkit 11020 [001] 66663.271497488: PERF_RECORD_SWITCH_CPU_WIDE OUT preempt  next pid/tid: 11019/11019
            forkit 11019 [001] 66663.271500523: PERF_RECORD_SWITCH_CPU_WIDE IN           prev pid/tid: 11020/11020
            forkit 11019 [001] 66663.271517241:          1 instructions:k:  ffffffffb24012cd error_entry+0x6d ([kernel.kallsyms])
            forkit 11019 [001] 66663.271664080: PERF_RECORD_EXIT(11019:11019):(1386:1386)
            forkit 11019 [001] 66663.271688752: PERF_RECORD_SWITCH_CPU_WIDE OUT          next pid/tid:    -1/-1
               :-1    -1 [001] 66663.271692086: PERF_RECORD_SWITCH_CPU_WIDE IN           prev pid/tid: 11019/11019
                :-1    -1 [001] 66663.271707466:          1 instructions:k:  ffffffffb18eb096 update_load_avg+0x306 ([kernel.kallsyms])

Fixes: 86c2786994 ("perf intel-pt: Add support for PERF_RECORD_SWITCH")
Signed-off-by: Adrian Hunter <adrian.hunter@intel.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-3-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Sasha Levin <sashal@kernel.org>
2020-10-30 10:38:19 +01:00
..
arch perf tools: Propagate get_cpuid() error 2019-11-06 13:05:42 +01:00
bench perf bench mem: Always memset source before memcpy 2020-08-21 11:05:38 +02:00
Documentation perf record/stat: Explicitly call out event modifiers in the documentation 2020-09-09 19:04:22 +02:00
examples/bpf perf trace: Handle "bpf-output" events associated with "__augmented_syscalls__" BPF map 2018-08-08 15:55:57 -03:00
include/bpf perf bpf: Add wrappers to BPF_FUNC_probe_read(_str) functions 2018-08-08 15:55:57 -03:00
jvmti perf jvmti: Address gcc string overflow warning for strncpy() 2019-07-26 09:14:04 +02:00
pmu-events perf jevents: Fix leak of mapfile memory 2020-10-01 13:14:36 +02:00
python perf python: Make twatch.py work with both python2 and python3 2018-02-19 12:28:08 -03:00
scripts perf script python: Fix export-to-sqlite.py sample columns 2018-09-25 11:37:05 -03:00
tests perf test: Fix test trace+probe_vfs_getname.sh on s390 2020-10-01 13:14:34 +02:00
trace perf trace: Fix the selection for architectures to generate the errno name tables 2020-10-01 13:14:46 +02:00
ui perf hists browser: Restore ESC as "Zoom out" of DSO/thread/etc 2020-03-05 16:42:22 +01:00
util perf intel-pt: Fix "context_switch event has no tid" error 2020-10-30 10:38:19 +01:00
.gitignore perf tools: Add trace/beauty/generated/ into .gitignore 2018-02-05 13:58:02 -03:00
Build perf trace: Remove audit-libs dependency if syscall tables are present 2018-01-23 09:51:38 -03:00
builtin-annotate.c perf annotate: Add --percent-type option 2018-08-08 15:55:53 -03:00
builtin-bench.c License cleanup: add SPDX GPL-2.0 license identifier to files with no license 2017-11-02 11:10:55 +01:00
builtin-buildid-cache.c perf buildid-cache: Warn --purge-all failures 2018-05-15 10:32:16 -03:00
builtin-buildid-list.c Merge branch 'linus' into perf/core, to fix conflicts 2017-11-07 10:30:18 +01:00
builtin-c2c.c perf c2c: Fix return type for histogram sorting comparision functions 2020-02-05 14:43:34 +00:00
builtin-config.c Merge branch 'linus' into perf/core, to fix conflicts 2017-11-07 10:30:18 +01:00
builtin-data.c License cleanup: add SPDX GPL-2.0 license identifier to files with no license 2017-11-02 11:10:55 +01:00
builtin-diff.c perf hists: Clarify callchain disabling when available 2018-07-24 14:37:33 -03:00
builtin-evlist.c Merge branch 'linus' into perf/core, to fix conflicts 2017-11-07 10:30:18 +01:00
builtin-ftrace.c perf ftrace: Fix failure to set cpumask when only one cpu is present 2019-08-29 08:28:46 +02:00
builtin-help.c perf help: Remove needless use of strncpy() 2019-07-03 13:14:41 +02:00
builtin-inject.c perf thread: Make thread__find_map() return the map 2018-04-26 13:47:08 -03:00
builtin-kallsyms.c perf machine: Ditch find_kernel_function variants 2018-04-30 12:20:54 -03:00
builtin-kmem.c perf kmem: Fix memory leak in compact_gfp_flags() 2019-11-10 11:27:25 +01:00
builtin-kvm.c perf tools: Propagate get_cpuid() error 2019-11-06 13:05:42 +01:00
builtin-list.c Merge branch 'linus' into perf/core, to fix conflicts 2017-11-07 10:30:18 +01:00
builtin-lock.c Merge branch 'linus' into perf/core, to fix conflicts 2017-11-07 10:30:18 +01:00
builtin-mem.c perf mem: Allow all record/report options 2018-04-18 15:35:48 -03:00
builtin-probe.c perf probe: Do not show the skipped events 2020-06-22 09:05:30 +02:00
builtin-record.c perf record: Synthesize features before events in pipe mode 2018-03-16 13:56:50 -03:00
builtin-report.c perf report: Fix NULL pointer dereference in hists__fprintf_nr_sample_events() 2020-06-25 15:33:05 +02:00
builtin-sched.c perf sched: Use sched->show_callchain where appropriate 2018-06-05 10:09:54 -03:00
builtin-script.c perf script: Fix brstackinsn for AUXTRACE 2020-01-04 19:13:13 +01:00
builtin-stat.c perf stat: Fix duration_time value for higher intervals 2020-10-01 13:14:46 +02:00
builtin-timechart.c perf tools: Add missing open_memstream() prototype for systems lacking it 2019-01-26 09:32:41 +01:00
builtin-top.c perf top: Fix stdio interface input handling with glibc 2.28+ 2020-10-14 10:31:22 +02:00
builtin-trace.c perf trace: Support multiple "vfs_getname" probes 2019-03-13 14:02:37 -07:00
builtin-version.c perf version: Fix segfault due to missing OPT_END() 2019-08-06 19:06:50 +02:00
builtin.h License cleanup: add SPDX GPL-2.0 license identifier to files with no license 2017-11-02 11:10:55 +01:00
check-headers.sh tools include: Adopt linux/bits.h 2019-04-27 09:36:40 +02:00
command-list.txt
CREDITS
design.txt
Makefile tools: Let O= makes handle a relative path with -C option 2020-04-02 15:28:17 +02:00
Makefile.config perf tools: Support Python 3.8+ in Makefile 2020-04-17 10:48:52 +02:00
Makefile.perf perf tools: Pass build flags to traceevent build 2018-10-16 14:57:59 -03:00
MANIFEST
perf-archive.sh License cleanup: add SPDX GPL-2.0 license identifier to files with no license 2017-11-02 11:10:55 +01:00
perf-completion.sh perf tools: Auto-complete for events with ':' 2017-12-27 12:16:00 -03:00
perf-read-vdso.c License cleanup: add SPDX GPL-2.0 license identifier to files with no license 2017-11-02 11:10:55 +01:00
perf-sys.h Drop a bunch of metag references 2018-02-23 14:29:59 +00:00
perf-with-kcore.sh
perf.c perf config: Honour $PERF_CONFIG env var to specify alternate .perfconfig 2019-10-05 13:09:40 +02:00
perf.h perf tools: Increase MAX_NR_CPUS and MAX_CACHES 2019-07-26 09:14:12 +02:00