From eb98a8b5a1259ccf37bb194a28012d72c873103c Mon Sep 17 00:00:00 2001 From: Yabin Cui Date: Tue, 7 May 2024 16:53:57 -0700 Subject: simpleperf: Enable ETM events after create aux buffer Otherwise, ETM events can't be enabled successfully. Bug: 336375740 Test: run simpleperf manually Change-Id: I6583aebced57d739f98769cc39dab862569ec8ad --- simpleperf/cmd_record.cpp | 11 +++++++--- simpleperf/event_selection_set.cpp | 45 ++++++++++++++++++++++++++++++++++++++ simpleperf/event_selection_set.h | 3 +++ 3 files changed, 56 insertions(+), 3 deletions(-) diff --git a/simpleperf/cmd_record.cpp b/simpleperf/cmd_record.cpp index 40582045..ee93e1ea 100644 --- a/simpleperf/cmd_record.cpp +++ b/simpleperf/cmd_record.cpp @@ -631,7 +631,7 @@ bool RecordCommand::PrepareRecording(Workload* workload) { } else { need_to_check_targets = true; } - if (delay_in_ms_ != 0) { + if (delay_in_ms_ != 0 || event_selection_set_.HasAuxTrace()) { event_selection_set_.SetEnableCondition(false, false); } @@ -755,6 +755,12 @@ bool RecordCommand::PrepareRecording(Workload* workload) { } } if (event_selection_set_.HasAuxTrace()) { + // ETM events can only be enabled successfully after MmapEventFiles(). + if (delay_in_ms_ == 0 && !event_selection_set_.IsEnabledOnExec()) { + if (!event_selection_set_.EnableETMEvents()) { + return false; + } + } // ETM data is dumped to kernel buffer only when there is no thread traced by ETM. It happens // either when all monitored threads are scheduled off cpu, or when all etm perf events are // disabled. @@ -762,8 +768,7 @@ bool RecordCommand::PrepareRecording(Workload* workload) { // makes less than expected data, especially in system wide recording. So add a periodic event // to flush etm data by temporarily disable all perf events. auto etm_flush = [this]() { - return event_selection_set_.SetEnableEvents(false) && - event_selection_set_.SetEnableEvents(true); + return event_selection_set_.DisableETMEvents() && event_selection_set_.EnableETMEvents(); }; if (!loop->AddPeriodicEvent(SecondToTimeval(kDefaultEtmDataFlushPeriodInSec), etm_flush)) { return false; diff --git a/simpleperf/event_selection_set.cpp b/simpleperf/event_selection_set.cpp index c75f8049..6a1e5a9e 100644 --- a/simpleperf/event_selection_set.cpp +++ b/simpleperf/event_selection_set.cpp @@ -233,6 +233,8 @@ bool EventSelectionSet::BuildAndCheckEventSelection(const std::string& event_nam // enabling/disabling etm devices. So don't adjust frequency by default. selection->event_attr.freq = 0; selection->event_attr.sample_period = 1; + // An ETM event can't be enabled without mmap aux buffer. So disable it by default. + selection->event_attr.disabled = 1; } else { selection->event_attr.freq = 1; // Set default sample freq here may print msg "Adjust sample freq to max allowed sample @@ -461,6 +463,17 @@ void EventSelectionSet::SetEnableCondition(bool enable_on_open, bool enable_on_e } } +bool EventSelectionSet::IsEnabledOnExec() const { + for (const auto& group : groups_) { + for (const auto& selection : group.selections) { + if (!selection.event_attr.enable_on_exec) { + return false; + } + } + } + return true; +} + void EventSelectionSet::SampleIdAll() { for (auto& group : groups_) { for (auto& selection : group.selections) { @@ -939,4 +952,36 @@ bool EventSelectionSet::SetEnableEvents(bool enable) { return true; } +bool EventSelectionSet::EnableETMEvents() { + for (auto& group : groups_) { + for (auto& sel : group.selections) { + if (!sel.event_type_modifier.event_type.IsEtmEvent()) { + continue; + } + for (auto& fd : sel.event_fds) { + if (!fd->SetEnableEvent(true)) { + return false; + } + } + } + } + return true; +} + +bool EventSelectionSet::DisableETMEvents() { + for (auto& group : groups_) { + for (auto& sel : group.selections) { + if (!sel.event_type_modifier.event_type.IsEtmEvent()) { + continue; + } + for (auto& fd : sel.event_fds) { + if (!fd->SetEnableEvent(false)) { + return false; + } + } + } + } + return true; +} + } // namespace simpleperf diff --git a/simpleperf/event_selection_set.h b/simpleperf/event_selection_set.h index e046035b..1b3d6b4e 100644 --- a/simpleperf/event_selection_set.h +++ b/simpleperf/event_selection_set.h @@ -122,6 +122,7 @@ class EventSelectionSet { std::map GetHardwareCountersForCpus() const; void SetEnableCondition(bool enable_on_open, bool enable_on_exec); + bool IsEnabledOnExec() const; void SampleIdAll(); // Only set sample rate for events that haven't set sample rate. void SetSampleRateForNewEvents(const SampleRate& rate); @@ -179,6 +180,8 @@ class EventSelectionSet { double check_interval_in_sec = DEFAULT_PERIOD_TO_CHECK_MONITORED_TARGETS_IN_SEC); bool SetEnableEvents(bool enable); + bool EnableETMEvents(); + bool DisableETMEvents(); private: struct EventSelection { -- cgit v1.2.3 From b89b1ef923929d2ada9770b4360e04c41c2670bd Mon Sep 17 00:00:00 2001 From: Yabin Cui Date: Tue, 7 May 2024 17:02:43 -0700 Subject: simpleperf: Flush ETM data at the end of recording So we can get the last ETM data generated during recording. Bug: 336375740 Test: run simpleperf manually Change-Id: I449517fb959e4f8310cd1fc582e2182552d0353d --- simpleperf/cmd_record.cpp | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/simpleperf/cmd_record.cpp b/simpleperf/cmd_record.cpp index ee93e1ea..d57c3422 100644 --- a/simpleperf/cmd_record.cpp +++ b/simpleperf/cmd_record.cpp @@ -805,6 +805,12 @@ bool RecordCommand::DoRecording(Workload* workload) { return false; } time_stat_.stop_recording_time = GetSystemClock(); + if (event_selection_set_.HasAuxTrace()) { + // Disable ETM events to flush the last ETM data. + if (!event_selection_set_.DisableETMEvents()) { + return false; + } + } if (!event_selection_set_.SyncKernelBuffer()) { return false; } -- cgit v1.2.3 From 9e247e80ae9346fe827822293e025246ac62c497 Mon Sep 17 00:00:00 2001 From: Yabin Cui Date: Wed, 8 May 2024 10:34:49 -0700 Subject: simpleperf: Rotate the last cpu disabling ETM events When using ETR, ETM data is flushed to the aux buffer of the last cpu disabling ETM events. To avoid overflowing the aux buffer for one cpu, rotate the last cpu disabling ETM events. Bug: 336375740 Test: run simpleperf manually Change-Id: I1b5f2b85935513a3485d84fe0b850b8223ad03b4 --- simpleperf/event_selection_set.cpp | 29 +++++++++++++++++++++++++++-- simpleperf/event_selection_set.h | 3 +++ 2 files changed, 30 insertions(+), 2 deletions(-) diff --git a/simpleperf/event_selection_set.cpp b/simpleperf/event_selection_set.cpp index 6a1e5a9e..1a7cdef8 100644 --- a/simpleperf/event_selection_set.cpp +++ b/simpleperf/event_selection_set.cpp @@ -974,9 +974,34 @@ bool EventSelectionSet::DisableETMEvents() { if (!sel.event_type_modifier.event_type.IsEtmEvent()) { continue; } + // When using ETR, ETM data is flushed to the aux buffer of the last cpu disabling ETM events. + // To avoid overflowing the aux buffer for one cpu, rotate the last cpu disabling ETM events. + if (etm_event_cpus_.empty()) { + for (const auto& fd : sel.event_fds) { + etm_event_cpus_.insert(fd->Cpu()); + } + if (etm_event_cpus_.empty()) { + continue; + } + etm_event_cpus_it_ = etm_event_cpus_.begin(); + } + int last_disabled_cpu = *etm_event_cpus_it_; + if (++etm_event_cpus_it_ == etm_event_cpus_.end()) { + etm_event_cpus_it_ = etm_event_cpus_.begin(); + } + for (auto& fd : sel.event_fds) { - if (!fd->SetEnableEvent(false)) { - return false; + if (fd->Cpu() != last_disabled_cpu) { + if (!fd->SetEnableEvent(false)) { + return false; + } + } + } + for (auto& fd : sel.event_fds) { + if (fd->Cpu() == last_disabled_cpu) { + if (!fd->SetEnableEvent(false)) { + return false; + } } } } diff --git a/simpleperf/event_selection_set.h b/simpleperf/event_selection_set.h index 1b3d6b4e..a892d51e 100644 --- a/simpleperf/event_selection_set.h +++ b/simpleperf/event_selection_set.h @@ -235,6 +235,9 @@ class EventSelectionSet { std::optional sample_rate_; std::optional> cpus_; + std::set etm_event_cpus_; + std::set::const_iterator etm_event_cpus_it_; + DISALLOW_COPY_AND_ASSIGN(EventSelectionSet); }; -- cgit v1.2.3 From 7a59f85e59772f2de6315195bffc3290ec730b83 Mon Sep 17 00:00:00 2001 From: Yabin Cui Date: Wed, 8 May 2024 10:55:28 -0700 Subject: simpleperf: Delay processing ETM data until the buffer is half full When using --decode-etm, the main thread is busy processing ETM data and can miss flushing ETM data. To fix this, we can delay processing ETM data after recording. This patch triggers ETM data processing when the buffer is at least half full. In the default configuration, the buffer is large enough to hold ETM data for several seconds. So effectively, this delays processing ETM data after recording. Bug: 336375740 Test: run simpleperf_unit_test Change-Id: Ib892aeea402773b1cab785f2c14886bb9f96d851 --- simpleperf/RecordReadThread.cpp | 12 ++++++++++++ simpleperf/RecordReadThread.h | 1 + 2 files changed, 13 insertions(+) diff --git a/simpleperf/RecordReadThread.cpp b/simpleperf/RecordReadThread.cpp index 2ab61278..2d034bc1 100644 --- a/simpleperf/RecordReadThread.cpp +++ b/simpleperf/RecordReadThread.cpp @@ -408,6 +408,7 @@ bool RecordReadThread::HandleAddEventFds(IOEventLoop& loop, success = false; break; } + has_etm_events_ = true; } cpu_map[fd->Cpu()] = fd; } else { @@ -620,6 +621,9 @@ void RecordReadThread::PushRecordToRecordBuffer(KernelRecordReader* kernel_recor } void RecordReadThread::ReadAuxDataFromKernelBuffer(bool* has_data) { + if (!has_etm_events_) { + return; + } for (auto& reader : kernel_record_readers_) { EventFd* event_fd = reader.GetEventFd(); if (event_fd->HasAuxBuffer()) { @@ -659,6 +663,14 @@ void RecordReadThread::ReadAuxDataFromKernelBuffer(bool* has_data) { } bool RecordReadThread::SendDataNotificationToMainThread() { + if (has_etm_events_) { + // For ETM recording, the default buffer size is large enough to hold ETM data for several + // seconds. To reduce impact of processing ETM data (especially when --decode-etm is used), + // delay processing ETM data until the buffer is half full. + if (record_buffer_.GetFreeSize() >= record_buffer_.size() / 2) { + return true; + } + } if (!has_data_notification_.load(std::memory_order_relaxed)) { has_data_notification_ = true; char unused = 0; diff --git a/simpleperf/RecordReadThread.h b/simpleperf/RecordReadThread.h index c104b083..893f8234 100644 --- a/simpleperf/RecordReadThread.h +++ b/simpleperf/RecordReadThread.h @@ -211,6 +211,7 @@ class RecordReadThread { std::unique_ptr read_thread_; std::vector kernel_record_readers_; pid_t exclude_pid_ = -1; + bool has_etm_events_ = false; std::unordered_set event_fds_disabled_by_kernel_; -- cgit v1.2.3 From 4ce35839e4a012790d2a21428b4ce468d97265f2 Mon Sep 17 00:00:00 2001 From: Yabin Cui Date: Wed, 8 May 2024 13:51:19 -0700 Subject: simpleperf: record: Add --etm-flush-interval Add --etm-flush-interval to adjust the interval between ETM data flushes. So we can use smaller interval when needed. Bug: 336375740 Test: run simpleperf_unit_test Change-Id: I1e6805446fa08ee85e9b4033ff827709c34ae530 --- simpleperf/cmd_record.cpp | 14 +++++++++++--- simpleperf/cmd_record_impl.h | 2 ++ simpleperf/cmd_record_test.cpp | 12 ++++++++++-- 3 files changed, 23 insertions(+), 5 deletions(-) diff --git a/simpleperf/cmd_record.cpp b/simpleperf/cmd_record.cpp index d57c3422..e08b153b 100644 --- a/simpleperf/cmd_record.cpp +++ b/simpleperf/cmd_record.cpp @@ -22,6 +22,7 @@ #include #include #include +#include #include #include #include @@ -111,8 +112,8 @@ static constexpr size_t DEFAULT_CALL_CHAIN_JOINER_CACHE_SIZE = 8 * kMegabyte; static constexpr size_t kDefaultAuxBufferSize = 4 * kMegabyte; // On Pixel 3, it takes about 1ms to enable ETM, and 16-40ms to disable ETM and copy 4M ETM data. -// So make default period to 100ms. -static constexpr double kDefaultEtmDataFlushPeriodInSec = 0.1; +// So make default interval to 100ms. +static constexpr uint32_t kDefaultEtmDataFlushIntervalInMs = 100; struct TimeStat { uint64_t prepare_recording_time = 0; @@ -316,6 +317,8 @@ RECORD_FILTER_OPTION_HELP_MSG_FOR_RECORDING "--record-timestamp Generate timestamp packets in ETM stream.\n" "--record-cycles Generate cycle count packets in ETM stream.\n" "--cycle-threshold Set cycle count counter threshold for ETM cycle count packets.\n" +"--etm-flush-interval Set the interval between ETM data flushes from the ETR buffer\n" +" to the perf event buffer (in milliseconds). Default is 100 ms.\n" "\n" "Other options:\n" "--exit-with-parent Stop recording when the thread starting simpleperf dies.\n" @@ -480,6 +483,7 @@ RECORD_FILTER_OPTION_HELP_MSG_FOR_RECORDING std::unique_ptr etm_branch_list_generator_; std::unique_ptr binary_name_regex_; + std::chrono::milliseconds etm_flush_interval_{kDefaultEtmDataFlushIntervalInMs}; }; std::string RecordCommand::LongHelpString() const { @@ -770,7 +774,7 @@ bool RecordCommand::PrepareRecording(Workload* workload) { auto etm_flush = [this]() { return event_selection_set_.DisableETMEvents() && event_selection_set_.EnableETMEvents(); }; - if (!loop->AddPeriodicEvent(SecondToTimeval(kDefaultEtmDataFlushPeriodInSec), etm_flush)) { + if (!loop->AddPeriodicEvent(SecondToTimeval(etm_flush_interval_.count() / 1000.0), etm_flush)) { return false; } @@ -1052,6 +1056,10 @@ bool RecordCommand::ParseOptions(const std::vector& args, if (options.PullBoolValue("--decode-etm")) { etm_branch_list_generator_ = ETMBranchListGenerator::Create(system_wide_collection_); } + uint32_t interval = 0; + if (options.PullUintValue("--etm-flush-interval", &interval)) { + etm_flush_interval_ = std::chrono::milliseconds(interval); + } if (options.PullBoolValue("--record-timestamp")) { ETMRecorder& recorder = ETMRecorder::GetInstance(); diff --git a/simpleperf/cmd_record_impl.h b/simpleperf/cmd_record_impl.h index 29f44809..e8561636 100644 --- a/simpleperf/cmd_record_impl.h +++ b/simpleperf/cmd_record_impl.h @@ -51,6 +51,8 @@ inline const OptionFormatMap& GetRecordCmdOptionFormats() { {"--cycle-threshold", {OptionValueType::UINT, OptionType::SINGLE, AppRunnerType::ALLOWED}}, {"--decode-etm", {OptionValueType::NONE, OptionType::SINGLE, AppRunnerType::ALLOWED}}, {"--delay", {OptionValueType::UINT, OptionType::SINGLE, AppRunnerType::ALLOWED}}, + {"--etm-flush-interval", + {OptionValueType::UINT, OptionType::SINGLE, AppRunnerType::ALLOWED}}, {"--record-timestamp", {OptionValueType::NONE, OptionType::SINGLE, AppRunnerType::ALLOWED}}, {"--record-cycles", {OptionValueType::NONE, OptionType::SINGLE, AppRunnerType::ALLOWED}}, {"--duration", {OptionValueType::DOUBLE, OptionType::SINGLE, AppRunnerType::ALLOWED}}, diff --git a/simpleperf/cmd_record_test.cpp b/simpleperf/cmd_record_test.cpp index 131f6da4..898d8756 100644 --- a/simpleperf/cmd_record_test.cpp +++ b/simpleperf/cmd_record_test.cpp @@ -1196,8 +1196,7 @@ TEST(record_cmd, cycle_threshold) { GTEST_LOG_(INFO) << "Omit this test since etm isn't supported on this device"; return; } - ASSERT_TRUE(RunRecordCmd({"-e", "cs-etm", "--record-cycles", - "--cycle-threshold", "8"})); + ASSERT_TRUE(RunRecordCmd({"-e", "cs-etm", "--record-cycles", "--cycle-threshold", "8"})); } // @CddTest = 6.1/C-0-2 @@ -1209,6 +1208,15 @@ TEST(record_cmd, binary_option) { ASSERT_TRUE(RunRecordCmd({"-e", "cs-etm", "--decode-etm", "--binary", ".*"})); } +// @CddTest = 6.1/C-0-2 +TEST(record_cmd, etm_flush_interval_option) { + if (!ETMRecorder::GetInstance().CheckEtmSupport().ok()) { + GTEST_LOG_(INFO) << "Omit this test since etm isn't supported on this device"; + return; + } + ASSERT_TRUE(RunRecordCmd({"-e", "cs-etm", "--etm-flush-interval", "10"})); +} + // @CddTest = 6.1/C-0-2 TEST(record_cmd, pmu_event_option) { TEST_REQUIRE_PMU_COUNTER(); -- cgit v1.2.3