From f158a752cf96f9d710314731c6cdc407230a80f6 Mon Sep 17 00:00:00 2001 From: Yabin Cui Date: Mon, 10 Jan 2022 15:35:59 -0800 Subject: profcollectd: add interface to wait for ETM after boot. ETM device may not be ready when profcollectd is started. So this CL adds interface to wait for ETM after boot: 1. In simpleperf_profcollect, split has_support() into has_driver_support() and has_device_support(). 2. In ProfcollectdBinderService and Scheduler, add interface to register ProviderStatusCallback, which is called when the trace provider is ready. 3. In profcollectd, register ProviderStatusCallback after boot. Then record boot profile and schedule periodic recording in the callback. Bug: 213519191 Test: on oriole EVT and DVT devices, profcollectd can record boot Test: profile and periodic profiles. Test: run simpleperf_unit_test. Change-Id: I87befcd372ad85a0131116a7925f303b4990ec47 --- profcollectd/Android.bp | 1 + .../android/server/profcollect/IProfCollectd.aidl | 3 ++ .../profcollect/IProviderStatusCallback.aidl | 22 +++++++++ profcollectd/libprofcollectd/lib.rs | 32 +++++++++++-- .../libprofcollectd/logging_trace_provider.rs | 4 ++ profcollectd/libprofcollectd/scheduler.rs | 54 +++++++++++++++++++++- profcollectd/libprofcollectd/service.rs | 29 +++++++++++- .../simpleperf_etm_trace_provider.rs | 6 ++- profcollectd/libprofcollectd/trace_provider.rs | 1 + simpleperf/ETMRecorder.cpp | 28 +++++------ simpleperf/ETMRecorder.h | 5 +- simpleperf/cmd_record_test.cpp | 8 ++-- simpleperf/event_selection_set.cpp | 3 +- simpleperf/include/simpleperf_profcollect.hpp | 3 +- simpleperf/profcollect.cpp | 10 +++- simpleperf/rust/lib.rs | 13 ++++-- 16 files changed, 190 insertions(+), 32 deletions(-) create mode 100644 profcollectd/binder/com/android/server/profcollect/IProviderStatusCallback.aidl diff --git a/profcollectd/Android.bp b/profcollectd/Android.bp index f1723006..122e4f61 100644 --- a/profcollectd/Android.bp +++ b/profcollectd/Android.bp @@ -59,6 +59,7 @@ filegroup { name: "profcollectd_aidl", srcs: [ "binder/com/android/server/profcollect/IProfCollectd.aidl", + "binder/com/android/server/profcollect/IProviderStatusCallback.aidl", ], path: "binder", } diff --git a/profcollectd/binder/com/android/server/profcollect/IProfCollectd.aidl b/profcollectd/binder/com/android/server/profcollect/IProfCollectd.aidl index c8f33a1e..bfc24446 100644 --- a/profcollectd/binder/com/android/server/profcollect/IProfCollectd.aidl +++ b/profcollectd/binder/com/android/server/profcollect/IProfCollectd.aidl @@ -16,6 +16,8 @@ package com.android.server.profcollect; +import com.android.server.profcollect.IProviderStatusCallback; + /** {@hide} */ interface IProfCollectd { void schedule(); @@ -24,4 +26,5 @@ interface IProfCollectd { void process(); @utf8InCpp String report(); @utf8InCpp String get_supported_provider(); + void registerProviderStatusCallback(IProviderStatusCallback cb); } diff --git a/profcollectd/binder/com/android/server/profcollect/IProviderStatusCallback.aidl b/profcollectd/binder/com/android/server/profcollect/IProviderStatusCallback.aidl new file mode 100644 index 00000000..b311cf91 --- /dev/null +++ b/profcollectd/binder/com/android/server/profcollect/IProviderStatusCallback.aidl @@ -0,0 +1,22 @@ +/* + * Copyright (C) 2022 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.profcollect; + +/** {@hide} */ +oneway interface IProviderStatusCallback { + void onProviderReady(); +} diff --git a/profcollectd/libprofcollectd/lib.rs b/profcollectd/libprofcollectd/lib.rs index abc11272..f95132f4 100644 --- a/profcollectd/libprofcollectd/lib.rs +++ b/profcollectd/libprofcollectd/lib.rs @@ -30,11 +30,34 @@ use anyhow::{Context, Result}; use profcollectd_aidl_interface::aidl::com::android::server::profcollect::IProfCollectd::{ self, BnProfCollectd, }; +use profcollectd_aidl_interface::aidl::com::android::server::profcollect::IProviderStatusCallback::{IProviderStatusCallback, BnProviderStatusCallback}; use profcollectd_aidl_interface::binder::{self, BinderFeatures}; -use service::ProfcollectdBinderService; +use service::{err_to_binder_status, ProfcollectdBinderService}; +use std::time::{Duration, Instant}; const PROFCOLLECTD_SERVICE_NAME: &str = "profcollectd"; +struct ProviderStatusCallback { + service_start_time: Instant, +} + +impl binder::Interface for ProviderStatusCallback {} + +impl IProviderStatusCallback for ProviderStatusCallback { + fn onProviderReady(&self) -> binder::Result<()> { + // If we have waited too long for the provider to be ready, then we have passed + // boot phase, and no need to collect boot profile. + // TODO: should we check boottime instead? + const TIMEOUT_TO_COLLECT_BOOT_PROFILE: Duration = Duration::from_secs(3); + let elapsed = Instant::now().duration_since(self.service_start_time); + if elapsed < TIMEOUT_TO_COLLECT_BOOT_PROFILE { + trace_once("boot").map_err(err_to_binder_status)?; + } + schedule().map_err(err_to_binder_status)?; + Ok(()) + } +} + /// Initialise profcollectd service. /// * `schedule_now` - Immediately schedule collection after service is initialised. pub fn init_service(schedule_now: bool) -> Result<()> { @@ -49,8 +72,11 @@ pub fn init_service(schedule_now: bool) -> Result<()> { .context("Failed to register service.")?; if schedule_now { - trace_once("boot")?; - schedule()?; + let cb = BnProviderStatusCallback::new_binder( + ProviderStatusCallback { service_start_time: Instant::now() }, + BinderFeatures::default(), + ); + get_profcollectd_service()?.registerProviderStatusCallback(&cb)?; } binder::ProcessState::join_thread_pool(); diff --git a/profcollectd/libprofcollectd/logging_trace_provider.rs b/profcollectd/libprofcollectd/logging_trace_provider.rs index 1325855d..fda4c66a 100644 --- a/profcollectd/libprofcollectd/logging_trace_provider.rs +++ b/profcollectd/libprofcollectd/logging_trace_provider.rs @@ -32,6 +32,10 @@ impl TraceProvider for LoggingTraceProvider { "logging" } + fn is_ready(&self) -> bool { + true + } + fn trace(&self, trace_dir: &Path, tag: &str, sampling_period: &Duration) { let trace_file = trace_provider::get_path(trace_dir, tag, LOGGING_TRACEFILE_EXTENSION); diff --git a/profcollectd/libprofcollectd/scheduler.rs b/profcollectd/libprofcollectd/scheduler.rs index 31a495a5..f58c4995 100644 --- a/profcollectd/libprofcollectd/scheduler.rs +++ b/profcollectd/libprofcollectd/scheduler.rs @@ -17,11 +17,13 @@ //! ProfCollect tracing scheduler. use std::fs; +use std::mem; use std::path::Path; use std::sync::mpsc::{sync_channel, SyncSender}; use std::sync::Arc; use std::sync::Mutex; use std::thread; +use std::time::{Duration, Instant}; use crate::config::{Config, PROFILE_OUTPUT_DIR, TRACE_OUTPUT_DIR}; use crate::trace_provider::{self, TraceProvider}; @@ -33,12 +35,17 @@ pub struct Scheduler { termination_ch: Option>, /// The preferred trace provider for the system. trace_provider: Arc>, + provider_ready_callbacks: Arc>>>, } impl Scheduler { pub fn new() -> Result { let p = trace_provider::get_trace_provider()?; - Ok(Scheduler { termination_ch: None, trace_provider: p }) + Ok(Scheduler { + termination_ch: None, + trace_provider: p, + provider_ready_callbacks: Arc::new(Mutex::new(Vec::new())), + }) } fn is_scheduled(&self) -> bool { @@ -106,6 +113,51 @@ impl Scheduler { pub fn get_trace_provider_name(&self) -> &'static str { self.trace_provider.lock().unwrap().get_name() } + + pub fn is_provider_ready(&self) -> bool { + self.trace_provider.lock().unwrap().is_ready() + } + + pub fn register_provider_ready_callback(&self, cb: Box) { + let mut locked_callbacks = self.provider_ready_callbacks.lock().unwrap(); + locked_callbacks.push(cb); + if locked_callbacks.len() == 1 { + self.start_thread_waiting_for_provider_ready(); + } + } + + fn start_thread_waiting_for_provider_ready(&self) { + let provider = self.trace_provider.clone(); + let callbacks = self.provider_ready_callbacks.clone(); + + thread::spawn(move || { + let start_time = Instant::now(); + loop { + let elapsed = Instant::now().duration_since(start_time); + if provider.lock().unwrap().is_ready() { + break; + } + // Decide check period based on how long we have waited: + // For the first 10s waiting, check every 100ms (likely to work on EVT devices). + // For the first 10m waiting, check every 10s (likely to work on DVT devices). + // For others, check every 10m. + let sleep_duration = if elapsed < Duration::from_secs(10) { + Duration::from_millis(100) + } else if elapsed < Duration::from_secs(60 * 10) { + Duration::from_secs(10) + } else { + Duration::from_secs(60 * 10) + }; + thread::sleep(sleep_duration); + } + + let mut locked_callbacks = callbacks.lock().unwrap(); + let v = mem::take(&mut *locked_callbacks); + for cb in v { + cb(); + } + }); + } } /// Run if space usage is under limit. diff --git a/profcollectd/libprofcollectd/service.rs b/profcollectd/libprofcollectd/service.rs index 0199c105..3f338024 100644 --- a/profcollectd/libprofcollectd/service.rs +++ b/profcollectd/libprofcollectd/service.rs @@ -18,8 +18,9 @@ use anyhow::{anyhow, Context, Error, Result}; use binder::Result as BinderResult; -use binder::Status; +use binder::{SpIBinder, Status}; use profcollectd_aidl_interface::aidl::com::android::server::profcollect::IProfCollectd::IProfCollectd; +use profcollectd_aidl_interface::aidl::com::android::server::profcollect::IProviderStatusCallback::IProviderStatusCallback; use std::ffi::CString; use std::fs::{read_dir, read_to_string, remove_file, write}; use std::str::FromStr; @@ -32,7 +33,7 @@ use crate::config::{ use crate::report::{get_report_ts, pack_report}; use crate::scheduler::Scheduler; -fn err_to_binder_status(msg: Error) -> Status { +pub fn err_to_binder_status(msg: Error) -> Status { let msg = format!("{:#?}", msg); let msg = CString::new(msg).expect("Failed to convert to CString"); Status::new_service_specific_error(1, Some(&msg)) @@ -89,6 +90,30 @@ impl IProfCollectd for ProfcollectdBinderService { fn get_supported_provider(&self) -> BinderResult { Ok(self.lock().scheduler.get_trace_provider_name().to_string()) } + + fn registerProviderStatusCallback( + &self, + cb: &binder::Strong<(dyn IProviderStatusCallback)>, + ) -> BinderResult<()> { + if self.lock().scheduler.is_provider_ready() { + if let Err(e) = cb.onProviderReady() { + log::error!("Failed to call ProviderStatusCallback {:?}", e); + } + return Ok(()); + } + + let cb_binder: SpIBinder = cb.as_binder(); + self.lock().scheduler.register_provider_ready_callback(Box::new(move || { + if let Ok(cb) = cb_binder.into_interface::() { + if let Err(e) = cb.onProviderReady() { + log::error!("Failed to call ProviderStatusCallback {:?}", e) + } + } else { + log::error!("SpIBinder is not a IProviderStatusCallback."); + } + })); + Ok(()) + } } impl ProfcollectdBinderService { diff --git a/profcollectd/libprofcollectd/simpleperf_etm_trace_provider.rs b/profcollectd/libprofcollectd/simpleperf_etm_trace_provider.rs index 14fb7509..f25f5ffc 100644 --- a/profcollectd/libprofcollectd/simpleperf_etm_trace_provider.rs +++ b/profcollectd/libprofcollectd/simpleperf_etm_trace_provider.rs @@ -34,6 +34,10 @@ impl TraceProvider for SimpleperfEtmTraceProvider { "simpleperf_etm" } + fn is_ready(&self) -> bool { + simpleperf_profcollect::has_device_support() + } + fn trace(&self, trace_dir: &Path, tag: &str, sampling_period: &Duration) { let trace_file = trace_provider::get_path(trace_dir, tag, ETM_TRACEFILE_EXTENSION); @@ -76,6 +80,6 @@ impl TraceProvider for SimpleperfEtmTraceProvider { impl SimpleperfEtmTraceProvider { pub fn supported() -> bool { - simpleperf_profcollect::has_support() + simpleperf_profcollect::has_driver_support() } } diff --git a/profcollectd/libprofcollectd/trace_provider.rs b/profcollectd/libprofcollectd/trace_provider.rs index 98cd5ec4..13059199 100644 --- a/profcollectd/libprofcollectd/trace_provider.rs +++ b/profcollectd/libprofcollectd/trace_provider.rs @@ -29,6 +29,7 @@ use crate::logging_trace_provider::LoggingTraceProvider; pub trait TraceProvider { fn get_name(&self) -> &'static str; + fn is_ready(&self) -> bool; fn trace(&self, trace_dir: &Path, tag: &str, sampling_period: &Duration); fn process(&self, trace_dir: &Path, profile_dir: &Path, binary_filter: &str) -> Result<()>; } diff --git a/simpleperf/ETMRecorder.cpp b/simpleperf/ETMRecorder.cpp index 7bef4f21..554e8f52 100644 --- a/simpleperf/ETMRecorder.cpp +++ b/simpleperf/ETMRecorder.cpp @@ -23,6 +23,7 @@ #include #include +#include #include #include #include @@ -34,6 +35,9 @@ namespace simpleperf { +using android::base::expected; +using android::base::unexpected; + static constexpr bool ETM_RECORD_TIMESTAMP = false; static const std::string ETM_DIR = "/sys/bus/event_source/devices/cs_etm/"; @@ -103,32 +107,30 @@ std::unique_ptr ETMRecorder::BuildEventType() { "CoreSight ETM instruction tracing", "arm"); } -bool ETMRecorder::CheckEtmSupport() { +bool ETMRecorder::IsETMDriverAvailable() { + return IsDir(ETM_DIR); +} + +expected ETMRecorder::CheckEtmSupport() { if (GetEtmEventType() == -1) { - LOG(ERROR) << "etm event type isn't supported on device"; - return false; + return unexpected("etm event type isn't supported on device"); } if (!ReadEtmInfo()) { - LOG(ERROR) << "etm devices are not available"; - return false; + return unexpected("etm devices are not available"); } for (const auto& p : etm_info_) { if (p.second.GetMajorVersion() < 4) { - LOG(ERROR) << "etm device version is less than 4.0"; - return false; + return unexpected("etm device version is less than 4.0"); } if (!p.second.IsContextIDSupported()) { - LOG(ERROR) << "etm device doesn't support contextID"; - return false; + return unexpected("etm device doesn't support contextID"); } if (!p.second.IsEnabled()) { - LOG(ERROR) << "etm device isn't enabled by the bootloader"; - return false; + return unexpected("etm device isn't enabled by the bootloader"); } } if (!FindSinkConfig()) { - LOG(ERROR) << "can't find etr device, which moves etm data to memory"; - return false; + return unexpected("can't find etr device, which moves etm data to memory"); } etm_supported_ = true; return true; diff --git a/simpleperf/ETMRecorder.h b/simpleperf/ETMRecorder.h index 1e33ed80..f304f601 100644 --- a/simpleperf/ETMRecorder.h +++ b/simpleperf/ETMRecorder.h @@ -21,6 +21,8 @@ #include #include +#include + #include "event_type.h" #include "perf_event.h" #include "record.h" @@ -55,7 +57,8 @@ class ETMRecorder { // If not found, return -1. int GetEtmEventType(); std::unique_ptr BuildEventType(); - bool CheckEtmSupport(); + bool IsETMDriverAvailable(); + android::base::expected CheckEtmSupport(); void SetEtmPerfEventAttr(perf_event_attr* attr); AuxTraceInfoRecord CreateAuxTraceInfoRecord(); size_t GetAddrFilterPairs(); diff --git a/simpleperf/cmd_record_test.cpp b/simpleperf/cmd_record_test.cpp index f51393f2..ef2c1b68 100644 --- a/simpleperf/cmd_record_test.cpp +++ b/simpleperf/cmd_record_test.cpp @@ -917,7 +917,7 @@ TEST(record_cmd, no_cut_samples_option) { } TEST(record_cmd, cs_etm_event) { - if (!ETMRecorder::GetInstance().CheckEtmSupport()) { + if (!ETMRecorder::GetInstance().CheckEtmSupport().ok()) { GTEST_LOG_(INFO) << "Omit this test since etm isn't supported on this device"; return; } @@ -952,7 +952,7 @@ TEST(record_cmd, cs_etm_event) { TEST(record_cmd, cs_etm_system_wide) { TEST_REQUIRE_ROOT(); - if (!ETMRecorder::GetInstance().CheckEtmSupport()) { + if (!ETMRecorder::GetInstance().CheckEtmSupport().ok()) { GTEST_LOG_(INFO) << "Omit this test since etm isn't supported on this device"; return; } @@ -960,7 +960,7 @@ TEST(record_cmd, cs_etm_system_wide) { } TEST(record_cmd, aux_buffer_size_option) { - if (!ETMRecorder::GetInstance().CheckEtmSupport()) { + if (!ETMRecorder::GetInstance().CheckEtmSupport().ok()) { GTEST_LOG_(INFO) << "Omit this test since etm isn't supported on this device"; return; } @@ -973,7 +973,7 @@ TEST(record_cmd, aux_buffer_size_option) { TEST(record_cmd, addr_filter_option) { TEST_REQUIRE_HW_COUNTER(); - if (!ETMRecorder::GetInstance().CheckEtmSupport()) { + if (!ETMRecorder::GetInstance().CheckEtmSupport().ok()) { GTEST_LOG_(INFO) << "Omit this test since etm isn't supported on this device"; return; } diff --git a/simpleperf/event_selection_set.cpp b/simpleperf/event_selection_set.cpp index a6d9a7e0..d5bca318 100644 --- a/simpleperf/event_selection_set.cpp +++ b/simpleperf/event_selection_set.cpp @@ -217,7 +217,8 @@ bool EventSelectionSet::BuildAndCheckEventSelection(const std::string& event_nam selection->event_attr.precise_ip = event_type->precise_ip; if (IsEtmEventType(event_type->event_type.type)) { auto& etm_recorder = ETMRecorder::GetInstance(); - if (!etm_recorder.CheckEtmSupport()) { + if (auto result = etm_recorder.CheckEtmSupport(); !result.ok()) { + LOG(ERROR) << result.error(); return false; } ETMRecorder::GetInstance().SetEtmPerfEventAttr(&selection->event_attr); diff --git a/simpleperf/include/simpleperf_profcollect.hpp b/simpleperf/include/simpleperf_profcollect.hpp index f2c48da6..67123e58 100644 --- a/simpleperf/include/simpleperf_profcollect.hpp +++ b/simpleperf/include/simpleperf_profcollect.hpp @@ -16,7 +16,8 @@ extern "C" { -bool HasSupport(); +bool HasDriverSupport(); +bool HasDeviceSupport(); bool Record(const char* event_name, const char* output, float duration); bool Inject(const char* traceInput, const char* profileOutput, const char* binary_filter); } diff --git a/simpleperf/profcollect.cpp b/simpleperf/profcollect.cpp index 3f64abd1..39c04ab7 100644 --- a/simpleperf/profcollect.cpp +++ b/simpleperf/profcollect.cpp @@ -24,8 +24,14 @@ using namespace simpleperf; -bool HasSupport() { - if (!ETMRecorder::GetInstance().CheckEtmSupport()) { +bool HasDriverSupport() { + return ETMRecorder::GetInstance().IsETMDriverAvailable(); +} + +bool HasDeviceSupport() { + auto result = ETMRecorder::GetInstance().CheckEtmSupport(); + if (!result.ok()) { + LOG(DEBUG) << result.error(); return false; } const EventType* type = FindEventTypeByName("cs-etm", false); diff --git a/simpleperf/rust/lib.rs b/simpleperf/rust/lib.rs index c76bf0ea..7d39273e 100644 --- a/simpleperf/rust/lib.rs +++ b/simpleperf/rust/lib.rs @@ -25,9 +25,16 @@ fn path_to_cstr(path: &Path) -> CString { CString::new(path.to_str().unwrap()).unwrap() } -/// Returns whether the system has support for simpleperf etm. -pub fn has_support() -> bool { - unsafe { simpleperf_profcollect_bindgen::HasSupport() } +/// Returns whether the system has etm driver. ETM driver should be available immediately +/// after boot. +pub fn has_driver_support() -> bool { + unsafe { simpleperf_profcollect_bindgen::HasDriverSupport() } +} + +/// Returns whether the system has etm device. ETM device may not be available immediately +/// after boot. +pub fn has_device_support() -> bool { + unsafe { simpleperf_profcollect_bindgen::HasDeviceSupport() } } /// ETM recording scope -- cgit v1.2.3