From d4097f1937f2242d0aa0a7c654d2159a6895e5c8 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Tue, 8 Oct 2019 07:33:08 -0300 Subject: perf trace: Introduce --filter for tracepoint events Similar to what is in 'perf record', works just like there: # perf trace -e msr:* 328.297 :0/0 msr:write_msr(msr: FS_BASE, val: 140240388381888) 328.302 :0/0 msr:write_msr(msr: FS_BASE, val: 140240388381888) 328.306 :0/0 msr:write_msr(msr: FS_BASE, val: 140240388381888) 328.317 :0/0 msr:write_msr(msr: FS_BASE, val: 140240388381888) 328.322 :0/0 msr:write_msr(msr: FS_BASE, val: 140240388381888) 328.327 :0/0 msr:write_msr(msr: FS_BASE, val: 140240388381888) 328.331 :0/0 msr:write_msr(msr: FS_BASE, val: 140240388381888) 328.336 :0/0 msr:write_msr(msr: FS_BASE, val: 140240388381888) 328.340 :0/0 ^Cmsr:write_msr(msr: FS_BASE, val: 140240388381888) # So, for a system wide trace session looking at the write_msr tracepoint we see a flood of MSR_FS_BASE, we need to get the number for that: # grep FS_BASE /tmp/build/perf/trace/beauty/generated/x86_arch_MSRs_array.c [0xc0000100 - x86_64_specific_MSRs_offset] = "FS_BASE", # And then use it in a filter: # perf trace -e msr:* --filter="msr!=0xc0000100" 942.177 :0/0 msr:write_msr(msr: IA32_TSC_DEADLINE, val: 3056931068232) 942.199 :0/0 msr:write_msr(msr: IA32_TSC_DEADLINE, val: 3057135655252) 942.203 :0/0 msr:write_msr(msr: IA32_TSC_DEADLINE, val: 3056931068222) 942.231 :0/0 msr:write_msr(msr: IA32_TSC_DEADLINE, val: 3056998373022) 942.241 :0/0 msr:write_msr(msr: IA32_TSC_DEADLINE, val: 3056931068236) # Ok, lets filter that too, too noisy: # grep TSC_DEADLINE /tmp/build/perf/trace/beauty/generated/x86_arch_MSRs_array.c [0x000006E0] = "IA32_TSC_DEADLINE", # # perf trace -e msr:* --filter="msr!=0xc0000100 && msr!=0x6e0" -a sleep 0.1 0.000 :0/0 msr:read_msr(msr: IA32_TSC_ADJUST) 0.066 CPU 0/KVM/4895 msr:write_msr(msr: IA32_SPEC_CTRL, val: 6) 0.070 CPU 0/KVM/4895 msr:write_msr(msr: 0x830, val: 34359740667) 0.099 CPU 0/KVM/4895 msr:read_msr(msr: IA32_SYSENTER_ESP, val: -2199021993472) 0.100 CPU 0/KVM/4895 msr:read_msr(msr: IA32_APICBASE, val: 4276096000) 0.101 CPU 0/KVM/4895 msr:read_msr(msr: IA32_DEBUGCTLMSR) 0.109 :0/0 msr:write_msr(msr: IA32_SPEC_CTRL) 1.000 :0/0 msr:write_msr(msr: 0x830, val: 17179871485) 18.893 :0/0 msr:write_msr(msr: 0x83f, val: 246) 28.810 :0/0 msr:write_msr(msr: 0x830, val: 68719479037) 40.117 CPU 0/KVM/4895 msr:write_msr(msr: IA32_SPEC_CTRL, val: 6) 40.127 CPU 0/KVM/4895 msr:read_msr(msr: IA32_DEBUGCTLMSR) 40.139 CPU 0/KVM/4895 msr:write_msr(msr: LSTAR, val: -2130661312) 40.141 CPU 0/KVM/4895 msr:write_msr(msr: SYSCALL_MASK, val: 14080) 40.142 CPU 0/KVM/4895 msr:write_msr(msr: TSC_AUX) 40.144 CPU 0/KVM/4895 msr:write_msr(msr: KERNEL_GS_BASE) 40.147 CPU 0/KVM/4895 msr:write_msr(msr: IA32_SPEC_CTRL) 40.148 CPU 0/KVM/4895 msr:write_msr(msr: IA32_FLUSH_CMD, val: 1) 40.151 CPU 0/KVM/4895 msr:write_msr(msr: IA32_SPEC_CTRL, val: 6) ^C # One can combine that with filtering pids as well: # perf trace -e msr:* --filter="msr!=0xc0000100 && msr!=0x6e0" --filter-pids 4895 -a sleep 0.09 0.000 :0/0 msr:write_msr(msr: 0x830, val: 4294969597) 0.291 gnome-terminal/2790 msr:write_msr(msr: SYSCALL_MASK, val: 292608) 0.294 gnome-terminal/2790 msr:write_msr(msr: LSTAR, val: -1935671280) 0.295 gnome-terminal/2790 msr:write_msr(msr: TSC_AUX, val: 6) 10.940 gnome-terminal/2790 msr:write_msr(msr: 0x830, val: 4294969597) 15.943 gnome-shell/2096 msr:write_msr(msr: 0x830, val: 4294969597) 16.975 :0/0 msr:write_msr(msr: 0x830, val: 4294969597) 19.560 :0/0 msr:write_msr(msr: 0x83f, val: 246) 25.162 :0/0 msr:read_msr(msr: IA32_TSC_ADJUST) 25.807 JS Watchdog/3635 msr:write_msr(msr: IA32_SPEC_CTRL, val: 6) 25.820 :0/0 msr:write_msr(msr: IA32_SPEC_CTRL) 25.941 gnome-terminal/2790 msr:write_msr(msr: 0x830, val: 4294969597) 26.941 gnome-terminal/2790 msr:write_msr(msr: 0x830, val: 4294969597) 29.942 gnome-terminal/2790 msr:write_msr(msr: 0x830, val: 4294969597) 45.313 :0/0 msr:write_msr(msr: 0x83f, val: 246) 56.945 gnome-terminal/2790 msr:write_msr(msr: 0x830, val: 4294969597) 60.946 gnome-terminal/2790 msr:write_msr(msr: 0x830, val: 4294969597) 74.096 JS Watchdog/8971 msr:write_msr(msr: IA32_SPEC_CTRL, val: 6) 74.130 :0/0 msr:write_msr(msr: IA32_SPEC_CTRL) 79.673 :0/0 msr:write_msr(msr: 0x83f, val: 246) 79.947 gnome-terminal/2790 msr:write_msr(msr: 0x830, val: 17179871485) # Or for just a pid, with callchains: # grep SYSCALL_MAS /tmp/build/perf/trace/beauty/generated/x86_arch_MSRs_array.c [0xc0000084 - x86_64_specific_MSRs_offset] = "SYSCALL_MASK", # perf trace -e msr:* --filter="msr==0xc0000084" --pid 2790 --call-graph=dwarf 0.000 gnome-terminal/2790 msr:write_msr(msr: SYSCALL_MASK, val: 292608) do_trace_write_msr ([kernel.kallsyms]) do_trace_write_msr ([kernel.kallsyms]) kvm_on_user_return ([kvm]) fire_user_return_notifiers ([kernel.kallsyms]) exit_to_usermode_loop ([kernel.kallsyms]) do_syscall_64 ([kernel.kallsyms]) entry_SYSCALL_64 ([kernel.kallsyms]) __GI___poll (inlined) 9299.073 gnome-terminal/2790 msr:write_msr(msr: SYSCALL_MASK, val: 292608) do_trace_write_msr ([kernel.kallsyms]) do_trace_write_msr ([kernel.kallsyms]) kvm_on_user_return ([kvm]) fire_user_return_notifiers ([kernel.kallsyms]) exit_to_usermode_loop ([kernel.kallsyms]) do_syscall_64 ([kernel.kallsyms]) entry_SYSCALL_64 ([kernel.kallsyms]) __GI___poll (inlined) 9348.374 gnome-terminal/2790 msr:write_msr(msr: SYSCALL_MASK, val: 292608) do_trace_write_msr ([kernel.kallsyms]) do_trace_write_msr ([kernel.kallsyms]) kvm_on_user_return ([kvm]) fire_user_return_notifiers ([kernel.kallsyms]) exit_to_usermode_loop ([kernel.kallsyms]) do_syscall_64 ([kernel.kallsyms]) entry_SYSCALL_64 ([kernel.kallsyms]) __GI___poll (inlined) # Ok, just another form of KVM to emit MSRs :-) Next step: elliminate those greps by getting the filter expression, looking for arg names, then for the arrays associated with it to do a reverse lookup. Also allow those filters to be associated with strace-like syscall names. After that: augment the 'val' arg for 'msr:write_msr' based on the first arg, 'msr'. Then, do that with eBPF too, not just with tracepoint filters. Cc: Adrian Hunter Cc: Brendan Gregg Cc: Jiri Olsa Cc: Luis Cláudio Gonçalves Cc: Marcelo Tosatti Cc: Namhyung Kim Link: https://lkml.kernel.org/n/tip-95bfe5d4tzy5f66bx49d05rj@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-trace.txt | 5 +++++ 1 file changed, 5 insertions(+) (limited to 'tools/perf/Documentation/perf-trace.txt') diff --git a/tools/perf/Documentation/perf-trace.txt b/tools/perf/Documentation/perf-trace.txt index ba16cd5b680f..3bb89c2e9020 100644 --- a/tools/perf/Documentation/perf-trace.txt +++ b/tools/perf/Documentation/perf-trace.txt @@ -42,6 +42,11 @@ OPTIONS Prefixing with ! shows all syscalls but the ones specified. You may need to escape it. +--filter=:: + Event filter. This option should follow an event selector (-e) which + selects tracepoint event(s). + + -D msecs:: --delay msecs:: After starting the program, wait msecs before measuring. This is useful to -- cgit v1.2.3