From c9f24e77d23fd70a40de21369f931182a57f8d58 Mon Sep 17 00:00:00 2001 From: Keno Fischer Date: Mon, 11 Jul 2016 20:07:14 -0400 Subject: [PATCH 1/4] WIP: Don't deschedule perf counters --- src/PerfCounters.cc | 58 ++++++++++++++++++++++++++------------------- src/PerfCounters.h | 2 +- src/Task.cc | 5 ++-- 3 files changed, 37 insertions(+), 28 deletions(-) diff --git a/src/PerfCounters.cc b/src/PerfCounters.cc index 50ec4bef6e8..6223a380db5 100644 --- a/src/PerfCounters.cc +++ b/src/PerfCounters.cc @@ -214,33 +214,37 @@ static ScopedFd start_counter(pid_t tid, int group_fd, void PerfCounters::reset(Ticks ticks_period) { assert(ticks_period >= 0); - stop(); - - struct perf_event_attr attr = rr::ticks_attr; - attr.sample_period = ticks_period; - fd_ticks = start_counter(tid, -1, &attr); - - struct f_owner_ex own; - own.type = F_OWNER_TID; - own.pid = tid; - if (fcntl(fd_ticks, F_SETOWN_EX, &own)) { - FATAL() << "Failed to SETOWN_EX ticks event fd"; - } - if (fcntl(fd_ticks, F_SETFL, O_ASYNC) || - fcntl(fd_ticks, F_SETSIG, PerfCounters::TIME_SLICE_SIGNAL)) { - FATAL() << "Failed to make ticks counter ASYNC with sig" - << signal_name(PerfCounters::TIME_SLICE_SIGNAL); - } + if (!started) { + struct perf_event_attr attr = rr::ticks_attr; + attr.sample_period = ticks_period; + fd_ticks = start_counter(tid, -1, &attr); + + struct f_owner_ex own; + own.type = F_OWNER_TID; + own.pid = tid; + if (fcntl(fd_ticks, F_SETOWN_EX, &own)) { + FATAL() << "Failed to SETOWN_EX ticks event fd"; + } + if (fcntl(fd_ticks, F_SETFL, O_ASYNC) || + fcntl(fd_ticks, F_SETSIG, PerfCounters::TIME_SLICE_SIGNAL)) { + FATAL() << "Failed to make ticks counter ASYNC with sig" + << signal_name(PerfCounters::TIME_SLICE_SIGNAL); + } - if (extra_perf_counters_enabled()) { - int group_leader = fd_ticks; - fd_hw_interrupts = start_counter(tid, group_leader, &hw_interrupts_attr); - fd_instructions_retired = - start_counter(tid, group_leader, &instructions_retired_attr); - fd_page_faults = start_counter(tid, group_leader, &page_faults_attr); + if (extra_perf_counters_enabled()) { + int group_leader = fd_ticks; + fd_hw_interrupts = start_counter(tid, group_leader, &hw_interrupts_attr); + fd_instructions_retired = + start_counter(tid, group_leader, &instructions_retired_attr); + fd_page_faults = start_counter(tid, group_leader, &page_faults_attr); + } + } else { + ioctl(fd_ticks, PERF_EVENT_IOC_RESET); + ioctl(fd_ticks, PERF_EVENT_IOC_PERIOD, &ticks_period); } - + started = true; + counting = true; } void PerfCounters::stop() { @@ -263,7 +267,11 @@ static int64_t read_counter(ScopedFd& fd) { } Ticks PerfCounters::read_ticks() { - return started ? read_counter(fd_ticks) : 0; + uint64_t period = UINT32_MAX; + uint64_t val = started ? read_counter(fd_ticks) : 0; + ioctl(fd_ticks, PERF_EVENT_IOC_RESET); + ioctl(fd_ticks, PERF_EVENT_IOC_PERIOD, &period); + return val; } PerfCounters::Extra PerfCounters::read_extra() { diff --git a/src/PerfCounters.h b/src/PerfCounters.h index c13764e4ca0..fe36568cfaf 100644 --- a/src/PerfCounters.h +++ b/src/PerfCounters.h @@ -81,7 +81,7 @@ class PerfCounters { Extra read_extra(); static const struct perf_event_attr& ticks_attr(); - + bool counting; private: pid_t tid; ScopedFd fd_ticks; diff --git a/src/Task.cc b/src/Task.cc index 10e6d55dfb1..9e95c20a4a6 100644 --- a/src/Task.cc +++ b/src/Task.cc @@ -1224,10 +1224,11 @@ void Task::emulate_syscall_entry(const Registers& regs) { } void Task::did_waitpid(WaitStatus status, siginfo_t* override_siginfo) { - Ticks more_ticks = hpc.read_ticks(); + Ticks more_ticks = hpc.counting ? hpc.read_ticks() : 0; + hpc.counting = false; // Stop PerfCounters ASAP to reduce the possibility that due to bugs or // whatever they pick up something spurious later. - hpc.stop(); + //hpc.stop(); ticks += more_ticks; session().accumulate_ticks_processed(more_ticks); From 90911e0f0bf2505972457bf04e5ecaeb4a6c13c4 Mon Sep 17 00:00:00 2001 From: Keno Fischer Date: Mon, 11 Jul 2016 20:34:42 -0400 Subject: [PATCH 2/4] Support emulation of newly used perf ioctls --- src/VirtualPerfCounterMonitor.cc | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/src/VirtualPerfCounterMonitor.cc b/src/VirtualPerfCounterMonitor.cc index d22a540424e..807fbe4b2d1 100644 --- a/src/VirtualPerfCounterMonitor.cc +++ b/src/VirtualPerfCounterMonitor.cc @@ -40,6 +40,20 @@ bool VirtualPerfCounterMonitor::emulate_ioctl(RecordTask* t, uint64_t* result) { *result = 0; enabled = true; break; + case PERF_EVENT_IOC_RESET: + { + *result = 0; + RecordTask* target = t->session().find_task(target_tuid); + initial_ticks = target->tick_count(); + } + break; + case PERF_EVENT_IOC_PERIOD: + { + *result = 0; + // Nominally we'd resent the interrupt here, but since we don't support + // that yet, just ignore it. + } + break; default: ASSERT(t, false) << "Unsupported perf event ioctl " << HEX((int)t->regs().arg2()); From 0bc102ccd12e3b3befef94c667598540efcadb99 Mon Sep 17 00:00:00 2001 From: Keno Fischer Date: Mon, 11 Jul 2016 22:10:40 -0400 Subject: [PATCH 3/4] Initial code for sampling --- CMakeLists.txt | 1 + src/PerfCommand.cc | 65 ++++++++++++++++++++++++++++++++++++++++++++ src/PerfCounters.cc | 62 ++++++++++++++++++++++++++++++++++++++---- src/PerfCounters.h | 16 +++++++++++ src/RecordCommand.cc | 16 +++++++++-- src/RecordSession.cc | 11 +++++--- src/RecordSession.h | 11 +++++--- src/RecordTask.cc | 18 ++++++++++++ src/RecordTask.h | 3 ++ src/Task.cc | 8 ++++-- src/Task.h | 2 ++ src/TraceStream.cc | 17 ++++++++++++ src/TraceStream.h | 10 +++++++ 13 files changed, 220 insertions(+), 20 deletions(-) create mode 100644 src/PerfCommand.cc diff --git a/CMakeLists.txt b/CMakeLists.txt index bd3dc8b1e29..c955921d1cd 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -247,6 +247,7 @@ set(RR_SOURCES src/MagicSaveDataMonitor.cc src/MonitoredSharedMemory.cc src/Monkeypatcher.cc + src/PerfCommand.cc src/PerfCounters.cc src/ProcMemMonitor.cc src/PsCommand.cc diff --git a/src/PerfCommand.cc b/src/PerfCommand.cc new file mode 100644 index 00000000000..e8b0809f442 --- /dev/null +++ b/src/PerfCommand.cc @@ -0,0 +1,65 @@ +/* -*- Mode: C++; tab-width: 8; c-basic-offset: 2; indent-tabs-mode: nil; -*- */ + +#include + +#include "Command.h" +#include "TraceStream.h" +#include "TraceTaskEvent.h" +#include "main.h" +#include "util.h" +#include "Flags.h" + +using namespace std; + +namespace rr { + +class PerfCommand : public Command { +public: + virtual int run(vector& args); + +protected: + PerfCommand(const char* name, const char* help) : Command(name, help) {} + + static PerfCommand singleton; +}; + +PerfCommand PerfCommand::singleton("perf", " rr perf []\n"); + + +static int perf(const string& trace_dir, FILE* out) { + TraceReader trace(trace_dir); + + if (!probably_not_interactive(STDOUT_FILENO) && !Flags::get().force_things) { + fprintf(stderr, "Cowardly refusing to write binary data to a tty. " + "Use -f to overwrite\n"); + return 1; + } + + // Write perf file header + + // Write perf file data + ssize_t total_bytes_left = trace.total_perf_bytes(); + while (trace.good() && total_bytes_left > 0) { + size_t to_read = min((ssize_t)0x1000, total_bytes_left); + auto data = trace.read_perf_records(to_read); + fwrite(data.data(), 1, data.size(), out); + total_bytes_left -= to_read; + } + + return 0; +}; + +int PerfCommand::run(vector& args) { + while (parse_global_option(args)) { + } + + string trace_dir; + if (!parse_optional_trace_dir(args, &trace_dir)) { + print_help(stderr); + return 1; + } + + return perf(trace_dir, stdout); +} + +} // namespace rr diff --git a/src/PerfCounters.cc b/src/PerfCounters.cc index 6223a380db5..934402e0f3b 100644 --- a/src/PerfCounters.cc +++ b/src/PerfCounters.cc @@ -11,6 +11,7 @@ #include #include #include +#include #include #include @@ -26,6 +27,7 @@ using namespace std; namespace rr { static bool attributes_initialized; +static struct perf_event_attr samples_attr; static struct perf_event_attr ticks_attr; static struct perf_event_attr page_faults_attr; static struct perf_event_attr hw_interrupts_attr; @@ -150,6 +152,33 @@ static void init_perf_event_attr(struct perf_event_attr* attr, attr->exclude_guest = 1; } +static void check_sampling_limit() { + static bool checked = false; + if (checked) + return; + // Check perf event sample rate and print a helpful error message + { + char line[64]; + int fd = open("/proc/sys/kernel/perf_event_max_sample_rate", O_RDONLY); + if (read(fd, line, sizeof(line)) > 0) { + assert(atoi(line) >= 4000 && + "Make sure /proc/sys/kernel/perf_event_max_sample_rate is set high enough"); + } + close(fd); + } +} + +static void init_samples_event() { + memset(&rr::samples_attr, 0, sizeof(rr::samples_attr)); + rr::samples_attr.type = PERF_TYPE_HARDWARE; + rr::samples_attr.size = sizeof(rr::samples_attr); + rr::samples_attr.config = PERF_COUNT_HW_CPU_CYCLES; + rr::samples_attr.sample_freq = 4000; + rr::samples_attr.freq = 1; + rr::samples_attr.sample_type = PERF_SAMPLE_IP|PERF_SAMPLE_TIME|PERF_SAMPLE_READ|PERF_SAMPLE_TID; + rr::samples_attr.read_format = PERF_FORMAT_GROUP; +} + static void init_attributes() { if (attributes_initialized) { return; @@ -175,6 +204,7 @@ static void init_attributes() { pmu->rinsn_cntr_event); init_perf_event_attr(&hw_interrupts_attr, PERF_TYPE_RAW, pmu->hw_intr_cntr_event); + init_samples_event(); // libpfm encodes the event with this bit set, so we'll do the // same thing. Unclear if necessary. hw_interrupts_attr.exclude_hv = 1; @@ -187,7 +217,8 @@ const struct perf_event_attr& PerfCounters::ticks_attr() { return rr::ticks_attr; } -PerfCounters::PerfCounters(pid_t tid) : tid(tid), started(false) { +PerfCounters::PerfCounters(pid_t tid) : tid(tid), started(false), + sampling_enabled(false) { init_attributes(); } @@ -211,13 +242,33 @@ static ScopedFd start_counter(pid_t tid, int group_fd, return fd; } +static const int SAMPLE_MMAP_SIZE = (1+(1<<10))*PAGE_SIZE; +void PerfCounters::samples_unmapper::operator()(void *ptr) +{ + munmap(ptr, SAMPLE_MMAP_SIZE); +} + void PerfCounters::reset(Ticks ticks_period) { assert(ticks_period >= 0); if (!started) { + int group_fd = -1; + if (enable_sampling() && !samples_mmap) { + check_sampling_limit(); + fd_samples = start_counter(tid, -1, &rr::samples_attr); + samples_mmap.reset(mmap(NULL, SAMPLE_MMAP_SIZE, PROT_READ|PROT_WRITE, + MAP_SHARED, fd_samples, 0)); + if (samples_mmap.get() == MAP_FAILED) { + FATAL() << "Failed to map samples page"; + } + group_fd = fd_samples; + } + struct perf_event_attr attr = rr::ticks_attr; attr.sample_period = ticks_period; - fd_ticks = start_counter(tid, -1, &attr); + fd_ticks = start_counter(tid, group_fd, &attr); + if (group_fd == -1) + group_fd = fd_ticks; struct f_owner_ex own; own.type = F_OWNER_TID; @@ -232,11 +283,10 @@ void PerfCounters::reset(Ticks ticks_period) { } if (extra_perf_counters_enabled()) { - int group_leader = fd_ticks; - fd_hw_interrupts = start_counter(tid, group_leader, &hw_interrupts_attr); + fd_hw_interrupts = start_counter(tid, group_fd, &hw_interrupts_attr); fd_instructions_retired = - start_counter(tid, group_leader, &instructions_retired_attr); - fd_page_faults = start_counter(tid, group_leader, &page_faults_attr); + start_counter(tid, group_fd, &instructions_retired_attr); + fd_page_faults = start_counter(tid, group_fd, &page_faults_attr); } } else { ioctl(fd_ticks, PERF_EVENT_IOC_RESET); diff --git a/src/PerfCounters.h b/src/PerfCounters.h index fe36568cfaf..cc3091413d6 100644 --- a/src/PerfCounters.h +++ b/src/PerfCounters.h @@ -10,6 +10,7 @@ #include #include #include +#include #include "ScopedFd.h" #include "Ticks.h" @@ -42,6 +43,11 @@ class PerfCounters { // for experimentation, but aren't necessary for core functionality. static bool extra_perf_counters_enabled() { return false; } + // Change this to 'true' to enable sampling + bool enable_sampling() { return sampling_enabled; } + + void set_sampling(bool sampling) { sampling_enabled = sampling; } + /** * Reset all counter values to 0 and program the counters to send * TIME_SLICE_SIGNAL when 'ticks_period' tick events have elapsed. (In reality @@ -81,14 +87,24 @@ class PerfCounters { Extra read_extra(); static const struct perf_event_attr& ticks_attr(); + + struct samples_unmapper { + public: + void operator()(void *ptr); + }; + std::unique_ptr samples_mmap; + bool counting; + private: pid_t tid; + ScopedFd fd_samples; ScopedFd fd_ticks; ScopedFd fd_page_faults; ScopedFd fd_hw_interrupts; ScopedFd fd_instructions_retired; bool started; + bool sampling_enabled; }; } // namespace rr diff --git a/src/RecordCommand.cc b/src/RecordCommand.cc index 9247c262476..71c73b482e6 100644 --- a/src/RecordCommand.cc +++ b/src/RecordCommand.cc @@ -58,7 +58,9 @@ RecordCommand RecordCommand::singleton( " just the initial process.\n" " --ignore-nested Directly start child process when running\n" " under nested rr recording, instead of\n" - " raising an error.\n"); + " raising an error.\n" + " --sample Record program-state samples at a fixed\n" + " time interval."); struct RecordFlags { vector extra_env; @@ -103,6 +105,8 @@ struct RecordFlags { /* Start child process directly if run under nested rr recording */ bool ignore_nested; + + bool do_sampling; RecordFlags() : max_ticks(Scheduler::DEFAULT_MAX_TICKS), @@ -116,7 +120,8 @@ struct RecordFlags { always_switch(false), chaos(false), wait_for_all(false), - ignore_nested(false) {} + ignore_nested(false), + do_sampling(false) {} }; static void parse_signal_name(ParsedOption& opt) { @@ -148,6 +153,7 @@ static bool parse_record_arg(vector& args, RecordFlags& flags) { { 1, "no-file-cloning", NO_PARAMETER }, { 2, "syscall-buffer-size", HAS_PARAMETER }, { 3, "ignore-nested", NO_PARAMETER }, + { 4, "sample", NO_PARAMETER }, { 'b', "force-syscall-buffer", NO_PARAMETER }, { 'c', "num-cpu-ticks", HAS_PARAMETER }, { 'h', "chaos", NO_PARAMETER }, @@ -205,6 +211,9 @@ static bool parse_record_arg(vector& args, RecordFlags& flags) { case 3: flags.ignore_nested = true; break; + case 4: + flags.do_sampling = true; + break; case 's': flags.always_switch = true; break; @@ -283,7 +292,8 @@ static WaitStatus record(const vector& args, const RecordFlags& flags) { LOG(info) << "Start recording..."; auto session = RecordSession::create( - args, flags.extra_env, flags.use_syscall_buffer, flags.bind_cpu); + args, flags.extra_env, flags.use_syscall_buffer, flags.bind_cpu, + flags.do_sampling); setup_session_from_flags(*session, flags); // Install signal handlers after creating the session, to ensure they're not diff --git a/src/RecordSession.cc b/src/RecordSession.cc index f0143ec9927..301ff35aa83 100644 --- a/src/RecordSession.cc +++ b/src/RecordSession.cc @@ -1473,7 +1473,8 @@ static string lookup_by_path(const string& name) { /*static*/ RecordSession::shr_ptr RecordSession::create( const vector& argv, const vector& extra_env, - SyscallBuffering syscallbuf, BindCPU bind_cpu) { + SyscallBuffering syscallbuf, BindCPU bind_cpu, + bool do_sampling) { // The syscallbuf library interposes some critical // external symbols like XShmQueryExtension(), so we // preload it whether or not syscallbuf is enabled. Indicate here whether @@ -1556,15 +1557,17 @@ static string lookup_by_path(const string& name) { env.push_back("MOZ_GDB_SLEEP=0"); shr_ptr session( - new RecordSession(full_path, argv, env, syscallbuf, bind_cpu)); + new RecordSession(full_path, argv, env, syscallbuf, bind_cpu, do_sampling)); return session; } RecordSession::RecordSession(const std::string& exe_path, const std::vector& argv, const std::vector& envp, - SyscallBuffering syscallbuf, BindCPU bind_cpu) - : trace_out(argv[0], choose_cpu(bind_cpu)), + SyscallBuffering syscallbuf, BindCPU bind_cpu, + bool do_sampling) + : do_sampling_(do_sampling), + trace_out(argv[0], choose_cpu(bind_cpu)), scheduler_(*this), ignore_sig(0), continue_through_sig(0), diff --git a/src/RecordSession.h b/src/RecordSession.h index 08f5c2da241..93bd489b45c 100644 --- a/src/RecordSession.h +++ b/src/RecordSession.h @@ -31,7 +31,8 @@ class RecordSession : public Session { const std::vector& argv, const std::vector& extra_env = std::vector(), SyscallBuffering syscallbuf = ENABLE_SYSCALL_BUF, - BindCPU bind_cpu = BIND_CPU); + BindCPU bind_cpu = BIND_CPU, + bool do_sampling = false); bool use_syscall_buffer() const { return use_syscall_buffer_; } size_t syscall_buffer_size() const { return syscall_buffer_size_; } @@ -109,18 +110,20 @@ class RecordSession : public Session { void set_wait_for_all(bool wait_for_all) { this->wait_for_all_ = wait_for_all; } - + virtual Task* new_task(pid_t tid, pid_t rec_tid, uint32_t serial, SupportedArch a); RecordTask* find_task(pid_t rec_tid) const; RecordTask* find_task(const TaskUid& tuid) const; - + + bool do_sampling_; private: RecordSession(const std::string& exe_path, const std::vector& argv, const std::vector& envp, - SyscallBuffering syscallbuf, BindCPU bind_cpu); + SyscallBuffering syscallbuf, BindCPU bind_cpu, + bool do_sampling); virtual void on_create(Task* t); diff --git a/src/RecordTask.cc b/src/RecordTask.cc index a6653bb8da3..60f027d4033 100644 --- a/src/RecordTask.cc +++ b/src/RecordTask.cc @@ -184,6 +184,7 @@ RecordTask::RecordTask(RecordSession& session, pid_t _tid, uint32_t serial, exit_code(0), termination_signal(0), tsc_mode(PR_TSC_ENABLE) { + hpc.set_sampling(session.do_sampling_); push_event(Event(EV_SENTINEL, NO_EXEC_INFO, RR_NATIVE_ARCH)); if (session.tasks().empty()) { // Initial tracee. It inherited its state from this process, so set it up. @@ -1105,6 +1106,23 @@ uint16_t RecordTask::get_ptrace_eventmsg_seccomp_data() { return data; } +#define ACCESS_ONCE(x) (*(volatile decltype(x) *)&(x)) +#define rmb() asm volatile("lfence":::"memory") + +void RecordTask::record_perf_records() { + struct perf_event_mmap_page *header = + (struct perf_event_mmap_page *)hpc.samples_mmap.get(); + if (header) { + uint64_t head = ACCESS_ONCE(header->data_head); + rmb(); + size_t size = head - header->data_tail; + trace_writer().write_perf_records( + ((uint8_t*)header) + 0x1000 + header->data_tail,size); + header->data_tail = head; + } +} + + void RecordTask::record_local(remote_ptr addr, ssize_t num_bytes, const void* data) { maybe_flush_syscallbuf(); diff --git a/src/RecordTask.h b/src/RecordTask.h index d3a2f1689a2..b1cf7fbb940 100644 --- a/src/RecordTask.h +++ b/src/RecordTask.h @@ -426,6 +426,9 @@ class RecordTask : public Task { enum { SYNTHETIC_TIME_SLICE_SI_CODE = -9999 }; +protected: + void record_perf_records(); + private: ~RecordTask(); diff --git a/src/Task.cc b/src/Task.cc index 9e95c20a4a6..177db8ac980 100644 --- a/src/Task.cc +++ b/src/Task.cc @@ -1224,11 +1224,13 @@ void Task::emulate_syscall_entry(const Registers& regs) { } void Task::did_waitpid(WaitStatus status, siginfo_t* override_siginfo) { + // If recording and sampling, save the perf records + if (hpc.enable_sampling()) { + record_perf_records(); + } + Ticks more_ticks = hpc.counting ? hpc.read_ticks() : 0; hpc.counting = false; - // Stop PerfCounters ASAP to reduce the possibility that due to bugs or - // whatever they pick up something spurious later. - //hpc.stop(); ticks += more_ticks; session().accumulate_ticks_processed(more_ticks); diff --git a/src/Task.h b/src/Task.h index 8cfca67e7b3..6360bb3de19 100644 --- a/src/Task.h +++ b/src/Task.h @@ -872,6 +872,8 @@ class Task { const std::vector& argv, const std::vector& envp, pid_t rec_tid = -1); + virtual void record_perf_records() { } + uint32_t serial; // The address space of this task. AddressSpace::shr_ptr as; diff --git a/src/TraceStream.cc b/src/TraceStream.cc index 09fac3cd332..247640a6945 100644 --- a/src/TraceStream.cc +++ b/src/TraceStream.cc @@ -43,6 +43,7 @@ static SubstreamData substreams[TraceStream::SUBSTREAM_COUNT] = { { "events", 1024 * 1024, 1 }, { "data_header", 1024 * 1024, 1 }, { "data", 1024 * 1024, 0 }, { "mmaps", 64 * 1024, 1 }, { "tasks", 64 * 1024, 1 }, { "generic", 64 * 1024, 1 }, + { "perf", 64 * 1024, 1} }; static const SubstreamData& substream(TraceStream::Substream s) { @@ -560,6 +561,22 @@ bool TraceReader::read_generic_for_frame(const TraceFrame& frame, return true; } +void TraceWriter::write_perf_records(const uint8_t* data, size_t len) { + auto& perf = writer(PERF_EVENTS); + perf.write(data, len); +} + +uint64_t TraceReader::total_perf_bytes() { + return reader(PERF_EVENTS).uncompressed_bytes(); +} + +std::vector TraceReader::read_perf_records(size_t nbytes) { + std::vector data; + data.resize(nbytes); + reader(PERF_EVENTS).read(data.data(), nbytes); + return data; +} + void TraceWriter::close() { for (auto& w : writers) { w->close(); diff --git a/src/TraceStream.h b/src/TraceStream.h index 1af911ff1cf..d772c45e9d6 100644 --- a/src/TraceStream.h +++ b/src/TraceStream.h @@ -54,6 +54,8 @@ class TraceStream { TASKS, // Substream that stores arbitrary per-event records GENERIC, + // Substream that records perf_event records + PERF_EVENTS, SUBSTREAM_COUNT }; @@ -146,6 +148,11 @@ class TraceWriter : public TraceStream { */ void write_generic(const void* data, size_t len); + /** + * Write a perf records to the trace + */ + void write_perf_records(const uint8_t* data, size_t len); + /** * Return true iff all trace files are "good". */ @@ -256,6 +263,9 @@ class TraceReader : public TraceStream { bool read_generic_for_frame(const TraceFrame& frame, std::vector& out); + uint64_t total_perf_bytes(); + std::vector read_perf_records(size_t nbytes); + /** * Return true iff all trace files are "good". * for more details. From 368fd9bf2826b85d26446be606baa899246c18c2 Mon Sep 17 00:00:00 2001 From: Keno Fischer Date: Wed, 13 Jul 2016 19:05:46 -0400 Subject: [PATCH 4/4] Save tick value in log before clearing --- src/PerfCounters.cc | 6 +++--- src/RecordTask.cc | 13 +++++++++++++ src/Task.cc | 11 ++++++----- 3 files changed, 22 insertions(+), 8 deletions(-) diff --git a/src/PerfCounters.cc b/src/PerfCounters.cc index 934402e0f3b..2ae567c7e6e 100644 --- a/src/PerfCounters.cc +++ b/src/PerfCounters.cc @@ -317,10 +317,10 @@ static int64_t read_counter(ScopedFd& fd) { } Ticks PerfCounters::read_ticks() { - uint64_t period = UINT32_MAX; + //uint64_t period = UINT32_MAX; uint64_t val = started ? read_counter(fd_ticks) : 0; - ioctl(fd_ticks, PERF_EVENT_IOC_RESET); - ioctl(fd_ticks, PERF_EVENT_IOC_PERIOD, &period); + //ioctl(fd_ticks, PERF_EVENT_IOC_RESET); + //ioctl(fd_ticks, PERF_EVENT_IOC_PERIOD, &period); return val; } diff --git a/src/RecordTask.cc b/src/RecordTask.cc index 60f027d4033..eb350b7761d 100644 --- a/src/RecordTask.cc +++ b/src/RecordTask.cc @@ -1109,6 +1109,13 @@ uint16_t RecordTask::get_ptrace_eventmsg_seccomp_data() { #define ACCESS_ONCE(x) (*(volatile decltype(x) *)&(x)) #define rmb() asm volatile("lfence":::"memory") +struct fake_perf_record { + uint32_t type; + uint16_t misc; + uint16_t size; + uint64_t base; +}; + void RecordTask::record_perf_records() { struct perf_event_mmap_page *header = (struct perf_event_mmap_page *)hpc.samples_mmap.get(); @@ -1119,6 +1126,12 @@ void RecordTask::record_perf_records() { trace_writer().write_perf_records( ((uint8_t*)header) + 0x1000 + header->data_tail,size); header->data_tail = head; + // Record the base tick count as a special record, so the actual tick count + // can be reconstructed. + fake_perf_record record {.type = 20, .misc = 0, + .size = sizeof(fake_perf_record), .base = 0}; + record.base = tick_count(); + trace_writer().write_perf_records((uint8_t*)&record, sizeof(record)); } } diff --git a/src/Task.cc b/src/Task.cc index 177db8ac980..4a1dbea98a0 100644 --- a/src/Task.cc +++ b/src/Task.cc @@ -791,6 +791,12 @@ void Task::resume_execution(ResumeRequest how, WaitRequest wait_how, hpc.reset(tick_period == RESUME_UNLIMITED_TICKS ? 0xffffffff : max(1, tick_period)); + + // If recording and sampling, save the perf records + if (hpc.enable_sampling()) { + record_perf_records(); + } + // Ensure preload_globals.thread_locals_initialized is up to date. Avoid // unnecessary writes by caching last written value per-AddressSpace. if (preload_globals) { @@ -1224,11 +1230,6 @@ void Task::emulate_syscall_entry(const Registers& regs) { } void Task::did_waitpid(WaitStatus status, siginfo_t* override_siginfo) { - // If recording and sampling, save the perf records - if (hpc.enable_sampling()) { - record_perf_records(); - } - Ticks more_ticks = hpc.counting ? hpc.read_ticks() : 0; hpc.counting = false; ticks += more_ticks;