perf/core improvements and fixes
Arnaldo Carvalho de Melo
maintainerHi Ingo,
Please consider pulling,
- Arnaldo
The following changes since commit d1b26c70246bc72922ae61d9f972d5c2588409e7:
perf/ring_buffer: Prepare writing into the ring-buffer from the end (2016-03-31 10:30:49 +0200)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tags/perf-core-for-mingo-20160401
for you to fetch changes up to d37ba880598654fda10b312331377cdca3edd574:
perf bpf: Add sample types for 'bpf-output' event (2016-04-01 18:46:25 -0300)
----------------------------------------------------------------
perf/core improvements and fixes:
User visible:
- Do not use events that don't have timestamps when setting 'perf trace's base timestamp, fixing up the timestamp column for syscalls (Arnaldo Carvalho de Melo)
- Make the 'bpf-output' sample_type be the same as tracepoint's, fixing up 'perf trace's timestamp column for bpf events (Wang Nan)
- Fix PMU term format max value calculation (Kan Liang)
- Pretty print 'seccomp', 'getrandom' syscalls in 'perf trace' (Arnaldo Carvalho de Melo)
Infrastructure:
- Add support for using TSC as an ARCH timestamp when synthesizing JIT records (Adrian Hunter)
----------------------------------------------------------------
Adrian Hunter (3):
perf tools: Add time conversion event
perf jit: Add support for using TSC as a timestamp perf intel-pt/bts: Define JITDUMP_USE_ARCH_TIMESTAMP
Arnaldo Carvalho de Melo (5):
perf trace: Do not process PERF_RECORD_LOST twice
perf trace: Pretty print seccomp() args
perf trace: Pretty print getrandom() args
perf trace: Introduce function to set the base timestamp
perf trace: Don't set the base timestamp using events without PERF_SAMPLE_TIME
Kan Liang (1):
perf tools: Fix PMU term format max value calculation
Wang Nan (1):
perf bpf: Add sample types for 'bpf-output' event
tools/perf/arch/x86/util/intel-bts.c | 5 ++ tools/perf/arch/x86/util/intel-pt.c | 5 ++ tools/perf/arch/x86/util/tsc.c | 32 +++++++++++- tools/perf/arch/x86/util/tsc.h | 17 ------- tools/perf/builtin-inject.c | 1 + tools/perf/builtin-record.c | 15 ++++++ tools/perf/builtin-trace.c | 99 ++++++++++++++++++++++++++++++++++-- tools/perf/jvmti/jvmti_agent.c | 43 +++++++++++++++- tools/perf/util/Build | 3 +- tools/perf/util/event.c | 1 + tools/perf/util/event.h | 9 ++++ tools/perf/util/evsel.c | 3 +- tools/perf/util/jitdump.c | 37 ++++++++++++-- tools/perf/util/jitdump.h | 3 ++ tools/perf/util/pmu.c | 13 +++-- tools/perf/util/session.c | 6 +++ tools/perf/util/session.h | 1 + tools/perf/util/tool.h | 1 + tools/perf/util/tsc.h | 21 +++++++- 19 files changed, 274 insertions(+), 41 deletions(-) delete mode 100644 tools/perf/arch/x86/util/tsc.h
Arnaldo Carvalho de Melo
maintainerPATCH 1/10 perf trace: Do not process PERF_RECORD_LOST twice
From: Arnaldo Carvalho de Melo <[email protected]>
We catch this record to provide a visual indication that events are getting lost, then call the default method to allow extra logging shared with the other tools to take place.
This extra logging was done twice because we were continuing to the "default" clause where machine__process_event() will end up calling machine__process_lost_event() again, fix it.
--- tools/perf/builtin-trace.c | 1 + 1 file changed, 1 insertion(+)
tools/perf/builtin-trace.c +1 -0
@@ -1618,6 +1618,7 @@ static int trace__process_event(struct trace *trace, struct machine *machine,color_fprintf (trace->output,PERF_COLOR_RED ,"LOST %" PRIu64" events!\n" , event->lost.lost); ret =machine__process_lost_event (machine, event, sample); +break ;default : ret =machine__process_event (machine, event, sample);break ;
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 2/10 perf trace: Pretty print seccomp() args
In reply to Arnaldo Carvalho de MeloFrom: Arnaldo Carvalho de Melo <[email protected]>
E.g:
# trace -e seccomp 200.061 (0.009 ms): :2441/2441 seccomp(op: FILTER, flags: TSYNC ) = -1 EFAULT Bad address 200.910 (0.121 ms): :2441/2441 seccomp(op: FILTER, flags: TSYNC, uargs: 0x7fff57479fe0) = 0
--- tools/perf/builtin-trace.c | 47 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 47 insertions(+)
tools/perf/builtin-trace.c +47 -0
@@ -40,6 +40,10 @@#include <sys/mman.h> #include <linux/futex.h> #include <linux/err.h> +#include <linux/seccomp.h> +#include <linux/filter.h> +#include <linux/audit.h> +#include <sys/ptrace.h> /* For older distros: */ #ifndef MAP_STACK
@@ -1001,6 +1005,46 @@ static const char *tioctls[] = { static DEFINE_STRARRAY_OFFSET(tioctls, 0x5401);#endif /* defined(__i386__) || defined(__x86_64__) */ +static size_t syscall_arg__scnprintf_seccomp_op (char *bf,size_t size,struct syscall_arg *arg) +{ +int op = arg->val; +size_t printed =0 ; + +switch (op) { +#define P_SECCOMP_SET_MODE_OP (n) case SECCOMP_SET_MODE_##n: printed = scnprintf(bf, size, #n); break +P_SECCOMP_SET_MODE_OP (STRICT ); +P_SECCOMP_SET_MODE_OP (FILTER ); +#undef P_SECCOMP_SET_MODE_OP +default : printed =scnprintf (bf, size,"%#x" , op);break ; + } + +return printed; +} + +#define SCA_SECCOMP_OP syscall_arg__scnprintf_seccomp_op + +static size_t syscall_arg__scnprintf_seccomp_flags (char *bf,size_t size, +struct syscall_arg *arg) +{ +int printed =0 , flags = arg->val; + +#define P_FLAG (n) \ + if (flags & SECCOMP_FILTER_FLAG_##n) { \ + printed += scnprintf(bf + printed, size - printed, "%s%s", printed ? "|" : "", #n); \ + flags &= ~SECCOMP_FILTER_FLAG_##n; \ + } + +P_FLAG (TSYNC ); +#undef P_FLAG + +if (flags) + printed +=scnprintf (bf + printed, size - printed,"%s%#x" , printed ?"|" :"" , flags); + +return printed; +} + +#define SCA_SECCOMP_FLAGS syscall_arg__scnprintf_seccomp_flags +#define STRARRAY (arg, name, array) \ .arg_scnprintf = { [arg] = SCA_STRARRAY, }, \ .arg_parm = { [arg] = &strarray__##array, }
@@ -1234,6 +1278,9 @@ static struct syscall_fmt { .arg_scnprintf = { [1] = SCA_SIGNUM, /* sig */ }, }, { .name = "rt_tgsigqueueinfo", .errmsg = true, .arg_scnprintf = { [2] = SCA_SIGNUM, /* sig */ }, }, + { .name = "seccomp", .errmsg = true, + .arg_scnprintf = { [0] = SCA_SECCOMP_OP, /* op */ + [1] = SCA_SECCOMP_FLAGS, /* flags */ }, }, { .name = "select", .errmsg = true, .timeout = true, }, { .name = "sendmmsg", .errmsg = true, .arg_scnprintf = { [0] = SCA_FD, /* fd */
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 3/10 perf trace: Pretty print getrandom() args
In reply to Arnaldo Carvalho de MeloFrom: Arnaldo Carvalho de Melo <[email protected]>
# trace -e getrandom 35622.560 ( 0.023 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35622.585 ( 0.006 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35622.594 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35627.395 ( 0.010 ms): libvirtd/1353 getrandom(buf: 0x7f7a1bfa35c0, count: 16, flags: NONBLOCK ) = 16 35630.940 ( 0.013 ms): fwupd/16120 getrandom(buf: 0x7f63243aa5c0, count: 16, flags: NONBLOCK ) = 16 35718.613 ( 0.015 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35718.629 ( 0.005 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35718.637 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35719.355 ( 0.010 ms): libvirtd/1353 getrandom(buf: 0x7f7a1bfa35c0, count: 16, flags: NONBLOCK ) = 16 35721.042 ( 0.030 ms): fwupd/16120 getrandom(buf: 0x7f63243aa5c0, count: 16, flags: NONBLOCK ) = 16 41090.830 ( 0.012 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41090.845 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41090.851 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41091.750 ( 0.010 ms): libvirtd/1353 getrandom(buf: 0x7f7a1bfa35c0, count: 16, flags: NONBLOCK ) = 16 41091.823 ( 0.006 ms): fwupd/16120 getrandom(buf: 0x7f63243aa5c0, count: 16, flags: NONBLOCK ) = 16 41122.078 ( 0.053 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41122.129 ( 0.009 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41122.139 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41124.492 ( 0.007 ms): libvirtd/1353 getrandom(buf: 0x7f7a1bfa35c0, count: 16, flags: NONBLOCK ) = 16 41124.470 ( 0.013 ms): fwupd/16120 getrandom(buf: 0x7f63243aa5c0, count: 16, flags: NONBLOCK ) = 16 41590.832 ( 0.014 ms): chrome/5957 getrandom(buf: 0x7fabac7b15b0, count: 16, flags: NONBLOCK ) = 16 41590.884 ( 0.004 ms): chrome/5957 getrandom(buf: 0x7fabac7b15c0, count: 16, flags: NONBLOCK ) = 16
--- tools/perf/builtin-trace.c | 26 ++++++++++++++++++++++++++ 1 file changed, 26 insertions(+)
tools/perf/builtin-trace.c +26 -0
@@ -44,6 +44,7 @@#include <linux/filter.h> #include <linux/audit.h> #include <sys/ptrace.h> +#include <linux/random.h> /* For older distros: */ #ifndef MAP_STACK
@@ -1045,6 +1046,29 @@ static size_t syscall_arg__scnprintf_seccomp_flags(char *bf, size_t size,#define SCA_SECCOMP_FLAGS syscall_arg__scnprintf_seccomp_flags +static size_t syscall_arg__scnprintf_getrandom_flags (char *bf,size_t size, +struct syscall_arg *arg) +{ +int printed =0 , flags = arg->val; + +#define P_FLAG (n) \ + if (flags & GRND_##n) { \ + printed += scnprintf(bf + printed, size - printed, "%s%s", printed ? "|" : "", #n); \ + flags &= ~GRND_##n; \ + } + +P_FLAG (RANDOM ); +P_FLAG (NONBLOCK ); +#undef P_FLAG + +if (flags) + printed +=scnprintf (bf + printed, size - printed,"%s%#x" , printed ?"|" :"" , flags); + +return printed; +} + +#define SCA_GETRANDOM_FLAGS syscall_arg__scnprintf_getrandom_flags +#define STRARRAY (arg, name, array) \ .arg_scnprintf = { [arg] = SCA_STRARRAY, }, \ .arg_parm = { [arg] = &strarray__##array, }
@@ -1137,6 +1161,8 @@ static struct syscall_fmt { { .name = "getdents64", .errmsg = true, .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, }, { .name = "getitimer", .errmsg = true, STRARRAY(0, which, itimers), }, + { .name = "getrandom", .errmsg = true, + .arg_scnprintf = { [2] = SCA_GETRANDOM_FLAGS, /* flags */ }, }, { .name = "getrlimit", .errmsg = true, STRARRAY(0, resource, rlimit_resources), }, { .name = "getxattr", .errmsg = true, .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 4/10 perf tools: Add time conversion event
In reply to Arnaldo Carvalho de MeloFrom: Adrian Hunter <[email protected]>
Intel PT uses the time members from the perf_event_mmap_page to convert between TSC and perf time.
Due to a lack of foresight when Intel PT was implemented, those time members were recorded in the (implementation dependent) AUXTRACE_INFO event, the structure of which is generally inaccessible outside of the Intel PT decoder. However now the conversion between TSC and perf time is needed when processing a jitdump file when Intel PT has been used for tracing.
So add a user event to record the time members. 'perf record' will synthesize the event if the information is available. And session processing will put a copy of the event on the session so that tools like 'perf inject' can easily access it.
--- tools/perf/arch/x86/util/tsc.c | 31 +++++++++++++++++++++++++++++++ tools/perf/builtin-inject.c | 1 + tools/perf/builtin-record.c | 15 +++++++++++++++ tools/perf/util/event.c | 1 + tools/perf/util/event.h | 9 +++++++++ tools/perf/util/session.c | 6 ++++++ tools/perf/util/session.h | 1 + tools/perf/util/tool.h | 1 + tools/perf/util/tsc.h | 10 ++++++++++ 9 files changed, 75 insertions(+)
tools/perf/arch/x86/util/tsc.c +31 -0
@@ -46,3 +46,34 @@ u64 rdtsc(void)return low | ((u64 )high) <<32 ; } + +int perf_event__synth_time_conv (const struct perf_event_mmap_page *pc, +struct perf_tool *tool, +perf_event__handler_t process, +struct machine *machine) +{ +union perf_event event = { + .time_conv = { + .header = { + .type =PERF_RECORD_TIME_CONV , + .size =sizeof (struct time_conv_event ), + }, + }, + }; +struct perf_tsc_conversion tc; +int err; + + err =perf_read_tsc_conversion (pc, &tc); +if (err == -EOPNOTSUPP ) +return 0 ; +if (err) +return err; + +pr_debug2 ("Synthesizing TSC conversion information\n" ); + + event.time_conv.time_mult = tc.time_mult; + event.time_conv.time_shift = tc.time_shift; + event.time_conv.time_zero = tc.time_zero; + +return process (tool, &event,NULL , machine); +}
tools/perf/builtin-inject.c +1 -0
@@ -748,6 +748,7 @@ int cmd_inject(int argc, const char **argv, const char *prefix __maybe_unused) .auxtrace_info = perf_event__repipe_op2_synth, .auxtrace = perf_event__repipe_auxtrace, .auxtrace_error = perf_event__repipe_op2_synth, + .time_conv = perf_event__repipe_op2_synth, .finished_round = perf_event__repipe_oe_synth, .build_id = perf_event__repipe_op2_synth, .id_index = perf_event__repipe_op2_synth,
tools/perf/builtin-record.c +15 -0
@@ -29,6 +29,7 @@#include "util/data.h" #include "util/perf_regs.h" #include "util/auxtrace.h" +#include "util/tsc.h" #include "util/parse-branch-options.h" #include "util/parse-regs-options.h" #include "util/llvm-utils.h"
@@ -512,6 +513,15 @@ static void workload_exec_failed_signal(int signo __maybe_unused,static void snapshot_sig_handler (int sig); +int __weak +perf_event__synth_time_conv (const struct perf_event_mmap_page *pc__maybe_unused , +struct perf_tool *tool__maybe_unused , +perf_event__handler_t process__maybe_unused , +struct machine *machine__maybe_unused ) +{ +return 0 ; +} +static int record__synthesize (struct record *rec) {struct perf_session *session = rec->session;
@@ -549,6 +559,11 @@ static int record__synthesize(struct record *rec) } } + err =perf_event__synth_time_conv (rec->evlist->mmap[0 ].base, tool, + process_synthesized_event, machine); +if (err) + goto out; +if (rec->opts.full_auxtrace) { err =perf_event__synthesize_auxtrace_info (rec->itr, tool, session, process_synthesized_event);
tools/perf/util/event.c +1 -0
@@ -45,6 +45,7 @@ static const char *perf_event__names[] = { [PERF_RECORD_STAT] = "STAT", [PERF_RECORD_STAT_ROUND] = "STAT_ROUND", [PERF_RECORD_EVENT_UPDATE] = "EVENT_UPDATE", + [PERF_RECORD_TIME_CONV] = "TIME_CONV", };const char *perf_event__name (unsigned int id)
tools/perf/util/event.h +9 -0
@@ -233,6 +233,7 @@ enum perf_user_event_type { /* above any possible kernel type */PERF_RECORD_STAT =76 ,PERF_RECORD_STAT_ROUND =77 ,PERF_RECORD_EVENT_UPDATE =78 , +PERF_RECORD_TIME_CONV =79 , PERF_RECORD_HEADER_MAX };
@@ -469,6 +470,13 @@ struct stat_round_event {u64 time; }; +struct time_conv_event { +struct perf_event_header header; +u64 time_shift; +u64 time_mult; +u64 time_zero; +}; +union perf_event {struct perf_event_header header;struct mmap_event mmap;
@@ -497,6 +505,7 @@ union perf_event {struct stat_config_event stat_config;struct stat_event stat;struct stat_round_event stat_round; +struct time_conv_event time_conv; };void perf_event__print_totals (void );
tools/perf/util/session.c +6 -0
@@ -409,6 +409,8 @@ void perf_tool__fill_defaults(struct perf_tool *tool) tool->stat = process_stat_stub;if (tool->stat_round ==NULL ) tool->stat_round = process_stat_round_stub; +if (tool->time_conv ==NULL ) + tool->time_conv = process_event_op2_stub; }static void swap_sample_id_all (union perf_event *event,void *data)
@@ -794,6 +796,7 @@ static perf_event__swap_op perf_event__swap_ops[] = { [PERF_RECORD_STAT] = perf_event__stat_swap, [PERF_RECORD_STAT_ROUND] = perf_event__stat_round_swap, [PERF_RECORD_EVENT_UPDATE] = perf_event__event_update_swap, + [PERF_RECORD_TIME_CONV] = perf_event__all64_swap, [PERF_RECORD_HEADER_MAX] = NULL, };
@@ -1341,6 +1344,9 @@ static s64 perf_session__process_user_event(struct perf_session *session,return tool->stat (tool, event, session);case PERF_RECORD_STAT_ROUND :return tool->stat_round (tool, event, session); +case PERF_RECORD_TIME_CONV : + session->time_conv = event->time_conv; +return tool->time_conv (tool, event, session);default :return -EINVAL ; }
tools/perf/util/session.h +1 -0
@@ -26,6 +26,7 @@ struct perf_session {struct itrace_synth_opts *itrace_synth_opts;struct list_head auxtrace_index;struct trace_event tevent; +struct time_conv_event time_conv;bool repipe;bool one_mmap;void *one_mmap_addr;
tools/perf/util/tool.h +1 -0
@@ -57,6 +57,7 @@ struct perf_tool { id_index, auxtrace_info, auxtrace_error, + time_conv, thread_map, cpu_map, stat_config,
tools/perf/util/tsc.h +10 -0
@@ -3,10 +3,20 @@#include <linux/types.h> +#include "event.h" #include "../arch/x86/util/tsc.h" u64 perf_time_to_tsc (u64 ns,struct perf_tsc_conversion *tc);u64 tsc_to_perf_time (u64 cyc,struct perf_tsc_conversion *tc);u64 rdtsc (void ); +struct perf_event_mmap_page ; +struct perf_tool ; +struct machine ; + +int perf_event__synth_time_conv (const struct perf_event_mmap_page *pc, +struct perf_tool *tool, +perf_event__handler_t process, +struct machine *machine); +#endif
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 5/10 perf jit: Add support for using TSC as a timestamp
In reply to Arnaldo Carvalho de MeloFrom: Adrian Hunter <[email protected]>
Intel PT uses TSC as a timestamp, so add support for using TSC instead of the monotonic clock. Use of TSC is selected by an environment variable "JITDUMP_USE_ARCH_TIMESTAMP" and flagged in the jitdump file with flag JITDUMP_FLAGS_ARCH_TIMESTAMP.
--- tools/perf/arch/x86/util/tsc.c | 1 - tools/perf/arch/x86/util/tsc.h | 17 ----------------- tools/perf/jvmti/jvmti_agent.c | 43 ++++++++++++++++++++++++++++++++++++++++-- tools/perf/util/Build | 3 +-- tools/perf/util/jitdump.c | 37 +++++++++++++++++++++++++++++++----- tools/perf/util/jitdump.h | 3 +++ tools/perf/util/tsc.h | 11 ++++++++++- 7 files changed, 87 insertions(+), 28 deletions(-) delete mode 100644 tools/perf/arch/x86/util/tsc.h
tools/perf/arch/x86/util/tsc.c +0 -1
@@ -7,7 +7,6 @@#include <linux/types.h> #include "../../util/debug.h" #include "../../util/tsc.h" -#include "tsc.h" int perf_read_tsc_conversion (const struct perf_event_mmap_page *pc,struct perf_tsc_conversion *tc)
tools/perf/arch/x86/util/tsc.h deleted +0 -17
@@ -1,17 +0,0 @@ -#ifndef TOOLS_PERF_ARCH_X86_UTIL_TSC_H__ -#define TOOLS_PERF_ARCH_X86_UTIL_TSC_H__ - -#include <linux/types.h> - -struct perf_tsc_conversion { -u16 time_shift; -u32 time_mult; -u64 time_zero; -}; - -struct perf_event_mmap_page ; - -int perf_read_tsc_conversion (const struct perf_event_mmap_page *pc, -struct perf_tsc_conversion *tc); - -#endif /* TOOLS_PERF_ARCH_X86_UTIL_TSC_H__ */
tools/perf/jvmti/jvmti_agent.c +41 -2
76 lines not on this page · raw message
tools/perf/util/Build +1 -2
@@ -69,8 +69,7 @@ libperf-y += stat-shadow.o libperf-y += record.o libperf-y += srcline.o libperf-y += data.o -libperf-$(CONFIG_X86) += tsc.o -libperf-$(CONFIG_AUXTRACE) += tsc.o +libperf-y += tsc.o libperf-y += cloexec.o libperf-y += thread-stack.o libperf-$(CONFIG_AUXTRACE) += auxtrace.o
tools/perf/util/jitdump.c +32 -5
@@ -17,6 +17,7 @@#include "strlist.h" #include <elf.h> +#include "tsc.h" #include "session.h" #include "jit.h" #include "jitdump.h"
@@ -33,6 +34,7 @@ struct jit_buf_desc {size_t bufsize;FILE *in;bool needs_bswap;/* handles cross-endianess */ +bool use_arch_timestamp;void *debug_data;size_t nr_debug_entries;uint32_t code_load_count;
@@ -158,13 +160,16 @@ jit_open(struct jit_buf_desc *jd, const char *name) header.flags =bswap_64 (header.flags); } + jd->use_arch_timestamp = header.flags &JITDUMP_FLAGS_ARCH_TIMESTAMP ; +if (verbose >2 ) -pr_debug ("version=%u\nhdr.size=%u\nts=0x%llx\npid=%d\nelf_mach=%d\n" , +pr_debug ("version=%u\nhdr.size=%u\nts=0x%llx\npid=%d\nelf_mach=%d\nuse_arch_timestamp=%d\n" , header.version, header.total_size, (unsigned long long )header.timestamp, header.pid, - header.elf_mach); + header.elf_mach, + jd->use_arch_timestamp);if (header.flags &JITDUMP_FLAGS_RESERVED ) { pr_err("jitdump file contains invalid or unsupported flags 0x%llx\n",
@@ -172,10 +177,15 @@ jit_open(struct jit_buf_desc *jd, const char *name) goto error; } +if (jd->use_arch_timestamp && !jd->session->time_conv.time_mult) { +pr_err ("jitdump file uses arch timestamps but there is no timestamp conversion\n" ); + goto error; + } +/* * validate event is using the correct clockid */ -if (jit_validate_events (jd->session)) { +if (!jd->use_arch_timestamp &&jit_validate_events (jd->session)) {pr_err ("error, jitted code must be sampled with perf record -k 1\n" ); goto error; }
@@ -329,6 +339,23 @@ jit_inject_event(struct jit_buf_desc *jd, union perf_event *event)return 0 ; } +static uint64_t convert_timestamp (struct jit_buf_desc *jd,uint64_t timestamp) +{ +struct perf_tsc_conversion tc; + +if (!jd->use_arch_timestamp) +return timestamp; + + tc.time_shift = jd->session->time_conv.time_shift; + tc.time_mult = jd->session->time_conv.time_mult; + tc.time_zero = jd->session->time_conv.time_zero; + +if (!tc.time_mult) +return 0 ; + +return tsc_to_perf_time (timestamp, &tc); +} +static int jit_repipe_code_load (struct jit_buf_desc *jd,union jr_entry *jr) {struct perf_sample sample;
@@ -410,7 +437,7 @@ static int jit_repipe_code_load(struct jit_buf_desc *jd, union jr_entry *jr) id->tid = tid; }if (jd->sample_type &PERF_SAMPLE_TIME ) - id->time = jr->load.p.timestamp; + id->time =convert_timestamp (jd, jr->load.p.timestamp);/* * create pseudo sample to induce dso hit increment
@@ -499,7 +526,7 @@ static int jit_repipe_code_move(struct jit_buf_desc *jd, union jr_entry *jr) id->tid = tid; }if (jd->sample_type &PERF_SAMPLE_TIME ) - id->time = jr->load.p.timestamp; + id->time =convert_timestamp (jd, jr->load.p.timestamp);/* * create pseudo sample to induce dso hit increment
tools/perf/util/jitdump.h +3 -0
@@ -23,9 +23,12 @@#define JITHEADER_VERSION 1enum jitdump_flags_bits { +JITDUMP_FLAGS_ARCH_TIMESTAMP_BIT ,JITDUMP_FLAGS_MAX_BIT , }; +#define JITDUMP_FLAGS_ARCH_TIMESTAMP (1ULL << JITDUMP_FLAGS_ARCH_TIMESTAMP_BIT) +#define JITDUMP_FLAGS_RESERVED (JITDUMP_FLAGS_MAX_BIT < 64 ? \ (~((1ULL << JITDUMP_FLAGS_MAX_BIT) - 1)) : 0)
tools/perf/util/tsc.h +10 -1
@@ -4,7 +4,16 @@#include <linux/types.h> #include "event.h" -#include "../arch/x86/util/tsc.h" + +struct perf_tsc_conversion { +u16 time_shift; +u32 time_mult; +u64 time_zero; +}; +struct perf_event_mmap_page ; + +int perf_read_tsc_conversion (const struct perf_event_mmap_page *pc, +struct perf_tsc_conversion *tc);u64 perf_time_to_tsc (u64 ns,struct perf_tsc_conversion *tc);u64 tsc_to_perf_time (u64 cyc,struct perf_tsc_conversion *tc);
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 6/10 perf intel-pt/bts: Define JITDUMP_USE_ARCH_TIMESTAMP
In reply to Arnaldo Carvalho de MeloFrom: Adrian Hunter <[email protected]>
For Intel PT / BTS, define the environment variable that selects TSC timestamps in the jitdump file.
--- tools/perf/arch/x86/util/intel-bts.c | 5 +++++ tools/perf/arch/x86/util/intel-pt.c | 5 +++++ 2 files changed, 10 insertions(+)
tools/perf/arch/x86/util/intel-bts.c +5 -0
@@ -438,6 +438,11 @@ struct auxtrace_record *intel_bts_recording_init(int *err)if (!intel_bts_pmu)return NULL ; +if (setenv ("JITDUMP_USE_ARCH_TIMESTAMP" ,"1" ,1 )) { + *err = -errno; +return NULL ; + } + btsr =zalloc (sizeof (struct intel_bts_recording ));if (!btsr) { *err = -ENOMEM ;
tools/perf/arch/x86/util/intel-pt.c +5 -0
@@ -1027,6 +1027,11 @@ struct auxtrace_record *intel_pt_recording_init(int *err)if (!intel_pt_pmu)return NULL ; +if (setenv ("JITDUMP_USE_ARCH_TIMESTAMP" ,"1" ,1 )) { + *err = -errno; +return NULL ; + } + ptr =zalloc (sizeof (struct intel_pt_recording ));if (!ptr) { *err = -ENOMEM ;
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 7/10 perf tools: Fix PMU term format max value calculation
In reply to Arnaldo Carvalho de MeloFrom: Kan Liang <[email protected]>
Currently the max value of format is calculated by the bits number. It relies on the continuity of the format.
However, uncore event format is not continuous. E.g. uncore qpi event format can be 0-7,21.
If bit 21 is set, there is parsing issues as below.
$ perf stat -a -e uncore_qpi_0/event=0x200002,umask=0x8/
event syntax error: '..pi_0/event=0x200002,umask=0x8/'
\___ value too big for format, maximum is 511This patch return the real max value by setting all possible bits to 1.
--- tools/perf/util/pmu.c | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-)
tools/perf/util/pmu.c +6 -7
@@ -602,14 +602,13 @@ static void pmu_format_value(unsigned long *format, __u64 value, __u64 *v,static __u64 pmu_format_max_value (const unsigned long *format) { -int w; +__u64 w =0 ; +int fbit; - w =bitmap_weight (format,PERF_PMU_FORMAT_BITS ); -if (!w) -return 0 ; -if (w <64 ) -return (1ULL << w) -1 ; -return -1 ; +for_each_set_bit (fbit, format,PERF_PMU_FORMAT_BITS ) + w |= (1ULL << fbit); + +return w; }/*
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 8/10 perf trace: Introduce function to set the base timestamp
In reply to Arnaldo Carvalho de MeloFrom: Arnaldo Carvalho de Melo <[email protected]>
That is used in both live runs, i.e.:
# trace ls
As when processing events recorded in a perf.data file:
# trace -i perf.data
--- tools/perf/builtin-trace.c | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-)
tools/perf/builtin-trace.c +11 -5
@@ -2400,6 +2400,14 @@ static bool skip_sample(struct trace *trace, struct perf_sample *sample)return false; } +static void trace__set_base_time (struct trace *trace, +struct perf_evsel *evsel__maybe_unused , +struct perf_sample *sample) +{ +if (trace->base_time ==0 && !trace->full_time) + trace->base_time = sample->time; +} + static int trace__process_sample(struct perf_tool *tool, union perf_event *event, struct perf_sample *sample,
@@ -2414,8 +2422,7 @@ static int trace__process_sample(struct perf_tool *tool,if (skip_sample (trace, sample))return 0 ; -if (!trace->full_time && trace->base_time ==0 ) - trace->base_time = sample->time; +trace__set_base_time (trace, evsel, sample);if (handler) { ++trace->nr_events;
@@ -2553,9 +2560,6 @@ static void trace__handle_event(struct trace *trace, union perf_event *event, stconst u32 type = event->header.type;struct perf_evsel *evsel; -if (!trace->full_time && trace->base_time ==0 ) - trace->base_time = sample->time; -if (type !=PERF_RECORD_SAMPLE ) {trace__process_event (trace, trace->host, event, sample);return ;
@@ -2567,6 +2571,8 @@ static void trace__handle_event(struct trace *trace, union perf_event *event, streturn ; } +trace__set_base_time (trace, evsel, sample); +if (evsel->attr.type ==PERF_TYPE_TRACEPOINT && sample->raw_data ==NULL ) { fprintf(trace->output, "%s sample with no payload for tid: %d, cpu %d, raw_size=%d, skipping...\n",
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 9/10 perf trace: Don't set the base timestamp using events without PERF_SAMPLE_TIME
In reply to Arnaldo Carvalho de MeloFrom: Arnaldo Carvalho de Melo <[email protected]>
This was causing bogus values to be shown at the timestamp column:
Before:
# trace --ev bpf-output/no-inherit,name=evt/ --ev /home/acme/bpf/test_bpf_trace.c/map:channel.event=evt/ usleep 10 94631143.385 ( 0.001 ms): brk( ) = 0x555555757000 94631143.398 ( 0.003 ms): mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1) = 0x7ffff7ff6000 94631143.406 ( 0.004 ms): access(filename: 0xf7df9e10, mode: R ) = -1 ENOENT No such file or directory 94631143.412 ( 0.004 ms): open(filename: 0xf7df8761, flags: CLOEXEC) = 3 94631143.415 ( 0.002 ms): fstat(fd: 3, statbuf: 0x7fffffffd6b0 ) = 0 94631143.419 ( 0.003 ms): mmap(len: 106798, prot: READ, flags: PRIVATE, fd: 3) = 0x7ffff7fdb000 94631143.420 ( 0.001 ms): close(fd: 3 ) = 0 94631143.432 ( 0.004 ms): open(filename: 0xf7ff6640, flags: CLOEXEC) = 3 <SNIP>
After:
# trace --ev bpf-output/no-inherit,name=evt/ --ev /home/acme/bpf/test_bpf_trace.c/map:channel.event=evt/ usleep 10 0.022 ( 0.001 ms): brk( ) = 0x55d7668a6000 0.037 ( 0.003 ms): mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1) = 0x7f8fbeb97000 0.123 ( 0.083 ms): access(filename: 0xbe995e10, mode: R ) = -1 ENOENT No such file or directory 0.130 ( 0.004 ms): open(filename: 0xbe994761, flags: CLOEXEC) = 3 0.133 ( 0.002 ms): fstat(fd: 3, statbuf: 0x7fff6487a890 ) = 0 0.138 ( 0.003 ms): mmap(len: 106798, prot: READ, flags: PRIVATE, fd: 3) = 0x7f8fbeb7c000 0.140 ( 0.001 ms): close(fd: 3 ) = 0 0.151 ( 0.004 ms): open(filename: 0xbeb97640, flags: CLOEXEC) = 3 <SNIP>
--- tools/perf/builtin-trace.c | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-)
tools/perf/builtin-trace.c +11 -2
@@ -2401,10 +2401,19 @@ static bool skip_sample(struct trace *trace, struct perf_sample *sample) }static void trace__set_base_time (struct trace *trace, -struct perf_evsel *evsel__maybe_unused , +struct perf_evsel *evsel,struct perf_sample *sample) { -if (trace->base_time ==0 && !trace->full_time) +/* +* BPF events were not setting PERF_SAMPLE_TIME, so be more robust +* and don't use sample->time unconditionally, we may end up having +* some other event in the future without PERF_SAMPLE_TIME for good +* reason, i.e. we may not be interested in its timestamps, just in +* it taking place, picking some piece of information when it +* appears in our event stream (vfs_getname comes to mind). +*/ +if (trace->base_time ==0 && !trace->full_time && + (evsel->attr.sample_type &PERF_SAMPLE_TIME )) trace->base_time = sample->time; }
Signature · 1 line
2.5.5
Arnaldo Carvalho de Melo
maintainerPATCH 10/10 perf bpf: Add sample types for 'bpf-output' event
In reply to Arnaldo Carvalho de MeloFrom: Wang Nan <[email protected]>
Before this patch we can see very large time in the events before the 'bpf-output' event. For example:
# perf trace -vv -T --ev sched:sched_switch \
--ev bpf-output/no-inherit,name=evt/ \
--ev ./test_bpf_trace.c/map:channel.event=evt/ \
usleep 10
...
18446744073709.551 (18446564645918.480 ms): usleep/4157 nanosleep(rqtp: 0x7ffd3f0dc4e0) ...
18446744073709.551 ( ): evt:Raise a BPF event!..)
179427791.076 ( ): perf_bpf_probe:func_begin:(ffffffff810eb9a0))
179427791.081 ( ): sched:sched_switch:usleep:4157 [120] S ==> swapper/2:0 [120])
...We can also see the differences between bpf-output events and breakpoint events:
For bpf output event:
sample_type IP|TID|RAW|IDENTIFIER
For tracepoint events:
sample_type IP|TID|TIME|CPU|PERIOD|RAW|IDENTIFIER
This patch fix this differences by adding more sample type for bpf-output events.
After this patch:
# perf trace -vv -T --ev sched:sched_switch \
--ev bpf-output/no-inherit,name=evt/ \
--ev ./test_bpf_trace.c/map:channel.event=evt/ \
usleep 10
...
179877370.878 ( 0.003 ms): usleep/5336 nanosleep(rqtp: 0x7ffff866c450) ...
179877370.878 ( ): evt:Raise a BPF event!..)
179877370.878 ( ): perf_bpf_probe:func_begin:(ffffffff810eb9a0))
179877370.882 ( ): sched:sched_switch:usleep:5336 [120] S ==> swapper/4:0 [120])
179877370.945 ( ): evt:Raise a BPF event!..)
... # ./perf trace -vv -T --ev sched:sched_switch \
--ev bpf-output/no-inherit,name=evt/ \
--ev ./test_bpf_trace.c/map:channel.event=evt/ \
usleep 10 2>&1 | grep sample_type
sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW
sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW
sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW
sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW
sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW
sample_type IP|TID|TIME|ID|CPU|PERIOD|RAWThe 'IDENTIFIER' info is not required because all events have the same sample_type.
Committer notes:
Further testing, on top of the changes making 'perf trace' avoid samples from events without PERF_SAMPLE_TIME:
Before:
# trace --ev bpf-output/no-inherit,name=evt/ --ev /home/acme/bpf/test_bpf_trace.c/map:channel.event=evt/ usleep 10
<SNIP>
0.560 ( 0.001 ms): brk( ) = 0x55e5a1df8000
18446640227439.430 (18446640227438.859 ms): nanosleep(rqtp: 0x7ffc96643370) ...
18446640227439.430 ( ): evt:Raise a BPF event!..)
0.576 ( ): perf_bpf_probe:func_begin:(ffffffff81112460))
18446640227439.430 ( ): evt:Raise a BPF event!..)
0.645 ( ): perf_bpf_probe:func_end:(ffffffff81112460 <- ffffffff81003d92))
0.646 ( 0.076 ms): ... [continued]: nanosleep()) = 0
#After:
# trace --ev bpf-output/no-inherit,name=evt/ --ev /home/acme/bpf/test_bpf_trace.c/map:channel.event=evt/ usleep 10
<SNIP>
0.292 ( 0.001 ms): brk( ) = 0x55c7cd6e1000
0.302 ( 0.004 ms): nanosleep(rqtp: 0x7ffedd8bc0f0) ...
0.302 ( ): evt:Raise a BPF event!..)
0.303 ( ): perf_bpf_probe:func_begin:(ffffffff81112460))
0.397 ( ): evt:Raise a BPF event!..)
0.397 ( ): perf_bpf_probe:func_end:(ffffffff81112460 <- ffffffff81003d92))
0.398 ( 0.100 ms): ... [continued]: nanosleep()) = 0--- tools/perf/util/evsel.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-)
tools/perf/util/evsel.c +2 -1
@@ -226,7 +226,8 @@ struct perf_evsel *perf_evsel__new_idx(struct perf_event_attr *attr, int idx)perf_evsel__init (evsel, attr, idx);if (perf_evsel__is_bpf_output (evsel)) { - evsel->attr.sample_type |=PERF_SAMPLE_RAW ; + evsel->attr.sample_type |= (PERF_SAMPLE_RAW |PERF_SAMPLE_TIME | +PERF_SAMPLE_CPU |PERF_SAMPLE_PERIOD ), evsel->attr.sample_period =1 ; }
Signature · 1 line
2.5.5
Quoted 72 lines · Arnaldo Carvalho de Melo
Hi Ingo,
Please consider pulling,
- Arnaldo
The following changes since commit
d1b26c70246bc72922ae61d9f972d5c2588409e7:perf/ring_buffer: Prepare writing into the ring-buffer from the end (2016-03-31 10:30:49 +0200)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.gittags/perf-core-for-mingo-20160401for you to fetch changes up to
d37ba880598654fda10b312331377cdca3edd574:perf bpf: Add sample types for 'bpf-output' event (2016-04-01 18:46:25 -0300)
----------------------------------------------------------------
perf/core improvements and fixes:User visible:
- Do not use events that don't have timestamps when setting 'perf trace's base timestamp, fixing up the timestamp column for syscalls (Arnaldo Carvalho de Melo)
- Make the 'bpf-output'
sample_typebe the same as tracepoint's, fixing up 'perf trace's timestamp column for bpf events (Wang Nan)- Fix PMU term format max value calculation (Kan Liang)
- Pretty print 'seccomp', 'getrandom' syscalls in 'perf trace' (Arnaldo Carvalho de Melo)
Infrastructure:
- Add support for using TSC as an ARCH timestamp when synthesizing JIT records (Adrian Hunter)
Signed-off-by Arnaldo Carvalho de Melo <[email protected]>----------------------------------------------------------------
Adrian Hunter (3):
perf tools: Add time conversion event
perf jit: Add support for using TSC as a timestamp perf intel-pt/bts: DefineJITDUMP_USE_ARCH_TIMESTAMPArnaldo Carvalho de Melo (5):
perf trace: Do not processPERF_RECORD_LOSTtwice
perf trace: Pretty printseccomp()args
perf trace: Pretty printgetrandom()args
perf trace: Introduce function to set the base timestamp
perf trace: Don't set the base timestamp using events withoutPERF_SAMPLE_TIMEKan Liang (1):
perf tools: Fix PMU term format max value calculationWang Nan (1):
perf bpf: Add sample types for 'bpf-output' eventtools/perf/arch/x86/util/intel-bts.c | 5 ++ tools/perf/arch/x86/util/intel-pt.c | 5 ++ tools/perf/arch/x86/util/tsc.c | 32 +++++++++++- tools/perf/arch/x86/util/tsc.h | 17 ------- tools/perf/builtin-inject.c | 1 + tools/perf/builtin-record.c | 15 ++++++ tools/perf/builtin-trace.c | 99 ++++++++++++++++++++++++++++++++++-- tools/perf/jvmti/jvmti_agent.c | 43 +++++++++++++++- tools/perf/util/Build | 3 +- tools/perf/util/event.c | 1 + tools/perf/util/event.h | 9 ++++ tools/perf/util/evsel.c | 3 +- tools/perf/util/jitdump.c | 37 ++++++++++++--
Quoted 8 lines
tools/perf/util/jitdump.h | 3 ++ tools/perf/util/pmu.c | 13 +++-- tools/perf/util/session.c | 6 +++ tools/perf/util/session.h | 1 + tools/perf/util/tool.h | 1 + tools/perf/util/tsc.h | 21 +++++++- 19 files changed, 274 insertions(+), 41 deletions(-) delete mode 100644 tools/perf/arch/x86/util/tsc.h
Pulled, thanks a lot Arnaldo!
Ingo